views:

46

answers:

3

Hi,

i am measuring physical time between two events like this:

#include <time.h>
#include <sys/time.h>

timeval wall_time0;
timeval wall_time1;

// start of period measurement
gettimeofday( &wall_time0 , 0);

...stuff happening 

// end of period measurement
gettimeofday( &wall_time1 , 0);

return ( ( wall_time1.tv_sec - wall_time0.tv_sec ) + (( wall_time1.tv_usec - wall_time0.tv_usec )/(double)1000000) );

But now, i need a way to measure the logical time that the thread is actually using. That is, in theory that should be the physical time, less the time spent running other threads and/or system & kernel logic.

I thought this was the way to do it:

clock_t mTime0;
clock_t mTime1;

//start of period measurement
mTime0=clock();

... stuff happening


//end of period measurement
mTime1=clock();
return (mTime1-mTime0)/(double)CLOCKS_PER_SEC;

but doing a few measurements, i noticed two problems:

1) for some measurements it is bigger than physical time, which is not right (i.e: for certain loop, physical time would be 0.2495.. and "logical" (measured with clock()) would be 0.27, for smaller measurements it would just round up to zero, which leads to the second issue...)

2) the resulting time seems to be a lot coarser than the one return by gettimeofday

is there a better way to measure local thread time in linux?

+2  A: 

There are some higher precision options you could use -- look at sys/timex.h. Also Boost Date.Time for example has millisecond and higher precision timers.

As for 'total time > physical elapsed time', I do have seen that in multi-threaded timing. That is simply an 'accounting' thingie: all cpu 'consumption' is added and could well be more than elapsed time in multithreaded code if all threads do work, some scheduling overheads gets added and presto you have more than elapsed time.

Dirk Eddelbuettel
interesting, however the test program i'm using is single-threaded... or so i think. i'm currently linking only against unittest-cpp, so maybe the library creates a thread somewhere
lurscher
using getrusage i now get a process time which is consistently lower than physical time - the clock result definitely looks weird
lurscher
Yes, but on a multi-tasking OS some other things are happening and need to be accounted for. Couldn't that be part of the difference between 'your' time and total time?
Dirk Eddelbuettel
+1  A: 

The tv_usec field of struct timeval is in microseconds, not in units of 1/(double)CLOCKS_PER_SEC.

Edgar Bonet
right! by pure chance, locally my CLOCKS_PER_SEC its equal to 10e6 so the results seemed fine
lurscher
A: 

Ok after a bit of researching i found out that getrusage fills both needs mentioned:

getrusage man page

so basically the required code is very similar to how i measure physical time with gettimeofday, only that now i use getrusage

#include <time.h>
#include <sys/time.h>
#include <sys/resource.h>

timeval processed_time0;
timeval processed_time1;
rusage paramStruct
// start of period measurement
int result = getrusage( &paramStruct);
processed_time0 = paramStruct.ru_utime;

...stuff happening 

// end of period measurement
int result = getrusage( &paramStruct );
processed_time1 = paramStruct.ru_utime;

return ( ( processed_time1.tv_sec - processed_time0.tv_sec ) + (( processed_time1.tv_usec - processed_time0.tv_usec )/(double)1000000) );

this way gives me both

1) current process consumed time

2) microsecond resolution

I investigated Boost Date.Time, but in the documentation there is nothing mentioning process or user versus system time, i think the library is just concerned with measuring physical time

lurscher
it seems that this solution is not complete either; apparently the result from rusage will not have a new value until a while (my guess is that it will not get a new value until the next context swap reentry). If that assumption is valid means that one has to implement a hackaround, store physical time each time logical time changes, then as long as reported logical time doesn't change one has to add the physical time delta since the last change. And probably neither this is entirely accurate since i don't know how far before last context swap. Time to take this to the linux mailing list
lurscher
i also tried with `clock_gettime`, and the result is something intermediate between the results of `getrusage` and the results of `gettimeofday`, and since we are ultimately after a reliable benchmark metric, i'm not convinced of any option being better than the other yet... http://www.guyrutenberg.com/2007/09/22/profiling-code-using-clock_gettime/
lurscher