Profiling Perl with DProf, with long Total elapsed times

Question

I just profiled my code with DProf:

Total Elapsed Time = 9.969922 Seconds
  User+System Time = 0.049922 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 40.0   0.020  0.020      2   0.0100 0.0100  main::difference
 40.0   0.020  0.020      3   0.0067 0.0066  main::BEGIN
 0.00       - -0.000      1        -      -  DynaLoader::dl_install_xsub
 0.00       - -0.000      1        -      -  Data::Dumper::bootstrap
 0.00       - -0.000      1        -      -  strict::import
 0.00       - -0.000      1        -      -  warnings::BEGIN
 0.00       - -0.000      1        -      -  warnings::import
 0.00       - -0.000      1        -      -  bytes::import
 0.00       - -0.000      1        -      -  strict::bits
 0.00       - -0.000      1        -      -  DynaLoader::dl_load_file
 0.00       - -0.000      1        -      -  DynaLoader::dl_undef_symbols
 0.00       - -0.000      1        -      -  DynaLoader::dl_find_symbol
 0.00       - -0.000      1        -      -  overload::BEGIN
 0.00       - -0.000      2        -      -  warnings::register::mkMask
 0.00       - -0.000      2        -      -  Exporter::import

So my difference subroutine takes around 40% of the time, and BEGIN takes up the other 40%. I'm not so sure what is going on for the other 9.8 seconds. Could anyone explain to me what Perl is doing for the rest of the time?

Basically, my code takes in two arrays, performs a set difference, and writes to a file. The files are not too large (23,028 characters). This is my difference subroutine, if you are curious:

sub difference {
    my @array1 = @{$_[0]};
    my @array2 = @{$_[1]};

    my %in_array1 = map {$_ => 1} @array1;
    my @diff  = grep {not $in_array1{$_}} @array2;
    return @diff;
}

DProf is old, and superseded by [Devel::NYTProf](https://metacpan.org/module/Devel::NYTProf): colour-coding, source maps, pretty drill-down graphics, statement-level profiling, … it's the profiler's heaven (unless you need threads). Why don't you re-profile your code with that modern tool, and look at the HTML output? — amon, Jul 10 '13 at 21:50

score 1 · Answer 1 · answered Jul 10 '13 at 21:50

1

Devel::DProf is deprecated, so I don't know it works or not.

Use Devel::NYTProf (https://metacpan.org/module/Devel::NYTProf), which is a super useful Perl profiler.

answered Jul 10 '13 at 21:50

FUJI Goro

869
10
19

I can't install Perl modules, and unfortunately I don't have NYTProf installed. Is there an alternative? – jh314 Jul 10 '13 at 22:01
I don't know an alternative, but if you can login the system with SSH and can use a C compiler, you can install NYTProf in your space using cpanm: `curl -L http://cpanmin.us | perl -- -l extlib Devel::NYTProf` and you can use it with `perl -Mlib=extlib/lib/perl5 -d:NYTProf`. – FUJI Goro Jul 10 '13 at 22:25
2

[Of course](http://stackoverflow.com/questions/251705/) [you can](http://stackoverflow.com/questions/2980297/) [install](http://stackoverflow.com/q/102850/168657) [Perl modules](http://stackoverflow.com/q/540640/168657). – mob Jul 11 '13 at 00:25

score 1 · Answer 2 · answered Jul 11 '13 at 07:53

1

Perl is very probably just waiting. Either there's a sleep() or the script is waiting for disk or network input/output or external commands (system/exec/backticks) or something similar. You can reproduce it very easily by using the following script:

#!/usr/bin/perl
x();
sub x {
    sleep 10;
}

dprofpp output on my system is:

Total Elapsed Time = 9.999998 Seconds
  User+System Time =        0 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 0.00       - -0.000      1        -      -  main::x

answered Jul 11 '13 at 07:53

Slaven Rezic

4,571
14
12

I do have a single backtick that is executed 3 times (in a loop). Is there a way to optimize it? – jh314 Jul 11 '13 at 13:51
Well, you don't have to optimize your perl script, but the command which is called in the backtick... – Slaven Rezic Jul 11 '13 at 13:58

Profiling Perl with DProf, with long Total elapsed times

2 Answers2