ViewVC Help
View File | Revision Log | Show Annotations | Download File
/cvs/Coro/Coro/Debug.pm
Revision: 1.84
Committed: Mon Jul 6 03:42:29 2009 UTC (14 years, 11 months ago) by root
Branch: MAIN
CVS Tags: rel-5_151
Changes since 1.83: +1 -1 lines
Log Message:
5.151

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 strict qw(subs vars);
105 no warnings;
106
107 use overload ();
108
109 use Carp ();
110 use Time::HiRes ();
111 use Scalar::Util ();
112
113 use Guard;
114
115 use AnyEvent ();
116 use AnyEvent::Util ();
117 use AnyEvent::Socket ();
118
119 use Coro ();
120 use Coro::Handle ();
121 use Coro::State ();
122 use Coro::AnyEvent ();
123 use Coro::Timer ();
124
125 our $VERSION = 5.151;
126
127 our %log;
128 our $SESLOGLEVEL = exists $ENV{PERL_CORO_DEFAULT_LOGLEVEL} ? $ENV{PERL_CORO_DEFAULT_LOGLEVEL} : -1;
129 our $ERRLOGLEVEL = exists $ENV{PERL_CORO_STDERR_LOGLEVEL} ? $ENV{PERL_CORO_STDERR_LOGLEVEL} : -1;
130
131 sub find_coro {
132 my ($pid) = @_;
133
134 if (my ($coro) = grep $_ == $pid, Coro::State::list) {
135 $coro
136 } else {
137 print "$pid: no such coroutine\n";
138 undef
139 }
140 }
141
142 sub format_msg($$) {
143 my ($time, $micro) = Time::HiRes::gettimeofday;
144 my ($sec, $min, $hour, $day, $mon, $year) = gmtime $time;
145 my $date = sprintf "%04d-%02d-%02dZ%02d:%02d:%02d.%04d",
146 $year + 1900, $mon + 1, $day, $hour, $min, $sec, $micro / 100;
147 sprintf "%s (%d) %s", $date, $_[0], $_[1]
148 }
149
150 sub format_num4($) {
151 my ($v) = @_;
152
153 return sprintf "%4d" , $v if $v < 1e4;
154 # 1e5 redundant
155 return sprintf "%3.0fk", $v / 1_000 if $v < 1e6;
156 return sprintf "%1.1fM", $v / 1_000_000 if $v < 1e7 * .995;
157 return sprintf "%3.0fM", $v / 1_000_000 if $v < 1e9;
158 return sprintf "%1.1fG", $v / 1_000_000_000 if $v < 1e10 * .995;
159 return sprintf "%3.0fG", $v / 1_000_000_000 if $v < 1e12;
160 return sprintf "%1.1fT", $v / 1_000_000_000_000 if $v < 1e13 * .995;
161 return sprintf "%3.0fT", $v / 1_000_000_000_000 if $v < 1e15;
162
163 "++++"
164 }
165
166 =item log $level, $msg
167
168 Log a debug message of the given severity level (0 is highest, higher is
169 less important) to all interested parties.
170
171 =item stderr_loglevel $level
172
173 Set the loglevel for logging to stderr (defaults to the value of the
174 environment variable PERL_CORO_STDERR_LOGLEVEL, or -1 if missing).
175
176 =item session_loglevel $level
177
178 Set the default loglevel for new coro debug sessions (defaults to the
179 value of the environment variable PERL_CORO_DEFAULT_LOGLEVEL, or -1 if
180 missing).
181
182 =cut
183
184 sub log($$) {
185 my ($level, $msg) = @_;
186 $msg =~ s/\s*$/\n/;
187 $_->($level, $msg) for values %log;
188 printf STDERR format_msg $level, $msg if $level <= $ERRLOGLEVEL;
189 }
190
191 sub session_loglevel($) {
192 $SESLOGLEVEL = shift;
193 }
194
195 sub stderr_loglevel($) {
196 $ERRLOGLEVEL = shift;
197 }
198
199 =item trace $coro, $loglevel
200
201 Enables tracing the given coroutine at the given loglevel. If loglevel is
202 omitted, use 5. If coro is omitted, trace the current coroutine. Tracing
203 incurs a very high runtime overhead.
204
205 It is not uncommon to enable tracing on oneself by simply calling
206 C<Coro::Debug::trace>.
207
208 A message will be logged at the given loglevel if it is not possible to
209 enable tracing.
210
211 =item untrace $coro
212
213 Disables tracing on the given coroutine.
214
215 =cut
216
217 sub trace {
218 my ($coro, $loglevel) = @_;
219
220 $coro ||= $Coro::current;
221 $loglevel = 5 unless defined $loglevel;
222
223 (Coro::async {
224 if (eval { Coro::State::trace $coro, Coro::State::CC_TRACE | Coro::State::CC_TRACE_SUB; 1 }) {
225 Coro::Debug::log $loglevel, sprintf "[%d] tracing enabled", $coro + 0;
226 $coro->{_trace_line_cb} = sub {
227 Coro::Debug::log $loglevel, sprintf "[%d] at %s:%d\n", $Coro::current+0, @_;
228 };
229 $coro->{_trace_sub_cb} = sub {
230 Coro::Debug::log $loglevel, sprintf "[%d] %s %s %s\n",
231 $Coro::current+0,
232 $_[0] ? "enter" : "leave",
233 $_[1],
234 $_[2] ? ($_[0] ? "with (" : "returning (") . (
235 join ",",
236 map {
237 my $x = ref $_ ? overload::StrVal $_ : $_;
238 (substr $x, 40) = "..." if 40 + 3 < length $x;
239 $x =~ s/([^\x20-\x5b\x5d-\x7e])/sprintf "\\x{%02x}", ord $1/ge;
240 $x
241 } @{$_[2]}
242 ) . ")" : "";
243 };
244
245 undef $coro; # the subs keep a reference which we do not want them to do
246 } else {
247 Coro::Debug::log $loglevel, sprintf "[%d] unable to enable tracing: %s", $Coro::current + 0, $@;
248 }
249 })->prio (Coro::PRIO_MAX);
250
251 Coro::cede;
252 }
253
254 sub untrace {
255 my ($coro) = @_;
256
257 $coro ||= $Coro::current;
258
259 (Coro::async {
260 Coro::State::trace $coro, 0;
261 delete $coro->{_trace_sub_cb};
262 delete $coro->{_trace_line_cb};
263 })->prio (Coro::PRIO_MAX);
264
265 Coro::cede;
266 }
267
268 =item command $string
269
270 Execute a debugger command, sending any output to STDOUT. Used by
271 C<session>, below.
272
273 =cut
274
275 sub command($) {
276 my ($cmd) = @_;
277
278 $cmd =~ s/\s+$//;
279
280 if ($cmd =~ /^ps (?:\s* (\S+))? $/x) {
281 my $times = Coro::State::enable_times;
282 my $flags = $1;
283 my $verbose = $flags =~ /v/;
284 my $desc_format = $flags =~ /w/ ? "%-24s" : "%-24.24s";
285 my $tim0_format = $times ? " %9s %8s " : " ";
286 my $tim1_format = $times ? " %9.3f %8.3f " : " ";
287 my $buf = sprintf "%20s %s%s %4s %4s$tim0_format$desc_format %s\n",
288 "PID", "S", "C", "RSS", "USES",
289 $times ? ("t_real", "t_cpu") : (),
290 "Description", "Where";
291 for my $coro (reverse Coro::State::list) {
292 my @bt;
293 Coro::State::call ($coro, sub {
294 # we try to find *the* definite frame that gives msot useful info
295 # by skipping Coro frames and pseudo-frames.
296 for my $frame (1..10) {
297 my @frame = caller $frame;
298 @bt = @frame if $frame[2];
299 last unless $bt[0] =~ /^Coro/;
300 }
301 });
302 $bt[1] =~ s/^.*[\/\\]// if @bt && !$verbose;
303 $buf .= sprintf "%20s %s%s %4s %4s$tim1_format$desc_format %s\n",
304 $coro+0,
305 $coro->is_new ? "N" : $coro->is_running ? "U" : $coro->is_ready ? "R" : "-",
306 $coro->is_traced ? "T" : $coro->has_cctx ? "C" : "-",
307 format_num4 $coro->rss,
308 format_num4 $coro->usecount,
309 $times ? $coro->times : (),
310 $coro->debug_desc,
311 (@bt ? sprintf "[%s:%d]", $bt[1], $bt[2] : "-");
312 }
313 print $buf;
314
315 } elsif ($cmd =~ /^bt\s+(\d+)$/) {
316 if (my $coro = find_coro $1) {
317 my $bt;
318 Coro::State::call ($coro, sub {
319 local $Carp::CarpLevel = 2;
320 $bt = eval { Carp::longmess "coroutine is" } || "$@";
321 });
322 if ($bt) {
323 print $bt;
324 } else {
325 print "$1: unable to get backtrace\n";
326 }
327 }
328
329 } elsif ($cmd =~ /^(?:e|eval)\s+(\d+)\s+(.*)$/) {
330 if (my $coro = find_coro $1) {
331 my $cmd = eval "sub { $2 }";
332 my @res;
333 Coro::State::call ($coro, sub { @res = eval { &$cmd } });
334 print $@ ? $@ : (join " ", @res, "\n");
335 }
336
337 } elsif ($cmd =~ /^(?:tr|trace)\s+(\d+)$/) {
338 if (my $coro = find_coro $1) {
339 trace $coro;
340 }
341
342 } elsif ($cmd =~ /^(?:ut|untrace)\s+(\d+)$/) {
343 if (my $coro = find_coro $1) {
344 untrace $coro;
345 }
346
347 } elsif ($cmd =~ /^cancel\s+(\d+)$/) {
348 if (my $coro = find_coro $1) {
349 $coro->cancel;
350 }
351
352 } elsif ($cmd =~ /^ready\s+(\d+)$/) {
353 if (my $coro = find_coro $1) {
354 $coro->ready;
355 }
356
357 } elsif ($cmd =~ /^kill\s+(\d+)(?:\s+(.*))?$/) {
358 my $reason = defined $2 ? $2 : "killed";
359
360 if (my $coro = find_coro $1) {
361 $coro->throw ($reason);
362 }
363
364 } elsif ($cmd =~ /^enable_times(\s+\S.*)?\s*$/) {
365 my $enable = defined $1 ? 1*eval $1 : !Coro::State::enable_times;
366
367 Coro::State::enable_times $enable;
368
369 print "per-thread real and process time gathering ", $enable ? "enabled" : "disabled", ".\n";
370
371 } elsif ($cmd =~ /^help$/) {
372 print <<EOF;
373 ps [w|v] show the list of all coroutines (wide, verbose)
374 bt <pid> show a full backtrace of coroutine <pid>
375 eval <pid> <perl> evaluate <perl> expression in context of <pid>
376 trace <pid> enable tracing for this coroutine
377 untrace <pid> disable tracing for this coroutine
378 kill <pid> <reason> throws the given <reason> string in <pid>
379 cancel <pid> cancels this coroutine
380 ready <pid> force <pid> into the ready queue
381 enable_times <enable> enable or disable time profiling in ps
382 <anything else> evaluate as perl and print results
383 <anything else> & same as above, but evaluate asynchronously
384 you can use (find_coro <pid>) in perl expressions
385 to find the coro with the given pid, e.g.
386 (find_coro 9768720)->ready
387 EOF
388
389 } elsif ($cmd =~ /^(.*)&$/) {
390 my $cmd = $1;
391 my $sub = eval "sub { $cmd }";
392 my $fh = select;
393 Coro::async_pool {
394 $Coro::current->{desc} = $cmd;
395 my $t = Time::HiRes::time;
396 my @res = eval { &$sub };
397 $t = Time::HiRes::time - $t;
398 print {$fh}
399 "\rcommand: $cmd\n",
400 "execution time: $t\n",
401 "result: ", $@ ? $@ : (join " ", @res) . "\n",
402 "> ";
403 };
404
405 } else {
406 my @res = eval $cmd;
407 print $@ ? $@ : (join " ", @res) . "\n";
408 }
409 }
410
411 =item session $fh
412
413 Run an interactive debugger session on the given filehandle. Each line entered
414 is simply passed to C<command>.
415
416 =cut
417
418 sub session($) {
419 my ($fh) = @_;
420
421 $fh = Coro::Handle::unblock $fh;
422 my $old_fh = select $fh;
423 my $guard = guard { select $old_fh };
424
425 my $loglevel = $SESLOGLEVEL;
426 local $log{$Coro::current} = sub {
427 return unless $_[0] <= $loglevel;
428 print $fh "\015", (format_msg $_[0], $_[1]), "> ";
429 };
430
431 print "coro debug session. use help for more info\n\n";
432
433 while ((print "> "), defined (my $cmd = $fh->readline ("\012"))) {
434 if ($cmd =~ /^exit\s*$/) {
435 print "bye.\n";
436 last;
437
438 } elsif ($cmd =~ /^(?:ll|loglevel)\s*(\d+)?\s*/) {
439 $loglevel = defined $1 ? $1 : -1;
440
441 } elsif ($cmd =~ /^(?:w|watch)\s*([0-9.]*)\s+(.*)/) {
442 my ($time, $cmd) = ($1*1 || 1, $2);
443 my $cancel;
444
445 Coro::async {
446 $Coro::current->{desc} = "watch $cmd";
447 select $fh;
448 until ($cancel) {
449 command $cmd;
450 Coro::Timer::sleep $time;
451 }
452 };
453
454 $fh->readable;
455 $cancel = 1;
456
457 } elsif ($cmd =~ /^help\s*/) {
458 command $cmd;
459 print <<EOF;
460 loglevel <int> enable logging for messages of level <int> and lower
461 watch <time> <command> repeat the given command until STDIN becomes readable
462 exit end this session
463 EOF
464 } else {
465 command $cmd;
466 }
467
468 Coro::cede;
469 }
470 }
471
472 =item $server = new_unix_server Coro::Debug $path
473
474 Creates a new unix domain socket that listens for connection requests and
475 runs C<session> on any connection. Normal unix permission checks and umask
476 applies, so you can protect your socket by puttint it into a protected
477 directory.
478
479 The C<socat> utility is an excellent way to connect to this socket:
480
481 socat readline /path/to/socket
482
483 Socat also offers history support:
484
485 socat readline:history=/tmp/hist.corodebug /path/to/socket
486
487 The server accepts connections until it is destroyed, so you must keep
488 the return value around as long as you want the server to stay available.
489
490 =cut
491
492 sub new_unix_server {
493 my ($class, $path) = @_;
494
495 unlink $path;
496 my $unlink_guard = guard { unlink $path };
497
498 AnyEvent::Socket::tcp_server "unix/", $path, sub {
499 my ($fh) = @_;
500 $unlink_guard; # mention it
501 Coro::async_pool {
502 $Coro::current->desc ("[Coro::Debug session]");
503 session $fh;
504 };
505 } or Carp::croak "Coro::Debug::new_unix_server($path): $!";
506 }
507
508 =item $server = new_tcp_server Coro::Debug $port
509
510 Similar to C<new_unix_server>, but binds on a TCP port. I<Note that this is
511 usually results in a gaping security hole>.
512
513 Currently, only a TCPv4 socket is created, in the future, a TCPv6 socket
514 might also be created.
515
516 =cut
517
518 sub new_tcp_server {
519 my ($class, $port) = @_;
520
521 AnyEvent::Socket::tcp_server undef, $port, sub {
522 my ($fh) = @_;
523 Coro::async_pool {
524 $Coro::current->desc ("[Coro::Debug session]");
525 session $fh;
526 };
527 } or Carp::croak "Coro::Debug::new_tcp_server($port): $!";
528 }
529
530 sub DESTROY {
531 my ($self) = @_;
532
533 unlink $self->{path} if exists $self->{path};
534 %$self = ();
535 }
536
537 1;
538
539 =back
540
541 =head1 AUTHOR
542
543 Marc Lehmann <schmorp@schmorp.de>
544 http://home.schmorp.de/
545
546 =cut
547
548