Re: csh(1), ksh(1), time(1): print durations with millisecond precision
Todd C. Miller wrote: > Other implementations of "time -p" (both builtin and standalone) > only display two digits after the radix point. I'm a little concerned > about breaking scripts that consume out the output of "time -p". I share that concern.
Re: csh(1), ksh(1), time(1): print durations with millisecond precision
Other implementations of "time -p" (both builtin and standalone) only display two digits after the radix point. I'm a little concerned about breaking scripts that consume out the output of "time -p". Changing the precission of the non-portable output format is fine. - todd
Re: csh(1), ksh(1), time(1): print durations with millisecond precision
On Tue, Jun 13, 2023 at 10:59:53PM -0500, Scott Cheloha wrote:
> This patch bumps the precision of durations printed by csh(1), ksh(1),
> and time(1) from centiseconds to milliseconds. The csh(1) and ksh(1)
> builtins "time" and "times" are affected.
>
> My thinking is:
>
> - All practical OpenBSD platforms have a timecounter with at least
> millisecond precision.
>
> - It's not uncommon for people to run a custom HZ=1000 kernel.
> At HZ=1000, the profiled user and system durations offered by
> getrusage(2) are (arguably) millisecond precision.
>
> Yes, I know those numbers are profiled and thus not especially
> trustworthy, but it's no different from the situation on a
> HZ=100 kernel.
>
> - The timing commands offered in other shells like bash and dash
> provide (at least) millisecond precision.
>
> - Centiseconds are a bit odd. They don't align with the tidy
> "thousands" separation typical of metric units.
>
> - The POSIX standard for time(1) and the "times" builtin specifies
> that the durations are formatted as a floating point value of
> seconds, i.e. "%f". This means millisecond precision is okay:
>
> https://pubs.opengroup.org/onlinepubs/9699919799/utilities/time.html
> https://pubs.opengroup.org/onlinepubs/9699919799/utilities/V3_chap02.html#times
One week bump.
Index: bin/csh/time.c
===
RCS file: /cvs/src/bin/csh/time.c,v
retrieving revision 1.18
diff -u -p -r1.18 time.c
--- bin/csh/time.c 8 Mar 2023 04:43:04 - 1.18
+++ bin/csh/time.c 14 Jun 2023 15:30:01 -
@@ -40,6 +40,7 @@
* C Shell - routines handling process timing and niceing
*/
static voidpdeltat(struct timeval *, struct timeval *);
+static voidpdelta_hms(const struct timespec *, const struct timespec *);
void
settimes(void)
@@ -145,7 +146,7 @@ prusage(struct rusage *r0, struct rusage
break;
case 'E': /* elapsed (wall-clock) time */
- pcsecs((long) ms);
+ pdelta_hms(e, b);
break;
case 'P': /* percent time spent running */
@@ -227,8 +228,7 @@ pdeltat(struct timeval *t1, struct timev
struct timeval td;
timersub(t1, t0, &td);
-(void) fprintf(cshout, "%lld.%01ld", (long long)td.tv_sec,
- td.tv_usec / 10);
+fprintf(cshout, "%lld.%03ld", (long long)td.tv_sec, td.tv_usec / 1000);
}
#define P2DIG(i) (void) fprintf(cshout, "%d%d", (i) / 10, (i) % 10)
@@ -254,23 +254,18 @@ minsec:
}
void
-pcsecs(long l) /* PWP: print mm:ss.dd, l is in sec*100 */
+pdelta_hms(const struct timespec *t1, const struct timespec *t0)
{
-int i;
+struct timespec elapsed;
+long long hours, minutes, seconds;
-i = l / 36;
-if (i) {
- (void) fprintf(cshout, "%d:", i);
- i = (l % 36) / 100;
- P2DIG(i / 60);
- goto minsec;
-}
-i = l / 100;
-(void) fprintf(cshout, "%d", i / 60);
-minsec:
-i %= 60;
-(void) fputc(':', cshout);
-P2DIG(i);
-(void) fputc('.', cshout);
-P2DIG((int) (l % 100));
+timespecsub(t1, t0, &elapsed);
+hours = elapsed.tv_sec / 3600;
+minutes = (elapsed.tv_sec % 3600) / 60;
+seconds = elapsed.tv_sec % 60;
+if (hours != 0)
+ fprintf(cshout, "%lld:%02lld:", hours, minutes);
+else
+ fprintf(cshout, "%lld:", minutes);
+fprintf(cshout, "%02lld.%03ld", seconds, elapsed.tv_nsec / 100);
}
Index: bin/ksh/c_sh.c
===
RCS file: /cvs/src/bin/ksh/c_sh.c,v
retrieving revision 1.64
diff -u -p -r1.64 c_sh.c
--- bin/ksh/c_sh.c 22 May 2020 07:50:07 - 1.64
+++ bin/ksh/c_sh.c 14 Jun 2023 15:30:01 -
@@ -681,13 +681,13 @@ p_tv(struct shf *shf, int posix, struct
char *suffix)
{
if (posix)
- shf_fprintf(shf, "%s%*lld.%02ld%s", prefix ? prefix : "",
- width, (long long)tv->tv_sec, tv->tv_usec / 1, suffix);
+ shf_fprintf(shf, "%s%*lld.%03ld%s", prefix ? prefix : "",
+ width, (long long)tv->tv_sec, tv->tv_usec / 1000, suffix);
else
- shf_fprintf(shf, "%s%*lldm%02lld.%02lds%s", prefix ? prefix :
"",
+ shf_fprintf(shf, "%s%*lldm%02lld.%03lds%s", prefix ? prefix :
"",
width, (long long)tv->tv_sec / 60,
(long long)tv->tv_sec % 60,
- tv->tv_usec / 1, suffix);
+ tv->tv_usec / 1000, suffix);
}
static void
@@ -695,14 +695,14 @@ p_ts(struct shf *shf, int posix, struct
char *suffix)
{
if (posix)
- shf_fprintf(shf, "%s%*lld.%02ld%s", prefix ? prefix : "",
- width, (long long)ts->tv_sec, ts->tv_nsec / 1000,
+ shf_fprintf(shf, "%s%*lld.%03ld%s", prefix ? prefix : "",
+ width, (long long)ts->tv_sec, ts->tv_nsec /
Re: csh(1), ksh(1), time(1): print durations with millisecond precision
On Wed, Jun 14, 2023 at 10:34:20AM -0400, Josiah Frentsos wrote:
> On Tue, Jun 13, 2023 at 10:59:53PM -0500, Scott Cheloha wrote:
> > Index: usr.bin/time/time.c
> > ===
> > RCS file: /cvs/src/usr.bin/time/time.c,v
> > retrieving revision 1.25
> > diff -u -p -r1.25 time.c
> > --- usr.bin/time/time.c 21 Aug 2017 13:38:02 - 1.25
> > +++ usr.bin/time/time.c 14 Jun 2023 03:23:29 -
> > @@ -100,19 +100,19 @@ main(int argc, char *argv[])
> > timespecsub(&after, &before, &during);
> >
> > if (portableflag) {
> > - fprintf(stderr, "real %9lld.%02ld\n",
> > - (long long)during.tv_sec, during.tv_nsec/1000);
> > - fprintf(stderr, "user %9lld.%02ld\n",
> > - (long long)ru.ru_utime.tv_sec,
> > ru.ru_utime.tv_usec/1);
> > - fprintf(stderr, "sys %9lld.%02ld\n",
> > - (long long)ru.ru_stime.tv_sec,
> > ru.ru_stime.tv_usec/1);
> > + fprintf(stderr, "real %9lld.%03ld\n",
> > + (long long)during.tv_sec, during.tv_nsec / 100);
> > + fprintf(stderr, "user %9lld.%03ld\n",
> > + (long long)ru.ru_utime.tv_sec, ru.ru_utime.tv_usec / 1000);
> > + fprintf(stderr, "sys %9lld.%03ld\n",
> > + (long long)ru.ru_stime.tv_sec, ru.ru_stime.tv_usec / 1000);
> > } else {
> > - fprintf(stderr, "%9lld.%02ld real ",
> > - (long long)during.tv_sec, during.tv_nsec/1000);
> > - fprintf(stderr, "%9lld.%02ld user ",
> > - (long long)ru.ru_utime.tv_sec,
> > ru.ru_utime.tv_usec/1);
> > - fprintf(stderr, "%9lld.%02ld sys\n",
> > - (long long)ru.ru_stime.tv_sec,
> > ru.ru_stime.tv_usec/1);
> > + fprintf(stderr, "%9lld.%03ld real ",
> > + (long long)during.tv_sec, during.tv_nsec / 100);
> > + fprintf(stderr, "%9lld.%0ld user ",
>
>
> Should this be "%03ld"?
Whoops, yep, good catch.
Index: bin/csh/time.c
===
RCS file: /cvs/src/bin/csh/time.c,v
retrieving revision 1.18
diff -u -p -r1.18 time.c
--- bin/csh/time.c 8 Mar 2023 04:43:04 - 1.18
+++ bin/csh/time.c 14 Jun 2023 15:30:01 -
@@ -40,6 +40,7 @@
* C Shell - routines handling process timing and niceing
*/
static voidpdeltat(struct timeval *, struct timeval *);
+static voidpdelta_hms(const struct timespec *, const struct timespec *);
void
settimes(void)
@@ -145,7 +146,7 @@ prusage(struct rusage *r0, struct rusage
break;
case 'E': /* elapsed (wall-clock) time */
- pcsecs((long) ms);
+ pdelta_hms(e, b);
break;
case 'P': /* percent time spent running */
@@ -227,8 +228,7 @@ pdeltat(struct timeval *t1, struct timev
struct timeval td;
timersub(t1, t0, &td);
-(void) fprintf(cshout, "%lld.%01ld", (long long)td.tv_sec,
- td.tv_usec / 10);
+fprintf(cshout, "%lld.%03ld", (long long)td.tv_sec, td.tv_usec / 1000);
}
#define P2DIG(i) (void) fprintf(cshout, "%d%d", (i) / 10, (i) % 10)
@@ -254,23 +254,18 @@ minsec:
}
void
-pcsecs(long l) /* PWP: print mm:ss.dd, l is in sec*100 */
+pdelta_hms(const struct timespec *t1, const struct timespec *t0)
{
-int i;
+struct timespec elapsed;
+long long hours, minutes, seconds;
-i = l / 36;
-if (i) {
- (void) fprintf(cshout, "%d:", i);
- i = (l % 36) / 100;
- P2DIG(i / 60);
- goto minsec;
-}
-i = l / 100;
-(void) fprintf(cshout, "%d", i / 60);
-minsec:
-i %= 60;
-(void) fputc(':', cshout);
-P2DIG(i);
-(void) fputc('.', cshout);
-P2DIG((int) (l % 100));
+timespecsub(t1, t0, &elapsed);
+hours = elapsed.tv_sec / 3600;
+minutes = (elapsed.tv_sec % 3600) / 60;
+seconds = elapsed.tv_sec % 60;
+if (hours != 0)
+ fprintf(cshout, "%lld:%02lld:", hours, minutes);
+else
+ fprintf(cshout, "%lld:", minutes);
+fprintf(cshout, "%02lld.%03ld", seconds, elapsed.tv_nsec / 100);
}
Index: bin/ksh/c_sh.c
===
RCS file: /cvs/src/bin/ksh/c_sh.c,v
retrieving revision 1.64
diff -u -p -r1.64 c_sh.c
--- bin/ksh/c_sh.c 22 May 2020 07:50:07 - 1.64
+++ bin/ksh/c_sh.c 14 Jun 2023 15:30:01 -
@@ -681,13 +681,13 @@ p_tv(struct shf *shf, int posix, struct
char *suffix)
{
if (posix)
- shf_fprintf(shf, "%s%*lld.%02ld%s", prefix ? prefix : "",
- width, (long long)tv->tv_sec, tv->tv_usec / 1, suffix);
+ shf_fprintf(shf, "%s%*lld.%03ld%s", prefix ? prefix : "",
+ width, (long long)tv->tv_sec, tv->tv_usec / 1000, suffix)
Re: csh(1), ksh(1), time(1): print durations with millisecond precision
On Tue, Jun 13, 2023 at 10:59:53PM -0500, Scott Cheloha wrote:
> Index: usr.bin/time/time.c
> ===
> RCS file: /cvs/src/usr.bin/time/time.c,v
> retrieving revision 1.25
> diff -u -p -r1.25 time.c
> --- usr.bin/time/time.c 21 Aug 2017 13:38:02 - 1.25
> +++ usr.bin/time/time.c 14 Jun 2023 03:23:29 -
> @@ -100,19 +100,19 @@ main(int argc, char *argv[])
> timespecsub(&after, &before, &during);
>
> if (portableflag) {
> - fprintf(stderr, "real %9lld.%02ld\n",
> - (long long)during.tv_sec, during.tv_nsec/1000);
> - fprintf(stderr, "user %9lld.%02ld\n",
> - (long long)ru.ru_utime.tv_sec,
> ru.ru_utime.tv_usec/1);
> - fprintf(stderr, "sys %9lld.%02ld\n",
> - (long long)ru.ru_stime.tv_sec,
> ru.ru_stime.tv_usec/1);
> + fprintf(stderr, "real %9lld.%03ld\n",
> + (long long)during.tv_sec, during.tv_nsec / 100);
> + fprintf(stderr, "user %9lld.%03ld\n",
> + (long long)ru.ru_utime.tv_sec, ru.ru_utime.tv_usec / 1000);
> + fprintf(stderr, "sys %9lld.%03ld\n",
> + (long long)ru.ru_stime.tv_sec, ru.ru_stime.tv_usec / 1000);
> } else {
> - fprintf(stderr, "%9lld.%02ld real ",
> - (long long)during.tv_sec, during.tv_nsec/1000);
> - fprintf(stderr, "%9lld.%02ld user ",
> - (long long)ru.ru_utime.tv_sec,
> ru.ru_utime.tv_usec/1);
> - fprintf(stderr, "%9lld.%02ld sys\n",
> - (long long)ru.ru_stime.tv_sec,
> ru.ru_stime.tv_usec/1);
> + fprintf(stderr, "%9lld.%03ld real ",
> + (long long)during.tv_sec, during.tv_nsec / 100);
> + fprintf(stderr, "%9lld.%0ld user ",
Should this be "%03ld"?
> + (long long)ru.ru_utime.tv_sec, ru.ru_utime.tv_usec / 1000);
> + fprintf(stderr, "%9lld.%03ld sys\n",
> + (long long)ru.ru_stime.tv_sec, ru.ru_stime.tv_usec / 1000);
> }
>
> if (lflag) {
csh(1), ksh(1), time(1): print durations with millisecond precision
This patch bumps the precision of durations printed by csh(1), ksh(1),
and time(1) from centiseconds to milliseconds. The csh(1) and ksh(1)
builtins "time" and "times" are affected.
My thinking is:
- All practical OpenBSD platforms have a timecounter with at least
millisecond precision.
- It's not uncommon for people to run a custom HZ=1000 kernel.
At HZ=1000, the profiled user and system durations offered by
getrusage(2) are (arguably) millisecond precision.
Yes, I know those numbers are profiled and thus not especially
trustworthy, but it's no different from the situation on a
HZ=100 kernel.
- The timing commands offered in other shells like bash and dash
provide (at least) millisecond precision.
- Centiseconds are a bit odd. They don't align with the tidy
"thousands" separation typical of metric units.
- The POSIX standard for time(1) and the "times" builtin specifies
that the durations are formatted as a floating point value of
seconds, i.e. "%f". This means millisecond precision is okay:
https://pubs.opengroup.org/onlinepubs/9699919799/utilities/time.html
https://pubs.opengroup.org/onlinepubs/9699919799/utilities/V3_chap02.html#times
Index: bin/csh/time.c
===
RCS file: /cvs/src/bin/csh/time.c,v
retrieving revision 1.18
diff -u -p -r1.18 time.c
--- bin/csh/time.c 8 Mar 2023 04:43:04 - 1.18
+++ bin/csh/time.c 14 Jun 2023 03:23:29 -
@@ -40,6 +40,7 @@
* C Shell - routines handling process timing and niceing
*/
static voidpdeltat(struct timeval *, struct timeval *);
+static voidpdelta_hms(const struct timespec *, const struct timespec *);
void
settimes(void)
@@ -145,7 +146,7 @@ prusage(struct rusage *r0, struct rusage
break;
case 'E': /* elapsed (wall-clock) time */
- pcsecs((long) ms);
+ pdelta_hms(e, b);
break;
case 'P': /* percent time spent running */
@@ -227,8 +228,7 @@ pdeltat(struct timeval *t1, struct timev
struct timeval td;
timersub(t1, t0, &td);
-(void) fprintf(cshout, "%lld.%01ld", (long long)td.tv_sec,
- td.tv_usec / 10);
+fprintf(cshout, "%lld.%03ld", (long long)td.tv_sec, td.tv_usec / 1000);
}
#define P2DIG(i) (void) fprintf(cshout, "%d%d", (i) / 10, (i) % 10)
@@ -254,23 +254,18 @@ minsec:
}
void
-pcsecs(long l) /* PWP: print mm:ss.dd, l is in sec*100 */
+pdelta_hms(const struct timespec *t1, const struct timespec *t0)
{
-int i;
+struct timespec elapsed;
+long long hours, minutes, seconds;
-i = l / 36;
-if (i) {
- (void) fprintf(cshout, "%d:", i);
- i = (l % 36) / 100;
- P2DIG(i / 60);
- goto minsec;
-}
-i = l / 100;
-(void) fprintf(cshout, "%d", i / 60);
-minsec:
-i %= 60;
-(void) fputc(':', cshout);
-P2DIG(i);
-(void) fputc('.', cshout);
-P2DIG((int) (l % 100));
+timespecsub(t1, t0, &elapsed);
+hours = elapsed.tv_sec / 3600;
+minutes = (elapsed.tv_sec % 3600) / 60;
+seconds = elapsed.tv_sec % 60;
+if (hours != 0)
+ fprintf(cshout, "%lld:%02lld:", hours, minutes);
+else
+ fprintf(cshout, "%lld:", minutes);
+fprintf(cshout, "%02lld.%03ld", seconds, elapsed.tv_nsec / 100);
}
Index: bin/ksh/c_sh.c
===
RCS file: /cvs/src/bin/ksh/c_sh.c,v
retrieving revision 1.64
diff -u -p -r1.64 c_sh.c
--- bin/ksh/c_sh.c 22 May 2020 07:50:07 - 1.64
+++ bin/ksh/c_sh.c 14 Jun 2023 03:23:29 -
@@ -681,13 +681,13 @@ p_tv(struct shf *shf, int posix, struct
char *suffix)
{
if (posix)
- shf_fprintf(shf, "%s%*lld.%02ld%s", prefix ? prefix : "",
- width, (long long)tv->tv_sec, tv->tv_usec / 1, suffix);
+ shf_fprintf(shf, "%s%*lld.%03ld%s", prefix ? prefix : "",
+ width, (long long)tv->tv_sec, tv->tv_usec / 1000, suffix);
else
- shf_fprintf(shf, "%s%*lldm%02lld.%02lds%s", prefix ? prefix :
"",
+ shf_fprintf(shf, "%s%*lldm%02lld.%03lds%s", prefix ? prefix :
"",
width, (long long)tv->tv_sec / 60,
(long long)tv->tv_sec % 60,
- tv->tv_usec / 1, suffix);
+ tv->tv_usec / 1000, suffix);
}
static void
@@ -695,14 +695,14 @@ p_ts(struct shf *shf, int posix, struct
char *suffix)
{
if (posix)
- shf_fprintf(shf, "%s%*lld.%02ld%s", prefix ? prefix : "",
- width, (long long)ts->tv_sec, ts->tv_nsec / 1000,
+ shf_fprintf(shf, "%s%*lld.%03ld%s", prefix ? prefix : "",
+ width, (long long)ts->tv_sec, ts->tv_nsec / 100,
suffix);
else
- shf_fprintf(shf, "%s%*lldm%02lld.%02lds%s", prefix ? prefix :
"",
+
