CODEWITHSUNDEEP
perloptimizationprofiling
jh314
jh314

Reputation: 27792

Profiling Perl with DProf, with long Total elapsed times

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;
}

Upvotes: 0

Views: 241

Answers (2)

Slaven Rezic
Slaven Rezic

Reputation: 4581

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

Upvotes: 1

FUJI Goro
FUJI Goro

Reputation: 889

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.

Upvotes: 1

Related Questions