Date: Wed, 31 Mar 2004 00:30:04 -0800 (PST) From: Chris Landauer <cal@rush.aero.org> To: freebsd-questions@freebsd.org Cc: cal@rush.aero.org Subject: /usr/bin/time and time errors (longish - 250 lines) Message-ID: <200403310830.i2V8U4887541@calamari.aero.org>
next in thread | raw e-mail | index | archive | help
hihi, all -
some while ago i asked about the wraparound properties of 'time' when running
long programs (the user cpu time seems to wrap after just under week), and the
experimental results are finally in
these programs seem to use a struct timeval, which has two longs, one for
seconds and one for microseconds (why are they not unsigned longs?), and the
seconds should not wrap for almost 50 days
another suggestion was to use /use/bin/time, which also uses struct timeval's
ok, well, both time and /usr/bin/time have the same problem - i wrote a busy
loop with intermediate (hourly) time reporting, and ran it on three different
freebsd machines that were otherwise unused, for about 170 hours of elapsed
time each (the difference in machine speeds only affects how many cycles of
the busy loop are executed in a given amount of time, not whether or not the
measured times are correct) - i've included the source code i used at the end
of this message (which is why it's pretty long), in case anyone can explain
what happened (i compiled it with gcc -o ts timetest.c)
the time measurements failed in the same way on all three machines - both time
and /usr/bin/time failed in the same way
failure point
machine started elapsed time ~ cpu time
olivia 03/23 11:26:26 107h ~ 377381.612089
calamari 03/23 17:13:21 107h ~ 378169.410382
endeavor 03/23 21:04:22 108h ~ 378719.759847
the cause of the failure is the same in all three cases; rusage stops being
updated, at about the same time - the data follows
more later,
cal
Dr. Christopher Landauer
Aerospace Integration Science Center
cal@aero.org
====
olivia 4.8-RELEASE (GENERIC) 1.8GHz P4, 1GB, gcc 3.2.2
command used to start the program (from csh)
time ts
output from program ts
...
2004/03/27 20:26:26 105, 370325.340004 sec, 97.9697%
2004/03/27 21:26:26 106, 373853.584012 sec, 97.9700%
2004/03/27 22:26:26 107, 377381.612089 sec, 97.9703%
2004/03/27 23:26:26 108, 377381.612089 sec, 97.0632%
...
2004/03/30 13:26:26 170, 377381.612089 sec, 61.6637%
kill -1 <pid> gave (after the last hourly line above)
377381.612u 10200.791s 170:17:08.00 63.2% 7+-46k 0+0io 0pf+0w
====
calamari 4.4-RELEASE (GENERIC) 1GHz P3, 512MB, gcc 2.95.3
command used to start the program (from csh)
/usr/bin/time -h ts
output from program ts
...
2004/03/28 02:13:21 105, 371105.844439 sec, 98.1761%
2004/03/28 03:13:21 106, 374630.579263 sec, 98.1736%
2004/03/28 04:13:21 107, 378169.410382 sec, 98.1748%
2004/03/28 05:13:21 108, 378169.410382 sec, 97.2658%
...
2004/03/30 19:13:21 170, 378169.410382 sec, 61.7924%
kill -1 <pid> gave (after the last hourly line above)
7d2h50m52.83s real 4d9h2m49.41s user 17h39m58.57s sys
(this is 615052.83) (this is 378169.41) (this is 63598.57)
378169.410u 63598.581s 170:50:52.84 71.8% 7+-39k 0+0io 0pf+0w
====
endeavor 5.1-RELEASE (GENERIC) 700 MHz P3, 512MB, gcc 3.2.2
command used to start the program (from csh)
time ts
output from program ts
...
2004/03/28 06:04:22 105, 368174.955995 sec, 97.4008%
2004/03/28 07:04:22 106, 371689.784981 sec, 97.4030%
2004/03/28 08:04:22 107, 375204.700310 sec, 97.4052%
2004/03/28 09:04:22 108, 378719.759847 sec, 97.4073%
2004/03/28 10:04:22 109, 378719.759847 sec, 96.5137%
...
2004/03/30 23:04:22 170, 378719.759847 sec, 61.8823%
kill -1 <pid> gave (after the last hourly line above)
378719.759u 218842.331s 170:31:54.69 97.3% 5+35k 0+0io 0pf+0w
================
/*
file timetest.c
test time computation
created 10:45-11:25 PST, 23 March 2004 at olivia
*/
#define timetest main
#include <stdio.h>
#include <signal.h>
#include <sys/types.h>
#include <sys/time.h>
#include <sys/resource.h>
/* interrupt handler */
static void erupt(int sig);
/* time itnerval structure */
static struct itimerval interval;
/* check intervals */
#define TEN_SEC 10
#define ONE_MIN 60
#define TEN_MIN 600
#define ONE_HOUR 3600
#define TEN_HOUR 36000
/* check interval to use */
static int check_interval = 0;
/* check interval flag */
static int check = 0;
/* check interval count */
static int check_times = 0;
/* continue flag */
static int go = 1;
int
timetest()
{
/* run one test */
int a = 0;
struct rusage rusage_out;
struct timeval time_out;
double time_cpu;
double time_lps;
struct tm * tm;
time_t t;
/* get actual time */
t = time(NULL);
tm = localtime(& t);
printf("%d/%02d/%02d %02d:%02d:%02d\t", 1900+tm->tm_year, tm->tm_mon+1, tm->tm_mday, tm->tm_hour, tm->tm_min, tm->tm_sec);
printf("%d\n", check_times);
fflush(stdout);
/* set check interval */
check_interval = TEN_SEC;
check_interval = ONE_MIN;
check_interval = TEN_MIN;
check_interval = TEN_HOUR;
check_interval = ONE_HOUR;
/* set up signal handlers */
(void) signal(SIGHUP, erupt);
(void) signal(SIGINT, erupt);
(void) signal(SIGALRM, erupt);
/* set interval timer values */
interval.it_interval.tv_sec = check_interval;
interval.it_interval.tv_usec = 0;
interval.it_value = interval.it_interval;
/* set up alarm interval */
(void) setitimer(ITIMER_REAL, & interval, NULL);
/* start the busy loop */
while(go)
{
/* check for something to do */
if (check)
{
/* count check time */
check_times++;
/* reset check flag */
check = 0;
/* get resource usage */
(void) getrusage(RUSAGE_SELF, & rusage_out);
/* get user time */
time_out = rusage_out.ru_utime;
/* compute user cpu time */
time_cpu = time_out.tv_usec / 1000000.0;
time_cpu += time_out.tv_sec;
/* compute approximate elapsed time */
time_lps = check_times * check_interval;
/* get actual time */
t = time(NULL);
tm = localtime(& t);
printf("%d/%02d/%02d %02d:%02d:%02d\t", 1900+tm->tm_year, tm->tm_mon+1, tm->tm_mday, tm->tm_hour, tm->tm_min, tm->tm_sec);
/* print the time */
printf("%d, %lu.%06lu sec, %.4f%%\n", check_times, time_out.tv_sec, time_out.tv_usec, 100.0 * time_cpu / time_lps);
fflush(stdout);
}
/* don't do very much else here */
a++;
}
printf("\n");
exit(0);
/* end of function timetest() */
}
static void
erupt(int sig)
{
/* interrupt handler */
/* set interrupt flag */
if (sig == SIGHUP)
{
go = 0;
}
else
if (sig == SIGINT)
{
go = 0;
}
else
if (sig == SIGALRM)
{
check = 1;
}
/* ignore the interrupt for now */
/* end of function erupt() */
}
/* end of file timetest.c */
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200403310830.i2V8U4887541>