Re: CPU usage truncated output

[Petr Pisar]

On Fri, Oct 30, 2020 at 10:14:31PM +0000, Philip Rowlands wrote:
> Is there any way to ask time for greater than 2 decimal points of precision?
> 
> I see in time.c that the formats for %U / %S / %E are fixed, e.g.
> 
> fprintf (fp, "%ld.%02ld",
>          (long int)(resp->ru.ru_utime.tv_sec),
>          (long int)(resp->ru.ru_utime.TV_MSEC / 10));
> 
> It's a toy example, but consider the output of the following command, where
> /bin/true takes 0.015625 seconds of user time, but time truncates the output
> to "0.01user".
> 
That's true even for the POSIX output (-p):

# LC_ALL=C /usr/bin/time -p /usr/bin/true
real 0.00
user 0.00
sys 0.00

which is documented in time(1) as:

    where the number of decimals in the output [...] is unspecified but is
    sufficient to express the clock tick accuracy, and at least one.

So I think the output contradicts to the documentation.

POSIX manual reads:

    The precision of the timing shall be no less than the granularity defined
    for the size of the clock tick unit on the system, but the results shall
    be reported in terms of standard time units (for example, 0.02 seconds,
    00:00:00.02, 1m33.75s, 365.21 seconds), not numbers of clock ticks.

And specifically for -p option:

    The precision used may be less than the default six digits of [printf(3)]
    %f, but shall be sufficiently precise to accommodate the size of the clock
    tick on the system (for example, if there were 60 clock ticks per second,
    at least two digits shall follow the radix character). The number of
    digits following the radix character shall be no less than one, even if
    this always results in a trailing zero.

The clock tick probably refers to time units used by times(2) (clock_t type).
I guess contemporary systems have much shorter tick than 100 Hz.

> $ strace -v -e wait4 time /bin/true
> wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0,
>   {ru_utime={tv_sec=0, tv_usec=15625},
>    ru_stime={tv_sec=0, tv_usec=0},
>    ru_maxrss=472,
>    ru_ixrss=0,
>    ru_idrss=0,
>    ru_isrss=0,
>    ru_minflt=146,
>    ru_majflt=0,
>    ru_nswap=0,
>    ru_inblock=0,
>    ru_oublock=0,
>    ru_msgsnd=0,
>    ru_msgrcv=0,
>    ru_nsignals=0,
>    ru_nvcsw=0,
>    ru_nivcsw=0}) = 168
> --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=168, si_uid=1000, 
> si_status=0, si_utime=0, si_stime=0} ---
> 0.01user 0.00system 0:00.01elapsed 125%CPU (0avgtext+0avgdata 472maxresident)k
> 0inputs+0outputs (0major+146minor)pagefaults 0swaps
> +++ exited with 0 +++
> 
But modern systems report the usage in struct rusage with much higher
accuracy. I think this deficiency of the time tool should be improved.

> I'm not suggesting changing the default, but perhaps extending the format
> syntax to allow for extra precision.

I wouldn't fear of the backward compatibility so much. First the fixed
precision is a bug, then the documentation allows more digits and last the
current truncated output is pretty useless.

-- Petr

signature.asc
Description: PGP signature