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