1 |
root |
1.4 |
=head1 Debuggen mit Coroutinen |
2 |
root |
1.1 |
|
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 |
root |
1.5 |
oder Debuggen, weil man sich die aktuellen Daten, die im Server geladen |
269 |
root |
1.1 |
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 |
root |
1.2 |
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 |
root |
1.1 |
|
305 |
|
|
if ($DOWNLOADS{$url}{$clientid} >= 4) { |
306 |
|
|
# abort, zu viele Verbindungen |
307 |
|
|
return; |
308 |
|
|
} |
309 |
|
|
|
310 |
|
|
++$DOWNLOADS{$url}{$clientid}; |
311 |
|
|
|
312 |
root |
1.2 |
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 |
root |
1.1 |
=head1 Coro::Debug |
342 |
|
|
|
343 |
root |
1.2 |
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 |
root |
1.6 |
Coroutinen nach Möglichkeit den gleichen Interpreter zu. Dies ist |
566 |
|
|
genau dann möglich, wenn sich die Coroutine in der äußersten |
567 |
root |
1.2 |
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 |
root |
1.1 |
=head1 Autor |
612 |
|
|
|
613 |
|
|
Marc Lehmann <schmorp@schmorp.de>. |
614 |
root |
1.3 |
|
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 |
root |
1.5 |
PApp::Catch_STDOUT ist ein Hack, den man in neueren Perls durch PerlIO |
641 |
root |
1.3 |
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 |
|
|
|