ksh-community / ksh

ksh93 maintenance and development
Eclipse Public License 1.0
26 stars 11 forks source link

"time" builtin does not correctly report a third decimal digit #7

Open jghub opened 4 years ago

jghub commented 4 years ago

by default time reports two decimal digits. this is controlled by the variable TIMEFORMAT. changing the latter to, e,g, TIMEFORMAT=$'\nreal\t%3R\tuser\t%3U\tsys\t%3S' enforces reporting of 3 decimal digits (more are not supported anyway according to manpage). however, the third digit is always reported as zero. example

 TIMEFORMAT=$'\nreal\t%3R\tuser\t%3U\tsys\t%3S'
time sleep 1.235 # → real   1.260   user    0.010   sys 0.000

(the observed output is of course somewhat variable but the third digit is reported consistently as 0). this is also broken in 93v- but works correctly in ksh2020.

such high precision timing (1 ms accuracy) usually is not of much relevance but it can be different during benchmarking when computing averages and standard deviations of multiple repeated runs.

hyenias commented 4 years ago

I have researched this issue and I do not believe the time keyword is broken; it is just that the underlying c function times has limited precision (0.01). In ksh2020, a new times special builtin was created along with updating the time keyword code to utilize the newer and more accurate c function getrusage which generally has a precision of µsec (0.000001).

In fact, getrusage appears in several AT&T Software Technology libraries. Additionally, the SECONDSdynamic variable utilizes higher precision date/time function(s) already. As such, enhancing the time keyword and perhaps altering the times alias to a special builtin as to allow for 3 or more precision places should be doable. I consider this issue to be an enhancement.

I will continue to research this enhancement to help improve my familiarity of the code base. If a more experienced C programmer wants to complete this enhancement before I do, have at it. However, the ksh-community needs to decide on the details of such an enhancement: default precision level, changing the times alias into a some sort of builtin, and etc.

jghub commented 4 years ago

thanks for looking into this. I suspected that the accuracy limitation is due to the called c function. this is not really bad in my view, but that changing the TIMEFORMAT to 3 digits w/o getting them, really, seems broken to me :). you are right that a better solution here will be to switch to getrusage probably.

but what about the times alias and why would it be good to replace it by a buitlin?

hyenias commented 4 years ago

I am not sure as to why ksh2020 decided to change times alias to a builtin. My guess is that they mimicked bash. The ksh2020 time and times statements produce the same output as bash ones. Overall, ksh93 time keyword provides real, user, and system status for the entire process and its children meant for timing pipelines. ksh93 times alias does not do anything more but just calls time without any commands while sending stderr into stdout.

The getrusage c function is capable of returning per process and overall process stats. A discussion should occur on how to approach this possible additional detail in use and output via time and times. Overall, it seems to me that additional functionality should be exposed via time possibly through additional command line options and/or TIMEFORMAT syntax. And, I can see the benefit of changing times to provide similar output as other shells.

saper commented 4 years ago

Works for me with ksh93v:

> TIMEFORMAT=$'\nreal\t%3R\tuser\t%3U\tsys\t%3S'
> time sleep 1
real    1,008   user    0,000   sys 0,000
> time ls
(...)
real    0,008   user    0,008   sys 0,000

Also spotted

> time ls -R p > /dev/null

 real   1,000   user    0,000   sys 0,008

Version ABIJM 93v- 2014-12-24 on FreeBSD 11.3-STABLE

jghub commented 4 years ago

interesting. wild guess: maybe the freebsd times C-function is different? I tested again and for me the native Version ABIJM 93v- 2014-12-24 definitely does not do it right on OSX:

sleep 1.234

never shows a non-zero third digit in so many runs just like initially reported.

saper commented 4 years ago

The New KornShell book does not define precision of time nor the use of the TIMEFORMAT variable (added in 03-03-18 release which is ksh93u).

Here is the definition of times(3) I have

     The times() function returns the value of time in CLK_TCK's of a second
     since the system startup time.  The current value of CLK_TCK, the
     frequency of the statistics clock in ticks per second, may be obtained
     through the sysconf(3) interface.`

On my system I get:

 $ getconf CLK_TCK
 128

On a random Linux system (Centos 6 with the 2.6.32-754.25.1.el6.x86_64 kernel and glibc-2.12-1.212.el6_10.3.x86_64) I get

  $ getconf CLK_TCK
  100

KornShell works as designed I'd say.

jghub commented 4 years ago

tend to agree. so the third digit you see on your system is not "real" either but approx equal to 1/128...

so "works as designed" is correct I'd say. but the third digit just is not usable in the present implementation that uses times(3). I believe this is not desirable. whether it needs "fixing"? maybe. as @hyenias said, $SECONDS obviously uses something else with higher resolution which might possibly be utilized for time as well?

hyenias commented 4 years ago

Can someone mark this issue with an enhancement label? Thanks.