I posted a bit ago about using PERFCTRS on SMP in the thread from
current-users and tech-smp noted in the references header. This was, as
I said, motivated because I was having trouble with getrusage(2) being
apparently useless for any benchmarking of execution time.
OK, so I've been doing a lot more experiments and code reading, and so
far all I've come up with are some weird results and more confusion.
It isn't just that getrusage() reported system and user times can seem
to go backward sometimes -- it doesn't seem reliable in any sense at
all.
The total of system and user time may be OK, but the distribution of
"real" time between them (by counting statclock ticks) seems more random
than by design, perhaps because somehow the statclock ticks are
inaccurate? I don't know -- I can't figure it out from reading the
kernel code myself since from the code it would seem to me that for
anything which chews up any significant amount of CPU time the results
should be relatively meaningful and consistent.
The attached program seems to demonstrate the problem, in part, at least
to my eyes, on both NetBSD-4 (on real hardware) and NetBSD-5 (on
VirtualBox), and it also shows that the problem does not seem to exist
on Mac OS X (10.6.8).
BTW, please send me any comments or criticisms of my test code, in
particular any related to the methodology of measuring and accounting
for execution time. I have the beginnings of a variant where I would
use fork() for each algorithm, but I haven't fleshed it out since it
seems the only benefit is getting the final whole-child-process rusage
instead of trying to use the difference between markers, and so far as I
can tell that will only protect from very tiny skips backwards that
might have happened at the point where the marker is taken. Given
sufficient iterations these differences should disappear in the noise,
no?
In particular note that the system time for each loop should be
approximately the same (one non-I/O system call per iteration), and the
user time for time() should be less than nulltime(), and all the true
function implementations of bit counting should be longer than
nulltime(), and the function wrapper count_bits() should be a bit slower
than COUNT_BITS() too I would expect.
This run on NetBSD-4, while the system was busy, but not too busy
running a NetBSD cvs update in the background, compiled using -O0:
time() = 0.3373 us/c user, 6.2696 us/c sys, 0.0182 us/c wait,
6.6251 us/c wall
nulltime() = 0.2507 us/c user, 6.1871 us/c sys, 0.0133 us/c wait,
6.4511 us/c wall
countbits_sparse() = 0.2400 us/c user, 6.0214 us/c sys, 0.0019 us/c wait,
6.2632 us/c wall
countbits_dense() = 0.2301 us/c user, 9.0277 us/c sys, 0.0161 us/c wait,
9.2739 us/c wall
COUNT_BITS() = 0.2505 us/c user, 6.8234 us/c sys, 0.0037 us/c wait,
7.0776 us/c wall
count_bits() = 0.4307 us/c user, 6.1112 us/c sys, 0.0121 us/c wait,
6.5541 us/c wall
count_ul_bits() = 0.4206 us/c user, 6.2782 us/c sys, 0.0133 us/c wait,
6.7121 us/c wall
With each run the results are completely unpredictable, and often
they're even more wacky than above!
With NetBSD-5 running on VirtualBox (on my desktop Mac) I get even
wonkier results (same static-linked binary as above, compiled on
NetBSD-4, though a native NetBSD-5 compile behaves the same):
time() = -0.0013 us/c user, 8.9611 us/c sys, 0.0005 us/c wait,
8.9604 us/c wall
nulltime() = 0.0100 us/c user, 8.8683 us/c sys, 0.0006 us/c wait,
8.8789 us/c wall
countbits_sparse() = 0.0100 us/c user, 8.9142 us/c sys, 0.0190 us/c wait,
8.9431 us/c wall
countbits_dense() = 0.0301 us/c user, 8.9428 us/c sys, 0.0007 us/c wait,
8.9736 us/c wall
COUNT_BITS() = 0.0200 us/c user, 8.9222 us/c sys, 0.0005 us/c wait,
8.9428 us/c wall
count_bits() = 0.0000 us/c user, 8.9315 us/c sys, 0.0013 us/c wait,
8.9328 us/c wall
count_ul_bits() = 0.0100 us/c user, 9.0339 us/c sys, 0.0322 us/c wait,
9.0761 us/c wall
I can understand getrusage() times going backwards a bit, but ultimately
they should catch up to be within a clock tick of reality after many
millions of clock ticks, no?
The results I get on my desktop Mac are much more consistent and
sensible, matching what I would expect from the code. Note I'm also
using -O0 here with gcc, and this run was with 20 million iterations
each:
i686-apple-darwin10-gcc-4.2.1 (GCC) 4.2.1 (Apple Inc. build 5666) (dot 3))
time() = 0.1820 us/c user, 0.0017 us/c sys, 0.0456 us/c wait,
0.2293 us/c wall
nulltime() = 0.1849 us/c user, 0.0020 us/c sys, 0.0493 us/c wait,
0.2362 us/c wall
countbits_sparse() = 0.2198 us/c user, 0.0024 us/c sys, 0.0682 us/c wait,
0.2905 us/c wall
countbits_dense() = 0.3039 us/c user, 0.0029 us/c sys, 0.0943 us/c wait,
0.4011 us/c wall
COUNT_BITS() = 0.1939 us/c user, 0.0020 us/c sys, 0.0561 us/c wait,
0.2521 us/c wall
count_bits() = 0.1968 us/c user, 0.0019 us/c sys, 0.0729 us/c wait,
0.2716 us/c wall
count_ul_bits() = 0.2629 us/c user, 0.0026 us/c sys, 0.0835 us/c wait,
0.3489 us/c wall
similarly good with clang (again with -O0):
Apple clang version 1.7 (tags/Apple/clang-77) (based on LLVM 2.9svn)
time() = 0.1796 us/c user, 0.0016 us/c sys, 0.0175 us/c wait,
0.1987 us/c wall
nulltime() = 0.1841 us/c user, 0.0014 us/c sys, 0.0185 us/c wait,
0.2040 us/c wall
countbits_sparse() = 0.2145 us/c user, 0.0019 us/c sys, 0.0308 us/c wait,
0.2472 us/c wall
countbits_dense() = 0.3065 us/c user, 0.0026 us/c sys, 0.0744 us/c wait,
0.3835 us/c wall
COUNT_BITS() = 0.1918 us/c user, 0.0016 us/c sys, 0.0407 us/c wait,
0.2341 us/c wall
count_bits() = 0.1961 us/c user, 0.0018 us/c sys, 0.0929 us/c wait,
0.2907 us/c wall
count_ul_bits() = 0.2548 us/c user, 0.0029 us/c sys, 0.1576 us/c wait,
0.4153 us/c wall
Interestingly, totally as an aside, with clang -O3 the differences in
the algorithms are so far in the noise as to be invisible, and it's
almost as if the compiler recognised every one of my functions and just
did something magic instead:
tcountbits: now running each algorithm for 30000000 iterations....
time() = 0.1782 us/c user, 0.0010 us/c sys, 0.0059 us/c wait,
0.1851 us/c wall
nulltime() = 0.1782 us/c user, 0.0011 us/c sys, 0.0057 us/c wait,
0.1850 us/c wall
countbits_sparse() = 0.1782 us/c user, 0.0010 us/c sys, 0.0073 us/c wait,
0.1864 us/c wall
countbits_dense() = 0.1782 us/c user, 0.0011 us/c sys, 0.0058 us/c wait,
0.1852 us/c wall
COUNT_BITS() = 0.1782 us/c user, 0.0011 us/c sys, 0.0051 us/c wait,
0.1844 us/c wall
count_bits() = 0.1782 us/c user, 0.0010 us/c sys, 0.0076 us/c wait,
0.1869 us/c wall
count_ul_bits() = 0.1782 us/c user, 0.0011 us/c sys, 0.0073 us/c wait,
0.1866 us/c wall
I want to try using OS X's mach_absolute_time() on my Mac instead of
gettimeofday(), and perhaps also in parallel to getrusage() since on OS
X the gettimeofday() calls to seed the values are done without context
switches (due to the magic of OS X's COMMPAGE) and thus I think I can
safely assume that there will be approximately no measurable system time
used for each iteration. That might give me reliable timing of each
algorithm to compare with getrusage().
I have also already looked at gprof(1) results to compare here as well,
but use of gprof(1) isn't always possible, and it doesn't necessarily
meet the same needs either -- sometimes "time -l" is all you've got, and
that means one must be able to trust getrusage() to give reproducible
results.
--
Greg A. Woods
Planix, Inc.
<woods%planix.com@localhost> +1 250 762-7675 http://www.planix.com/
#include <sys/cdefs.h>
#include <sys/types.h>
#include <sys/resource.h>
#include <sys/time.h>
#include <err.h>
#include <errno.h>
#include <limits.h>
#include <stdbool.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sysexits.h>
#include <unistd.h>
/*
* WARNING: time can appear to have gone backwards with getrusage(2)!
*
* See NetBSD Problem Report #30115 (and PR#10201).
* See FreeBSD Problem Report #975 (and PR#10402).
*
* Problem has existed in all *BSDs since 4.4BSD if not earlier.
*
* Only FreeBSD has implemented a "fix" (as of rev.1.45 (svn r44725) of
* kern_resource.c (etc.) on April 13, 1999)
*
* But maybe it is even worse than that -- distribution of time between user
* and system doesn't seem to match reality!
*
* See the GNU MP Library (GMP)'s tune/time.c code for better timing?
*/
#if defined(__APPLE__)
# define MILLIONS 10 /* my mac is way faster! :-) */
#else
# define MILLIONS 1
#endif
static unsigned int iter = MILLIONS * 1000000UL;
char *argv0 = "progname";
/*
* for info about the worker algorithms used here see:
* <URL:http://graphics.stanford.edu/~seander/bithacks.html>
*/
/*
* do nothing much, but make sure you do it!
*/
unsigned int nullfunc(unsigned long);
unsigned int
nullfunc(unsigned long v)
{
volatile unsigned int bc = (unsigned int) v;
return bc;
}
/*
* return the number of bits set to one in a value
*
* old-fashioned bit-by-bit bit-twiddling.... very slow!
*/
unsigned int count_ul_bits(unsigned long);
unsigned int
count_ul_bits(unsigned long v)
{
unsigned int c;
c = 0;
/*
* we optimize away any high-order zero'd bits...
*/
while (v) {
c += (v & 1);
v >>= 1;
}
return c;
}
/*
* return the number of bits set to one in a value
*
* Subtraction of 1 from a number toggles all the bits (from right to left) up
* to and including the righmost set bit.
*
* So, if we decrement a number by 1 and do a bitwise and (&) with itself
* ((n-1) & n), we will clear the righmost set bit in the number.
*
* Therefore if we do this in a loop and count the number of iterations then we
* get the count of set bits.
*
* Executes in O(n) operations where n is number bits set to one in a given
* integer value.
*/
unsigned int countbits_sparse(unsigned long);
unsigned int
countbits_sparse(unsigned long v)
{
volatile unsigned int bc = 0;
while (v) {
v &= v - 1; /* clear the least significant bit set to one */
bc++;
}
return bc;
}
unsigned int countbits_dense(unsigned long);
unsigned int
countbits_dense(unsigned long v)
{
volatile unsigned int bc = sizeof(v) * CHAR_BIT;
v ^= (unsigned long) -1;
while (v) {
v &= v - 1; /* clear the least significant bit set to one */
bc--;
}
return bc;
}
/*
* most efficient non-lookup variant from the URL above....
*/
#define COUNT_BITS(T, x, c)
\
{
\
T n = (x);
\
\
n = n - ((n >> 1) & (T)~(T)0/3);
\
n = (n & (T)~(T)0/15*3) + ((n >> 2) & (T)~(T)0/15*3);
\
n = (n + (n >> 4)) & (T)~(T)0/255*15;
\
c = (T)(n * ((T)~(T)0/255)) >> (sizeof(T) - 1) * CHAR_BIT;
\
}
\
unsigned int count_bits(unsigned long);
unsigned int
count_bits(unsigned long v)
{
volatile unsigned int c;
COUNT_BITS(unsigned long, v, c)
return c;
}
#define MAX_STRLEN_OCTAL(t) ((int) ((sizeof(t) * CHAR_BIT / 3) + 2))
/* XXX see also timevalsub() */
suseconds_t difftval(struct timeval, struct timeval);
suseconds_t
difftval(struct timeval tstart, struct timeval tend)
{
tend.tv_sec -= tstart.tv_sec;
tend.tv_usec -= tstart.tv_usec;
while (tend.tv_usec < 0) {
tend.tv_sec--;
tend.tv_usec += 1000000;
}
while (tend.tv_usec >= 1000000) {
tend.tv_sec++;
tend.tv_usec -= 1000000;
}
return (suseconds_t) ((tend.tv_sec * 1000000) + tend.tv_usec);
}
suseconds_t microtime(void);
/*
* microtime() - return number of microseconds since some epoch
*
* the particular epoch is irrelevant -- we just use the difference between two
* of these samples taken sufficiently far appart enough that the resolution is
* also relatively unimportant, though better than 1 second is expected....
*/
#ifdef CLOCK_MONOTONIC
suseconds_t
microtime()
{
struct timespec tsnow;
(void) clock_gettime(CLOCK_MONOTONIC, &tsnow);
return (suseconds_t) ((tsnow.tv_sec * 1000000) + (tsnow.tv_nsec /
1000));
}
#else /* !CLOCK_MONOTONIC */
/*
* XXX this is currently for Darwin/Mac OS X, which does not implement the
* POSIX (IEEE Std 1003.1b-1993) clock_gettime() API
*
* Note that on OS X the gettimeofday() function is implemented in libc as a
* wrapper to either the _commpage_gettimeofday() function, if available, or
* the normal system call. If using the COMMPAGE helper then gettimeofday()
* simply returns the value stored in the COMMPAGE and thus can execute without
* a context switch.
*/
suseconds_t
microtime()
{
struct timeval tvnow;
(void) gettimeofday(&tvnow, (void *) NULL);
return (suseconds_t) ((tvnow.tv_sec * 1000000) + tvnow.tv_usec);
}
#endif /* CLOCK_MONOTONIC */
void show_time(char *, suseconds_t, suseconds_t, suseconds_t);
void
show_time(char *fname, suseconds_t us_u, suseconds_t us_s, suseconds_t us_c)
{
suseconds_t us_w = (us_c - (us_s + us_u));
double pc_u = (double) us_u / (double) iter ;
double pc_s = (double) us_s / (double) iter ;
double pc_w = (double) us_w / (double) iter ;
double pc_c = (double) us_c / (double) iter ;
/*
* note in the calculation of us_w above that wall clock elapsed time
* (us_c) is expected to be longer than the sum of user (us_u) and
* system (us_s) time, and we will display the difference as "wait"
* time, suggesting the amount of time the process was waiting for the
* CPU (shown here per call)
*/
printf("%18s = %5.4f us/c user, %7.4f us/c sys, %5.4f us/c wait, %7.4f
us/c wall\n",
fname,
pc_u,
pc_s,
pc_w,
pc_c);
}
void usage(void) __dead;
void
usage()
{
fprintf(stderr, "Usage: %s [-t] [-i millions_of_iterations]\n", argv0);
fprintf(stderr, "-t: don't run the verbose proof of concept test --
just do timing runs");
fprintf(stderr, "(default iterations: %lu * 10^6)\n", iter / 1000000UL);
exit(EX_USAGE);
}
bool dotest = true;
extern char *optarg;
extern int optind;
extern int optopt;
extern int opterr;
extern int optreset;
int main(int, char *[]);
int
main(int argc, char *argv[])
{
int ch;
size_t i;
struct rusage rus;
struct rusage ruf;
#ifdef CLOCK_MONOTONIC
struct timespec res;
#endif
suseconds_t nulltime_u;
suseconds_t nulltime_s;
suseconds_t nulltime_w;
suseconds_t timetime_u;
suseconds_t timetime_s;
suseconds_t timetime_w;
suseconds_t totaltime_u;
suseconds_t totaltime_s;
suseconds_t totaltime_w;
argv0 = (argv0 = strrchr(argv[0], '/')) ? argv0 + 1 : argv[0];
optind = 1; /* Start options parsing */
opterr = 0; /* I'll print my own errors! */
while ((ch = getopt(argc, argv, ":hi:t")) != -1) {
long ltmp;
char *ep;
switch (ch) {
case 'i':
/*
* extremely pedantic parameter evaluation
*/
errno = 0;
ltmp = strtol(optarg, &ep, 0);
if (ep == optarg) {
err(EX_USAGE,
"-%c param of '%s' is not a valid number",
optopt,
optarg);
}
if (*ep) {
err(EX_USAGE,
"-%c param of '%s' has unsupported trailing
unit specification characters",
optopt,
optarg);
}
if (errno != 0) {
err(EX_USAGE,
"-%c param of '%s' is not convertible: %s",
optopt,
optarg,
strerror(errno));
}
if (ltmp > INT_MAX) {
err(EX_USAGE,
"-%c param of %ld is too large (must be <=
%d)",
optopt,
ltmp,
INT_MAX);
}
if (ltmp < 1) {
err(EX_USAGE,
"-%c param of %ld is too small (must be >
0)",
optopt,
ltmp);
}
iter = (unsigned int) ltmp * 1000000UL;
break;
case 't':
dotest = false;
break;
case 'h':
usage();
case '?':
warnx("unknown option -- '%c'", optopt);
usage();
case ':':
/*
* NOTE: a leading ':' in optstring causes getopt() to
* return a ':' when an option is missing its parameter.
*/
warnx("missing parameter for -%c", optopt);
usage();
default:
warnx("programming error, unhandled flag: %c", ch);
abort();
}
}
argc -= optind;
argv += optind;
if (argc) {
usage();
}
/* show that they all work.... */
for (i = (dotest ? 1 : INT_MAX); i < (sizeof(unsigned long) *
CHAR_BIT); i++) {
unsigned long v = 1UL << i;
unsigned int c;
COUNT_BITS(unsigned long, v/2+1, c)
printf("%#-*lo (v/2+1) = %d, %d, %d, %d\n",
MAX_STRLEN_OCTAL(typeof(v)),
v/2+1, countbits_sparse(v/2+1), countbits_dense(v/2+1),
count_ul_bits(v/2+1), c);
COUNT_BITS(unsigned long, v-2, c)
printf("%#-*lo (v-2) = %d, %d, %d, %d\n",
MAX_STRLEN_OCTAL(typeof(v)),
v-2, countbits_sparse(v-2), countbits_dense(v-2),
count_ul_bits(v-2), c);
COUNT_BITS(unsigned long, v-1, c)
printf("%#-*lo (v-1) = %d, %d, %d, %d\n",
MAX_STRLEN_OCTAL(typeof(v)),
v-1, countbits_sparse(v-1), countbits_dense(v-1),
count_ul_bits(v-1), c);
COUNT_BITS(unsigned long, v, c)
printf("%#-*lo (%2d bits) = %d, %d, %d, %d\n",
MAX_STRLEN_OCTAL(typeof(v)),
v, (int) i, countbits_sparse(v), countbits_dense(v),
count_ul_bits(v), c);
puts("--------");
}
#ifdef CLOCK_MONOTONIC
/* XXX "#ifdef CLOCK_PROCESS_CPUTIME_ID"??? */
if (clock_getres(CLOCK_MONOTONIC, &res) == -1) {
err(EXIT_FAILURE, "clock_getres(CLOCK_MONOTONIC)");
}
warnx("using CLOCK_MONOTONIC timer with resolution: %ld s, %ld ns",
res.tv_sec, res.tv_nsec);
#endif
warnx("now running each algorithm for %u iterations....", iter);
/*
* Timing anomalies
*
* time(1) uses gettimeofday() to show the "real" time, by which it
* means the wall-clock time it took to run the process, including the
* time to do the vfork() and execvp(), ignore some signals, and call
* wait4().
*
* However currently on NetBSD we can see getrusage() report a total of
* system plus user time of as much as 0.06 seconds longer than
* gettimeofay() says it took for the whole thing! E.g.:
*
* $ /usr/bin/time -p false
* real 0.00
* user 0.03
* sys 0.03
*
* Furthermore gettimeofday() can wander, e.g. due to NTP, or worse.
*
* Use clock_gettime(CLOCK_MONOTONIC, tspec) instead if possible!
*
* We also see from below that getrusage() can report _RADICALLY_
* different amounts of both _user_ time and system time for the exact
* same code to run!
*/
/* time time() */
timetime_w = microtime();
getrusage(RUSAGE_SELF, &rus);
for (i = 0; i < iter; i++) {
(void) time((time_t *) NULL);
}
getrusage(RUSAGE_SELF, &ruf);
timetime_w = microtime() - timetime_w;
timetime_u = difftval(rus.ru_utime, ruf.ru_utime);
timetime_s = difftval(rus.ru_stime, ruf.ru_stime);
show_time("time()", timetime_u, timetime_s, timetime_w);
/* time nullfunc() */
nulltime_w = microtime();
getrusage(RUSAGE_SELF, &rus);
for (i = 0; i < iter; i++) {
nullfunc((unsigned long) time((time_t *) NULL));
}
getrusage(RUSAGE_SELF, &ruf);
nulltime_w = microtime() - nulltime_w;
nulltime_u = difftval(rus.ru_utime, ruf.ru_utime);
nulltime_s = difftval(rus.ru_stime, ruf.ru_stime);
show_time("nulltime()", nulltime_u, nulltime_s, nulltime_w);
/* note: leave nulltime_* as sum of nullfunc() time and time() time */
/* time countbits_sparse() */
totaltime_w = microtime();
getrusage(RUSAGE_SELF, &rus);
for (i = 0; i < iter; i++) {
countbits_sparse((unsigned long) time((time_t *) NULL));
}
getrusage(RUSAGE_SELF, &ruf);
totaltime_w = microtime() - totaltime_w;
totaltime_u = difftval(rus.ru_utime, ruf.ru_utime);
totaltime_s = difftval(rus.ru_stime, ruf.ru_stime);
show_time("countbits_sparse()", totaltime_u, totaltime_s, totaltime_w);
/* time countbits_dense() */
totaltime_w = microtime();
getrusage(RUSAGE_SELF, &rus);
for (i = 0; i < iter; i++) {
countbits_dense((unsigned long) time((time_t *) NULL));
}
getrusage(RUSAGE_SELF, &ruf);
totaltime_w = microtime() - totaltime_w;
totaltime_u = difftval(rus.ru_utime, ruf.ru_utime);
totaltime_s = difftval(rus.ru_stime, ruf.ru_stime);
show_time("countbits_dense()", totaltime_u, totaltime_s, totaltime_w);
/* time COUNT_BITS() */
totaltime_w = microtime();
getrusage(RUSAGE_SELF, &rus);
for (i = 0; i < iter; i++) {
unsigned int c;
COUNT_BITS(unsigned long, (unsigned long) time((time_t *)
NULL), c)
}
getrusage(RUSAGE_SELF, &ruf);
totaltime_w = microtime() - totaltime_w;
totaltime_u = difftval(rus.ru_utime, ruf.ru_utime);
totaltime_s = difftval(rus.ru_stime, ruf.ru_stime);
show_time("COUNT_BITS()", totaltime_u, totaltime_s, totaltime_w);
/* time count_bits() */
totaltime_w = microtime();
getrusage(RUSAGE_SELF, &rus);
for (i = 0; i < iter; i++) {
count_bits((unsigned long) time((time_t *) NULL));
}
getrusage(RUSAGE_SELF, &ruf);
totaltime_w = microtime() - totaltime_w;
totaltime_u = difftval(rus.ru_utime, ruf.ru_utime);
totaltime_s = difftval(rus.ru_stime, ruf.ru_stime);
show_time("count_bits()", totaltime_u, totaltime_s, totaltime_w);
/* time count_ul_bits() */
totaltime_w = microtime();
getrusage(RUSAGE_SELF, &rus);
for (i = 0; i < iter; i++) {
count_ul_bits((unsigned long) time((time_t *) NULL));
}
getrusage(RUSAGE_SELF, &ruf);
totaltime_w = microtime() - totaltime_w;
totaltime_u = difftval(rus.ru_utime, ruf.ru_utime);
totaltime_s = difftval(rus.ru_stime, ruf.ru_stime);
show_time("count_ul_bits()", totaltime_u, totaltime_s, totaltime_w);
exit(0);
}
Attachment:
pgpDyH0drbMXg.pgp
Description: PGP signature