Beefy Boxes and Bandwidth Generously Provided by pair Networks
Perl Monk, Perl Meditation

NYTProf times don't add up

by alain_desilets (Beadle)
on Jun 26, 2012 at 16:41 UTC ( #978463=perlquestion: print w/replies, xml ) Need Help??
alain_desilets has asked for the wisdom of the Perl Monks concerning the following question:

I am trying to profile a perl script with NYTProf, and am seeing very strange things in the report.

Firstly, I get error message:

"Warning: 233 subroutine calls had negative time! The clock being used + (-1) is probably unstable, so the results will be as well.

Which has been the subject of this node:

I gather that this is due to the fact that the clocks on the different cores of my machine are not always synchronized. From reading the above node, I had understood that this would only be an issue for methods that are run a great number of times, each running for a very short time.

But that doesn't seem to be the case. Indeed, the second most time consuming sub in the report was called only 4 times, for a total of 7.03 secs. Yet, its timings seems completely inaccurate. When I add up the inclusive times of each of the lines in that sub, I get a total of 2.8 secs, which is quite short of the 7.03 secs NYTProf claims was spent in that sub.

Another strange thing is that for some of the lines, the Exclusive time is larger than the Inclusive time. I thought Inclusive time was supposed to always be greater or equal to the Exclusive time, since it includes not only the time spent on that line, but also the time spent inside the subs being called by that line (whereas Exclusive is only the time spent on that line).

Am I missing anything? Below is the part of the report that relates to that sub.

# spent 7.03s (4.16+2.87) within FastAligner::_get_urls_to_files which + was called 4 times, avg 1.76s/call: # 4 times (4.16s+2.87s) by FastAligner::get_alignments at line 184, av +g 1.76s/call sub _get_urls_to_files { 50 4 0s my ($self, $slid, $tlid, $source_url, $target +_url) = @_; 51 4 0s 4 0s Tracing::trace('FastAligner._get_urls_to_f +iles', "** \$slid=$slid, \$tlid=$tlid"); # spent 0s making 4 calls to Tracing::trace, avg 0s/call 52 4 0s my $urls_to_files = {}; 53 4 0s my $aldir = undef; 54 4 0s my $found_source_url = undef; 55 4 0s my $found_target_url = undef; 56 57 # Alignments directory can be Alignments_ssal_en +_fr or Alignments_ssal_fr_en 58 59 4 0s my $aldir_sl_tl = $self->{alignments_director +y}."_".$slid."_".$tlid; 60 4 0s my $aldir_tl_sl = $self->{alignments_director +y}."_".$tlid."_".$slid; 61 62 # WEBITEXT_CORPORA contains directories named af +ter prealigned corpora (genomics, etc). 63 # In each of these directories, there's an Align +ment_ssal_sl_tl directory. 64 # In each of these, there's a file called aligne +d_to_url.txt, that contains mapping from url to 65 # the file containing aligned sentences for that + url. urls_to_files will contain that mapping 66 # for source_url and target_url 67 68 4 0s 8 0s opendir(WBT_CORP_DIR, $self->wbt_corpora_d +ir()); # spent 0s making 4 calls to FastAligner::CORE:open_dir, avg 0s/call # + spent 0s making 4 calls to ObjectWithHelpers::AUTOLOAD, avg 0s/call 69 70 4 0s 4 0s foreach my $index_dir (readdir(WBT_CORP_DI +R)) # spent 0s making 4 calls to FastAligner::CORE:readdir, avg 0s/call 71 { 72 44 0s if (!($index_dir eq '.') && !($index_dir eq +'..')) 73 { 74 36 10.0ms 72 0s my $index_dir_path = File::Spec->can +onpath($self->wbt_corpora_dir()."/".$index_dir); # spent 0s making 36 calls to File::Spec::Win32::canonpath, avg 0s/cal +l # spent 0s making 36 calls to ObjectWithHelpers::AUTOLOAD, avg 0s/c +all 75 36 0s 36 0s opendir(INDEX_DIR, $index_dir_path); # spent 0s making 36 calls to FastAligner::CORE:open_dir, avg 0s/call 76 36 0s 36 0s foreach my $dir (readdir(INDEX_DIR)) # spent 0s making 36 calls to FastAligner::CORE:readdir, avg 0s/call 77 { 78 304 0s if (($dir eq $aldir_sl_tl) || ($dir eq $ald +ir_tl_sl)) 79 { 80 16 0s 32 0s my $alfile = File::Spec->canonpath($self +->wbt_corpora_dir()."/". # spent 0s making 16 calls to File::Spec::Win32::canonpath, avg 0s/cal +l # spent 0s making 16 calls to ObjectWithHelpers::AUTOLOAD, avg 0s/c +all 81 $index_dir."/".$dir."/aligned_to_url.txt"); 82 83 16 10.0ms 16 10.0ms open F, "<", $alfile; # spent 10.0ms making 16 calls to FastAligner::CORE:open, avg 625Ás/ca +ll 84 16 0s 16 0s while (<F>) { # spent 0s making 16 calls to FastAligner::CORE:readline, avg 0s/call 85 527384 193ms my $line = $_; 86 527384 245ms chomp $line; 87 527384 3.18s 527384 1.86s $line =~ /(.+) >>> (.+)/; # spent 1.86s making 527384 calls to FastAligner::CORE:match, avg 4Ás/ +call 88 527384 610ms if ($source_url eq $2) { 89 $urls_to_files->{$source_url} = $1; 90 $found_source_url = 1; 91 } elsif ($target_url eq $2) { 92 $urls_to_files->{$target_url} = $1; 93 $found_target_url = 1; 94 } 95 527384 2.77s 527384 997ms if (defined($found_source_ +url) && defined($found_target_url)) # spent 997ms making 527384 calls to FastAligner::CORE:readline, avg 2 +Ás/call 96 { 97 $aldir = File::Spec->canonpath($self->wbt_corpor +a_dir()."/". 98 $index_dir."/".$dir); 99 close F; 100 closedir(INDEXDIR); 101 closedir(WBT_CORP_DIR); 102 return ($aldir,$urls_to_files); 103 } 104 } 105 16 0s 16 0s close F; # spent 0s making 16 calls to FastAligner::CORE:close, avg 0s/call 106 } 107 } 108 36 10.0ms 36 0s closedir(INDEXDIR); # spent 0s making 36 calls to FastAligner::CORE:closedir, avg 0s/call 109 } 110 } 111 4 0s 4 0s closedir(WBT_CORP_DIR); # spent 0s making 4 calls to FastAligner::CORE:closedir, avg 0s/call 112 4 0s return undef; 113 }

Replies are listed 'Best First'.
Re: NYTProf times don't add up
by tim.bunce (Scribe) on Jun 27, 2012 at 13:22 UTC

    I've added a section to the docs to help explain the likely cause:

    Let me know if that doesn't help enough. (Ideally via the mailing list.)

    p.s. Thanks to moritz++ for alerting me to this node as I'm an infrequent visitor to the monastery.

      Since finding the diff through was a bit of work for me, I've decided to paste the new content into this thread:

      =head2 Warning: %d subroutine calls had negative time

      There are two likely causes for this: clock instability, or accumulated timing errors.

      Clock instability, if present on your system, is most likely to be noticable on very small/fast subroutines that are called very few times.

      Accumulated timing errors can arise because the subroutine profiler uses floating point values (NVs) to store the times. They are most likely to be noticed on subroutines that are called a few times but which make a large number of calls to very fast subroutines (such as opcodes). In this case the accumulated time apparently spent making those calls can be greater than the time spent in the calling subroutine.

      If you rerun nytprofhtml (etc.) with the L</trace=N> option set >0 you'll see trace messages like "%s call has negative time: incl %fs, excl %fs" for each affected subroutine.

      Try profiling with the L</slowops=N> option set to 0 to disable the profiling of opcodes. Since opcodes often execute in a few microseconds they are a common cause of this warning.

      You could also try recompiling perl to use 'long doubles' for the NV floating point type (use Configure -Duselongdouble). If you try this please let me know. I'd also happily take a patch to use long doubles, if available, by default.

      Thanks for that update.

      - tye        

Log In?

What's my password?
Create A New User
Node Status?
node history
Node Type: perlquestion [id://978463]
Front-paged by Corion
and all is quiet...

How do I use this? | Other CB clients
Other Users?
Others avoiding work at the Monastery: (8)
As of 2018-06-22 13:44 GMT
Find Nodes?
    Voting Booth?
    Should cpanminus be part of the standard Perl release?

    Results (124 votes). Check out past polls.