Devel::YCallTrace -- noch ein anderes Werkzeug zur Analyse von Perl Programmen

28 Apr 2013

Das ist Vortrag, den ich auf Deutscher Perl Workshop’‘2013 gehalten habe.

Die Konferenz: http://act.yapc.eu/gpw2013/

Der Vortrag: http://act.yapc.eu/gpw2013/talk/4483

Slides: speakerdeck

Das Modul auf Github: https://github.com/liruoko/y_call_trace

...

Adstract

Devel::CallTrace, Devel::CallStack, Devel::RemoteTrace, Devel::Trace, Devel::TraceMore, Devel::TraceVars, Devel::TraceSubs – es gibt viele Module die die Ausführung eines Perl Programms verfolgen helfen. Was noch kann man wollen? Doch haben wir in unserem Team vor einige Jahre noch ein Modul entwickelt. Das Modul heißt Devel::YCallTrace und ist auf GitHub erreichbar.

Ich möchte die vorhandene Werkzeuge kurz beschreiben und ihre Vorteile und Nachteile angeben. Dann zeige ich, wie man unser Modul benutzen kann und welche Aufgabe sind möglich damit zu lösen.

Wer bin ich

Ich heiße Lena, ich komme aus Moskau, Russland. Es freut mich hier mit euch zu sein, und ich möchte ich mich entschuldigen für Akzent und Fehlern ;) Der Vortrag war mein erster großer Vortrag auf Deutsch, und das ist der größte Text, den ich auf Deutsch geschrieben habe.

Ich arbeite bei Yandex. Yandex ist die größte suchmaschine in Russland, wir haben dort etwa 60% des Suchmarkts. Und Yandex ist jetzt die 4. größte Suchmaschine der Welt an der Zahl der Suchanfragen, nur noch hinter den Suchmaschinen Google, Baidu und Yahoo.

Naturlich, die Suchmaschine selbst ist nicht in Perl geschrieben, aber Yandex hat auch viele andere Teile und Dienste, die verschidene Programmesprache nutzen, and Perl auch. Darum eigentlich arbeite ich bei Yandex.

Heute möchte ich über ein Werkzeug erzählen, die wir in unser Team für Diagnostizieren gebrauchen.

Problemstellung

Erstens, was ist das Problem? Du hast ein Programm geschrieben, und es sieht gut aus, aber funkzioniert nicht richtig. Wie kann man die Fehlern finden?

Na, es gibt viele Möglichkeiten. Zum Beispiel, kann man das Programm aufmerksam lesen. Oder Unittests schreiben und damit die Fehler etwa lokalisieren. Oder das Programm im debugger öffnen und Einzelschritt-Verarbeitung machen.

perl -d my_script.pl

Debugger ist ein gutes Werkzeug. Aber was ist wenn das Programm ziemlich gross ist und komplizierte Logik hat? Wenn du keine Idee hast, in welchem Teil des Programs das Fehler sein kann, dann kann Einzelschritt-Verarbeitung zu langweilich sein. Dazu kann das Programm ein Teil von einem Webdienst sein und unter mod_perl laufen, oder so was. Dann kann es schwierig sein, einen gewönlichen Debugger zu nutzen.

Es wäre gut einen “automatischer Debugger” zu haben: das Programm auszuführen und dann einer Logdatei bekommen mit alle interesanten Sachen: welche Operationen ausgeführt wurden, mit welchem Resultat und so weiter.

Was bietet CPAN?

Gut, gucken wir was es auf CPAN gibt.

Hier sind einige Beispiele.

Devel::RemoteTrace

Druckt jede Zeile die ausführt wird.
Verlangsamung: sehr bedeutend

  + use Devel::RemoteTrace;
  
  > netcat -u -l 9999
  > kill -USR2 <pid>

Bericht:

...
[18952]  ./sudoku-solver.pl:264:  my %index;
[18952]  ./sudoku-solver.pl:265:  my %digit;
[18952]  ./sudoku-solver.pl:266:  for my $j (@$s){
[18952]  ./sudoku-solver.pl:267:      my $ind = $g->[$j];
[18952]  ./sudoku-solver.pl:268:      next SUBSET if $board->{$ind}->{content};
[18952]  ./sudoku-solver.pl:264:  my %index;
[18952]  ./sudoku-solver.pl:265:  my %digit;
[18952]  ./sudoku-solver.pl:266:  for my $j (@$s){
[18952]  ./sudoku-solver.pl:267:      my $ind = $g->[$j];
[18952]  ./sudoku-solver.pl:268:      next SUBSET if $board->{$ind}->{content};
[18952]  ./sudoku-solver.pl:269:      $index{$ind} = 1;
[18952]  ./sudoku-solver.pl:270:      for my $d (keys %{$board->{$ind}->{hypothesis}}) {
[18952]  ./sudoku-solver.pl:270:      for my $d (keys %{$board->{$ind}->{hypothesis}}) {
[18952]  ./sudoku-solver.pl:271:          next if $board->{$ind}->{hypothesis}->{$d} == 0;
[18952]  ./sudoku-solver.pl:272:          $digit{$d} = 1;
[18952]  ./sudoku-solver.pl:271:          next if $board->{$ind}->{hypothesis}->{$d} == 0;
...

Devel::TraceSubs

Druckt die Namen der Funktionen die ausführt werden, und ihre Parametern.
Verlangsamung: ~20x
warnings:
defined(%hash) is deprecated
Modification of non-creatable array value attempted

Initialisierung

+use Devel::TraceSubs;
+    my $dbg = Devel::TraceSubs->new(
+        verbose => 0, 
+        pre => '>',
+        post => '<',
+        level => '~',
+        params => 1,
+        wrap => ['<!--', '-->'],
+    );
+    $dbg->trace('main::');

Bericht:

<!--~~> main::fib( ''4'' )-->
 at sample_scripts/fib.pl line 32
<!--~~~> main::fib( '3' )-->
 at sample_scripts/fib.pl line 42
<!--~~~~> main::fib( '2' )-->
 at sample_scripts/fib.pl line 42
<!--~~~~< main::fib => 1-->
 at sample_scripts/fib.pl line 42
<!--~~~~> main::fib( '1' )-->
 at sample_scripts/fib.pl line 42
<!--~~~~< main::fib => 1-->
 at sample_scripts/fib.pl line 42
<!--~~~< main::fib => 2-->
 at sample_scripts/fib.pl line 42
<!--~~~> main::fib( '2' )-->
 at sample_scripts/fib.pl line 42
<!--~~~< main::fib => 1-->
 at sample_scripts/fib.pl line 42

Bericht 2:

<!--~~> main::read_board-->
 at ./sudoku-solver.pl line 27
<!--~~< main::read_board-->
 at ./sudoku-solver.pl line 27
<!--~~> main::print_board( '{'33' => {'content' => '','type' => 'solution','hypothesis' => {'6' => 1,'3' => 1,'7' =>
 at ./sudoku-solver.pl line 33
<!--~~< main::print_board => <void>-->
 at ./sudoku-solver.pl line 33
<!--~~> main::solve( '{'33' => {'content' => '','type' => 'solution','hypothesis' => {'6' => 1,'3' => 1,'7' => 1,'9'
 at ./sudoku-solver.pl line 34
<!--~~~> main::generate_groups-->
 at ./sudoku-solver.pl line 126
<!--~~~< main::generate_groups-->
 at ./sudoku-solver.pl line 126
<!--~~~> main::generate_subsets-->
 at ./sudoku-solver.pl line 127
<!--~~~< main::generate_subsets-->
 at ./sudoku-solver.pl line 127
<!--~~~> main::explain_hypothesis( '{'33' => {'content' => '','type' => 'solution','hypothesis' => {'6' => 1,'3' => 1
 at ./sudoku-solver.pl line 131
...

Devel::CallTrace

Hier sind auch die Namen der Funktionen, doch ohne Parametern.
Gebraucht den Debugger
Verlangsmanung: ~1.5x

perl -d:CallTrace script.pl

Bericht

...   
   main::explain_state (./sudoku-solver.pl:300-307)
   main::explain_hypothesis (./sudoku-solver.pl:310-317)
   main::rule_0 (./sudoku-solver.pl:186-202)
    main::explain (./sudoku-solver.pl:291-297)
   main::explain_state (./sudoku-solver.pl:300-307)
   main::explain_hypothesis (./sudoku-solver.pl:310-317)
   main::rule_0 (./sudoku-solver.pl:186-202)
   main::rule_1 (./sudoku-solver.pl:205-226)
    main::explain (./sudoku-solver.pl:291-297)
    main::explain (./sudoku-solver.pl:291-297)
    main::explain (./sudoku-solver.pl:291-297)
   main::explain_state (./sudoku-solver.pl:300-307)
   main::explain_hypothesis (./sudoku-solver.pl:310-317)
   main::rule_0 (./sudoku-solver.pl:186-202)
...

Devel::CallStack

druckt wieviel Mal man jeden Zustand den Stapelspeicher sah.

Verlangsamung: 2-10x
Gesamtbericht über den Stapelspeicher

perl -d:CallStack script.pl less callstack.out

Bericht:

main::run 1 1
main::run,Data::Dumper::Dumper 2 1
main::run,Data::Dumper::Dumper,Data::Dumper::Dump 3 1
main::run,Data::Dumper::Dumper,Data::Dumper::Dump,Data::Dumper::Dumpxs 4 1
main::run,Data::Dumper::Dumper,Data::Dumper::Dump,Data::Dumper::new 4 1
main::run,main::explain_hypothesis 2 1
main::run,main::explain_hypothesis,main::print_hypothesis 3 1
main::run,main::print_board 2 2
main::run,main::read_board 2 1
main::run,main::solve 2 1
main::run,main::solve,main::explain_hypothesis 3 141
main::run,main::solve,main::explain_hypothesis,main::print_hypothesis 4 141
main::run,main::solve,main::explain_state 3 140
main::run,main::solve,main::explain_state,main::print_board 4 140
main::run,main::solve,main::generate_groups 3 1
main::run,main::solve,main::generate_subsets 3 1
main::run,main::solve,main::rule_0 3 1339
...

Devel::Trace

Wieder jede Zeile (wie sh -x)

perl -d:Trace script.pl

Bericht:

...
>> ./sudoku-solver.pl:56:     for my $i ( 1 .. 9 ){
>> ./sudoku-solver.pl:57:         for my $j (1 .. 9){
>> ./sudoku-solver.pl:58:             my $c = shift @arr;
>> ./sudoku-solver.pl:59:             if ($c eq '.'){
>> ./sudoku-solver.pl:66:                 $board->{"$i$j"} = {
>> ./sudoku-solver.pl:58:             my $c = shift @arr;
>> ./sudoku-solver.pl:59:             if ($c eq '.'){
>> ./sudoku-solver.pl:66:                 $board->{"$i$j"} = {
>> ./sudoku-solver.pl:58:             my $c = shift @arr;
>> ./sudoku-solver.pl:59:             if ($c eq '.'){
>> ./sudoku-solver.pl:63:                     hypothesis => { map { $_ => 1 } 1 .. 9 },
>> ./sudoku-solver.pl:60:                 $board->{"$i$j"} = {
>> ./sudoku-solver.pl:60:                 $board->{"$i$j"} = {
>> ./sudoku-solver.pl:60:                 $board->{"$i$j"} = {
...

Devel::TraceVars

Noch einmal alle Zeilen die ausführt wurden. Jetzt mit Variablenwerte.

  > perl -d:TraceVars script.pl

Bericht:

...
>> ./sudoku-solver.pl 58: my $c = shift @arr;
>> ./sudoku-solver.pl 59: if (8 eq '.'){
>> ./sudoku-solver.pl 66: HASH(0x13746d0)->{"14"} = {
>> ./sudoku-solver.pl 58: my $c = shift @arr;
>> ./sudoku-solver.pl 59: if (. eq '.'){
>> ./sudoku-solver.pl 63: hypothesis => { map { $_ => 1 } 1 .. 9 },
>> ./sudoku-solver.pl 60: HASH(0x13746d0)->{"15"} = {
>> ./sudoku-solver.pl 60: HASH(0x13746d0)->{"15"} = {
>> ./sudoku-solver.pl 60: HASH(0x13746d0)->{"15"} = {
>> ./sudoku-solver.pl 60: HASH(0x13746d0)->{"15"} = {
>> ./sudoku-solver.pl 60: HASH(0x13746d0)->{"15"} = {
>> ./sudoku-solver.pl 60: HASH(0x13746d0)->{"15"} = {
>> ./sudoku-solver.pl 60: HASH(0x13746d0)->{"15"} = {
>> ./sudoku-solver.pl 58: my $c = shift @arr;
...

Ist alles schon gut? Leider nicht

Also, mit Devel::CallTrace und Devel::CallStack bekommt man zu wenig Information: nur die Namen der Funktionen (die aufgeruft wurden).

Mit Devel::RemoteTrace, Devel::Trace, Devel::TraceVars bekommt man sehr große Logdateien. Zum Beispiel, ich möchte Devel::Trace für ein kleines Programm benutzen. Das program war nur 300 Zeile groß und lief für 2 Sekunden ohne Debugger. Ich bekam 300 Megabyte Logdatei. Es ist unbequem, einen solchen großen File zu bearbeiten. Und für ein größes Program würde es vielleicht uberhaupt unmöglich. Und doch fehlt da einige interresante Informationen: Werte der Variablen, Rückgabewerte der Funktionen unn so weiter.

Mir gefällt am liebsten Devel::TraceSubs. Aber riesiges File ist sowieso unbequem zu untersuchen.

Devel::YCallTrace

So, hier kommt unser Modul. Er heißt Devel::YCallTrace, und mit ihm wir versuchen den goldenen Mittelweg zu finden. Gespeichert werden die Aufrufen der Funktionen, Paremetern und Rückgabewerte. Die Logdatei wird in einer Datenbank gespeichert. Um eienen Bericht zu lesen, kann man einen specialen Html-Schnittstelle benutzen.

Demo

Hier is ein kleines Programm für Fibonacci-Zahlen Rechnung.

require Devel::YCallTrace; 
Devel::YCallTrace::init();     # Hier ist Initialisierung.
print fib($N);
sub fib{
    my ($N) = @_;
    if ($N <= 2 ){
        return 1;
    } else {
        return fib($N-1) + fib($N-2);
    }
}

Führen wir das Programm aus und starten wir den Webdienst um den Bericht zu sehen.

> ./fib.pl 8
21
> ./yct_view.pl
Please contact me at: http://lena-san-thinkpad:39539/ 
> firefox http://lena-san-thinkpad:39539/

Hier ist die Liste, alle Logdateien:

Hier sind Parametern und Rückgabewerte:

Und jetzt zwei speciäle Fällen: wenn ein Funktion exit() oder die aufruft.

Dass ist die Fibonacci-Function, die in zufälligen Moment stirbt.

sub fib
{
    my ($N) = @_;

    die "lucky you! ($N)" if int(rand $DIE_RATE) == 0;

    if ($N <= 2 ){
        return 1;
    } else {
        return fib($N-1) + fib($N-2);
    }
}

Und hier ist die Logdatei:

Hier ist eine änliche Programme mit exit statt die.

sub fib
{
    my ($N) = @_;

    exit 42 if int(rand $DIE_RATE) == 0;

    if ($N <= 2 ){
        return 1;
    } else {
        return fib($N-1) + fib($N-2);
    }
}

Und hier ist die Logdatei:

Das alle waren Beispielen mit Initialisirung im Quelltext. Das kann nicht immer passen. Dann können wir YCallTrace als ein Debugger gebrauchen. Zum Beispiel, ich suche etwas mit dem Programm ack, und will wissen, was das Programm dabei tut.

  > perl -Ilib -d:YCallTraceDbg=namespaces,App::Ack /usr/bin/ack-grep AUTOLOAD

So, hier ist die Logdatei.

Devel::YCallTrace: Nutzung

Also, es gibt 3 Varianten wie man dieses Modul gebrauchen kann.

Prozedurale Schnittstelle. Die Logdatei wird im END block gespeihert.

  require Devel::YCallTrace;
  Devel::YCallTrace::init();

Objektorientirte Schnitstelle mit “Guard object”. perl Der Logdatei wird gespeihert wenn der Objekt zerstört wird.

  require Devel::YCallTrace;
  my $yct = new Devel::YCallTrace;

Als einen Debugger

  perl -d:YCallTraceDbg=namespaces,App::Ack /usr/bin/ack-grep my

Irgendwie im Quelltext einer Webdienst

Was unser Team anbetrifft, wir etwieckeln einen Webdienst und haben im Quelltext etwa so:

if( !production() && cookie('yct_debug') ){
    Devel::YCallTrace::init(...);
    Apache2::RequestUtil->request->pool->cleanup_register( 
        sub {
            Devel::YCallTrace::finish();  
        }
    );
}

Wenn es keine Protuktivumgebung ist und es bei request ein speciales Cookie gibt, dann speichern den Logdatei.

Es ist ziemlich bequem: wenn beim einigem Request etwas merkwürdig passiert, kann man dieses Cookie erzeugen, einen Request machen und dann den Bericht prüfen. Oft ist alles ziemlich schnell clar. Mir gefällt das.

Also, das ist das Werkzeug.

Der Adresse auf github: https://github.com/liruoko/y_call_trace.git

Bitte, probieren Sie mal aus. Es wäre sehr interresant irgendwelches Feedback zu bekommen.