Re: timevar: further work

[Bruno Haible]

Hi Akim,

> The choice between proper time and self+children
> seems a reasonable option to offer, but if we are to keep just one,
> I’d stick with the one we have currently: including subprocesses.

OK.

> > So, very obviously, the resolution of times() is [10] milliseconds (!).
> […]
> > So, the resolution of getrusage() is 4 ms. Slightly better than times(),
> 
> I’m surprised by this.  I would have bet both shared the same
> basic implementation.

A "jiffie" duration is 4 ms nowadays [1] but it was 10 ms many years ago [2].
Since the times() call produces its output in units of 1/HZ seconds and HZ
is a constant (defined to 100 in <sys/param.h>), the Linux or glibc
implementors could not change it.

[1] 
https://unix.stackexchange.com/questions/51978/when-do-jiffies-increment-how-a-process-runs-in-a-jiffy
[2] https://elinux.org/Kernel_Timer_Systems

> > In summary, I think the user needs to have the choice:
> >  - For low-precision timings, offer getrusage with RUSAGE_CHILDREN or
> >    optionally RUSAGE_SELF as an alternative.
> >  - For high-precision timings, offer CLOCK_MONOTONIC and don't call
> >    neither getrusage nor times (because the point of high-precision
> >    timings is to have minimal system call overhead).
> > 
> > And this choice needs to be made at runtime. It would be silly to have
> > to recompile a program just to measure longer vs. shorter tasks.
> 
> You lost me here.  CLOCK_MONOTONIC is about wall time, the ‘real’ time
> ...
> I think that at this stage we want usr/sys via getrusage and wall via
> CLOCK_MONOTONIC.  

Ah, I was thinking we would need to distinguish two cases: low-precision
timings, for programs that run > 1 sec, and high-precision timings, for
programs that run < 1 sec. Yeah, probably we don't to distinguish them.

Just make sure that the user understands that the wall clock timings
have microsecond resolution wheras the user+system time values have
a lower resolutions. Since they are in the same line of output, it's
not obvious to understand.

What would be the best way to clarify this? By using an appropriate
number of decimal digits?

Execution times (seconds)
read                  :   0.091 (19%) usr   0.080 (80%) sys   0.090242 (18%) 
wall
read: scan            :   0.043 ( 9%) usr   0.080 (80%) sys   0.123492 (26%) 
wall
read: parse           :   0.056 (10%) usr   0.000 ( 0%) sys   0.052384 (10%) 
wall
work                  :   0.333 (70%) usr   0.000 ( 0%) sys   0.353432 (71%) 
wall
work: phase 1         :   0.301 (64%) usr   0.000 ( 0%) sys   0.307234 (64%) 
wall
work: phase 2         :   0.139 (28%) usr   0.000 ( 0%) sys   0.144232 (29%) 
wall
output                :   0.043 ( 9%) usr   0.020 (20%) sys   0.040233 ( 8%) 
wall
total time            :   0.474             0.100             0.492343

Or by using column headers?

Execution times (seconds)
                          CPU user      CPU system    wall clock
                          (4 ms res.)   (4 ms res.)   (1 µs res.)
read                  :   0.091 (19%)   0.080 (80%)   0.090242 (18%)
read: scan            :   0.043 ( 9%)   0.080 (80%)   0.123492 (26%)
read: parse           :   0.056 (10%)   0.000 ( 0%)   0.052384 (10%)
work                  :   0.333 (70%)   0.000 ( 0%)   0.353432 (71%)
work: phase 1         :   0.301 (64%)   0.000 ( 0%)   0.307234 (64%)
work: phase 2         :   0.139 (28%)   0.000 ( 0%)   0.144232 (29%)
output                :   0.043 ( 9%)   0.020 (20%)   0.040233 ( 8%)
total time            :   0.474         0.100         0.492343

Bruno