From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 2558 invoked from network); 7 Oct 2004 01:44:47 -0000 Received: from ns2.primenet.com.au (HELO primenet.com.au) (?psSPkqt+fIeRFmSKHL14+x5azIWbrl6j?@203.24.36.3) by ns1.primenet.com.au with SMTP; 7 Oct 2004 01:44:47 -0000 Received: (qmail 6523 invoked from network); 6 Oct 2004 17:07:37 -0000 Received: from news.dotsrc.org (HELO a.mx.sunsite.dk) (130.225.247.88) by proxy.melb.primenet.com.au with SMTP; 6 Oct 2004 17:07:37 -0000 Received: (qmail 94014 invoked from network); 6 Oct 2004 17:06:32 -0000 Received: from sunsite.dk (130.225.247.90) by a.mx.sunsite.dk with SMTP; 6 Oct 2004 17:06:32 -0000 Received: (qmail 5707 invoked by alias); 6 Oct 2004 17:06:28 -0000 Mailing-List: contact zsh-workers-help@sunsite.dk; run by ezmlm Precedence: bulk X-No-Archive: yes X-Seq: 20462 Received: (qmail 5689 invoked from network); 6 Oct 2004 17:06:27 -0000 Received: from news.dotsrc.org (HELO a.mx.sunsite.dk) (130.225.247.88) by sunsite.dk with SMTP; 6 Oct 2004 17:06:27 -0000 Received: (qmail 93707 invoked from network); 6 Oct 2004 17:06:27 -0000 Received: from lhuumrelay3.lnd.ops.eu.uu.net (62.189.58.19) by a.mx.sunsite.dk with SMTP; 6 Oct 2004 17:06:25 -0000 Received: from MAILSWEEPER01.csr.com (mailhost1.csr.com [62.189.183.235]) by lhuumrelay3.lnd.ops.eu.uu.net (8.11.0/8.11.0) with ESMTP id i96H6Ov15570 for ; Wed, 6 Oct 2004 17:06:24 GMT Received: from EXCHANGE02.csr.com (unverified [192.168.137.45]) by MAILSWEEPER01.csr.com (Content Technologies SMTPRS 4.3.12) with ESMTP id for ; Wed, 6 Oct 2004 18:05:23 +0100 Received: from news01.csr.com ([192.168.143.38]) by EXCHANGE02.csr.com with Microsoft SMTPSVC(5.0.2195.6713); Wed, 6 Oct 2004 18:08:35 +0100 Received: from news01.csr.com (localhost.localdomain [127.0.0.1]) by news01.csr.com (8.12.11/8.12.11) with ESMTP id i96H6Lx6010318 for ; Wed, 6 Oct 2004 18:06:22 +0100 Received: from csr.com (pws@localhost) by news01.csr.com (8.12.11/8.12.11/Submit) with ESMTP id i96H6LTO010315 for ; Wed, 6 Oct 2004 18:06:21 +0100 Message-Id: <200410061706.i96H6LTO010315@news01.csr.com> X-Authentication-Warning: news01.csr.com: pws owned process doing -bs To: zsh-workers@sunsite.dk Subject: Re: bug with for and time In-reply-to: <20041006134818.089f5218@buddha.localdomain.de> References: <41616CDC.8020701@codesourcery.com> <200410041610.i94GAl92005952@news01.csr.com> <20041005113848.6f3715bd@buddha.localdomain.de> <20041005181820.GC30419@dan.emsphone.com> <20041006134818.089f5218@buddha.localdomain.de> Date: Wed, 06 Oct 2004 18:06:20 +0100 From: Peter Stephenson X-OriginalArrivalTime: 06 Oct 2004 17:08:35.0626 (UTC) FILETIME=[1D9370A0:01C4ABC7] X-Spam-Checker-Version: SpamAssassin 2.63 on a.mx.sunsite.dk X-Spam-Level: X-Spam-Status: No, hits=0.0 required=6.0 tests=none autolearn=no version=2.63 X-Spam-Hits: 0.0 > 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 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 **********************************************************************