time builtin

time builtin

[Goran Larsson]

I just observed this broken behaviour in 3.0.0 and 3.1.0.
The real time reported by builtin time (%E) is almost
always less than %U + %S. A quick test shows that this
behaviour is not present in 2.6-beta13.

Now printtime() in 2.6-beta13 had this code:

    if (percent > 100)
        percent = 100;   /* just to make it look right */

but that was removed in 3.0.0. Reinserting those two lines
in 3.0.0 obviously ``fixes'' the problem, or perhaps it is
more accurate to say that it hides the real problem again.

Is it possible to fix this, or are the times here just to
close to the resolution provided by the kernel?

$ echo $ZSH_VERSION
3.0.0
$ echo $OSTYPE
sunos4.1.4
$ echo $TIMEFMT
%*E real  %*U user  %*S system  %P (%J)
$ 
$ time ls
adapter.gif     hpdat
0.048 real  0.017 user  0.033 system  103% (ls)
adapter.gif     hpdat
$ time ls
adapter.gif     hpdat
0.001 real  0.000 user  0.017 system  2810% (ls)
$ time ls
adapter.gif     hpdat
0.048 real  0.017 user  0.033 system  103% (ls)
$ time ls
adapter.gif     hpdat
0.001 real  0.017 user  0.000 system  2692% (ls)
$ time ls
adapter.gif     hpdat
0.021 real  0.033 user  0.017 system  236% (ls)
$ time ls
adapter.gif     hpdat
0.001 real  0.000 user  0.033 system  5555% (ls)
$ time ls
adapter.gif     hpdat
0.035 real  0.000 user  0.033 system  93% (ls)
$ time ls
adapter.gif     hpdat
0.001 real  0.000 user  0.017 system  2741% (ls)
$ 

-- 
 Goran Larsson                mailto:hoh @ approve . se
 I was an atheist,            http://home1.swipnet . se/%7Ew-12153/
 until I found out I was God.

Re: time builtin

[Zoltan Hidvegi]

Goran Larsson wrote:
> Now printtime() in 2.6-beta13 had this code:
> 
>     if (percent > 100)
>         percent = 100;   /* just to make it look right */
> 
> but that was removed in 3.0.0. Reinserting those two lines
> in 3.0.0 obviously ``fixes'' the problem, or perhaps it is
> more accurate to say that it hides the real problem again.
> 
> Is it possible to fix this, or are the times here just to
> close to the resolution provided by the kernel?

Perhaps.  Or it may be a kernel bug.  Solaris has one.  Try the program
below.  It prints three time lines, and the last two shoud be the same.
That's not the case on Solaris.

What happens:

A forks B, B forks C and exits.  C consumes CPU time then exits.  This is
accounted for A but A does not receive the child signal when C dies so it
siply accounts this time to its next child.

Zoltan


#include <unistd.h>
#include <sys/types.h>
#include <signal.h>
#include <sys/wait.h>
#include <sys/times.h>
#include <stdio.h>

void
printsig(int signum)
{
    printf("Received signal %d\n", signum);
}

void
install_handler(int sig, void (*handler)(int))
{
    struct sigaction act;
 
    act.sa_handler = handler;
    sigemptyset(&act.sa_mask);        /* only block sig while in handler */
    act.sa_flags = 0;
    sigaction(sig, &act, (struct sigaction *)NULL);
}

int
main(int argc, char *argv[])
{
    pid_t ppid = getpid();
    pid_t pid, wpid;
    int status;
    struct tms tms;
    double clktck = sysconf(_SC_CLK_TCK);

    pid = fork();
    if (pid < 0) {
	perror(argv[0]);
	exit(1);
    } else if (!pid) {
	int i;

	if (fork())
	    exit(0);
	for (i = 100000000; i--;);
	kill(ppid, SIGUSR1);
	exit(1);
    }
    install_handler(SIGUSR1, printsig);
    install_handler(SIGCHLD, printsig);
    while ((wpid = wait(&status)) == -1)
	perror(argv[0]);
    if (wpid != pid) {
	fprintf(stderr, "%s: unknown child: %d instead of %d.\n",
		argv[0], (int) wpid, (int) pid);
	exit(1);
    }
    times(&tms);
    printf("%.2fs system, %.2fs user\n",
	   tms.tms_cstime / clktck, tms.tms_cutime / clktck);
    pause();
    times(&tms);
    printf("%.2fs system, %.2fs user\n",
	   tms.tms_cstime / clktck, tms.tms_cutime / clktck);
    sleep(2);
    times(&tms);
    printf("%.2fs system, %.2fs user\n",
	   tms.tms_cstime / clktck, tms.tms_cutime / clktck);
    exit(0);
}