From owner-freebsd-questions@FreeBSD.ORG Tue Jan 11 11:07:10 2005 Return-Path: Delivered-To: freebsd-questions@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 036B716A4CE for ; Tue, 11 Jan 2005 11:07:10 +0000 (GMT) Received: from rosebud.otenet.gr (rosebud.otenet.gr [195.170.0.26]) by mx1.FreeBSD.org (Postfix) with ESMTP id 60E6343D49 for ; Tue, 11 Jan 2005 11:07:08 +0000 (GMT) (envelope-from keramida@ceid.upatras.gr) Received: from orion.daedalusnetworks.priv (aris.bedc.ondsl.gr [62.103.39.226])j0BB740F017698; Tue, 11 Jan 2005 13:07:04 +0200 Received: from orion.daedalusnetworks.priv (orion [127.0.0.1]) j0BB73XV003269; Tue, 11 Jan 2005 13:07:03 +0200 (EET) (envelope-from keramida@ceid.upatras.gr) Received: (from keramida@localhost)j0BB73Uq003268; Tue, 11 Jan 2005 13:07:03 +0200 (EET) (envelope-from keramida@ceid.upatras.gr) Date: Tue, 11 Jan 2005 13:07:03 +0200 From: Giorgos Keramidas To: Ulrich Spoerlein Message-ID: <20050111110703.GB1926@orion.daedalusnetworks.priv> References: <20050111094057.GA813@galgenberg.net> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20050111094057.GA813@galgenberg.net> cc: freebsd-questions@freebsd.org Subject: Re: How to reliably measure user time (getrusage(2)) X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 11 Jan 2005 11:07:10 -0000 On 2005-01-11 10:40, Ulrich Spoerlein 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 % 2 #include % 3 #include % % 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