How to reliably measure user time (getrusage(2))

[Giorgos Keramidas]

On 2005-01-11 10:40, Ulrich Spoerlein <q at uni.de> wrote:
> Hi all,
>
> I need to measure the time spent in user mode for rather short-lived
> processes. Sadly the results vary highly
>
> % while true;do \time -p woptsa tsplib/pla7397/pla7397.tsp 2>&1|sed -n /user/p;done
> user 1.13
> user 0.67
> user 0.65
> user 0.65
> user 0.64
> user 0.65

The first time is the one that varies.  This is usually normal, since
the system hasn't loaded the program's image in memory and is taking the
penalty of reading from slow media (i.e. a disk).

> % while true;do \time -p woptsa tsplib/pla7397/pla7397.tsp 2>&1|sed -n /user/p;sleep 1;done
> user 1.22
> user 0.87
> user 0.75
> user 0.67
> user 0.86
> user 0.74

Same here.

> % while true;do \time -p woptsa tsplib/pla7397/pla7397.tsp 2>&1|sed -n /user/p;sleep 3;done
> user 1.24
> user 1.23
> user 1.27
> user 1.27
> user 1.10
> user 1.19

The load of a system is constantly changing.  The fact that you have
observed larger times by running exactly the same program multiple times
may be an effect of an increase in the system load.

> I fail to see how sleeping or waiting between consecutive runs could
> affect user time.

Other processes get more time to load and start doing their own things
more often.  If those other processes fill up the buffer cache so much
that your program image gets pushed out of it, you constantly take the
penalty of reloading the program from disk.

> Everything from page faults to I/O is handled inside the kernel, so it
> shouldn't affect user-time, no?

Unless, of course, the program has to wait for I/O operations and
changes its behavior depending on user data.  The following program is
CPU-bound and *does* run within a pretty stable user time period:

% orion:/tmp/foo$ nl foo.c
%      1  #include <err.h>
%      2  #include <stdlib.h>
%      3  #include <strings.h>
%
%      4  #define BUFLEN  8192
%      5  #define RUNS    (1024 * 1024)
%
%      6  int
%      7  main(void)
%      8  {
%      9          char *p;
%     10          int k;
%
%     11          p = malloc(BUFLEN * sizeof(char));
%     12          if (p == NULL)
%     13                  err(1, "malloc");
%
%     14          for (k = 0; k < RUNS; k++)
%     15                  bzero(p, BUFLEN);
%     16          return (0);
%     17  }
%
% orion:/tmp/foo$ for count in $(jot 10 1 10); do
%     ( time -p ./foo ) 2>&1 | sed -n /user/p ; done | tslog
% 2005-01-11 11:04:20 - user 0.97
% 2005-01-11 11:04:21 - user 0.97
% 2005-01-11 11:04:22 - user 0.97
% 2005-01-11 11:04:23 - user 0.97
% 2005-01-11 11:04:24 - user 0.97
% 2005-01-11 11:04:25 - user 0.97
% 2005-01-11 11:04:26 - user 0.97
% 2005-01-11 11:04:27 - user 0.97
% 2005-01-11 11:04:28 - user 0.97
% 2005-01-11 11:04:29 - user 0.97