perl -d:DProf foo.pl #### perl -MDevel::Profiler foo.pl #### dprofpp #### main(); sub main { my $now = time(); for( my $x = 0; $x <= 1_000_000; $x++ ) { print scalar localtime, "\n" if $now != time(); $now = time(); } return; } #### Total Elapsed Time = 1.859881 Seconds User+System Time = 1.389881 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 98.5 1.370 1.370 1 1.3700 1.3700 main::main 0.72 0.010 0.010 2 0.0050 0.0050 main::BEGIN #### main(); sub main { all_the_work() } sub all_the_work { my $now = time(); for( my $x = 0; $x <= 1_000_000; $x++ ) { print scalar localtime, "\n" if $now != time(); $now = time(); } return; } #### Total Elapsed Time = 1.809848 Seconds User+System Time = 1.379848 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 98.5 1.360 1.360 1 1.3600 1.3600 main::all_the_work 0.00 - 1.360 1 - 1.3600 main::main 0.00 - 0.010 2 - 0.0050 main::BEGIN #### main(); sub main { do_nothing(); all_the_work(); } sub do_nothing { sleep 5 } sub all_the_work { my $now = time(); for( my $x = 0; $x <= 1_000_000; $x++ ) { print scalar localtime, "\n" if $now != time(); $now = time(); } return; } #### Total Elapsed Time = 6.809867 Seconds User+System Time = 1.459867 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 97.9 1.430 1.430 1 1.4300 1.4300 main::all_the_work 0.68 0.010 0.010 2 0.0050 0.0050 main::BEGIN 0.00 - -0.000 1 - - main::do_nothing 0.00 - 1.430 1 - 1.4300 main::main #### Total Elapsed Time = 6.799829 Seconds Real Time = 6.799829 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 73.5 5.000 5.000 1 5.0000 5.0000 main::do_nothing 26.1 1.780 1.780 1 1.7800 1.7800 main::all_the_work 0.15 0.010 0.020 2 0.0050 0.0100 main::BEGIN 0.00 - 6.780 1 - 6.7800 main::main