Easy way (?) to get Benchmark.pm (with Time::HiRes) to show 6 (versus 5) decimal points of accuracy

[hulkster]

---

[Please describe your issue here]
Easy way (?) to get Benchmark.pm (with Time::HiRes) to show 6 (versus 5) decimal points of accuracy

Disclaimer: I don't claim to be a Perl guru so I defer to the wizards if there a better way to do this and/or it's an old issue. But this seems like a simple solution that (using my limited Google kung-fu skills) that I did not see discussed.

So I recently stumbled across a race condition in some legacy code and was curious how long the time window was ... so added some simple calls to Benchmark.

I had an existing framework, but it's literally nothing more than doing a "Benchmark->new" when the program starts and then doing various snapshots. When done, I do some simple timediff's. Since I've specified "use Benchmark qw(:hireswallclock);", I expected to see 6 decimal points of timing accuracy - i.e. to the microsecond.

However, I was only seeing 5 digits of accuracy ... so after lots of WTF and searching for solutions, I finally stumbled across a snippet in the Time::HiRes documentation at https://perldoc.perl.org/Time::HiRes
NOTE 2: Since Sunday, September 9th, 2001 at 01:46:40 AM GMT, when the time() seconds since epoch rolled over to 1_000_000_000, the default floating point format of Perl and the seconds since epoch have conspired to produce an apparent bug: if you print the value of Time::HiRes::time() you seem to be getting only five decimals, not six as promised (microseconds). Not to worry, the microseconds are there (assuming your platform supports such granularity in the first place). What is going on is that the default floating point format of Perl only outputs 15 digits. In this case that means ten digits before the decimal separator and five after. To see the microseconds you can use either printf/sprintf with "%.6f", or the gettimeofday() function in list context, which will give you the seconds and microseconds as two separate values.

After some more head-scratching, I realized that if I modified line 654 in Benchmark.pm (which is used in a subsequent sprintf) as follows, I would then see six digits.
# my $w = $hirestime ? "%2g" : "%2d";
my $w = $hirestime ? "%.6f" : "%2d";

This seems to be consistent with the note in Time::HiRes and fixed my problem. But I'm wondering if this was the "right" way to do it ... and if so, should Benchmark.pm (an oldy but goldy that hasn't seen many updates) be changed? Again, I defer to the Perl wizards, but it seems like this would be a fairly simple fix to address this issue.

[Please do not change anything below this line]

---

Flags:
category=library
severity=low
module=Benchmark

This perlbug was built using Perl 5.32.1 - Thu Apr 6 17:07:50 UTC 2023
It is being executed now by Perl 5.32.1 - Thu Apr 6 13:06:13 EDT 2023.

Site configuration information for perl 5.32.1:

Configured by Red Hat, Inc. at Thu Apr 6 13:06:13 EDT 2023.

Summary of my perl5 (revision 5 version 32 subversion 1) configuration:

Platform:
osname=linux
osvers=4.18.0-425.3.1.el8.x86_64
archname=x86_64-linux-thread-multi
uname='linux 70a103858837433dbfc3ed5de4202b9b 4.18.0-425.3.1.el8.x86_64 #1 smp tue nov 8 14:08:25 est 2022 x86_64 x86_64 x86_64 gnulinux '
config_args='-des -Doptimize=none -Dccflags=-O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -march=x86-64-v2 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -Dldflags=-Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -Dccdlflags=-Wl,--enable-new-dtags -Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -Dlddlflags=-shared -Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1
-Dshrpdir=/usr/lib64 -DDEBUGGING=-g -Dversion=5.32.1 -Dmyhostname=localhost -Dperladmin=root@localhost -Dcc=gcc -Dcf_by=Red Hat, Inc. -Dprefix=/usr -Dvendorprefix=/usr -Dsiteprefix=/usr/local -Dsitelib=/usr/local/share/perl5/5.32 -Dsitearch=/usr/local/lib64/perl5/5.32 -Dprivlib=/usr/share/perl5 -Dvendorlib=/usr/share/perl5/vendor_perl -Darchlib=/usr/lib64/perl5 -Dvendorarch=/usr/lib64/perl5/vendor_perl -Darchname=x86_64-linux-thread-multi -Dlibpth=/usr/local/lib64 /lib64 /usr/lib64 -Duseshrplib -Dusethreads -Duseithreads -Dusedtrace=/usr/bin/dtrace -Duselargefiles -Dd_semctl_semun -Di_db -Ui_ndbm -Di_gdbm -Di_shadow -Di_syslog -Dman3ext=3pm -Duseperlio -Dinstallusrbinperl=n -Ubincompat5005 -Uversiononly -Dpager=/usr/bin/less -isr -Dd_gethostent_r_proto -Ud_endhostent_r_proto -Ud_sethostent_r_proto -Ud_endprotoent_r_proto -Ud_setprotoent_r_proto -Ud_endservent_r_proto
-Ud_setservent_r_proto -Dscriptdir=/usr/bin -Dusesitecustomize -Duse64bitint'
hint=recommended
useposix=true
d_sigaction=define
useithreads=define
usemultiplicity=define
use64bitint=define
use64bitall=define
uselongdouble=undef
usemymalloc=n
default_inc_excludes_dot=define
bincompat5005=undef
Compiler:
cc='gcc'
ccflags ='-D_REENTRANT -D_GNU_SOURCE -O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -march=x86-64-v2 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -fwrapv -fno-strict-aliasing -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64'
optimize=' -g'
cppflags='-D_REENTRANT -D_GNU_SOURCE -O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -march=x86-64-v2 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -fwrapv -fno-strict-aliasing -I/usr/local/include'
ccversion=''
gccversion='11.3.1 20221121 (Red Hat 11.3.1-4)'
gccosandvers=''
intsize=4
longsize=8
ptrsize=8
doublesize=8
byteorder=12345678
doublekind=3
d_longlong=define
longlongsize=8
d_longdbl=define
longdblsize=16
longdblkind=3
ivtype='long'
ivsize=8
nvtype='double'
nvsize=8
Off_t='off_t'
lseeksize=8
alignbytes=8
prototype=define

Linker and Libraries:
ld='gcc'
ldflags ='-Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -fstack-protector-strong -L/usr/local/lib'
libpth=/usr/local/lib64 /lib64 /usr/lib64 /usr/local/lib /usr/lib /lib/../lib64 /usr/lib/../lib64 /lib
libs=-lpthread -lresolv -lgdbm -ldb -ldl -lm -lcrypt -lutil -lc -lgdbm_compat
perllibs=-lpthread -lresolv -ldl -lm -lcrypt -lutil -lc
libc=/lib/../lib64/libc.so.6
so=so
useshrplib=true
libperl=libperl.so
gnulibc_version='2.34'
Dynamic Linking:
dlsrc=dl_dlopen.xs
dlext=so
d_dlsymun=undef
ccdlflags='-Wl,--enable-new-dtags -Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 '
cccdlflags='-fPIC'
lddlflags='-lpthread -shared -Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -L/usr/local/lib -fstack-protector-strong'

Locally applied patches:
Fedora Patch1: Removes date check, Fedora/RHEL specific
Fedora Patch2: support for libdir64
Fedora Patch3: use libresolv instead of libbind
Fedora Patch4: USE_MM_LD_RUN_PATH
Fedora Patch5: Provide MM::maybe_command independently (bug #1129443)
Fedora Patch6: Dont run one io test due to random builder failures
Fedora Patch8: Define SONAME for libperl.so
Fedora Patch9: Install libperl.so to -Dshrpdir value
Fedora Patch10: Make *DBM_File desctructors thread-safe (RT#61912)
Fedora Patch11: Replace EU::MakeMaker dependency with EU::MM::Utils in IPC::Cmd (bug #1129443)
Fedora Patch12: Link XS modules to pthread library to fix linking with -z defs
Fedora Patch13: Pass the correct CFLAGS to dtrace
Fedora Patch14: Do not use C compiler reserved identifiers
Fedora Patch15: Fix SvUV_nomg() macro definition
Fedora Patch16: Fix SvTRUE() documentation
Fedora Patch17: Fix ext/XS-APItest/t/utf8_warn_base.pl tests
Fedora Patch18: Fix IO::Handle::error() to report write errors (GH#6799)
Fedora Patch19: Fix IO::Handle::error() to report write errors (GH#6799)
Fedora Patch21: Fix setting a non-blocking mode in IO::Socket::UNIX (GH#17787)
Fedora Patch22: Fix running actions after stepping in a debugger (GH#17901)
Fedora Patch23: Fix running actions after stepping in a debugger (GH#17901)
Fedora Patch24: Fix running actions after stepping in a debugger (GH#17901)
Fedora Patch25: Fix a buffer size for asctime_r() and ctime_r() functions
Fedora Patch26: Prevent from an integer overflow in RenewDouble() macro
Fedora Patch28: Fix a number of arguments passed to a BOOT XS subroutine (GH#17755)
Fedora Patch29: Fix an IO::Handle spurious error reported for regular file handles (GH#18019)
Fedora Patch30: Fix inheritance resolution of lexial objects in a debugger (GH#17661)
Fedora Patch35: Fix sorting with a block that calls return (GH#18081)
Fedora Patch38: Fix sv_collxfrm macro to respect locale
Fedora Patch39: Fix an iterator signedness in handling an mro exception (GH#18155)
Fedora Patch40: Fix a code flow in Perl_sv_inc_nomg()
Fedora Patch41: Fix an undefined behavior in Perl_custom_op_get_field()
Fedora Patch42: Fix Config variable names in in t/op tests
Fedora Patch43: Fix fetching a magic on the stacked file test operators
Fedora Patch44: Fix a crash in optimizing split() (GH#18232)
Fedora Patch45: Fix a crash in optimizing split() (GH#18232)
Fedora Patch46: Fix a crash in optimizing split() (GH#18232)
Fedora Patch47: Fix a crash in optimizing split() (GH#18232)
Fedora Patch48: Make accessing environment by DynaLoader thread-safe
Fedora Patch49: Use duplocale() if available
Fedora Patch50: Fix fc() in Turkish locale
Fedora Patch51: Fix croaking on "my $_" when "use utf8" is in effect (GH#18449)
Fedora Patch52: Fix PERL_UNUSED_ARG() definition in XSUB.h
Fedora Patch53: Add missing entries to perldiag (GH#18276)
Fedora Patch54: Protect locale tests from LANGUAGE environment variable
Fedora Patch55: Prevent the number of buckets in a hash from getting too large
Fedora Patch56: Fix a memory leak when compiling a regular expression (GH#18604)
Fedora Patch57: Fix dumping a hash entry of PL_strtab type
Fedora Patch57: Fix an arithmetic left shift of a minimal integer value (GH#18639)
Fedora Patch200: Link XS modules to libperl.so with EU::CBuilder on Linux
Fedora Patch201: Link XS modules to libperl.so with EU::MM on Linux
Fedora Patch202: Add definition of OPTIMIZE to .ph files (bug #2159759)

---

@inc for perl 5.32.1:
/usr/local/lib64/perl5/5.32
/usr/local/share/perl5/5.32
/usr/lib64/perl5/vendor_perl
/usr/share/perl5/vendor_perl
/usr/lib64/perl5
/usr/share/perl5

---

Environment for perl 5.32.1:
HOME=/home/USERNAME
LANG=en_US.UTF-8
LANGUAGE (unset)
LD_LIBRARY_PATH (unset)
LOGDIR (unset)
PATH=/home/USERNAME/bin:/sbin:/usr/sbin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
PERL_BADLANG (unset)
SHELL=/bin/csh

[hulkster]

Pinging this again as it seems like the fix is fairly easy ...

[jkeenan]

I created a branch from your suggestion.

$ git diff -w blead..gh-21618-benchmark-20240115 -- lib/Benchmark.pm
diff --git a/lib/Benchmark.pm b/lib/Benchmark.pm
index 51a30b737d..b886f98369 100644
--- a/lib/Benchmark.pm
+++ b/lib/Benchmark.pm
@@ -482,7 +482,7 @@ our(@ISA, @EXPORT, @EXPORT_OK, %EXPORT_TAGS, $VERSION);
              clearcache clearallcache disablecache enablecache);
 %EXPORT_TAGS=( all => [ @EXPORT, @EXPORT_OK ] ) ;
 
-$VERSION = 1.25;
+$VERSION = 1.26;
 
 # --- ':hireswallclock' special handling
 
@@ -651,7 +651,7 @@ sub timestr {
     return '' if $style eq 'none';
     $style = ($ct>0) ? 'all' : 'noc' if $style eq 'auto';
     my $s = "@t $style"; # default for unknown style
-    my $w = $hirestime ? "%2g" : "%2d";
+    my $w = $hirestime ? "%.6f" : "%2d";
     $s = sprintf("$w wallclock secs (%$f usr %$f sys + %$f cusr %$f csys = %$f CPU)",
                            $r,$pu,$ps,$cu,$cs,$tt) if $style eq 'all';
     $s = sprintf("$w wallclock secs (%$f usr + %$f sys = %$f CPU)",

This broke two files in the CPAN Test-Harness distribution (which is shipped with core).

$ cd t; TEST_JOBS=1 ./perl harness ../cpan/Test-Harness/t/file.t ../cpan/Test-Harness/t/harness.t; cd -
../cpan/Test-Harness/t/file.t ..... 1/56 
#   Failed test '... and the report summary should look correct'
#   at t/file.t line 84.
#                   'Files=1, Tests=1, 0.000000 wallclock secs ( 0.01 usr +  0.00 sys =  0.01 CPU)'
#     doesn't match '(?^:^Files=1, Tests=1, +\d+ wallclock secs)'

#   Failed test '... and the report summary should look correct'
#   at t/file.t line 113.
#                   'Files=1, Tests=1, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=1, Tests=1, +\d+ wallclock secs)'

#   Failed test '... and the report summary should look correct'
#   at t/file.t line 148.
#                   'Files=2, Tests=2, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=2, Tests=2, +\d+ wallclock secs)'

#   Failed test '... and the report summary should look correct'
#   at t/file.t line 172.
#                   'Files=1, Tests=1, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=1, Tests=1, +\d+ wallclock secs)'

#   Failed test '... and the report summary should look correct'
#   at t/file.t line 193.
#                   'Files=1, Tests=1, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=1, Tests=1, +\d+ wallclock secs)'

#   Failed test '... and the report summary should look correct'
#   at t/file.t line 312.
#                   'Files=1, Tests=3, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=1, Tests=3, +\d+ wallclock secs)'
# Looks like you failed 6 tests of 56.
../cpan/Test-Harness/t/file.t ..... Dubious, test returned 6 (wstat 1536, 0x600)
Failed 6/56 subtests 
../cpan/Test-Harness/t/harness.t .. 1/133 
#   Failed test '... and the report summary should look correct'
#   at t/harness.t line 143.
#                   'Files=1, Tests=1, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=1, Tests=1, +\d+ wallclock secs)'

#   Failed test '... and the report summary should look correct'
#   at t/harness.t line 178.
#                   'Files=1, Tests=1, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=1, Tests=1, +\d+ wallclock secs)'

#   Failed test '... and the report summary should look correct'
#   at t/harness.t line 223.
#                   'Files=2, Tests=2, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=2, Tests=2, +\d+ wallclock secs)'

#   Failed test '... and the report summary should look correct'
#   at t/harness.t line 246.
#                   'Files=1, Tests=1, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=1, Tests=1, +\d+ wallclock secs)'

#   Failed test '... and the report summary should look correct'
#   at t/harness.t line 267.
#                   'Files=1, Tests=1, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=1, Tests=1, +\d+ wallclock secs)'

#   Failed test '... and the report summary should look correct'
#   at t/harness.t line 401.
#                   'Files=1, Tests=3, 0.000000 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU)'
#     doesn't match '(?^:^Files=1, Tests=3, +\d+ wallclock secs)'
../cpan/Test-Harness/t/harness.t .. 86/133 # Looks like you failed 6 tests of 133.
../cpan/Test-Harness/t/harness.t .. Dubious, test returned 6 (wstat 1536, 0x600)
Failed 6/133 subtests 

Test Summary Report
-------------------
../cpan/Test-Harness/t/file.t   (Wstat: 1536 (exited 6) Tests: 56 Failed: 6)
  Failed tests:  8, 13, 18, 22, 26, 39
  Non-zero exit status: 6
../cpan/Test-Harness/t/harness.t (Wstat: 1536 (exited 6) Tests: 133 Failed: 6)
  Failed tests:  49, 54, 59, 62, 65, 74
  Non-zero exit status: 6
Files=2, Tests=189, 1.000000 wallclock secs ( 0.01 usr  0.00 sys +  0.17 cusr  0.03 csys =  0.21 CPU)
Result: FAIL
Finished test run at Mon Jan 15 18:11:54 2024.

I suspect adopting this change would break a lot of code in CPAN and out in the wild. If you want to implement it as a CPAN module, be our guest -- but I don't think it's appropriate for core.

[hulkster]

Thanks for looking into it - bummer all the secondary/collateral damage with the test suites ... since it seems like especially for benchmarking, one would be interested in more precise measurements ... and it's such a simple fix.

Maybe I'm missing something obvious, but shouldn't this match the regular expression?
"0.000000 wallclock secs"
"+\d+ wallclock secs"

[mauke]

The regex doesn't match because +\d+ matches 1 or more spaces followed by 1 or more digits. . is not a digit.

As for seeing more precision, you could try changing %2g to %2.15g, but that might output more decimal places than expected in some places.

[hulkster]

First, I appreciate the Perl wizards chiming in - thanks!
And sorry I brain-farted and missed the decimal point since of course the regex doesn't match - DUH! ;-)

Yea, looks like "%2.15g" provides PLENTY of resolution ... LOL if anyone things there is true clock accuracy to the Atto-Second ... ;-)

However, does it make sense to fix this to at least provide (true) Micro-second resolution ... and maybe even Nano-Second which Time::HiRes supports ... albeit it warns you don't expect it to be accurate - "Do not expect nanosleep() to be exact down to one nanosecond. Getting even accuracy of one thousand nanoseconds is good."

I pulled down Test-Harness and saw the same results that @jkeenan saw using %.6f. However, it looks like the "g" format passes.

Again, this known bug has existed for a couple of decades, so I was just thinking there might be an easy fix to roll into the distribution ... but I totally "get it" that you don't want to break things.

I'll mention again this snippet in the https://perldoc.perl.org/Time::HiRes documentation:
NOTE 2: Since Sunday, September 9th, 2001 at 01:46:40 AM GMT, when the time() seconds since epoch rolled over to 1_000_000_000, the default floating point format of Perl and the seconds since epoch have conspired to produce an apparent bug: if you print the value of Time::HiRes::time() you seem to be getting only five decimals, not six as promised (microseconds). Not to worry, the microseconds are there (assuming your platform supports such granularity in the first place). What is going on is that the default floating point format of Perl only outputs 15 digits. In this case that means ten digits before the decimal separator and five after. To see the microseconds you can use either printf/sprintf with "%.6f", or the gettimeofday() function in list context, which will give you the seconds and microseconds as two separate values.