Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
p5pRT opened this issue Dec 17, 1999 · 2 comments
Closed

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

p5pRT opened this issue Dec 17, 1999 · 2 comments

Comments

@p5pRT
Copy link

p5pRT commented Dec 17, 1999

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

Searchable as RT1913$

@p5pRT
Copy link
Author

p5pRT commented Dec 17, 1999

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
Copy link
Author

p5pRT commented Dec 17, 1999

From @TimToady

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

111% of crap is everything. --Steodore Thurgeon

Larry

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

1 participant