Bug #72941 for Devel-DProf: [perl #59384] DProf reports wrong elapsed times

> This is a bug report for perl from jeff.holt@method-r.com, > generated with the help of perlbug 1.36 running under perl 5.10.0. > > > ----------------------------------------------------------------- > [Please enter your report here] > > The runtime of the following command was about 2 minutes: > > perl -d:DProf p5k.pl x.zip > x.xml > > It created a 395MB tmon.out file (deflated is 5MB). Then I executed > dprofpp > and it printed this (only the first few lines are shown): > > Total Elapsed Time = 6.188358 Seconds > User+System Time = 6.108358 Seconds > Exclusive Times > %Time ExclSec CumulS #Calls sec/call Csec/c Name > 264. 16.13 16.158 1611 0.0100 0.0100 > Shared::SharedSQL::sharable > 171. 10.45 10.458 202314 0.0000 0.0000 Unicode::String::utf8 > 152. 9.287 8.602 284349 0.0000 0.0000 > Bit::Vector::_fetch_operand > 105. 6.473 6.473 164688 0.0000 0.0000 main::to_valid_xml > 97.0 5.930 6.427 961170 0.0000 0.0000 > IO::Uncompress::Base::_getline > 80.4 4.912 15.645 50229 0.0001 0.0003 main::parseBind > 49.6 3.031 9.458 961170 0.0000 0.0000 > IO::Uncompress::Base::getline > 41.9 2.565 14.161 147925 0.0000 0.0001 main::calcExclusive > 31.7 1.942 6.156 155559 0.0000 0.0000 Bit::Vector::_add > 26.3 1.608 11.221 195194 0.0000 0.0001 main::applyCursorWaits > 23.6 1.442 1.442 410550 0.0000 0.0000 > Shared::Util::scientificToFloat > 22.5 1.375 2.171 296605 0.0000 0.0000 main::parseWait > 21.9 1.343 1.476 207731 0.0000 0.0000 main::mergeIntoStmt > 20.5 1.253 3.028 149767 0.0000 0.0000 main::applyUAF > 17.5 1.071 1.728 358528 0.0000 0.0000 main::addRecStat > > The exclusive times for each function are also probably incorrect. I > ran it with > the "-O 200" argument and the total exclusive time was ~83 seconds; > far less > than the actual response time. So it's difficult for me to believe any > of the data > in this report. > > I suppose these times could be incorrect if they are only estimates. > For example, > the Oracle RDBMS estimates elapsed time when constructing row sources > because > to execute gettimeofday more frequently would cause horribly excessive > response > times. Maybe DProf does the same thing? If so, that would explain the > outrageously > incorrect response times. > > Here's what dprofpp -V prints > C:\progra~1\perl-5.10.0.1004\bin/dprofpp.bat version: 20050603.00 > XS_VERSION: DProf 20050603.00 > > [Please do not change anything below this line] > ----------------------------------------------------------------- > --- > Flags: > category=library > severity=low > --- > Site configuration information for perl 5.10.0: > > Configured by SYSTEM at Wed Sep 3 13:16:08 2008. > > Summary of my perl5 (revision 5 version 10 subversion 0) > configuration: > Platform: > osname=MSWin32, osvers=5.00, archname=MSWin32-x86-multi-thread > uname='' > config_args='undef' > hint=recommended, useposix=true, d_sigaction=undef > useithreads=define, usemultiplicity=define > useperlio=define, d_sfio=undef, uselargefiles=define, > usesocks=undef > use64bitint=undef, use64bitall=undef, uselongdouble=undef > usemymalloc=n, bincompat5005=undef > Compiler: > cc='cl', ccflags ='-nologo -GF -W3 -MD -Zi -DNDEBUG -O1 -DWIN32 > -D_CONSOLE -DNO_STRICT -DHAVE_DES_FCRYPT -DUSE_SITECUSTOMIZE > -DPRIVLIB_LAST_IN_INC -DPERL_IMPLICIT_CONTEXT -DPERL_IMPLICIT_SYS > -DUSE_PERLIO -DPERL_MSVCRT_READFIX', > optimize='-MD -Zi -DNDEBUG -O1', > cppflags='-DWIN32' > ccversion='12.00.8804', gccversion='', gccosandvers='' > intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234 > d_longlong=undef, longlongsize=8, d_longdbl=define, longdblsize=10 > ivtype='long', ivsize=4, nvtype='double', nvsize=8, > Off_t='__int64', lseeksize=8 > alignbytes=8, prototype=define > Linker and Libraries: > ld='link', ldflags ='-nologo -nodefaultlib -debug -opt:ref,icf > -libpath:"C:\progra~1\perl-5.10.0.1004\lib\CORE" -machine:x86' > libpth=\lib > libs= oldnames.lib kernel32.lib user32.lib gdi32.lib winspool.lib > comdlg32.lib advapi32.lib shell32.lib ole32.lib oleaut32.lib > netapi32.lib uuid.lib ws2_32.lib mpr.lib winmm.lib version.lib > odbc32.lib odbccp32.lib msvcrt.lib > perllibs= oldnames.lib kernel32.lib user32.lib gdi32.lib > winspool.lib comdlg32.lib advapi32.lib shell32.lib ole32.lib > oleaut32.lib netapi32.lib uuid.lib ws2_32.lib mpr.lib winmm.lib > version.lib odbc32.lib odbccp32.lib msvcrt.lib > libc=msvcrt.lib, so=dll, useshrplib=true, libperl=perl510.lib > gnulibc_version='' > Dynamic Linking: > dlsrc=dl_win32.xs, dlext=dll, d_dlsymun=undef, ccdlflags=' ' > cccdlflags=' ', lddlflags='-dll -nologo -nodefaultlib -debug > -opt:ref,icf -libpath:"C:\progra~1\perl-5.10.0.1004\lib\CORE" > -machine:x86' > > Locally applied patches: > ACTIVEPERL_LOCAL_PATCHES_ENTRY > 33741 avoids segfaults invoking S_raise_signal() (on Linux) > 33763 Win32 process ids can have more than 16 bits > 32809 Load 'loadable object' with non-default file extension > 32728 64-bit fix for Time::Local > > --- > @INC for perl 5.10.0: > C:\Documents and Settings\jholt\My Documents\Source > C:/progra~1/perl-5.10.0.1004/site/lib > C:/progra~1/perl-5.10.0.1004/lib > . > > --- > Environment for perl 5.10.0: > CYGWIN=C:\Program Files\cygwin > HOME (unset) > LANG (unset) > LANGUAGE (unset) > LD_LIBRARY_PATH (unset) > LOGDIR (unset) > PATH=C:\Program > Files\pdk-7.2\bin;C:\progra~1\perl- > 5.10.0.1004\site\bin;C:\progra~1\perl- >

> Files\TortoiseSVN\bin;C:\Program Files\SSH Communications Security\SSH > Tectia\SSH Tectia AUX;C:\Program Files\SSH Communications Security\SSH > Tectia\SSH Tectia AUX/Support binaries;C:\Program Files\SSH > Communications Security\SSH Tectia\SSH Tectia Broker;C:\Program > Files\SSH Communications Security\SSH Tectia\SSH Tectia > Client;C:\Program Files\OpenVPN\bin;C:\Documents and Settings\jholt\My > Documents\bin;C:\Program Files\ant-1.7.1\bin;C:\Program >

> Files\Method R\P5\bin;C:\Program Files\Method R\P5\bin;C:\Program > Files\cygwin\bin > PERL5LIB=C:\Documents and Settings\jholt\My Documents\Source > PERL_BADLANG (unset) > SHELL (unset)