ViewVC Help
View File | Revision Log | Show Annotations | Download File
/cvs/Coro/Coro/Debug.pm
Revision: 1.113
Committed: Thu Dec 13 00:20:40 2012 UTC (11 years, 5 months ago) by root
Branch: MAIN
Changes since 1.112: +3 -1 lines
Log Message:
*** empty log message ***

File Contents

# Content
1 =head1 NAME
2
3 Coro::Debug - various functions that help debugging Coro programs
4
5 =head1 SYNOPSIS
6
7 use Coro::Debug;
8
9 our $server = new_unix_server Coro::Debug "/tmp/socketpath";
10
11 $ socat readline unix:/tmp/socketpath
12
13 =head1 DESCRIPTION
14
15 This module is an L<AnyEvent> user, you need to make sure that you use and
16 run a supported event loop.
17
18 This module provides some debugging facilities. Most will, if not handled
19 carefully, severely compromise the security of your program, so use it
20 only for debugging (or take other precautions).
21
22 It mainly implements a very primitive debugger that is evry easy to
23 integrate in your program:
24
25 our $server = new_unix_server Coro::Debug "/tmp/somepath";
26 # see new_unix_server, below, for more info
27
28 It lets you list running coroutines:
29
30 state (rUnning, Ready, New or neither)
31 |cctx allocated
32 || resident set size (octets)
33 || | scheduled this many times
34 > ps || | |
35 PID SC RSS USES Description Where
36 14572344 UC 62k 128k [main::] [dm-support.ext:47]
37 14620056 -- 2260 13 [coro manager] [Coro.pm:358]
38 14620128 -- 2260 166 [unblock_sub scheduler] [Coro.pm:358]
39 17764008 N- 152 0 [EV idle process] -
40 13990784 -- 2596 10k timeslot manager [cf.pm:454]
41 81424176 -- 18k 4758 [async pool idle] [Coro.pm:257]
42 23513336 -- 2624 1 follow handler [follow.ext:52]
43 40548312 -- 15k 5597 player scheduler [player-scheduler.ext:13]
44 29138032 -- 2548 431 music scheduler [player-env.ext:77]
45 43449808 -- 2260 3493 worldmap updater [item-worldmap.ext:115]
46 33352488 -- 19k 2845 [async pool idle] [Coro.pm:257]
47 81530072 -- 13k 43k map scheduler [map-scheduler.ext:65]
48 30751144 -- 15k 2204 [async pool idle] [Coro.pm:257]
49
50 Lets you do backtraces on about any coroutine:
51
52 > bt 18334288
53 coroutine is at /opt/cf/ext/player-env.ext line 77
54 eval {...} called at /opt/cf/ext/player-env.ext line 77
55 ext::player_env::__ANON__ called at -e line 0
56 Coro::_run_coro called at -e line 0
57
58 Or lets you eval perl code:
59
60 > 5+7
61 12
62
63 Or lets you eval perl code within other coroutines:
64
65 > eval 18334288 caller(1); $DB::args[0]->method
66 1
67
68 It can also trace subroutine entry/exits for most coroutines (those not
69 having recursed into a C function), resulting in output similar to:
70
71 > loglevel 5
72 > trace 94652688
73 2007-09-27Z20:30:25.1368 (5) [94652688] enter Socket::sockaddr_in with (8481,\x{7f}\x{00}\x{00}\x{01})
74 2007-09-27Z20:30:25.1369 (5) [94652688] leave Socket::sockaddr_in returning (\x{02}\x{00}...)
75 2007-09-27Z20:30:25.1370 (5) [94652688] enter Net::FCP::Util::touc with (client_get)
76 2007-09-27Z20:30:25.1371 (5) [94652688] leave Net::FCP::Util::touc returning (ClientGet)
77 2007-09-27Z20:30:25.1372 (5) [94652688] enter AnyEvent::Impl::Event::io with (AnyEvent,fh,GLOB(0x9256250),poll,w,cb,CODE(0x8c963a0))
78 2007-09-27Z20:30:25.1373 (5) [94652688] enter Event::Watcher::__ANON__ with (Event,poll,w,fd,GLOB(0x9256250),cb,CODE(0x8c963a0))
79 2007-09-27Z20:30:25.1374 (5) [94652688] enter Event::io::new with (Event::io,poll,w,fd,GLOB(0x9256250),cb,CODE(0x8c963a0))
80 2007-09-27Z20:30:25.1375 (5) [94652688] enter Event::Watcher::init with (Event::io=HASH(0x8bfb120),HASH(0x9b7940))
81
82 If your program uses the Coro::Debug::log facility:
83
84 Coro::Debug::log 0, "important message";
85 Coro::Debug::log 9, "unimportant message";
86
87 Then you can even receive log messages in any debugging session:
88
89 > loglevel 5
90 2007-09-26Z02:22:46 (9) unimportant message
91
92 Other commands are available in the shell, use the C<help> command for a list.
93
94 =head1 FUNCTIONS
95
96 None of the functions are being exported.
97
98 =over 4
99
100 =cut
101
102 package Coro::Debug;
103
104 use common::sense;
105
106 use overload ();
107
108 use Carp ();
109 use Time::HiRes ();
110 use Scalar::Util ();
111
112 use Guard;
113
114 use AnyEvent ();
115 use AnyEvent::Util ();
116 use AnyEvent::Socket ();
117
118 use Coro ();
119 use Coro::Handle ();
120 use Coro::State ();
121 use Coro::AnyEvent ();
122 use Coro::Timer ();
123
124 our $VERSION = 6.23;
125
126 our %log;
127 our $SESLOGLEVEL = exists $ENV{PERL_CORO_DEFAULT_LOGLEVEL} ? $ENV{PERL_CORO_DEFAULT_LOGLEVEL} : -1;
128 our $ERRLOGLEVEL = exists $ENV{PERL_CORO_STDERR_LOGLEVEL} ? $ENV{PERL_CORO_STDERR_LOGLEVEL} : -1;
129
130 sub find_coro {
131 my ($pid) = @_;
132
133 if (my ($coro) = grep $_ == $pid, Coro::State::list) {
134 $coro
135 } else {
136 print "$pid: no such coroutine\n";
137 undef
138 }
139 }
140
141 sub format_msg($$) {
142 my ($time, $micro) = Time::HiRes::gettimeofday;
143 my ($sec, $min, $hour, $day, $mon, $year) = gmtime $time;
144 my $date = sprintf "%04d-%02d-%02dZ%02d:%02d:%02d.%04d",
145 $year + 1900, $mon + 1, $day, $hour, $min, $sec, $micro / 100;
146 sprintf "%s (%d) %s", $date, $_[0], $_[1]
147 }
148
149 sub format_num4($) {
150 my ($v) = @_;
151
152 return sprintf "%4d" , $v if $v < 1e4;
153 # 1e5 redundant
154 return sprintf "%3.0fk", $v / 1_000 if $v < 1e6;
155 return sprintf "%1.1fM", $v / 1_000_000 if $v < 1e7 * .995;
156 return sprintf "%3.0fM", $v / 1_000_000 if $v < 1e9;
157 return sprintf "%1.1fG", $v / 1_000_000_000 if $v < 1e10 * .995;
158 return sprintf "%3.0fG", $v / 1_000_000_000 if $v < 1e12;
159 return sprintf "%1.1fT", $v / 1_000_000_000_000 if $v < 1e13 * .995;
160 return sprintf "%3.0fT", $v / 1_000_000_000_000 if $v < 1e15;
161
162 "++++"
163 }
164
165 =item log $level, $msg
166
167 Log a debug message of the given severity level (0 is highest, higher is
168 less important) to all interested parties.
169
170 =item stderr_loglevel $level
171
172 Set the loglevel for logging to stderr (defaults to the value of the
173 environment variable PERL_CORO_STDERR_LOGLEVEL, or -1 if missing).
174
175 =item session_loglevel $level
176
177 Set the default loglevel for new coro debug sessions (defaults to the
178 value of the environment variable PERL_CORO_DEFAULT_LOGLEVEL, or -1 if
179 missing).
180
181 =cut
182
183 sub log($$) {
184 my ($level, $msg) = @_;
185 $msg =~ s/\s*$/\n/;
186 $_->($level, $msg) for values %log;
187 printf STDERR format_msg $level, $msg if $level <= $ERRLOGLEVEL;
188 }
189
190 sub session_loglevel($) {
191 $SESLOGLEVEL = shift;
192 }
193
194 sub stderr_loglevel($) {
195 $ERRLOGLEVEL = shift;
196 }
197
198 =item trace $coro, $loglevel
199
200 Enables tracing the given coroutine at the given loglevel. If loglevel is
201 omitted, use 5. If coro is omitted, trace the current coroutine. Tracing
202 incurs a very high runtime overhead.
203
204 It is not uncommon to enable tracing on oneself by simply calling
205 C<Coro::Debug::trace>.
206
207 A message will be logged at the given loglevel if it is not possible to
208 enable tracing.
209
210 =item untrace $coro
211
212 Disables tracing on the given coroutine.
213
214 =cut
215
216 sub trace {
217 my ($coro, $loglevel) = @_;
218
219 $coro ||= $Coro::current;
220 $loglevel = 5 unless defined $loglevel;
221
222 (Coro::async {
223 if (eval { Coro::State::trace $coro, Coro::State::CC_TRACE | Coro::State::CC_TRACE_SUB; 1 }) {
224 Coro::Debug::log $loglevel, sprintf "[%d] tracing enabled", $coro + 0;
225 $coro->{_trace_line_cb} = sub {
226 Coro::Debug::log $loglevel, sprintf "[%d] at %s:%d\n", $Coro::current+0, @_;
227 };
228 $coro->{_trace_sub_cb} = sub {
229 Coro::Debug::log $loglevel, sprintf "[%d] %s %s %s\n",
230 $Coro::current+0,
231 $_[0] ? "enter" : "leave",
232 $_[1],
233 $_[2] ? ($_[0] ? "with (" : "returning (") . (
234 join ",",
235 map {
236 my $x = ref $_ ? overload::StrVal $_ : $_;
237 (substr $x, 40) = "..." if 40 + 3 < length $x;
238 $x =~ s/([^\x20-\x5b\x5d-\x7e])/sprintf "\\x{%02x}", ord $1/ge;
239 $x
240 } @{$_[2]}
241 ) . ")" : "";
242 };
243
244 undef $coro; # the subs keep a reference which we do not want them to do
245 } else {
246 Coro::Debug::log $loglevel, sprintf "[%d] unable to enable tracing: %s", $Coro::current + 0, $@;
247 }
248 })->prio (Coro::PRIO_MAX);
249
250 Coro::cede;
251 }
252
253 sub untrace {
254 my ($coro) = @_;
255
256 $coro ||= $Coro::current;
257
258 (Coro::async {
259 Coro::State::trace $coro, 0;
260 delete $coro->{_trace_sub_cb};
261 delete $coro->{_trace_line_cb};
262 })->prio (Coro::PRIO_MAX);
263
264 Coro::cede;
265 }
266
267 sub ps_listing {
268 my $times = Coro::State::enable_times;
269 my $flags = $1;
270 my $verbose = $flags =~ /v/;
271 my $desc_format = $flags =~ /w/ ? "%-24s" : "%-24.24s";
272 my $tim0_format = $times ? " %9s %8s " : " ";
273 my $tim1_format = $times ? " %9.3f %8.3f " : " ";
274 my $buf = sprintf "%20s %s%s %4s %4s$tim0_format$desc_format %s\n",
275 "PID", "S", "C", "RSS", "USES",
276 $times ? ("t_real", "t_cpu") : (),
277 "Description", "Where";
278 for my $coro (reverse Coro::State::list) {
279 my @bt;
280 Coro::State::call ($coro, sub {
281 # we try to find *the* definite frame that gives msot useful info
282 # by skipping Coro frames and pseudo-frames.
283 for my $frame (1..10) {
284 my @frame = caller $frame;
285 @bt = @frame if $frame[2];
286 last unless $bt[0] =~ /^Coro/;
287 }
288 });
289 $bt[1] =~ s/^.*[\/\\]// if @bt && !$verbose;
290 $buf .= sprintf "%20s %s%s %4s %4s$tim1_format$desc_format %s\n",
291 $coro+0,
292 $coro->is_new ? "N" : $coro->is_running ? "U" : $coro->is_ready ? "R" : "-",
293 $coro->is_traced ? "T" : $coro->has_cctx ? "C" : "-",
294 format_num4 $coro->rss,
295 format_num4 $coro->usecount,
296 $times ? $coro->times : (),
297 $coro->debug_desc,
298 (@bt ? sprintf "[%s:%d]", $bt[1], $bt[2] : "-");
299 }
300
301 $buf
302 }
303
304 =item command $string
305
306 Execute a debugger command, sending any output to STDOUT. Used by
307 C<session>, below.
308
309 =cut
310
311 sub command($) {
312 my ($cmd) = @_;
313
314 $cmd =~ s/\s+$//;
315
316 if ($cmd =~ /^ps (?:\s* (\S+))? $/x) {
317 print ps_listing;
318
319 } elsif ($cmd =~ /^bt\s+(\d+)$/) {
320 if (my $coro = find_coro $1) {
321 my $bt;
322 Coro::State::call ($coro, sub {
323 local $Carp::CarpLevel = 2;
324 $bt = eval { Carp::longmess "coroutine is" } || "$@";
325 });
326 if ($bt) {
327 print $bt;
328 } else {
329 print "$1: unable to get backtrace\n";
330 }
331 }
332
333 } elsif ($cmd =~ /^(?:e|eval)\s+(\d+)\s+(.*)$/) {
334 if (my $coro = find_coro $1) {
335 my $cmd = eval "sub { $2 }";
336 my @res;
337 Coro::State::call ($coro, sub { @res = eval { &$cmd } });
338 print $@ ? $@ : (join " ", @res, "\n");
339 }
340
341 } elsif ($cmd =~ /^(?:tr|trace)\s+(\d+)$/) {
342 if (my $coro = find_coro $1) {
343 trace $coro;
344 }
345
346 } elsif ($cmd =~ /^(?:ut|untrace)\s+(\d+)$/) {
347 if (my $coro = find_coro $1) {
348 untrace $coro;
349 }
350
351 } elsif ($cmd =~ /^cancel\s+(\d+)$/) {
352 if (my $coro = find_coro $1) {
353 $coro->cancel;
354 }
355
356 } elsif ($cmd =~ /^ready\s+(\d+)$/) {
357 if (my $coro = find_coro $1) {
358 $coro->ready;
359 }
360
361 } elsif ($cmd =~ /^kill\s+(\d+)(?:\s+(.*))?$/) {
362 my $reason = defined $2 ? $2 : "killed";
363
364 if (my $coro = find_coro $1) {
365 $coro->throw ($reason);
366 }
367
368 } elsif ($cmd =~ /^enable_times(\s+\S.*)?\s*$/) {
369 my $enable = defined $1 ? 1*eval $1 : !Coro::State::enable_times;
370
371 Coro::State::enable_times $enable;
372
373 print "per-thread real and process time gathering ", $enable ? "enabled" : "disabled", ".\n";
374
375 } elsif ($cmd =~ /^help$/) {
376 print <<EOF;
377 ps [w|v] show the list of all coroutines (wide, verbose)
378 bt <pid> show a full backtrace of coroutine <pid>
379 eval <pid> <perl> evaluate <perl> expression in context of <pid>
380 trace <pid> enable tracing for this coroutine
381 untrace <pid> disable tracing for this coroutine
382 kill <pid> <reason> throws the given <reason> string in <pid>
383 cancel <pid> cancels this coroutine
384 ready <pid> force <pid> into the ready queue
385 enable_times <enable> enable or disable time profiling in ps
386 <anything else> evaluate as perl and print results
387 <anything else> & same as above, but evaluate asynchronously
388 you can use (find_coro <pid>) in perl expressions
389 to find the coro with the given pid, e.g.
390 (find_coro 9768720)->ready
391 EOF
392
393 } elsif ($cmd =~ /^(.*)&$/) {
394 my $cmd = $1;
395 my $sub = eval "sub { $cmd }";
396 my $fh = select;
397 Coro::async_pool {
398 $Coro::current->{desc} = $cmd;
399 my $t = Time::HiRes::time;
400 my @res = eval { &$sub };
401 $t = Time::HiRes::time - $t;
402 print {$fh}
403 "\rcommand: $cmd\n",
404 "execution time: $t\n",
405 "result: ", $@ ? $@ : (join " ", @res) . "\n",
406 "> ";
407 };
408
409 } else {
410 my @res = eval $cmd;
411 print $@ ? $@ : (join " ", @res) . "\n";
412 }
413
414 local $| = 1;
415 }
416
417 =item session $fh
418
419 Run an interactive debugger session on the given filehandle. Each line entered
420 is simply passed to C<command> (with a few exceptions).
421
422 =cut
423
424 sub session($) {
425 my ($fh) = @_;
426
427 $fh = Coro::Handle::unblock $fh;
428 my $old_fh = select $fh;
429 my $guard = guard { select $old_fh };
430
431 my $loglevel = $SESLOGLEVEL;
432 local $log{$Coro::current} = sub {
433 return unless $_[0] <= $loglevel;
434 print $fh "\015", (format_msg $_[0], $_[1]), "> ";
435 };
436
437 print "coro debug session. use help for more info\n\n";
438
439 while ((print "> "), defined (my $cmd = $fh->readline ("\012"))) {
440 if ($cmd =~ /^exit\s*$/) {
441 print "bye.\n";
442 last;
443
444 } elsif ($cmd =~ /^(?:ll|loglevel)\s*(\d+)?\s*/) {
445 $loglevel = defined $1 ? $1 : -1;
446
447 } elsif ($cmd =~ /^(?:w|watch)\s*([0-9.]*)\s+(.*)/) {
448 my ($time, $cmd) = ($1*1 || 1, $2);
449 my $cancel;
450
451 Coro::async {
452 $Coro::current->{desc} = "watch $cmd";
453 select $fh;
454 until ($cancel) {
455 command $cmd;
456 Coro::Timer::sleep $time;
457 }
458 };
459
460 $fh->readable;
461 $cancel = 1;
462
463 } elsif ($cmd =~ /^help\s*/) {
464 command $cmd;
465 print <<EOF;
466 loglevel <int> enable logging for messages of level <int> and lower
467 watch <time> <command> repeat the given command until STDIN becomes readable
468 exit end this session
469 EOF
470 } else {
471 command $cmd;
472 }
473
474 Coro::cede;
475 }
476 }
477
478 =item $server = new_unix_server Coro::Debug $path
479
480 Creates a new unix domain socket that listens for connection requests and
481 runs C<session> on any connection. Normal unix permission checks and umask
482 applies, so you can protect your socket by puttint it into a protected
483 directory.
484
485 The C<socat> utility is an excellent way to connect to this socket:
486
487 socat readline /path/to/socket
488
489 Socat also offers history support:
490
491 socat readline:history=/tmp/hist.corodebug /path/to/socket
492
493 The server accepts connections until it is destroyed, so you must keep
494 the return value around as long as you want the server to stay available.
495
496 =cut
497
498 sub new_unix_server {
499 my ($class, $path) = @_;
500
501 unlink $path;
502 my $unlink_guard = guard { unlink $path };
503
504 AnyEvent::Socket::tcp_server "unix/", $path, sub {
505 my ($fh) = @_;
506 $unlink_guard; # mention it
507 Coro::async_pool {
508 $Coro::current->desc ("[Coro::Debug session]");
509 session $fh;
510 };
511 } or Carp::croak "Coro::Debug::new_unix_server($path): $!";
512 }
513
514 =item $server = new_tcp_server Coro::Debug $port
515
516 Similar to C<new_unix_server>, but binds on a TCP port. I<Note that this is
517 usually results in a gaping security hole>.
518
519 Currently, only a TCPv4 socket is created, in the future, a TCPv6 socket
520 might also be created.
521
522 =cut
523
524 sub new_tcp_server {
525 my ($class, $port) = @_;
526
527 AnyEvent::Socket::tcp_server undef, $port, sub {
528 my ($fh) = @_;
529 Coro::async_pool {
530 $Coro::current->desc ("[Coro::Debug session]");
531 session $fh;
532 };
533 } or Carp::croak "Coro::Debug::new_tcp_server($port): $!";
534 }
535
536 sub DESTROY {
537 my ($self) = @_;
538
539 unlink $self->{path} if exists $self->{path};
540 %$self = ();
541 }
542
543 1;
544
545 =back
546
547 =head1 AUTHOR
548
549 Marc Lehmann <schmorp@schmorp.de>
550 http://home.schmorp.de/
551
552 =cut
553
554