ViewVC Help
View File | Revision Log | Show Annotations | Download File
/cvs/cvsroot/docs/corodebug.pod
Revision: 1.6
Committed: Sun Jan 13 13:29:43 2008 UTC (18 years, 8 months ago) by root
Branch: MAIN
Changes since 1.5: +2 -2 lines
Log Message:
*** empty log message ***

File Contents

# Content
1 =head1 Debuggen mit Coroutinen
2
3 =head1 Einführung
4
5 Im Laufe der Jahre habe ich eine ganz eigene Methode zum Debuggen
6 meiner Programme entwickelt. Diese Methode kombiniert einige Konzepte
7 (interkative Shell in jedem Programm, Coroutinen), die mehr als reines
8 Debugging ermöglichen.
9
10 Diese Methode möchte ich hiermit vorstellen, vielleicht bringt sie
11 den einen oder andreen auf Gedanken oder stellt sich gar als nützlich
12 heraus...
13
14 =head1 "Traditionelle" Debugging-Methoden
15
16 Nun, es gibt den Perl-Debugger; über diesen wird tatsächlich viel
17 erzählt und geschrieben, und ich nehme an, er wird wirklich häufig
18 benutzt. Aber aus welchen Gründen auch immer, ich konnte mich mit ihm
19 (anders als mit gdb) nie wirklich anfreunden: die einzige Funktion, die
20 ich mit einiger Regelmäßigkeit benutze, ist die Trace-Funktion. Das kann
21 ich sogar als "Fest im Gehirn eingebautes Makro" sofort tippen: "perl -d
22 xxx, dann t, dann c", andere Debugger-Befehle kenne ich nicht.
23
24 Diese Trace-Funktion hat aber viele Nachteile: sie macht das Programm sehr
25 langsam, sie funktioniert nur, während man im Debugger ist, und häufig
26 hängt mein Programm aus nicht nachvollziehbaren Gründen, und die Ausgabe
27 ist zu umfangreich. Die Hauptnachteile sind aber, daß man den Debugger
28 nicht ein- oder ausschalten kann und daß er interaktiv arbeitet.
29
30 Die Mehrheit meiner Programme sind langlebige Hintergrundprogramme. Diese
31 sind immerhin so gut getestet, daß sie in Produktion selten Probleme
32 entwickeln, aber manchmal kommt das natürlich vor. Das erklärt
33 wahrscheinlich, weshalb ich den Perl-Debugger nicht benutze: man kann den
34 Perl-Debugger (meines Wissens) nicht an bestehende Prozesse attachen, man
35 kann die Programme nicht dauerhaft unter dem Debugger starten und man hat
36 im Allgemeinen auch keinen interkativen Zugang.
37
38 Startet man das Programm neu (z.B. nach Einbau einiger warn-statements
39 oder um es unter dem Debugger laufen zu lassen) tritt das Problem häufig
40 nicht mehr auf.
41
42 Hinzu kommt, daß viele meiner Programme stark Ereignisgesteuert
43 arbeiten: Hält man das Programm an, gibt es unerwünschte Timeouts;
44 erstellt man einen Trace, springt dieser wild zwischen Programmteilen hin-
45 und her, die nichts miteinander zu tun haben.
46
47 Als einzige Möglichkeit (die auch häufig implementiert wird), bleibt
48 häufig nur, extrem viel mitzuloggen, so daß man im Fehlerfall zumindest
49 auf eine Art Trace zurückgreifen kann. Natürlich sind die schweren
50 Fehler selten dort, wo man gerade viel mitloggt.
51
52 =head1 Die Entwicklung eines anderen Ansatzes
53
54 =head2 Die Anfänge: ein Webserver
55
56 Um das Jahr 2000 herum schrieb ich einen Web-Server, der vollkommen
57 Event-gesteuert war (buchstäblich: er benutzte das Event-Modul dazu).
58
59 Weil es so einfach war, bekam er bald eine interaktive Shell verpasst:
60
61 sub shell {
62 my $fh = shift;
63
64 while (defined (print $fh "cmd> "), $_ = <$fh>) {
65 s/\015?\012$//;
66
67 # bearbeite Kommandos
68 }
69 }
70
71 my $port = new Coro::Socket
72 LocalPort => $CMDSHELL_PORT,
73 ReuseAddr => 1,
74 Listen => 1,
75 or die "unable to bind cmdshell port: $!";
76
77 push @listen_sockets, $port;
78
79 async {
80 while () {
81 async \&shell, scalar $port->accept;
82 }
83 };
84
85 Der Code benutzt Coroutinen, sollte aber einfach verständlich
86 sein: C<Coro::Socket> ist das Pendant zu C<IO::Socket>, bei dem Aufrufe
87 wie C<accept> die anderen coroutinen nicht blockieren; die Funktion
88 C<async> startet eine neue ("asynchrone") Coroutine für jedes neue
89 Verbindung, und die C<shell>-Funktion schließlich liest in einer Schleife
90 Befehle von der Socket und führt sie aus.
91
92 Ursprünglich dazu gedacht, eine Liste von aktiven Verbindungen zu
93 erhalten bzw. bisweilen IP-Adressen zu blockieren, hatte ich irgendwann
94 eine offensichtliche aber doch nicht so offensichtliche idee:
95
96 } elsif ($cmd eq "print") {
97 my @res = eval $_;
98 print $fh "eval: $@\n" if $@;
99 print $fh "RES = ", (join " : ", @res), "\n";
100
101 Mit dem "print"-Kommando (eigentlich wäre "eval" ein besserer Name)
102 lassen sich erstaunlich viele Dinge erledigen:
103
104 Erlaube 200 gleichzeitige Verbindungen mehr:
105
106 print $conn::connections->adjust (200)
107
108 Setze die Downloadrate auf 1MB/s:
109
110 print $conn::tbf_top->{rate} = 1e6
111
112 Erlaube 20 gleichzeitige Downloads mehr:
113
114 print $conn::queue_file->{slots} += 20
115
116 Das erste Beispiel benutzt die korrekte "API" zum anpassen einer
117 Semaphore, dei beiden letzteren Beispiele sind eigentlich "böse
118 Hacks" weil der Code diese Möglichkeit der Anpassung nicht explizit
119 unterstützt, sie funktionieren aber trotzdem.
120
121 Auf diese Weise läßt sich bisweilen auch debuggen: wenn z.B. eine
122 Verbindung hängt, kann man versuchen, sie zu finden und dann versuchen,
123 herauszufinden, woran es liegt, indem man sich verschiedene globale
124 Variablen anschaut oder kleine "Suchprogramme" mit C<print do "dateiname">
125 ausführt.
126
127 Das kann eine extreme Hilfe sein, ist aber immer noch recht umständlich.
128
129 =head2 Perl ist besser als jede Shell: Deliantra
130
131 Der Deliantra-Server (ein MORPG) ist ebenfalls vollkommen
132 Ereignisgesteuert und besitzt ebenfalls eine Shell, die (fast) ohne
133 Coroutinen auskommt:
134
135 sub tcp_serve($) {
136 my ($fh) = @_;
137
138 binmode $fh, ":raw:perlio:utf8";
139 print $fh "\n> ";
140
141 my $iow; $iow = EV::io $fh, EV::READ, sub {
142 if (defined (my $cmd = <$fh>)) {
143 $cmd =~ s/\s+$//;
144
145 if ($cmd =~ /^\s*exit\b/i) {
146 print $fh "will not exit() server.\n";
147
148 # andere befehle
149 }
150 };
151 }
152
153 our $LISTENER;
154
155 # now a shell listening on a tcp-port - let the firewall decide access rights
156 if ($cf::CFG{perl_shell}) {
157 if (my $listen = new IO::Socket::INET LocalAddr => $cf::CFG{perl_shell}, Listen => 1, ReuseAddr => 1, Blocking => 0) {
158 $LISTENER = EV::io $listen, EV::READ, sub { tcp_serve $listen->accept };
159 }
160 }
161
162 Deliantra benutzt EV als Event-Bibliothek, ansonsteb habe ich aus meinen
163 früheren Versuchen gelernt und implementiere keine Kommandos mehr direkt,
164 sondern erlaube direkt die Eingabe von Perl-Ausdrücken:
165
166 ...
167 } else {
168 my $sub = sub {
169 package cf;
170 select $fh;
171
172 # compile first, then execute, as Coro does not support switching in eval string
173 my $cb = eval "sub { $cmd \n}";
174
175 my $t1 = Time::HiRes::time;
176 my @res = $@ ? () : eval { $cb->() };
177 my $t2 = Time::HiRes::time;
178
179 print "\n",
180 "command: '$cmd'\n",
181 "execution time: ", $t2 - $t1, "\n";
182 warn "evaluation error: $@" if $@;
183 print "evaluation error: $@\n" if $@;
184 print "result:\n", cf::dumpval @res > 1 ? \@res : $res[0] if @res;
185 print "\n> ";
186
187 select STDOUT;
188 };
189
190 if ($cmd =~ s/\s*&$//) {
191 cf::async {
192 $Coro::current->desc ($cmd);
193 $sub->()
194 };
195 } else {
196 $sub->();
197 }
198
199 Die Befehlsausführung ist weitaus komplexer: Zuerst wird die eingegebene
200 Zeile kompilziert und dann evaluiert. Danach wird das Ergebnis, etwaige
201 Laufzeitfehler und die Ausführungszeit ausgegeben.
202
203 Da man als Administrator manchmal Befehle im "Hauptprogramm" (die
204 Coroutine, die die Event-Schleife ausführt) ausführen muss, der Server
205 aber all 120ms ein update generieren muss, muss man lang dauernde Befehle
206 in den "Hintergrund" (eine weitere Coroutine) schieben, was mit einem
207 angehängten "&" geschieht.
208
209 Eine Beispielsession sieht so aus:
210
211 # dmshell
212 Welcome!
213
214 ext::help::reload &
215 ext::books::reload &
216 ext::map_tags::reload &
217 ext::map_world::reload &
218 print JSON::XS->new->pretty->encode({cf::mallinfo})
219
220 > ext::map_world::reload &
221
222 >
223 command: 'ext::map_world::reload'
224 execution time: 0.0744819641113281
225
226 > ext::map_tags::reload &
227
228 >
229 command: 'ext::map_tags::reload'
230 execution time: 1.14403510093689
231
232 > $cf::PLAYER-{schmorp}
233
234 command: '$cf::PLAYER-{schmorp}'
235 execution time: 5.00679016113281e-06
236 evaluation error: Bareword "schmorp" not allowed while "strict subs" in use at (eval 180) line 1, <GEN63> line 6.
237
238 > $cf::PLAYER{schmorp}
239
240 command: '$cf::PLAYER{schmorp}'
241 execution time: 1.09672546386719e-05
242 result:
243 bless( {
244 log_told => {},
245 last_save => "32009728.5217925",
246 rent => {
247 last_online_check => "1200189659",
248 last_offline_check => "1200189659",
249 balance => "-0.737118053715676",
250 apartment => {
251 "/brest/apartments/brest_town_house" => undef,
252 "/scorn/apartment/apartments" => undef
253 }
254 },
255 hintmode => 0,
256 npc_dialog_active => {}
257 }, 'cf::player::wrap' )
258
259 >
260 > "schmorp"->cf::player::find->ob->stats->hp
261
262 command: '"schmorp"->cf::player::find->ob->stats->hp'
263 execution time: 4.79221343994141e-05
264 result:
265 520
266
267 und so weiter... Das ist natürlich eine große Hilfe beim Administrieren
268 oder Debuggen, weil man sich die aktuellen Daten, die im Server geladen
269 sind direkt ansehen kann.
270
271 Sehr angenehm ist es auch, direkt im Spielbetrieb Bugs zu fixen, indem man
272 einzelne Routinen direkt überschreibt:
273
274 # cat /tmp/bugfix
275 package cf;
276 sub _can_merge {
277 # neue merge-logik, vielleicht mit printf-style-debugging
278 }
279 1
280
281 # dmshell
282 > do "/tmp/bugfix"
283
284 So kann man im laufenden Betrieb schon sehr angenehm am Server arbeiten,
285 aber man muss sich jedesmal eine Shell ausdenken, sie implementieren, und
286 kann dennoch nur herumstochern.
287
288 Doch mit Coroutinen kann mehr wesentlich mehr...
289
290
291 =head1 Coroutinen
292
293 Mit Perl hat man prinzipiell zwei Methoden der
294 "parallelverarbeitung": Coroutinen (teilen sich einen gemeinsamen
295 Adressraum, laufen aber nicht wirklich parallel) und Prozesse (haben
296 getrennte Adressräume, laufen aber parallel (mit entsprechender
297 Hardware)). Threads (gemeinsamer Adressraum und echte Parallelität)
298 werden von Perl nicht angeboten.
299
300 Gegenüber Prozessen hat man den Vorteil extrem einfacher Kommunikation
301 zwischen den einzelnen Instanzen, beispielsweise implementiert der schon
302 genannte Webserver einen Schutz gegen segmentierte Downloads, indem er die
303 gerade heruntergeladenen URLs pro Klient in einem globale Hash speichert:
304
305 if ($DOWNLOADS{$url}{$clientid} >= 4) {
306 # abort, zu viele Verbindungen
307 return;
308 }
309
310 ++$DOWNLOADS{$url}{$clientid};
311
312 Mit mehreren Prozessen ist dies natürlich nicht so einfach.
313
314 Ein weitere Vorteil von Coroutinen ist das stark verinfachte Locking: es
315 gibt praktisch keine Race-conditions, denn solange man nicht absichtlich
316 Rechenzeit abgibt.
317
318 Aber wie hilft das beim Debuggen?
319
320 In einem ereignisgesteuerten Programm hat man meistens wenige Watcher
321 (z.B. einen pro TCP-Verbindung). Der aktuelle Zustand einer Verbindung
322 steht in irgendwelchen Variablen serialisiert. Das kann entweder eine
323 Zustandsmaschine sein (entweder Ad-Hoc oder z.B. mit POE) oder auch
324 per Continuation-Style durch den auf den Watcher gebundenen Callback,
325 mit einigen lexikalischen Variablen, in die man garnicht so einfach
326 reinschauen kann.
327
328 Die ausgeführten Programmzeilen sind relativ uninteressant, das Programm
329 verbringt wohl die meiste Zeit in der Hauptschleife (z.B. C<EV::loop> oder
330 C<< Gtk->main >>), und Backtraces helfen garnicht ("steckt das Programm in
331 C<lese_von_socket> weil es noch auf den Header wartet oder ist es schon
332 beim Lesen des Request-Bodies?").
333
334 Bei einem "herkömmlichen" - nicht ereigenisgesteuerten - Programm ist
335 es viel einfacher: "Programm steckt in Zeile 231, da liest er gerade den
336 Header ein".
337
338 Und genau das kriegt man mit Coroutinen. Natürlich braucht man Hilfe vom
339 Laufzeitsystem, und diese Hilfe kommt von...
340
341 =head1 Coro::Debug
342
343 Seit Version 4.0 gibt es in der Coro-Distribution das
344 C<Coro::Debug>-Modul.
345
346 Dieses implementiert nicht nur eine interaktive Shell (bzw. auch
347 Einzelteile, mit denen man das selbst tun kann), sondern auch eine
348 Übersicht über die Coroutinen, Backtraces und Aufruftraces.
349
350 =head2 Benutzung
351
352 Die einfachste Methode, um an eine Shell zu kommen, ist es, einen "UNIX
353 Socket Server" zu starten:
354
355 use Coro::Debug;
356
357 $CORO_DEBUGGER = new_unix_server Coro::Debug "/tmp/debug";
358
359 Und schon kann man sich mit F</tmp/debug> verbinden... Oder auch
360 nicht: Die bisherigen Beispiele benutzen TCP-Sockets, da konnte man
361 C<telnet> benutzen, aber wie macht man das mit UNIX Sockets, und
362 warum?
363
364 An dieser Stelle möchte ich herzlichst ein feines Werkzeug namens
365 C<socat> empfehlen, mit dme man sehr einfach Verbindungen zwischen zwei
366 Punkten schaffen kann, z.B. zwischen der Readline-Bibliothek und einer
367 UNIX Socket:
368
369 socat readline unix:/tmp/debug
370
371 Und man hat, im Gegensatz zum Perl-Debugger, auch noch echtes Readline
372 :-> C<socat> kann übrigens auch anders, z.B. C<netcat> ersetzen: C<socat
373 readline tcp:127.0.0.1:80>. Oder einen UDP-Server implementieren: C<socat
374 system:mcookie udp-listen:676>. Sehr hilfreich!
375
376 Der Grund eine UNIX Socket zu benutzen ist der Sicherheitsaspekt: Um einen
377 TCP-Port zu schützen (die Shell macht ja keinerlei sicherheitsabfrage)
378 braucht man schon einen Firewall, um eine UNIX Socket zu schützen
379 muss man sie nur in ein Verzeichnis legen auf das nur legitime
380 Benutzer/Programme Zugriff besitzen (F</tmp/debug> ist also ein schlechtes
381 Beispiel). Auf diese Weise kann man diese Shell relativ unbedenklich
382 immer aktiv lassen (z.B. in der Produktionsumgebung):
383
384 system "rm -rf /tmp/myprog";
385 mkdir "/tmp/myprog", 0700 or die "/tmp/myprog: $!";
386 $CORO_DEBUGGER = new_unix_server Coro::Debug "/tmp/myprog/debug";
387
388 Auf diese Weise haben nur diejenigen Zugriff auf den Prozess, die sowieso
389 Zugriff haben.
390
391 =head2 "Prozessliste"
392
393 Mit dem C<ps>-Kommando erhält man eine Übersicht aller laufenden
394 Coroutinen, hier als Beispiel in eine laufenden Deliantra-Server:
395
396 > ps
397 PID SS RSS USES Description Where
398 10289200 US 865k 830k [main::] [/deliantra/ext/dm-support.ext:47]
399 10289392 -- 2508 66 [coro manager] [/opt/perl/lib/perl5/Coro.pm:177]
400 10289712 -- 2508 2094 [unblock_sub scheduler] [/opt/perl/lib/perl5/Coro.pm:589]
401 13776976 -- 2548 13 [EV idle process] [/opt/perl/lib/perl5/Coro/EV.pm:65]
402 18176656 -- 2964 53k timeslot manager [/deliantra/cf.pm:397]
403 23103792 -- 19k 42k player scheduler [/deliantra/ext/login.ext:510]
404 46912554817888 -- 2980 1 follow handler [/deliantra/ext/follow.ext:50]
405 19457280 -- 138k 432k map scheduler [/deliantra/ext/map-scheduler.ext:65]
406 18681088 -- 3228 6312 music scheduler [/deliantra/ext/player-env.ext:77]
407 26391616 -- 2980 40k worldmap updater [/deliantra/ext/item-worldmap.ext:114]
408 140130800 -- 16k 3746 [async_pool idle] [/opt/perl/lib/perl5/Coro.pm:258]
409 286210960 -- 16k 22k [async_pool idle] [/opt/perl/lib/perl5/Coro.pm:258]
410 196084816 -- 10k 1251 [async_pool idle] [/opt/perl/lib/perl5/Coro.pm:258]
411 439518192 -- 3268 2 addme init [/deliantra/ext/login.ext:21]
412
413 Die C<PID> ist nichts anderes als die Addresse des Perl-Coroutinenobjektes
414 (C<$obj+0>). Die C<SS>-Spalte (State/Stack) gibt an, ob eine Coroutine
415 gerade läuft (rB<U>nning, B<R>eady oder weder noch), bzw. ob sie einen
416 eigenen C-Stack hat (B<S>) oder nicht (B<->), oder gerade getraced wird
417 (C<T>), mehr dazu später. C<RSS> ist der Speicherverbrauch der Coroutine
418 in Bytes. C<Uses> gibt an, wie oft die Coroutine Rechenzeit zugeteilt bzw.
419 wieder abgegeben hat.
420
421 Die C<Description>-Spalte gibt lediglich den Inhalt des C<desc>-Members
422 der Coroutinenstruktur wieder, den man einfach setzen kann:
423
424 $Coro::current->{desc} = "login phase 1";
425 ... tue etwas
426 $Coro::current->{desc} = "login phase 2";
427 ...
428
429 Die meisten Coroutinen setzen einfach einen Namen, manche ändern den
430 Namen je nach Ort, so daß man sofort sehen kann, in welchen "Zustand" die
431 Coroutine ist.
432
433 Der Server benutzt eine Menge Coroutinen (die meisten sind sehr
434 kurzlebig): Spieler regelmäßig speichern erledigt z.B. der C<player
435 scheduler>, der hier gerade in Zeile C<510> von C<login.ext> steckt:
436
437 Coro::EV::timer_once $SCHEDULE_INTERVAL;
438
439 Das macht Sinn, da er nur alle paar Sekunden aktiv wird und den Rest der
440 Zeit schläft.
441
442 Ein anderes Beispiel ist C<addme init>, was ein Teil des Login-Prozesses
443 darstellt. Zeile C<21> ist in einer Funktion C<query>, die den Benutzer
444 etwas frägt (naheligenderweise Name oder Passwort). Um mehr zu erfahren,
445 braucht man einen Backtrace:
446
447 =head2 Backtraces
448
449 Backtraces erhält man mit dem C<bt>-Kommando und der "PID" als Argument:
450
451 > bt 439518192
452 coroutine is at /deliantra/ext/login.ext line 21
453 ext::login::query('cf::client::wrap=HASH(0x3d7dfb0)',
454 0, 'What is your name?\x{a}:')
455 called at /deliantra/ext/login.ext line 208
456 ext::login::__ANON__ called at -e line 0
457 Coro::_run_coro called at -e line 0
458
459 Nicht nur sieht man sofort, was den Benutzer gefragt wird (weil C<query>
460 den Fragetext als Parameter übergeben bekommt), sondern man sieht auch,
461 wo im Login-Prozess man sich gerade befindet, nämlich in Zeile C<208>
462 (was innerhalb des C<on_addme>-Callbacks von Deliantra ist).
463
464 Noch mehr Informationen erhält man mit einem Aufruftrace:
465
466 =head2 Aufruftraces/Ablaufverfolgung
467
468 Zuerst sollte man den "Logging Level" in seiner Shell auf 5 oder höher schrauben:
469
470 > loglevel 5
471
472 Dann kann man Aufruftraces mit C<tr> und C<ut> starten und stoppen:
473
474 > tr 439518192
475 2008-01-13Z04:03:28.1954 (5) [439518192] tracing enabled
476 (timestanmps usf. im Folgenden gekürzt)
477 .8374 (5) [pid] enter Coro::State::_cctx_init with (277569264)
478 .8375 (5) [pid] leave Coro::State::_cctx_init returning ()
479 .8375 (5) [pid] leave ext::login::query returning (schmorp)
480 .8376 (5) [pid] enter ext::login::check_playing with (cf::client::wrap=HASH(0x3d7dfb0),name)
481 .8376 (5) [pid] enter cf::player::find_active with (schmorp)
482 .8376 (5) [pid] leave cf::player::find_active returning ()
483 .8378 (5) [pid] enter cf::client::send_drawinfo with
484 (cf::client::wrap=HASH(0x3d7dfb0),Welcome name, please enter your password...,5)
485 .8378 (5) [pid] leave cf::client::send_drawinfo returning ()
486 .8379 (5) [pid] enter ext::login::query with (
487 cf::client::wrap=HASH(0x3d7dfb0),4,What is your password?\x{0a}:)
488 .8380 (5) [pid] enter cf::client::query with (
489 cf::client::wrap=HASH(0x3d7dfb0),4,What is your password?\x{0a}:,CODE(0x6fca040))
490 .8380 (5) [pid] leave cf::client::query returning ()
491
492 Bei diesem Tracing wird bei jedem Funktionsaufruf bzw. bei jeder Rückkehr
493 aus einer Funktion eine Zeile ausgegeben die Funktionsnamen, Argumente
494 bzw. Resultatsliste ausgibt.
495
496 Im Beispiel wurde die Ablaufverfolgung aktiviert, während der
497 Spiel-Klient noch in der Namensabfrage steckte (der Aufruf von
498 C<_cctx_init> ist ein Implementationsdetail von Coro, der das Starten
499 eines neuen Interpreters anzeigt, mehr dazu später). Konsequenterweise
500 sieht man daher nur die Rückkehr aus dem C<query>-Aufruf, mit dem Namen
501 als Resultat (C<schmorp>).
502
503 Danach schaut der Server nach, ob der User gerade spielt
504 (C<check_playing), was wiederum C<find_active>) aufruft). Weil er nicht
505 spielt kann man mit dem Login fortfahren und nach dem Passwort Fragen,
506 usf.
507
508 Es ist gut möglich, daß der Server während der Ausführung einer
509 Coroutine viele andere Dinge tut (wenn der Login-Callback den Spieler von
510 der Platte lädt, läuft der Server erstmal weiter, denn der Zugriff kann
511 durchaus mal eine Sekunde oder länger dauern, wenn z.B. gerade viel I/O
512 stattfindet). Da die Ablaufvergolgung nur für eine (die interessante)
513 Coroutine aktiviert ist, bekommt man auch nur für diese die Meldungen,
514 was ungemein hilfreich ist.
515
516 C<Coro> selbst untertsützt auch Zeilenweise Ablaufverfolgung, es gibt
517 jedoch noch kein Kommando um dieses zu aktivieren (ich habs noch nie
518 gebraucht). Wenn man sich das C<Coro::Debug>-Modul ansieht, sieht man
519 such, daß man seine eigenen Trace-Callbacks definieren kann und damit
520 recht viele Tricks möglich sind.
521
522 =head3 "printf-debugging"
523
524 Die Ablaufverfolgung benutzt die C<Coro::Debug::log $loglevel,
525 $msg>-Funktion zum Ausgeben der Meldungen, mit der man auch eigene Meldungen ausgeben kann,
526 wahlweise auch nur wenn Tradcing aktiviert ist:
527
528 Coro::Debug::log 6, "some log message"
529 if $Coro::current->is_traced;
530
531 (Vielleicht sollte die nächste Version von Coro::Debug einen
532 coroutinenabhängigen Loglevel anbieten...)
533
534 =head3 Automatische Aktivierung
535
536 Die Ablaufverfolgung kann man auch progrrammatisch aktivieren, z.B. wenn die Coroutine kurzlebig ist oder
537 man unbedignt den Anfang mitkriegen möchte:
538
539 Coro::Debug::trace;
540 # ab hier wird getraced
541
542 Coro::Debug::untrace;
543 # ab hier nicht mehr, boa!
544
545 =head3 Problemchen
546
547 Ablaufverfolgung geht nicht mit allen Coroutinen:
548
549 PID SS RSS USES Description Where
550 10289200 US 865k 926k [main::] [/deliantra/ext/dm-support.ext:47]
551
552 > coro tr 10289200
553 2008-01-13Z04:33:58.7787 (5) [123282976] unable to enable tracing:
554 cannot enable tracing on coroutine with custom stack
555 at /opt/perl/lib/perl5/Coro/Debug.pm line 205, <GEN88> line 2.
556
557 Der Grund liegt in der Implementation: Sowohl der Perl-Debugger als auch
558 Coro müssen eine andere Implementation des Interpreters verwenden, der
559 langsamer läuft, aber den Ablauf verfolgen kann. Wie also kann man diese
560 mit Coro an- oder abschalten?
561
562 Coro arbeitet, indem jede Coroutine quasi ihren eigenen (abgespeckten)
563 Interpreter verpasst bekommt. Damit der Speicherverbrauch gering und
564 vor allem die Geschwindigkeit hoch sind, teilt Coro verschiedenen
565 Coroutinen nach Möglichkeit den gleichen Interpreter zu. Dies ist
566 genau dann möglich, wenn sich die Coroutine in der äußersten
567 Interpreterschleife befindet (d.h. keine rekursiven Aufrufe gemacht
568 wurden. Ein rekursiver Aufruf findet statt, wenn man eine C/XS-Funktion
569 aufruft und diese wiederum Perl, was z.B. bei fast allen Callback-Systemen
570 vorkommt). Außerdem hat das Hautprogramm immer seinen eigenen
571 Interpreter.
572
573 Genau dies sieht man im rechten Teil der C<SS>-Spalte: Tracing kann
574 nur dann aktiviert werden, wenn dort ein C<-> steht, und auch nur dann
575 deaktiviert werden, wenn die Coroutine während des Tracens keine
576 rekursiven Mätzchen macht.
577
578 In der Praxis ist das kein Problem: man kann ja einfach alles in eine
579 Coroutine verlegen und das Hauptprogramm schlafenlegen, oder das Tracing
580 aktivieren (z.b. programmatisch), bevor man z.B. in die Event-Schleife
581 springt: Das verlangsamt die Ausführung zwar, aber nicht sehr (einige
582 Prozent).
583
584 =head2 Code-Injection
585
586 Manchmal kann es recht hilfreich sein, einer Coroutine etwas Code
587 unterzujubeln. Auf diese Weise kann man z.B. Backtraces erhalten:
588
589 > eval 277575488 Carp::cluck "holladrio"
590
591 Oder man kann auf lokale Variablen zugreifen (z.B. mit dem
592 C<PadWalker>-Modul).
593
594 Das ganze geht auch programmatisch:
595
596 $coro->eval ("string");
597 $coro->call (sub { ... });
598
599
600 =head1 Ausblick
601
602 C<Coro::Debug> ist recht neu und die sich ergebenden Möglichkeiten noch
603 nicht wirklich ausgelotet. Ich denke, daß es aber jetzt schon sehr
604 hilfreiche Mittel zum Debugging zur Verfügung stellt.
605
606 Ich hoffe auch, ich konnte ein paar Anregungen zum Thema "jedes
607 Perl-Programm braucht eine interaktive Shell" zu liefern: Es ist
608 wirklich hilfreich, und mit Perl (mit oder ohne Coro) sehr einfach zu
609 implementieren.
610
611 =head1 Autor
612
613 Marc Lehmann <schmorp@schmorp.de>.
614
615 =head1 Anhang: dumpval
616
617 Wen's interessiert, ich verwende die folgende "dumpval"-Funktion schon
618 seit vielen Jahren, und sie gibt recht lesbare Debug-Dumps:
619
620 # dumpval $ref
621
622 sub dumpval {
623 eval {
624 local $SIG{__DIE__};
625 my $d;
626 $d = new Data::Dumper([$_[0]], ["*var"]);
627 $d->Terse(1);
628 $d->Indent(2);
629 $d->Quotekeys(0);
630 $d->Useqq(1);
631 #$d->Bless(...);
632 $d->Seen($_[1]) if @_ > 1;
633 $d = $d->Dump();
634 $d =~ s/([\x00-\x07\x09\x0b\x0c\x0e-\x1f])/sprintf "\\x%02x", ord($1)/ge;
635 $d
636 } || "[unable to dump $_[0]: '$@']";
637 }
638
639 Früher habe ich mal Dumpvalue benutzt, ist auch nicht schlecht (das
640 PApp::Catch_STDOUT ist ein Hack, den man in neueren Perls durch PerlIO
641 ersetzen kann):
642
643 sub dumpval {
644 eval {
645 local $SIG{__DIE__};
646 my $d;
647 local *STDOUT;
648 local *PApp::output;
649 tie *STDOUT, PApp::Catch_STDOUT;
650
651 require Dumpvalue;
652 $d = new Dumpvalue globPrint => 1, compactDump => 0, veryCompact => 0;
653 $d->dumpValue($_[0]);
654 $d = $PApp::output;
655 $d =~ s/([\x00-\x07\x09\x0b\x0c\x0e-\x1f])/sprintf "\\x%02x", ord($1)/ge;
656 $d;
657 } || "[unable to dump $_[0]: '$@']";
658 }
659