Perl / perl5

🐪 The Perl programming language
https://dev.perl.org/perl5/
Other
1.98k stars 559 forks source link

DProf reports > 100% of time for sub with eval in it #966

Closed p5pRT closed 20 years ago

p5pRT commented 24 years ago

Migrated from rt.perl.org#1913 (status was 'resolved')

Searchable as RT1913$

p5pRT commented 24 years ago

From haimson@mollusc.cnd.hp.com

The following is the command line and output for profiling my script mk.ovperms.conf.pl​:

  $ perl -d​:DProf mk.ovperms.conf.pl -v 2 $(cat input)   mk.ovperms.conf.pl​: Processing directories   mk.ovperms.conf.pl​: Processing AGENT-MAN   mk.ovperms.conf.pl​: Processing MASTER   mk.ovperms.conf.pl​: Processing OVDB-RUN   mk.ovperms.conf.pl​: Warning​: OVDB-RUN line 7​:   /var/opt/OV/share/databases/analysis/default/backup​:   directory not found in directories file   mk.ovperms.conf.pl​: Warning​: OVDB-RUN line 7​:   /var/opt/OV/share/databases/analysis/default/backup​:   owner not defined\, defaulting to "bin"   group not defined\, defaulting to "bin"   mode not defined\, defaulting to 0555   mk.ovperms.conf.pl​: Processing OVEVENT-MIN   mk.ovperms.conf.pl​: Processing OVEVENTMIN-MAN   mk.ovperms.conf.pl​: Processing OVISP   mk.ovperms.conf.pl​: Processing OVISP-JPN   mk.ovperms.conf.pl​: Processing OVISP-MAN   mk.ovperms.conf.pl​: Processing OVMIB-CONTRIB   mk.ovperms.conf.pl​: Processing OVMIN   mk.ovperms.conf.pl​: Processing OVMIN-MAN   mk.ovperms.conf.pl​: Processing OVMIN-PRG   mk.ovperms.conf.pl​: Processing OVMIN-PRG-MAN   mk.ovperms.conf.pl​: Processing OVNNM-DOC-REUS   mk.ovperms.conf.pl​: Processing OVNNM-RUN   mk.ovperms.conf.pl​: Processing OVNNM-RUN-MAN   mk.ovperms.conf.pl​: Processing OVNNMGR-JPN   mk.ovperms.conf.pl​: Processing OVPMD-MIN   mk.ovperms.conf.pl​: Processing OVPMD-MIN-MAN   mk.ovperms.conf.pl​: Processing OVRPT-RUN   mk.ovperms.conf.pl​: Processing OVSNMP-MIN   mk.ovperms.conf.pl​: Processing OVSNMP-MIN-MAN   mk.ovperms.conf.pl​: Processing OVSNMP-PRG   mk.ovperms.conf.pl​: Processing OVSNMP-PRG-MAN   mk.ovperms.conf.pl​: Processing OVWIN   mk.ovperms.conf.pl​: Processing OVWIN-BGROUND   mk.ovperms.conf.pl​: Processing OVWIN-MAN   mk.ovperms.conf.pl​: Processing OVWIN-PRG   mk.ovperms.conf.pl​: Processing OVWIN-PRG-MAN   mk.ovperms.conf.pl​: Processing OVWWW-EVNT   mk.ovperms.conf.pl​: Processing OVWWW-FW   mk.ovperms.conf.pl​: Processing OVWWW-JPN   mk.ovperms.conf.pl​: Warning​: OVWWW-JPN line 77​:   /opt/OV/www/protected/htdocs/ja_JP.SJIS​:   Directory not found in directories file   mk.ovperms.conf.pl​: Warning​: OVWWW-JPN line 77​:   /opt/OV/www/protected/htdocs/ja_JP.eucJP​:   Directory not found in directories file   mk.ovperms.conf.pl​: Processing OVWWW-SRV   mk.ovperms.conf.pl​: Processing SUBAGT-HPUNIX   mk.ovperms.conf.pl​: Processing SUBAGT-HPUNIXTB   mk.ovperms.conf.pl​: Processing SUBAGT-MIB2   mk.ovperms.conf.pl​: Processing SUBAGT-MIB2TB   mk.ovperms.conf.pl​: Processing SUBAGT-NAA

The following is the output of dprofpp for this run​:

  $ dprofpp tmon.out   Total Elapsed Time = 259.3314 Seconds   User+System Time = 99.30836 Seconds   Exclusive Times   %Time ExclSec CumulS #Calls sec/call Csec/c Name   111. 110.7 125.14 3592 0.0308 0.0348 main​::replaceVar   14.8 14.71 7.741 222796 0.0001 0.0000 Env​::FETCH   14.4 14.37 7.062 233551 0.0001 0.0000 main​::Info   3.67 3.648 1.836 57912 0.0001 0.0000 main​::MoreInfo   3.35 3.324 128.92 3782 0.0009 0.0341 main​::processEntry   2.12 2.106 132.52 1 2.1057 132.52 main​::ProcessFPFiles   0.66 0.656 125.57 3592 0.0002 0.0350 main​::universalPath   0.28 0.279 0.167 3592 0.0001 0.0000 main​::remapPath   0.20 0.199 0.176 756 0.0003 0.0002 main​::basename   0.10 0.100 0.050 1583 0.0001 0.0000 main​::isApplicable   0.10 0.099 0.228 328 0.0003 0.0007 main​::manDest   0.05 0.050 0.140 3 0.0166 0.0467 main​::BEGIN   0.03 0.025 0.051 1 0.0253 0.0506 Env​::import   0.02 0.020 0.020 1 0.0200 0.0200 vars​::import   0.02 0.020 0.020 1 0.0199 0.0198 Cwd​::BEGIN

Note that %Time reported for main​::replaceVar is 111%. The sum of the rest of the %Times suggests it should be more like 60%. I'm guessing that the profiler doesn't correctly handle the eval in main​::replaceVar\, which I would expect is taking most of the time​:

  #   # For each variable in the list of variable names passed in the array\,   # replace an instance of the variable's value with its name.   # For example\, if $OV_NODELOCK is set to "/var/opt/ifor"\, replace an   # instance of "/var/opt/ifor" in path with "$OV_NODELOCK".   #

  sub replaceVar ($\,@​) {   my($path) = shift;   my($var\, $snippet\, $subsnippet1\, $subsnippet2);

  $snippet = "";   foreach $var (@​_) {   $subsnippet1 = "\$path =~ s%^\$$var(\\W)%\\\$$var\$1%;\n";   &Info(8\, "subsnippet1 = \"%s\""\, "$subsnippet1");   $subsnippet2 = "\$path =~ s%^\$$var\$%\\\$$var%;\n";   &Info(8\, "subsnippet2 = \"%s\""\, "$subsnippet2");   $snippet .= $subsnippet1 . $subsnippet2;   }   eval($snippet);   return($path);   }


Site configuration information for perl 5.00502​:

Configured by root at Mon Dec 14 16​:32​:18 MET 1998.

Summary of my perl5 (5.0 patchlevel 5 subversion 2) configuration​:   Platform​:   osname=hpux\, osvers=10.20\, archname=PA-RISC1.1   uname='hp-ux hpcsmnsd b.10.20 c 9000782 2012425771 32-user license '   hint=recommended\, useposix=true\, d_sigaction=define   usethreads=undef useperlio=undef d_sfio=undef   Compiler​:   cc='cc'\, optimize='-O +Onolimit'\, gccversion=   cppflags='+DAportable -Ae -I/usr/local/include -I/opt/gnu/include -I/opt/hppd/include -I/opt/bzip2/include -I/opt/zlib/include -I/usr/contrib/include -I/usr/contrib/X11R6/include'   ccflags ='+DAportable -Ae -I/usr/local/include -I/opt/gnu/include -I/opt/hppd/include -I/opt/bzip2/include -I/opt/zlib/include -I/usr/contrib/include -I/usr/contrib/X11R6/include'   stdchar='unsigned char'\, d_stdstdio=define\, usevfork=true   intsize=4\, longsize=4\, ptrsize=4\, doublesize=8   d_longlong=define\, longlongsize=8\, d_longdbl=define\, longdblsize=16   alignbytes=8\, usemymalloc=y\, prototype=define   Linker and Libraries​:   ld='ld'\, ldflags =' -L/usr/local/lib -L/opt/gnu/lib -L/opt/hppd/lib -L/opt/bzip2/lib -L/usr/contrib/X11R6/lib -L/usr/contrib/lib -L/opt/socks/lib'   libpth=/usr/local/lib /opt/gnu/lib /opt/hppd/lib /opt/bzip2/lib /usr/contrib/X11R6/lib /usr/contrib/lib /opt/socks/lib /lib/pa1.1 /lib /usr/lib /usr/ccs/lib   libs=-lnsl_s -lndbm -lgdbm -ldb -ldld -lm -lc -lndir -lcrypt -lSocks   libc=/lib/libc.sl\, so=sl\, useshrplib=false\, libperl=libperl.a   Dynamic Linking​:   dlsrc=dl_hpux.xs\, dlext=sl\, d_dlsymun=undef\, ccdlflags='-Wl\,-E -Wl\,-B\,deferred '   cccdlflags='+z'\, lddlflags='-b -L/usr/local/lib -L/opt/gnu/lib -L/opt/hppd/lib -L/opt/bzip2/lib -L/usr/contrib/X11R6/lib -L/usr/contrib/lib -L/opt/socks/lib'

Locally applied patches​:  


@​INC for perl 5.00502​:   /opt/perl5.005/lib/5.00502/PA-RISC1.1   /opt/perl5.005/lib/5.00502   /opt/perl5.005/lib/site_perl/5.005/PA-RISC1.1   /opt/perl5.005/lib/site_perl/5.005   .


Environment for perl 5.00502​:   HOME=/home/haimson   LANG=C   LD_LIBRARY_PATH=/usr/lib/X11​:/view/dmh_601CPE/DE/libovw/lib/10.0HPUX_800​:/view/dmh_601CPE/DE/libov/lib/10.0HPUX_800​:/view/dmh_601CPE/DE/util_libs/lib/10.0HPUX_800​:/view/dmh_601CPE/DE/snmpCore/libovsnmp/lib/10.0HPUX_800​:/view/dmh_601CPE/DE/misc_libs/10.0HPUX_800   LOGDIR (unset)   PATH=/opt/CC/bin​:/home/haimson/bin​:/bin​:/usr/bin​:/usr/local/bin​:/usr/contrib/bin​:/usr/bin/X11​:/usr/local/bin/X11​:/usr/contrib/bin/X11​:/usr/etc​:/usr/ucb​:/usr/openwin/bin​:/usr/gnu/bin​:/opt/SUNWspro/bin​:/opt/langtools/bin​:/opt/perl5/bin​:/usr/local/bin/mh​:.​:/opt/langtools/bin​:/usr/dt/bin​:/opt/OV/bin​:/usr/atria/bin​:/view/dmh_601CPE/DE/ClearCase/scripts​:./10.0HPUX_800   PERL_BADLANG (unset)   SHELL=/bin/ksh

p5pRT commented 24 years ago

From @TimToady

David Haimson writes​: : Note that %Time reported for main​::replaceVar is 111%.

111% of crap is everything. --Steodore Thurgeon

Larry