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
2. Wer bin ich Russland, Moskau, Yandex
3. Problemstellung Mein Programm funktioniert nicht richtig. Warum?
4. Lösung: Debugger perl -d my_script.pl
5. Einzelschritt-Verarbeitung • nimmt viel Zeit • langweilig • unter mod_perl – ?
6. Automatischer Debugger • man führt die Programm aus • nötige Logdateien werden automatisch speichern • dann kann man die Logdateien lesen und prüfen
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 ...
8. Beispiele
9. Devel::RemoteTrace “Attachable call trace of perl scripts” Verlangsamung: sehr bedeutend + use Devel::RemoteTrace; > netcat ­u ­l 9999 > kill ­USR2 <pid>
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;
11. Devel::TraceSubs Verlangsamung: ~20x vervolgt Aufrufen der Subroutinen warnings: defined(%hash) is deprecated Modification of non­creatable array value attempted
12. Devel::TraceSubs - Initialisierung +use Devel::TraceSubs; + my $dbg = Devel::TraceSubs­>new( + verbose => 0, + pre => '>', + post => '<', + level => '~', + params => 1, + wrap => ['<!­­', '­­>'], + ); + $dbg­>trace('main::');
13. Devel::TraceSubs - 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
14. Devel::TraceSubs – 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 ...
15. Devel::CallTrace Verlangsmanung: ~1.5x vervolgt Aufrufen der Subroutinen gebraucht der Debugger .deb > perl ­d:CallTrace script.pl
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) ...
17. Devel::CallStack Verlangsamung: 2-10x Gesamtbericht über den Stapelspeicher > perl ­d:CallStack script.pl > less callstack.out
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 ...
19. Devel::Trace Verlangsamung: ~20x druckt jede Zeile Code (wie sh -x) > perl ­d:Trace script.pl
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"} = { ...
21. Devel::TraceVars Verlangsamung: sehr bedeutend druckt jede Zeile Code (mit Variablen) riesige Logdatei > perl ­d:TraceVars script.pl
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; ...
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 – ...
24. Devel::YCallTrace
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
26. Live Demo
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); } }
28. > ./fib.pl 8 21 > ./yct_view.pl Please contact me at: http://lena­ san­thinkpad:39539/ > firefox http://lena­san­ thinkpad:39539/
36. Devel::YCallTrace: Nutzung
37. Prozedurale Schnittstelle require Devel::YCallTrace; Devel::YCallTrace::init(); Die Logdatei wird im END-block gespeichert
38. Objektorientirte Schnitstelle require Devel::YCallTrace; my $yct = new Devel::YCallTrace; Die Logdatei wird gespeichert wenn der Objekt zerstört wird
39. Als ein Debugger perl ­d:YCallTraceDbg=namespaces,App::A ck /usr/bin/ack­grep my Die Logdatei wird im END block gespeichert
40. Irgendwie im Quelltext einer Webdienst if( !production() && cookie('yct_debug') ){ Devel::YCallTrace::init(...); Apache2::RequestUtil­>request­>pool ­>cleanup_register( sub { Devel::YCallTrace::finish(); } ); }
41. https://github.com/liruoko/y_call_trace.git
42. Danke! Elena Bolshakova helena@cpan.org