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.01; |
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 |
|
415 |
=item session $fh |
416 |
|
417 |
Run an interactive debugger session on the given filehandle. Each line entered |
418 |
is simply passed to C<command>. |
419 |
|
420 |
=cut |
421 |
|
422 |
sub session($) { |
423 |
my ($fh) = @_; |
424 |
|
425 |
$fh = Coro::Handle::unblock $fh; |
426 |
my $old_fh = select $fh; |
427 |
my $guard = guard { select $old_fh }; |
428 |
|
429 |
my $loglevel = $SESLOGLEVEL; |
430 |
local $log{$Coro::current} = sub { |
431 |
return unless $_[0] <= $loglevel; |
432 |
print $fh "\015", (format_msg $_[0], $_[1]), "> "; |
433 |
}; |
434 |
|
435 |
print "coro debug session. use help for more info\n\n"; |
436 |
|
437 |
while ((print "> "), defined (my $cmd = $fh->readline ("\012"))) { |
438 |
if ($cmd =~ /^exit\s*$/) { |
439 |
print "bye.\n"; |
440 |
last; |
441 |
|
442 |
} elsif ($cmd =~ /^(?:ll|loglevel)\s*(\d+)?\s*/) { |
443 |
$loglevel = defined $1 ? $1 : -1; |
444 |
|
445 |
} elsif ($cmd =~ /^(?:w|watch)\s*([0-9.]*)\s+(.*)/) { |
446 |
my ($time, $cmd) = ($1*1 || 1, $2); |
447 |
my $cancel; |
448 |
|
449 |
Coro::async { |
450 |
$Coro::current->{desc} = "watch $cmd"; |
451 |
select $fh; |
452 |
until ($cancel) { |
453 |
command $cmd; |
454 |
Coro::Timer::sleep $time; |
455 |
} |
456 |
}; |
457 |
|
458 |
$fh->readable; |
459 |
$cancel = 1; |
460 |
|
461 |
} elsif ($cmd =~ /^help\s*/) { |
462 |
command $cmd; |
463 |
print <<EOF; |
464 |
loglevel <int> enable logging for messages of level <int> and lower |
465 |
watch <time> <command> repeat the given command until STDIN becomes readable |
466 |
exit end this session |
467 |
EOF |
468 |
} else { |
469 |
command $cmd; |
470 |
} |
471 |
|
472 |
Coro::cede; |
473 |
} |
474 |
} |
475 |
|
476 |
=item $server = new_unix_server Coro::Debug $path |
477 |
|
478 |
Creates a new unix domain socket that listens for connection requests and |
479 |
runs C<session> on any connection. Normal unix permission checks and umask |
480 |
applies, so you can protect your socket by puttint it into a protected |
481 |
directory. |
482 |
|
483 |
The C<socat> utility is an excellent way to connect to this socket: |
484 |
|
485 |
socat readline /path/to/socket |
486 |
|
487 |
Socat also offers history support: |
488 |
|
489 |
socat readline:history=/tmp/hist.corodebug /path/to/socket |
490 |
|
491 |
The server accepts connections until it is destroyed, so you must keep |
492 |
the return value around as long as you want the server to stay available. |
493 |
|
494 |
=cut |
495 |
|
496 |
sub new_unix_server { |
497 |
my ($class, $path) = @_; |
498 |
|
499 |
unlink $path; |
500 |
my $unlink_guard = guard { unlink $path }; |
501 |
|
502 |
AnyEvent::Socket::tcp_server "unix/", $path, sub { |
503 |
my ($fh) = @_; |
504 |
$unlink_guard; # mention it |
505 |
Coro::async_pool { |
506 |
$Coro::current->desc ("[Coro::Debug session]"); |
507 |
session $fh; |
508 |
}; |
509 |
} or Carp::croak "Coro::Debug::new_unix_server($path): $!"; |
510 |
} |
511 |
|
512 |
=item $server = new_tcp_server Coro::Debug $port |
513 |
|
514 |
Similar to C<new_unix_server>, but binds on a TCP port. I<Note that this is |
515 |
usually results in a gaping security hole>. |
516 |
|
517 |
Currently, only a TCPv4 socket is created, in the future, a TCPv6 socket |
518 |
might also be created. |
519 |
|
520 |
=cut |
521 |
|
522 |
sub new_tcp_server { |
523 |
my ($class, $port) = @_; |
524 |
|
525 |
AnyEvent::Socket::tcp_server undef, $port, sub { |
526 |
my ($fh) = @_; |
527 |
Coro::async_pool { |
528 |
$Coro::current->desc ("[Coro::Debug session]"); |
529 |
session $fh; |
530 |
}; |
531 |
} or Carp::croak "Coro::Debug::new_tcp_server($port): $!"; |
532 |
} |
533 |
|
534 |
sub DESTROY { |
535 |
my ($self) = @_; |
536 |
|
537 |
unlink $self->{path} if exists $self->{path}; |
538 |
%$self = (); |
539 |
} |
540 |
|
541 |
1; |
542 |
|
543 |
=back |
544 |
|
545 |
=head1 AUTHOR |
546 |
|
547 |
Marc Lehmann <schmorp@schmorp.de> |
548 |
http://home.schmorp.de/ |
549 |
|
550 |
=cut |
551 |
|
552 |
|