Zsh Mailing List Archive
Messages sorted by: Reverse Date, Date, Thread, Author

Re: bug with for and time

> 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@xxxxxxx>                  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
**********************************************************************
Messages sorted by: Reverse Date, Date, Thread, Author