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

Benchmark module doesn't use documented format for times #15388

Closed
p5pRT opened this issue Jun 8, 2016 · 6 comments
Labels

Comments

@p5pRT
Copy link
Collaborator

@p5pRT p5pRT commented Jun 8, 2016

Migrated from rt.perl.org#128349 (status was 'rejected')

Searchable as RT128349$

@p5pRT

This comment has been minimized.

Copy link
Collaborator Author

@p5pRT p5pRT commented Jun 8, 2016

From perl-diddler@tlinx.org

I looked at the Benchmark modules and it seems the bugs for it are in the perl5 category -- I guess that means it's part of 'Core'?

Anyway, that's why I'm reporting this here.

This is using the Inst_Version 1.13 distributed with 5.16.3 -- I.E. this may already be fixed, not easily testable at this point.

But using a call to Benchmark​::timestr​:

my $time_str = Benchmark​::timestr($diff, 'all', '20.9F');
print "time_str=$time_str\n";

I got​:
time_str=4.36661 wallclock secs ( 0.010000000 usr 0.000000000 sys + 0.390000000 cusr 1.460000000 csys = 1.860000000 CPU)

note, at the top, I have​:
use Benchmark qw(​:all :hireswallclock);

So, it should be giving microsecond accuracy. Drilling down
to /usr/include/bits/time.h, I see​:

/* A time value that is accurate to the nearest
  microsecond but also has a range of years. */
struct timeval
  {
  __time_t tv_sec; /* Seconds. */
  __suseconds_t tv_usec; /* Microseconds. */
  };

So the cpu seconds only appear to be accurage to 100's of a second, but clock_info on my system shows​:

clock_info
  Name​: Current value Resolution
  CLOCK_REALTIME​: 1465424223.084752159 1 ns
  CLOCK_MONOTONIC​: 8954268.857661674 1 ns
  CLOCK_MONOTONIC_RAW​: 8953806.267750053 1 ns
CLOCK_PROCESS_CPUTIME_ID​: 0.001527207 1 ns
CLOCK_THREAD_CPUTIME_ID​: 0.001535497 1 ns
  CLOCK_MONOTONIC_RAW​: 8953806.267778595 1 ns
  CLOCK_REALTIME_COARSE​: 1465424223.083592029 1 ms
  CLOCK_MONOTONIC_COARSE​: 8954268.856492955 1 ms
  CLOCK_BOOTTIME​: 8954268.857743661 1 ns
  CLOCK_REALTIME_ALARM​: 1465424223.084872396 1 ns
  CLOCK_BOOTTIME_ALARM​: 8954268.857790177 1 ns
CLOCK_SGI_CYCLE​: Invalid argument
  CLOCK_TAI​: 1465424223.084927434 1 ns


(My cpu clock is set to 1000Hz​:

zgrep CONFIG_HZ /proc/config.gz
# CONFIG_HZ_PERIODIC is not set
# CONFIG_HZ_100 is not set
# CONFIG_HZ_250 is not set
# CONFIG_HZ_300 is not set
CONFIG_HZ_1000=y
CONFIG_HZ=1000 )

so that would make it logical that cpu times might only be accurate to 1ms, but it doesn't appear to have used the 20.9F format for the realtime either.

I was a bit surprised by the output -- I expected a space-separated string of 5 numbers (for real, parent process and children processes). I must have not been clear on the documentation about the extra verbiage being included.

Side question​: Is there anyway just to get back the array of 5 numbers so no conversions are necessary -- especially since the conversion thing doesn't seem to work right? (thought 20.9F would give me double precision (64-bits?)... thought I'd at least get back more than centisecs...

Note clock_info does *seem* to return time in nanoseconds...but haven't investigated those sources (not that I need such accuracy, but was trying, simply, to store the full accuracy of what Benchmark had stored internally -- thus my sideQ about a way to get values w/o conversions or breaking into the Benchmark object).

At the very least, if that accuracy is the best that is possible, that might be mentioned in the manpage, though it's pretty clearly not using the precision for the real-time clock.

@p5pRT

This comment has been minimized.

Copy link
Collaborator Author

@p5pRT p5pRT commented Jun 8, 2016

From zefram@fysh.org

Linda Walsh wrote​:

I looked at the Benchmark modules and it seems the bugs for it are in
the perl5 category -- I guess that means it's part of 'Core'?

The module is distributed only with the Perl core; this is indeed the
correct place to report issues with it.

time_str=4.36661 wallclock secs ( 0.010000000 usr 0.000000000 sys + 0.390000000 cusr 1.460000000 csys = 1.860000000 CPU)

note, at the top, I have​:
use Benchmark qw(​:all :hireswallclock);

So, it should be giving microsecond accuracy.

As the name suggests, and as the documentation explicitly says,
:hireswallclock enables high-resolution timing *of the wallclock time*.
That's how you got a fractional "4.36661 wallclock secs". The CPU timers
are unaffected by this option.

As you note, higher-resolution CPU timers are available on some hosts
via the POSIX clock interface. It would be nice for Benchmark.pm to
use those where available, but it is not a bug that it does not.

The documentation is not clear that the format string passed to
timestr() is only used for the CPU time fields. This is a flaw in the
documentation.

-zefram

@p5pRT

This comment has been minimized.

Copy link
Collaborator Author

@p5pRT p5pRT commented Jun 8, 2016

The RT System itself - Status changed from 'new' to 'open'

@p5pRT

This comment has been minimized.

Copy link
Collaborator Author

@p5pRT p5pRT commented Jun 9, 2016

From perl-diddler@tlinx.org

On Wed Jun 08 16​:16​:16 2016, zefram@​fysh.org wrote​:

:hireswallclock enables high-resolution timing *of the wallclock
time*.
That's how you got a fractional "4.36661 wallclock secs".


It's doubly unclear that the "FORMAT" only applies to the cpu times -- for which anything greater than 5.2f appears useless. I.e. the 1 place where > %5.2f could be seen, (wall clock) is is apparent that the FORMAT is ignored, vs. being used on the cpu-times where the :hireswallclock makes no difference. (i.e. - Irony?).
-l

@p5pRT

This comment has been minimized.

Copy link
Collaborator Author

@p5pRT p5pRT commented Dec 15, 2017

From zefram@fysh.org

As already discussed, there is no bug here. This ticket should be closed.

-zefram

@p5pRT

This comment has been minimized.

Copy link
Collaborator Author

@p5pRT p5pRT commented Dec 15, 2017

@iabyn - Status changed from 'open' to 'rejected'

@p5pRT p5pRT closed this Dec 15, 2017
@p5pRT p5pRT added the Severity Low label Oct 19, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
1 participant
You can’t perform that action at this time.