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

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

Transcript

1. Devel::YCallTrace
   – noch ein anderes Werkzeug zur
   Analyse von Perl Programmen
   Elena Bolshakova
   helena@cpan.org
   

   View Slide

2. Wer bin ich
   Russland, Moskau, Yandex
   

   View Slide

3. Problemstellung
   Mein Programm funktioniert nicht richtig.
   Warum?
   

   View Slide

4. Lösung: Debugger
   perl -d my_script.pl
   

   View Slide

5. Einzelschritt-Verarbeitung
   ●
   nimmt viel Zeit
   ●
   langweilig
   ●
   unter mod_perl – ?
   

   View Slide

6. Automatischer Debugger
   ●
   man führt die Programm aus
   ●
   nötige Logdateien werden automatisch speichern
   ●
   dann kann man die Logdateien lesen und prüfen
   

   View Slide

7. “Automatishe Debuggers” auf CPAN
   Devel::CallChecker Devel::CallParser Devel::CallStack
   Devel::CallTrace Devel::Calltree Devel::DTrace
   Devel::DumpTrace Devel::DumpTrace::PPI
   Devel::Optrace Devel::PrettyTrace Devel::RemoteTrace
   Devel::SimpleTrace Devel::Spy Devel::STrace
   Devel::Trace Devel::TraceCalls Devel::Trace::Cwd
   Devel::Trace::Fork Devel::Trace::Method
   Devel::TraceMethods Devel::Trace::More
   Devel::TraceSubs Devel::TraceUse Devel::TraceVars
   Devel::TrackObjects Runops::Recorder Runops::Trace
   ...
   

   View Slide

8. Beispiele
   

   View Slide

9. Devel::RemoteTrace
   “Attachable call trace of perl scripts”
   Verlangsamung: sehr bedeutend
   + use Devel::RemoteTrace;
   > netcat ­u ­l 9999
   > kill ­USR2
   

   View Slide

10. Devel::RemoteTrace – 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;
    

    View Slide

11. Devel::TraceSubs
    Verlangsamung: ~20x
    vervolgt Aufrufen der Subroutinen
    warnings:
    defined(%hash) is deprecated
    Modification of non­creatable array value
    attempted
    

    View Slide

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

    View Slide

13. Devel::TraceSubs - Bericht
    
    at sample_scripts/fib.pl line 32
    
    at sample_scripts/fib.pl line 42
    
    at sample_scripts/fib.pl line 42
    
    at sample_scripts/fib.pl line 42
    
    at sample_scripts/fib.pl line 42
    
    at sample_scripts/fib.pl line 42
    
    at sample_scripts/fib.pl line 42
    
    at sample_scripts/fib.pl line 42
    
    at sample_scripts/fib.pl line 42
    

    View Slide

14. Devel::TraceSubs – Bericht 2
    
    at ./sudoku-solver.pl line 27
    
    at ./sudoku-solver.pl line 27
    
    at ./sudoku-solver.pl line 33
    
    at ./sudoku-solver.pl line 126
    
    at ./sudoku-solver.pl line 126
    
    at ./sudoku-solver.pl line 127
    
    at ./sudoku-solver.pl line 127
    

    View Slide

15. Devel::CallTrace
    Verlangsmanung: ~1.5x
    vervolgt Aufrufen der Subroutinen
    gebraucht der Debugger
    .deb
    > perl ­d:CallTrace script.pl
    

    View Slide

16. Devel::CallTrace – 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)
    ...
    

    View Slide

17. Devel::CallStack
    Verlangsamung: 2-10x
    Gesamtbericht über den Stapelspeicher
    > perl ­d:CallStack script.pl
    > less callstack.out
    

    View Slide

18. Devel::CallStack – 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
    ...
    

    View Slide

19. Devel::Trace
    Verlangsamung: ~20x
    druckt jede Zeile Code (wie sh -x)
    > perl ­d:Trace script.pl
    

    View Slide

20. Devel::Trace – 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"} = {
    ...
    

    View Slide

21. Devel::TraceVars
    Verlangsamung: sehr bedeutend
    druckt jede Zeile Code (mit Variablen)
    riesige Logdatei
    > perl ­d:TraceVars script.pl
    

    View Slide

22. Devel::TraceVars – 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;
    ...
    

    View Slide

23. Ist alles schon gut? Leider nicht
    ●
    riesige Logdateien
    – schwierig zu lesen und grep'en
    – passt nicht für die große Programme
    ●
    doch gibt es einige Informationen nicht
    – Werte der Variablen
    – ob die Subroutine ihre Parametern modifiziert hat
    – ...
    

    View Slide

24. Devel::YCallTrace
    

    View Slide

25. Devel::YCallTrace
    vervolgt Aufrufen der Funktionen
    Verlangsamung bis 50-100x
    prozedurale, objektorientirte und debugger
    Schnittstelle
    mod_perl kompatibel
    perl >= 5.8 kompatibel
    erfordet Aspect, Template::Toolkit,
    HTTP::Daemon
    gebraucht SQLite oder andere DB
    

    View Slide

26. Live Demo
    

    View Slide

27. Plan B for live demo
    # Fibonacci numbers, recursively
    require Devel::YCallTrace;
    Devel::YCallTrace::init();
    print fib($N);
    sub fib{
    my ($N) = @_;
    if ($N <= 2 ){
    return 1;
    } else {
    return fib($N­1) + fib($N­2);
    }
    }
    

    View Slide

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

    View Slide

29. View Slide

30. View Slide

31. View Slide

32. View Slide

33. View Slide

34. View Slide

35. View Slide

36. Devel::YCallTrace: Nutzung
    

    View Slide

37. Prozedurale Schnittstelle
    require Devel::YCallTrace;
    Devel::YCallTrace::init();
    Die Logdatei wird im END-block gespeichert
    

    View Slide

38. Objektorientirte Schnitstelle
    require Devel::YCallTrace;
    my $yct = new Devel::YCallTrace;
    Die Logdatei wird gespeichert wenn der
    Objekt zerstört wird
    

    View Slide

39. Als ein Debugger
    perl
    ­d:YCallTraceDbg=namespaces,App::A
    ck /usr/bin/ack­grep my
    Die Logdatei wird im END block gespeichert
    

    View Slide

40. Irgendwie im Quelltext einer
    Webdienst
    if( !production() && cookie('yct_debug') ){
    Devel::YCallTrace::init(...);
    Apache2::RequestUtil­>request­>pool
    ­>cleanup_register(
    sub {
    Devel::YCallTrace::finish();
    }
    );
    }
    

    View Slide

41. https://github.com/liruoko/y_call_trace.git
    

    View Slide

42. Danke!
    Elena Bolshakova
    helena@cpan.org
    

    View Slide