bug with for and time

bug with for and time

[Nathan Sidwell]

Zsh 4.0.4 appears to lose the time command in the following,

nathan@garibaldi:363>for i in 1 2 ; time echo


but, place the command in a subshell, and it works.

nathan@garibaldi:364>for i in 1 2 ; time (echo)

( echo )  0.00s user 0.00s system 0% cpu 0.000 total

( echo )  0.00s user 0.00s system 0% cpu 0.000 total


nathan
-- 
Nathan Sidwell    ::   http://www.codesourcery.com   ::     CodeSourcery LLC
nathan@codesourcery.com    ::     http://www.planetfall.pwp.blueyonder.co.uk

Re: bug with for and time

[Peter Stephenson]

Nathan Sidwell wrote:
> Zsh 4.0.4 appears to lose the time command in the following,
> 
> nathan@garibaldi:363>for i in 1 2 ; time echo
> 
> 
> but, place the command in a subshell, and it works.

Yes, that's always been an annoying limitation: "time" works by gettings
system information about subprocesses, and there isn't one in this case.

-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR Ltd., Science Park, Milton Road,
Cambridge, CB4 0WH, UK                          Tel: +44 (0)1223 692070


**********************************************************************
This email and any files transmitted with it are confidential and
intended solely for the use of the individual or entity to whom they
are addressed. If you have received this email in error please notify
the system manager.

This footnote also confirms that this email message has been swept by
MIMEsweeper for the presence of computer viruses.

www.mimesweeper.com
**********************************************************************

Re: bug with for and time

[Matthias B.]

On Mon, 04 Oct 2004 17:10:47 +0100 Peter Stephenson <pws@csr.com> wrote:

> Nathan Sidwell wrote:
> > Zsh 4.0.4 appears to lose the time command in the following,
> > 
> > nathan@garibaldi:363>for i in 1 2 ; time echo
> > 
> > 
> > but, place the command in a subshell, and it works.
> 
> Yes, that's always been an annoying limitation: "time" works by gettings
> system information about subprocesses, and there isn't one in this case.

Then how does bash do it? bash can time builtins just fine.

MSB

-- 
I will continue to be an impossible person
as long as those who are now possible remain possible.

Re: bug with for and time

[Dan Nelson]

In the last episode (Oct 05), Matthias B. said:
> On Mon, 04 Oct 2004 17:10:47 +0100 Peter Stephenson <pws@csr.com> wrote:
> > Nathan Sidwell wrote:
> > > Zsh 4.0.4 appears to lose the time command in the following,
> > > 
> > > nathan@garibaldi:363>for i in 1 2 ; time echo
> > > 
> > > but, place the command in a subshell, and it works.
> > 
> > Yes, that's always been an annoying limitation: "time" works by
> > gettings system information about subprocesses, and there isn't one
> > in this case.
> 
> Then how does bash do it? bash can time builtins just fine.

It probably calls getrusage(RUSAGE_SELF) before and after whatever
you're timing, then prints the deltas.

-- 
	Dan Nelson
	dnelson@allantgroup.com

Re: bug with for and time

[Matthias B.]

On Tue, 5 Oct 2004 13:18:20 -0500 Dan Nelson <dnelson@allantgroup.com>
wrote:

> In the last episode (Oct 05), Matthias B. said:
> > On Mon, 04 Oct 2004 17:10:47 +0100 Peter Stephenson <pws@csr.com>
> > wrote:
> > > Nathan Sidwell wrote:
> > > > Zsh 4.0.4 appears to lose the time command in the following,
> > > > 
> > > > nathan@garibaldi:363>for i in 1 2 ; time echo
> > > > 
> > > > but, place the command in a subshell, and it works.
> > > 
> > > Yes, that's always been an annoying limitation: "time" works by
> > > gettings system information about subprocesses, and there isn't one
> > > in this case.
> > 
> > Then how does bash do it? bash can time builtins just fine.
> 
> It probably calls getrusage(RUSAGE_SELF) before and after whatever
> you're timing, then prints the deltas.

Then maybe zsh should do that, too. Right now, zsh's time function doesn't
work very well. Look at this:

/home/msb> TIMEFMT=$'real\t%*Es\nuser\t%*Us\nsys \t%*Ss\ncpu \t%P'
/home/msb> time /bin/echo foo
foo
real    0.000s
user    0.000s
sys     0.010s
cpu     8695%
/home/msb> time /bin/echo foo
foo
real    0.006s
user    0.000s
sys     0.000s
cpu     0%
/home/msb> time /bin/echo foo
foo
real    0.000s
user    0.010s
sys     0.000s
cpu     8928%


The numbers don't add up properly. I've never seen something like this
with bash.

MSB

-- 
Happiness through ignorance!

Re: bug with for and time

[Nikolai Weibull]

* Matthias B. <msbREMOVE-THIS@winterdrache.de> [Oct 06, 2004 13:50]:
> /home/msb> time /bin/echo foo
> foo
> real    0.000s
> user    0.010s
> sys     0.000s
> cpu     8928%

I can beat that:

regex '(a|aa)*' aaa: real: 0.000 user: 0.020 system: 0.000 (50000%)

is what I got when executing a test program for my regular expression
engine,
	nikolai

--
::: name: Nikolai Weibull    :: aliases: pcp / lone-star / aka :::
::: born: Chicago, IL USA    :: loc atm: Gothenburg, Sweden    :::
::: page: www.pcppopper.org  :: fun atm: gf,lps,ruby,lisp,war3 :::
main(){printf(&linux["\021%six\012\0"],(linux)["have"]+"fun"-97);}

Re: bug with for and time

[Peter Stephenson]

> Then maybe zsh should do that, too. Right now, zsh's time function doesn't
> work very well. Look at this:
> 
> /home/msb> TIMEFMT=$'real\t%*Es\nuser\t%*Us\nsys \t%*Ss\ncpu \t%P'
> /home/msb> time /bin/echo foo
> foo
> real    0.000s
> user    0.000s
> sys     0.010s
> cpu     8695%

This has never been great.  There appear to be two problems.

First, zsh is using times() instead of getrusage().  The former has much
worse resolution, typically only 100th of second (probably the case
here).

Second, zsh's "real" time is taken by measuring the time till the
process is harvested, but starting *after* the fork in the parent
process.  This can make a big difference, given that the fork can
include arbitrary amounts of real time starting off the child process.

The following tries to address both problems.  It's basically working,
but there could easily be glitches.

There are a couple of places where the shell calls fork() instead of
zfork() (which I've commented).  It would make the code simpler to use
zfork() owing to the gettimeofday() call I've embedded in that.  I
suspect that's OK to do (apart from fixing up redundant error messages),
but I haven't looked closely enough yet.

This doesn't do anything for builtins.  Last I looked the code
structure didn't make that too easy.

Index: configure.ac
===================================================================
RCS file: /cvsroot/zsh/zsh/configure.ac,v
retrieving revision 1.19
diff -u -r1.19 configure.ac
--- configure.ac	30 Jul 2004 11:09:17 -0000	1.19
+++ configure.ac	6 Oct 2004 16:57:27 -0000
@@ -1043,7 +1043,7 @@
 	       initgroups nis_list \
 	       setuid seteuid setreuid setresuid setsid \
 	       memcpy memmove strstr strerror \
-	       getrlimit \
+	       getrlimit getrusage \
 	       setlocale \
 	       uname \
 	       signgam \
Index: Src/exec.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/exec.c,v
retrieving revision 1.72
diff -u -r1.72 exec.c
--- Src/exec.c	5 Oct 2004 10:39:43 -0000	1.72
+++ Src/exec.c	6 Oct 2004 16:57:30 -0000
@@ -212,9 +212,10 @@
 
 /**/
 static pid_t
-zfork(void)
+zfork(struct timeval *tv)
 {
     pid_t pid;
+    struct timezone dummy_tz;
 
     /*
      * Is anybody willing to explain this test?
@@ -223,6 +224,8 @@
 	zerr("job table full", NULL, 0);
 	return -1;
     }
+    if (tv)
+	gettimeofday(tv, &dummy_tz);
     pid = fork();
     if (pid == -1) {
 	zerr("fork failed: %e", NULL, errno);
@@ -313,6 +316,7 @@
 int list_pipe = 0, simple_pline = 0;
 
 static pid_t list_pipe_pid;
+static struct timeval list_pipe_start;
 static int nowait, pline_level = 0;
 static int list_pipe_child = 0, list_pipe_job;
 static char list_pipe_text[JOBTEXTSIZE];
@@ -1101,7 +1105,8 @@
 
 		    curjob = newjob;
 		    DPUTS(!list_pipe_pid, "invalid list_pipe_pid");
-		    addproc(list_pipe_pid, list_pipe_text, 0);
+		    addproc(list_pipe_pid, list_pipe_text, 0,
+			    &list_pipe_start);
 
 		    /* If the super-job contains only the sub-shell, the
 		       sub-shell is the group leader. */
@@ -1157,9 +1162,13 @@
 		      (jobtab[list_pipe_job].stat & STAT_STOPPED)))) {
 		    pid_t pid;
 		    int synch[2];
+		    struct timezone dummy_tz;
+		    struct timeval bgtime;
 
 		    pipe(synch);
 
+		    gettimeofday(&bgtime, &dummy_tz);
+		    /* Any reason this isn't zfork? */
 		    if ((pid = fork()) == -1) {
 			trashzle();
 			close(synch[0]);
@@ -1177,6 +1186,7 @@
 			lpforked = 
 			    (killpg(jobtab[list_pipe_job].gleader, 0) == -1 ? 2 : 1);
 			list_pipe_pid = pid;
+			list_pipe_start = bgtime;
 			nowait = errflag = 1;
 			breaks = loops;
 			close(synch[1]);
@@ -1289,8 +1299,12 @@
 	 * rest of the pipeline in the current shell.         */
 	if (wc_code(code) >= WC_CURSH && (how & Z_SYNC)) {
 	    int synch[2];
+	    struct timeval bgtime;
+	    struct timezone dummy_tz;
 
 	    pipe(synch);
+	    gettimeofday(&bgtime, &dummy_tz);
+	    /* any reason this isn't zfork? */
 	    if ((pid = fork()) == -1) {
 		close(synch[0]);
 		close(synch[1]);
@@ -1299,7 +1313,7 @@
 		char dummy, *text;
 
 		text = getjobtext(state->prog, state->pc);
-		addproc(pid, text, 0);
+		addproc(pid, text, 0, &bgtime);
 		close(synch[1]);
 		read(synch[0], &dummy, 1);
 		close(synch[0]);
@@ -1437,8 +1451,9 @@
 	char buf[TCBUFSIZE];
 	int len, i;
 	pid_t pid;
+	struct timeval bgtime;
 
-	if ((pid = zfork())) {
+	if ((pid = zfork(&bgtime))) {
 	    for (i = 0; i < mn->ct; i++)
 		zclose(mn->fds[i]);
 	    zclose(mn->pipe);
@@ -1448,7 +1463,7 @@
 	    }
 	    mn->ct = 1;
 	    mn->fds[0] = fd;
-	    addproc(pid, NULL, 1);
+	    addproc(pid, NULL, 1, &bgtime);
 	    return;
 	}
 	/* pid == 0 */
@@ -2108,11 +2123,12 @@
 	pid_t pid;
 	int synch[2];
 	char dummy;
+	struct timeval bgtime;
 
 	child_block();
 	pipe(synch);
 
-	if ((pid = zfork()) == -1) {
+	if ((pid = zfork(&bgtime)) == -1) {
 	    close(synch[0]);
 	    close(synch[1]);
             opts[AUTOCONTINUE] = oautocont;
@@ -2140,7 +2156,7 @@
 			  3 : WC_ASSIGN_NUM(ac) + 2);
 		}
 	    }
-	    addproc(pid, text, 0);
+	    addproc(pid, text, 0, &bgtime);
             opts[AUTOCONTINUE] = oautocont;
 	    return;
 	}
@@ -2697,7 +2713,7 @@
     zleactive = 0;
     if (cl)
 	clearjobtab(monitor);
-    times(&shtms);
+    get_usage();
     forklevel = locallevel;
 }
 
@@ -2843,7 +2859,7 @@
     mpipe(pipes);
     child_block();
     cmdoutval = 0;
-    if ((cmdoutpid = pid = zfork()) == -1) {
+    if ((cmdoutpid = pid = zfork(NULL)) == -1) {
 	/* fork error */
 	zclose(pipes[0]);
 	zclose(pipes[1]);
@@ -2979,7 +2995,7 @@
     child_block();
     fd = open(nam, O_WRONLY | O_CREAT | O_EXCL | O_NOCTTY, 0600);
 
-    if (fd < 0 || (cmdoutpid = pid = zfork()) == -1) {
+    if (fd < 0 || (cmdoutpid = pid = zfork(NULL)) == -1) {
 	/* fork or open error */
 	child_unblock();
 	return nam;
@@ -3040,6 +3056,7 @@
     int out = *cmd == Inang;
     char *pnam;
     pid_t pid;
+    struct timeval bgtime;
 
 #ifndef PATH_DEV_FD
     int fd;
@@ -3054,11 +3071,11 @@
 	jobtab[thisjob].filelist = znewlinklist();
     zaddlinknode(jobtab[thisjob].filelist, ztrdup(pnam));
 
-    if ((pid = zfork())) {
+    if ((pid = zfork(&bgtime))) {
 	if (pid == -1)
 	    return NULL;
 	if (!out)
-	    addproc(pid, NULL, 1);
+	    addproc(pid, NULL, 1, &bgtime);
 	return pnam;
     }
     closem(0);
@@ -3078,7 +3095,7 @@
     if (!(prog = parsecmd(cmd)))
 	return NULL;
     mpipe(pipes);
-    if ((pid = zfork())) {
+    if ((pid = zfork(&bgtime))) {
 	sprintf(pnam, "%s/%d", PATH_DEV_FD, pipes[!out]);
 	zclose(pipes[out]);
 	if (pid == -1)
@@ -3089,7 +3106,7 @@
 	fdtable[pipes[!out]] = 2;
 	if (!out)
 	{
-	    addproc(pid, NULL, 1);
+	    addproc(pid, NULL, 1, &bgtime);
 	}
 	return pnam;
     }
@@ -3116,17 +3133,18 @@
     Eprog prog;
     int pipes[2], out = *cmd == Inang;
     pid_t pid;
+    struct timeval bgtime;
 
     if (!(prog = parsecmd(cmd)))
 	return -1;
     mpipe(pipes);
-    if ((pid = zfork())) {
+    if ((pid = zfork(&bgtime))) {
 	zclose(pipes[out]);
 	if (pid == -1) {
 	    zclose(pipes[!out]);
 	    return -1;
 	}
-	addproc(pid, NULL, 1);
+	addproc(pid, NULL, 1, &bgtime);
 	return pipes[!out];
     }
     entersubsh(Z_ASYNC, 1, 0, 0);
Index: Src/init.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/init.c,v
retrieving revision 1.44
diff -u -r1.44 init.c
--- Src/init.c	20 Sep 2004 13:37:41 -0000	1.44
+++ Src/init.c	6 Oct 2004 16:57:30 -0000
@@ -856,7 +856,7 @@
 #endif
     }
 
-    times(&shtms);
+    get_usage();
 
     /* Close the file descriptors we opened to block off 0 to 9 */
     for (i = 0; i < 10; i++)
Index: Src/jobs.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/jobs.c,v
retrieving revision 1.31
diff -u -r1.31 jobs.c
--- Src/jobs.c	2 Jun 2004 22:14:26 -0000	1.31
+++ Src/jobs.c	6 Oct 2004 16:57:31 -0000
@@ -80,7 +80,15 @@
 /* shell timings */
  
 /**/
-struct tms shtms;
+#ifdef HAVE_GETRUSAGE
+/**/
+static struct rusage child_usage;
+/**/
+#else
+/**/
+static struct tms shtms;
+/**/
+#endif
  
 /* 1 if ttyctl -f has been executed */
  
@@ -93,8 +101,6 @@
 /**/
 int prev_errflag, prev_breaks, errbrk_saved;
 
-static struct timeval dtimeval, now;
-
 /**/
 int numpipestats, pipestats[MAX_PIPESTATS];
 
@@ -250,6 +256,21 @@
     return 0;
 }
 
+
+/* Get the latest usage information */
+
+/**/
+void 
+get_usage(void)
+{
+#ifdef HAVE_GETRUSAGE
+    getrusage(RUSAGE_CHILDREN, &child_usage);
+#else
+    times(shtms);
+#endif
+}
+
+
 /* Update status of process that we have just WAIT'ed for */
 
 /**/
@@ -257,17 +278,31 @@
 update_process(Process pn, int status)
 {
     struct timezone dummy_tz;
+#ifdef HAVE_GETRUSAGE
+    struct timeval childs, childu;
+#else
     long childs, childu;
+#endif
 
+#ifdef HAVE_GETRUSAGE
+    childs = child_usage.ru_stime;
+    childu = child_usage.ru_utime;
+#else
     childs = shtms.tms_cstime;
     childu = shtms.tms_cutime;
-    times(&shtms);                          /* get time-accounting info          */
+#endif
+    /* get time-accounting info          */
+    get_usage();
+    gettimeofday(&pn->endtime, &dummy_tz);  /* record time process exited        */
 
     pn->status = status;                    /* save the status returned by WAIT  */
+#ifdef HAVE_GETRUSAGE
+    dtime(&pn->ti.sys, &childs, &child_usage.ru_stime);
+    dtime(&pn->ti.usr, &childu, &child_usage.ru_utime);
+#else
     pn->ti.st  = shtms.tms_cstime - childs; /* compute process system space time */
     pn->ti.ut  = shtms.tms_cutime - childu; /* compute process user space time   */
-
-    gettimeofday(&pn->endtime, &dummy_tz);  /* record time process exited        */
+#endif
 }
 
 /* Update status of job, possibly printing it */
@@ -473,6 +508,8 @@
     prevjob = -1;
 }
 
+/**/
+#ifndef HAVE_GETRUSAGE
 static long clktck = 0;
 
 /**/
@@ -501,6 +538,8 @@
 # endif
 #endif
 }
+/**/
+#endif
 
 /**/
 static void
@@ -519,9 +558,8 @@
 	fprintf(stderr,           "%.3f",              secs);
 }
 
-/**/
 static void
-printtime(struct timeval *real, struct timeinfo *ti, char *desc)
+printtime(struct timeval *real, child_times_t *ti, char *desc)
 {
     char *s;
     double elapsed_time, user_time, system_time;
@@ -530,13 +568,21 @@
     if (!desc)
 	desc = "";
 
-    set_clktck();
     /* go ahead and compute these, since almost every TIMEFMT will have them */
     elapsed_time = real->tv_sec + real->tv_usec / 1000000.0;
+
+#ifdef HAVE_GETRUSAGE
+    user_time = ti->usr.tv_sec + ti->usr.tv_usec / 1000000.0;
+    system_time = ti->sys.tv_sec + ti->sys.tv_usec / 1000000.0;
+    percent = 100.0 * (user_time + system_time)
+	/ (real->tv_sec + real->tv_usec / 1000000.0);
+#else
+    set_clktck();
     user_time    = ti->ut / (double) clktck;
     system_time  = ti->st / (double) clktck;
     percent      =  100.0 * (ti->ut + ti->st)
 	/ (clktck * real->tv_sec + clktck * real->tv_usec / 1000000.0);
+#endif
 
     queue_signals();
     if (!(s = getsparam("TIMEFMT")))
@@ -598,11 +644,13 @@
 dumptime(Job jn)
 {
     Process pn;
+    struct timeval dtimeval;
 
     if (!jn->procs)
 	return;
     for (pn = jn->procs; pn; pn = pn->next)
-	printtime(dtime(&dtimeval, &pn->bgtime, &pn->endtime), &pn->ti, pn->text);
+	printtime(dtime(&dtimeval, &pn->bgtime, &pn->endtime), &pn->ti,
+		  pn->text);
 }
 
 /* Check whether shell should report the amount of time consumed   *
@@ -617,7 +665,7 @@
     struct value vbuf;
     Value v;
     char *s = "REPORTTIME";
-    int reporttime;
+    zlong reporttime;
 
     /* if the time keyword was used */
     if (j->stat & STAT_TIMED)
@@ -634,8 +682,15 @@
     if (!j->procs)
 	return 0;
 
+#ifdef HAVE_GETRUSAGE
+    reporttime -= j->procs->ti.usr.tv_sec + j->procs->ti.sys.tv_sec;
+    if (j->procs->ti.usr.tv_usec + j->procs->ti.sys.tv_usec >= 1000000)
+	reporttime--;
+    return reporttime <= 0;
+#else
     set_clktck();
     return ((j->procs->ti.ut + j->procs->ti.st) / clktck >= reporttime);
+#endif
 }
 
 /* !(lng & 3) means jobs    *
@@ -899,10 +954,9 @@
 
 /**/
 void
-addproc(pid_t pid, char *text, int aux)
+addproc(pid_t pid, char *text, int aux, struct timeval *bgtime)
 {
     Process pn, *pnlist;
-    struct timezone dummy_tz;
 
     DPUTS(thisjob == -1, "No valid job in addproc.");
     pn = (Process) zshcalloc(sizeof *pn);
@@ -916,7 +970,7 @@
 
     if (!aux)
     {
-	gettimeofday(&pn->bgtime, &dummy_tz);
+	pn->bgtime = *bgtime;
 	/* if this is the first process we are adding to *
 	 * the job, then it's the group leader.          */
 	if (!jobtab[thisjob].gleader)
@@ -1158,18 +1212,40 @@
 void
 shelltime(void)
 {
-    struct timeinfo ti;
     struct timezone dummy_tz;
+    struct timeval dtimeval, now;
+#ifdef HAVE_GETRUSAGE
+    struct rusage ru;
+    child_times_t ti;
+#else
+    struct timeinfo ti;
     struct tms buf;
+#endif
+
+    gettimeofday(&now, &dummy_tz);
 
+#ifdef HAVE_GETRUSAGE
+    getrusage(RUSAGE_SELF, &ru);
+    ti.sys = ru.ru_stime;
+    ti.usr = ru.ru_utime;
+#else
     times(&buf);
+
     ti.ut = buf.tms_utime;
     ti.st = buf.tms_stime;
-    gettimeofday(&now, &dummy_tz);
+#endif
     printtime(dtime(&dtimeval, &shtimer, &now), &ti, "shell");
+
+#ifdef HAVE_GETRUSAGE
+    getrusage(RUSAGE_CHILDREN, &ru);
+    ti.sys = ru.ru_stime;
+    ti.usr = ru.ru_utime;
+#else
     ti.ut = buf.tms_cutime;
     ti.st = buf.tms_cstime;
-    printtime(dtime(&dtimeval, &shtimer, &now), &ti, "children");
+#endif
+    printtime(&dtimeval, &ti, "children");
+
 }
 
 /* see if jobs need printing */
Index: Src/signals.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/signals.c,v
retrieving revision 1.30
diff -u -r1.30 signals.c
--- Src/signals.c	29 Jul 2004 15:09:51 -0000	1.30
+++ Src/signals.c	6 Oct 2004 16:57:31 -0000
@@ -484,7 +484,7 @@
 			*procsubval = (0200 | WTERMSIG(status));
 		    else
 			*procsubval = WEXITSTATUS(status);
-		    times(&shtms);
+		    get_usage();
 		    goto cont;
 		}
 		if (!es)
@@ -514,7 +514,7 @@
 		 * children in sub processes anyway:  otherwise, this
 		 * will get added on to the next found process that terminates.
 		 */
-		times(&shtms);
+		get_usage();
 	    }
         }
         break;
Index: Src/zsh.h
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/zsh.h,v
retrieving revision 1.62
diff -u -r1.62 zsh.h
--- Src/zsh.h	1 Oct 2004 19:10:59 -0000	1.62
+++ Src/zsh.h	6 Oct 2004 16:57:32 -0000
@@ -739,12 +739,21 @@
 
 /* node in job process lists */
 
+#ifdef HAVE_GETRUSAGE
+typedef struct {
+    struct timeval sys;
+    struct timeval usr;
+} child_times_t;
+#else
+typedef struct timeinfo child_times_t;
+#endif
+
 struct process {
     struct process *next;
     pid_t pid;                  /* process id                       */
     char text[JOBTEXTSIZE];	/* text to print when 'jobs' is run */
     int status;			/* return code from waitpid/wait3() */
-    struct timeinfo ti;
+    child_times_t ti;
     struct timeval bgtime;	/* time job was spawned             */
     struct timeval endtime;	/* time job exited                  */
 };

-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR Ltd., Science Park, Milton Road,
Cambridge, CB4 0WH, UK                          Tel: +44 (0)1223 692070


**********************************************************************
This email and any files transmitted with it are confidential and
intended solely for the use of the individual or entity to whom they
are addressed. If you have received this email in error please notify
the system manager.

This footnote also confirms that this email message has been swept by
MIMEsweeper for the presence of computer viruses.

www.mimesweeper.com
**********************************************************************

Re: bug with for and time

[Dan Nelson]

In the last episode (Oct 06), Peter Stephenson said:
> This has never been great.  There appear to be two problems.

Actually it _was_ great back in zsh 2.5, which did use getrusage().  It
was dropped in zsh 3.0 for some reason.  My TIMEFMT is still set to
"U:%U S:%S E:%E CPU:%P Faults:%F Swaps:%W" as a reminder to put it back
in (not a very effective reminder I guess).

> The following tries to address both problems.  It's basically working,
> but there could easily be glitches.

Bonus points for anyone who adds back the extra TIMEFMT options too.

-- 
	Dan Nelson
	dnelson@allantgroup.com

Re: bug with for and time

[Peter Stephenson]

Dan Nelson wrote:
> In the last episode (Oct 06), Peter Stephenson said:
> > This has never been great.  There appear to be two problems.
> 
> Actually it _was_ great back in zsh 2.5, which did use getrusage().  It
> was dropped in zsh 3.0 for some reason.  My TIMEFMT is still set to
> "U:%U S:%S E:%E CPU:%P Faults:%F Swaps:%W" as a reminder to put it back
> in (not a very effective reminder I guess).

I can vaguely remember that the getrusage() fields which didn't
correspond to times were dropped when we switched to autoconf, simply
because it became hard to test for all the fields.  I didn't notice
getrusage() disappearing entirely then, but it certainly must have at
some point.

I suppose this will give us a base for putting them back, with suitable
configuration tests.  Here's what we're aiming at (from 2.5.03):

TIMEFMT
       The format of process time reports with the time keyword.
       The default is "%E real  %U  user   %S  system   %P  %J".
       Recognizes the following escape sequences:

        %U     CPU seconds spent in user mode.
        %S     CPU seconds spent in kernel mode.
        %E     Elapsed time in seconds.
        %P     The CPU percentage, computed as (%U+%S)/%E.
        %W     Number of times the process was swapped.
        %X     The average amount in (shared) text space used in
               Kbytes.
        %D     The average amount in (unshared) data/stack space
               used in Kbytes.
        %K     The total space used (%X+%D) in Kbytes.
        %M     The  maximum memory the process had in use at any
               time in Kbytes.
        %F     The number of major page faults (page  needed  to
               be brought from disk).
        %R     The number of minor page faults.
        %I     The number of input operations.
        %O     The number of output operations.
        %r     The number of socket messages received.
        %s     The number of socket messages sent.
        %k     The number of signals received.
        %w     Number of voluntary context switches (waits).
        %c     Number of involuntary context switches.
        %J     The name of this job.

-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR Ltd., Science Park, Milton Road,
Cambridge, CB4 0WH, UK                          Tel: +44 (0)1223 692070


**********************************************************************
This email and any files transmitted with it are confidential and
intended solely for the use of the individual or entity to whom they
are addressed. If you have received this email in error please notify
the system manager.

This footnote also confirms that this email message has been swept by
MIMEsweeper for the presence of computer viruses.

www.mimesweeper.com
**********************************************************************

Re: bug with for and time

[Dan Nelson]

In the last episode (Oct 07), Peter Stephenson said:
> I can vaguely remember that the getrusage() fields which didn't
> correspond to times were dropped when we switched to autoconf, simply
> because it became hard to test for all the fields.  I didn't notice
> getrusage() disappearing entirely then, but it certainly must have at
> some point.

I did some mailinglist searches, and back in 1999, workers-2526 says
that getrusage was removed because it wasn't POSIX and the autoconf
test was too complex. It is now, though, and was in SUS as far back as
1997.  Unfortunately, only two struct members are defined:

        struct timeval ru_utime  User time used.
        struct timeval ru_stime  System time used.

Fortunately, the remaining members defined by AIX, FreeBSD, Linux,
Solaris, and Tru64 are identical.  Solaris doesn't fill in ru_ixrss or
ru_isrss (%X and %D), but they are in the struct.  Testing for each
member individually if you wanted to wouldn't be hard, anyway.  One
AC_CHECK_MEMBERS call with 14 arguments is all that's needed, plus the
appropriate #if defined checks around each resource in the TIMEFMT
expansion code.

-- 
	Dan Nelson
	dnelson@allantgroup.com

Re: bug with for and time

[Peter Stephenson]

Dan Nelson wrote:
> I did some mailinglist searches, and back in 1999, workers-2526 says
> that getrusage was removed because it wasn't POSIX and the autoconf
> test was too complex.

There's another issue... we used to get the usage for a child by calling
wait3(), which can set a struct rusage.  (Modern systems have wait4,
which allows you to wait for a particular PID, but it looks like we
don't actually use that anyway.)  However, this isn't part of the latest
standards.  So the only standardised way of doing it is to call
getrusage and subtract all appropriate elements.  With some (maximum
value), you can't actually tell for sure whether it's applicable to the
last child or not.

Maybe we should prefer wait3(), which is widely available, and do the
best we can elsewhere, but it's not ideal.  Still, both wait3() and the
additional rusage elements came from BSD; maybe I can rely on either
both or neither being available and skip the case where we can't tie
usage to individual processes.

> One AC_CHECK_MEMBERS call with 14 arguments is all that's needed, plus the
> appropriate #if defined checks around each resource in the TIMEFMT
> expansion code.

This bit I can easily get working.

-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR Ltd., Science Park, Milton Road,
Cambridge, CB4 0WH, UK                          Tel: +44 (0)1223 692070


**********************************************************************
This email and any files transmitted with it are confidential and
intended solely for the use of the individual or entity to whom they
are addressed. If you have received this email in error please notify
the system manager.

This footnote also confirms that this email message has been swept by
MIMEsweeper for the presence of computer viruses.

www.mimesweeper.com
**********************************************************************

Re: bug with for and time

[Peter Stephenson]

Peter Stephenson wrote:
> Still, both wait3() and the
> additional rusage elements came from BSD; maybe I can rely on either
> both or neither being available and skip the case where we can't tie
> usage to individual processes.

This is what I've done.  I'm not sure doing anything else is necessary
or sensible.  Enjoy.

I replaced the fork()s with zfork()s as threatened.  As far as I can
see, the only issue is error messages, and they're not very common
errors.  They should still print something sensible.

Index: configure.ac
===================================================================
RCS file: /cvsroot/zsh/zsh/configure.ac,v
retrieving revision 1.20
diff -u -r1.20 configure.ac
--- configure.ac	7 Oct 2004 09:45:43 -0000	1.20
+++ configure.ac	8 Oct 2004 14:13:15 -0000
@@ -1448,6 +1448,32 @@
 
 
 dnl --------------------------------------------
+dnl Check for members of struct rusage
+dnl --------------------------------------------
+if test $ac_cv_func_getrusage = yes; then
+  AC_CHECK_MEMBERS([struct rusage.ru_maxrss,
+		    struct rusage.ru_ixrss,
+		    struct rusage.ru_idrss,
+		    struct rusage.ru_isrss,
+		    struct rusage.ru_minflt,
+		    struct rusage.ru_majflt,
+		    struct rusage.ru_nswap,
+		    struct rusage.ru_inblock,
+		    struct rusage.ru_oublock,
+		    struct rusage.ru_msgsnd,
+		    struct rusage.ru_msgrcv,
+		    struct rusage.ru_nsignals,
+		    struct rusage.ru_nvcsw,
+		    struct rusage.ru_nivcsw],,,
+[#include <sys/types.h>
+#ifdef HAVE_SYS_TIME_H
+#include <sys/time.h>
+#endif
+#include <sys/resource.h>])
+fi
+
+
+dnl --------------------------------------------
 dnl CHECK FOR DEFAULT PATH (used for command -p)
 dnl --------------------------------------------
 AC_CACHE_VAL(zsh_cv_cs_path,
Index: Doc/Zsh/params.yo
===================================================================
RCS file: /cvsroot/zsh/zsh/Doc/Zsh/params.yo,v
retrieving revision 1.22
diff -u -r1.22 params.yo
--- Doc/Zsh/params.yo	22 Jun 2004 13:10:02 -0000	1.22
+++ Doc/Zsh/params.yo	8 Oct 2004 14:13:18 -0000
@@ -1047,7 +1047,9 @@
 item(tt(TIMEFMT))(
 The format of process time reports with the tt(time) keyword.
 The default is `tt(%E real  %U user  %S system  %P %J)'.
-Recognizes the following escape sequences:
+Recognizes the following escape sequences, although not all
+may be available on all systems, and some that are available
+may not be useful:
 
 startsitem()
 sitem(tt(%%))(A `tt(%)'.)
@@ -1055,6 +1057,23 @@
 sitem(tt(%S))(CPU seconds spent in kernel mode.)
 sitem(tt(%E))(Elapsed time in seconds.)
 sitem(tt(%P))(The CPU percentage, computed as (tt(%U)PLUS()tt(%S))/tt(%E).)
+sitem(tt(%W))(Number of times the process was swapped.)
+sitem(tt(%X))(The average amount in (shared) text space used in Kbytes.)
+sitem(tt(%D))(The average amount in (unshared) data/stack space used in
+Kbytes.)
+sitem(tt(%K))(The total space used (%X+%D) in Kbytes.)
+sitem(tt(%M))(The  maximum memory the process had in use at any time in
+Kbytes.)
+sitem(tt(%F))(The number of major page faults (page needed to be brought
+from disk).)
+sitem(tt(%R))(The number of minor page faults.)
+sitem(tt(%I))(The number of input operations.)
+sitem(tt(%O))(The number of output operations.)
+sitem(tt(%r))(The number of socket messages received.)
+sitem(tt(%s))(The number of socket messages sent.)
+sitem(tt(%k))(The number of signals received.)
+sitem(tt(%w))(Number of voluntary context switches (waits).)
+sitem(tt(%c))(Number of involuntary context switches.)
 sitem(tt(%J))(The name of this job.)
 endsitem()
 
Index: Src/exec.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/exec.c,v
retrieving revision 1.73
diff -u -r1.73 exec.c
--- Src/exec.c	7 Oct 2004 09:45:46 -0000	1.73
+++ Src/exec.c	8 Oct 2004 14:13:25 -0000
@@ -1162,18 +1162,14 @@
 		      (jobtab[list_pipe_job].stat & STAT_STOPPED)))) {
 		    pid_t pid;
 		    int synch[2];
-		    struct timezone dummy_tz;
 		    struct timeval bgtime;
 
 		    pipe(synch);
 
-		    gettimeofday(&bgtime, &dummy_tz);
-		    /* Any reason this isn't zfork? */
-		    if ((pid = fork()) == -1) {
+		    if ((pid = zfork(&bgtime)) == -1) {
 			trashzle();
 			close(synch[0]);
 			close(synch[1]);
-			putc('\n', stderr);
 			fprintf(stderr, "zsh: job can't be suspended\n");
 			fflush(stderr);
 			makerunning(jn);
@@ -1300,15 +1296,11 @@
 	if (wc_code(code) >= WC_CURSH && (how & Z_SYNC)) {
 	    int synch[2];
 	    struct timeval bgtime;
-	    struct timezone dummy_tz;
 
 	    pipe(synch);
-	    gettimeofday(&bgtime, &dummy_tz);
-	    /* any reason this isn't zfork? */
-	    if ((pid = fork()) == -1) {
+	    if ((pid = zfork(&bgtime)) == -1) {
 		close(synch[0]);
 		close(synch[1]);
-		zerr("fork failed: %e", NULL, errno);
 	    } else if (pid) {
 		char dummy, *text;
 
Index: Src/jobs.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/jobs.c,v
retrieving revision 1.32
diff -u -r1.32 jobs.c
--- Src/jobs.c	7 Oct 2004 09:45:46 -0000	1.32
+++ Src/jobs.c	8 Oct 2004 14:13:28 -0000
@@ -271,6 +271,7 @@
 }
 
 
+#ifndef HAVE_GETRUSAGE
 /* Update status of process that we have just WAIT'ed for */
 
 /**/
@@ -278,32 +279,19 @@
 update_process(Process pn, int status)
 {
     struct timezone dummy_tz;
-#ifdef HAVE_GETRUSAGE
-    struct timeval childs, childu;
-#else
     long childs, childu;
-#endif
 
-#ifdef HAVE_GETRUSAGE
-    childs = child_usage.ru_stime;
-    childu = child_usage.ru_utime;
-#else
     childs = shtms.tms_cstime;
     childu = shtms.tms_cutime;
-#endif
     /* get time-accounting info          */
     get_usage();
     gettimeofday(&pn->endtime, &dummy_tz);  /* record time process exited        */
 
     pn->status = status;                    /* save the status returned by WAIT  */
-#ifdef HAVE_GETRUSAGE
-    dtime(&pn->ti.sys, &childs, &child_usage.ru_stime);
-    dtime(&pn->ti.usr, &childu, &child_usage.ru_utime);
-#else
     pn->ti.st  = shtms.tms_cstime - childs; /* compute process system space time */
     pn->ti.ut  = shtms.tms_cutime - childu; /* compute process user space time   */
-#endif
 }
+#endif
 
 /* Update status of job, possibly printing it */
 
@@ -563,6 +551,9 @@
 {
     char *s;
     double elapsed_time, user_time, system_time;
+#ifdef HAVE_GETRUSAGE
+    double total_time;
+#endif
     int percent;
 
     if (!desc)
@@ -572,10 +563,11 @@
     elapsed_time = real->tv_sec + real->tv_usec / 1000000.0;
 
 #ifdef HAVE_GETRUSAGE
-    user_time = ti->usr.tv_sec + ti->usr.tv_usec / 1000000.0;
-    system_time = ti->sys.tv_sec + ti->sys.tv_usec / 1000000.0;
+    user_time = ti->ru_utime.tv_sec + ti->ru_utime.tv_usec / 1000000.0;
+    system_time = ti->ru_stime.tv_sec + ti->ru_stime.tv_usec / 1000000.0;
     percent = 100.0 * (user_time + system_time)
 	/ (real->tv_sec + real->tv_usec / 1000000.0);
+    total_time = user_time + system_time;
 #else
     set_clktck();
     user_time    = ti->ut / (double) clktck;
@@ -620,6 +612,97 @@
 	    case 'P':
 		fprintf(stderr, "%d%%", percent);
 		break;
+#ifdef HAVE_STRUCT_RUSAGE_RU_NSWAP
+	    case 'W':
+		fprintf(stderr, "%ld", ti->ru_nswap);
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_IXRSS
+	    case 'X':
+		fprintf(stderr, "%ld", (long)(ti->ru_ixrss / total_time));
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_IDRSS
+	    case 'D':
+		fprintf(stderr, "%ld",
+			(long) ((ti->ru_idrss
+#ifdef HAVE_STRUCT_RUSAGE_RU_ISRSS
+				 + ti->ru_isrss
+#endif
+				    ) / total_time));
+		break;
+#endif
+#if defined(HAVE_STRUCT_RUSAGE_RU_IDRSS) || \
+    defined(HAVE_STRUCT_RUSAGE_RU_ISRSS) || \
+    defined(HAVE_STRUCT_RUSAGE_RU_IXRSS)
+	    case 'K':
+		/* treat as D if X not available */
+		fprintf(stderr, "%ld",
+			(long) ((
+#ifdef HAVE_STRUCT_RUSAGE_RU_IXRSS
+				    ti->ru_ixrss
+#else
+				    0
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_IDRSS
+				    + ti->ru_idrss
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_ISRSS
+				    + ti->ru_isrss
+#endif
+				    ) / total_time));
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_MAXRSS
+	    case 'M':
+		fprintf(stderr, "%ld", ti->ru_maxrss / 1024);
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_MAJFLT
+	    case 'F':
+		fprintf(stderr, "%ld", ti->ru_majflt);
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_MINFLT
+	    case 'R':
+		fprintf(stderr, "%ld", ti->ru_minflt);
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_INBLOCK
+	    case 'I':
+		fprintf(stderr, "%ld", ti->ru_inblock);
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_OUBLOCK
+	    case 'O':
+		fprintf(stderr, "%ld", ti->ru_oublock);
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_MSGRCV
+	    case 'r':
+		fprintf(stderr, "%ld", ti->ru_msgrcv);
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_MSGSND
+	    case 's':
+		fprintf(stderr, "%ld", ti->ru_msgsnd);
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_NSIGNALS
+	    case 'k':
+		fprintf(stderr, "%ld", ti->ru_nsignals);
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_NVCSW
+	    case 'w':
+		fprintf(stderr, "%ld", ti->ru_nvcsw);
+		break;
+#endif
+#ifdef HAVE_STRUCT_RUSAGE_RU_NIVCSW
+	    case 'c':
+		fprintf(stderr, "%ld", ti->ru_nivcsw);
+		break;
+#endif
 	    case 'J':
 		fprintf(stderr, "%s", desc);
 		break;
@@ -683,8 +766,9 @@
 	return 0;
 
 #ifdef HAVE_GETRUSAGE
-    reporttime -= j->procs->ti.usr.tv_sec + j->procs->ti.sys.tv_sec;
-    if (j->procs->ti.usr.tv_usec + j->procs->ti.sys.tv_usec >= 1000000)
+    reporttime -= j->procs->ti.ru_utime.tv_sec + j->procs->ti.ru_stime.tv_sec;
+    if (j->procs->ti.ru_utime.tv_usec +
+	j->procs->ti.ru_stime.tv_usec >= 1000000)
 	reporttime--;
     return reporttime <= 0;
 #else
@@ -1214,20 +1298,15 @@
 {
     struct timezone dummy_tz;
     struct timeval dtimeval, now;
-#ifdef HAVE_GETRUSAGE
-    struct rusage ru;
     child_times_t ti;
-#else
-    struct timeinfo ti;
+#ifndef HAVE_GETRUSAGE
     struct tms buf;
 #endif
 
     gettimeofday(&now, &dummy_tz);
 
 #ifdef HAVE_GETRUSAGE
-    getrusage(RUSAGE_SELF, &ru);
-    ti.sys = ru.ru_stime;
-    ti.usr = ru.ru_utime;
+    getrusage(RUSAGE_SELF, &ti);
 #else
     times(&buf);
 
@@ -1237,9 +1316,7 @@
     printtime(dtime(&dtimeval, &shtimer, &now), &ti, "shell");
 
 #ifdef HAVE_GETRUSAGE
-    getrusage(RUSAGE_CHILDREN, &ru);
-    ti.sys = ru.ru_stime;
-    ti.usr = ru.ru_utime;
+    getrusage(RUSAGE_CHILDREN, &ti);
 #else
     ti.ut = buf.tms_cutime;
     ti.st = buf.tms_cstime;
Index: Src/signals.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/signals.c,v
retrieving revision 1.31
diff -u -r1.31 signals.c
--- Src/signals.c	7 Oct 2004 09:45:46 -0000	1.31
+++ Src/signals.c	8 Oct 2004 14:13:31 -0000
@@ -400,18 +400,6 @@
     return ret;
 }
 
-/* What flavor of waitpid/wait3/wait shall we use? */
- 
-#ifdef HAVE_WAITPID
-# define  WAIT(pid, statusp, options) waitpid(pid, statusp, options)
-#else
-# ifdef HAVE_WAIT3
-#  define WAIT(pid, statusp, options) wait3((void *) statusp, options, NULL)
-# else
-#  define WAIT(pid, statusp, options) wait(statusp)
-# endif
-#endif
-
 /* the signal handler */
  
 /**/
@@ -471,7 +459,25 @@
 	    int *procsubval = &cmdoutval;
 	    struct execstack *es = exstack;
 
-            pid = WAIT(-1, &status, WNOHANG|WUNTRACED);  /* reap the child process */
+	    /*
+	     * Reap the child process.
+	     * If we want usage information, we need to use wait3.
+	     */
+#ifdef HAVE_WAIT3
+# ifdef HAVE_GETRUSAGE
+	    struct rusage ru;
+
+	    pid = wait3((void *)&status, WNOHANG|WUNTRACED, &ru);
+# else
+	    pid = wait3((void *)&status, WNOHANG|WUNTRACED, NULL);
+# endif
+#else
+# ifdef HAVE_WAITPID
+	    pid = waitpid(-1, &status, WNOHANG|WUNTRACED);
+# else
+	    pid = wait(&status);
+# endif
+#endif
 
             if (!pid)  /* no more children to reap */
                 break;
@@ -504,7 +510,14 @@
 
 	    /* Find the process and job containing this pid and update it. */
 	    if (findproc(pid, &jn, &pn, 0)) {
+#if defined(HAVE_WAIT3) && defined(HAVE_GETRUSAGE)
+		struct timezone dummy_tz;
+		gettimeofday(&pn->endtime, &dummy_tz);
+		pn->status = status;
+		pn->ti = ru;
+#else
 		update_process(pn, status);
+#endif
 		update_job(jn);
 	    } else if (findproc(pid, &jn, &pn, 1)) {
 		pn->status = status;
Index: Src/zsh.h
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/zsh.h,v
retrieving revision 1.63
diff -u -r1.63 zsh.h
--- Src/zsh.h	7 Oct 2004 09:45:46 -0000	1.63
+++ Src/zsh.h	8 Oct 2004 14:13:35 -0000
@@ -740,10 +740,7 @@
 /* node in job process lists */
 
 #ifdef HAVE_GETRUSAGE
-typedef struct {
-    struct timeval sys;
-    struct timeval usr;
-} child_times_t;
+typedef struct rusage child_times_t;
 #else
 typedef struct timeinfo child_times_t;
 #endif

-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR Ltd., Science Park, Milton Road,
Cambridge, CB4 0WH, UK                          Tel: +44 (0)1223 692070


**********************************************************************
This email and any files transmitted with it are confidential and
intended solely for the use of the individual or entity to whom they
are addressed. If you have received this email in error please notify
the system manager.

This footnote also confirms that this email message has been swept by
MIMEsweeper for the presence of computer viruses.

www.mimesweeper.com
**********************************************************************