8

I have written some C code which I call form MATLAB after I compile it using MEX. Inside the C code, I measure the time of a part of the computation using the following code:

clock_t begin, end;
double time_elapsed;
begin = clock();
/* do stuff... */
end = clock();
time_elapsed = (double) ((double) (end - begin) / (double) CLOCKS_PER_SEC);

Elapsed time should be the execution time in seconds.

I then output the value time_elapsed to MATLAB (it is properly exported; I checked). Then MATLAB-side I call this C function (after I compile it using MEX) and I measure its execution time using tic and toc. What turns out to be a complete absurdity is that the time I compute using tic and toc is 0.0011s (average on 500 runs, st. dev. 1.4e-4) while the time that is returned by the C code is 0.037s (average on 500 runs, st. dev. 0.0016).

Here one may notice two very strange facts:

  1. The execution time for the whole function is lower than the execution time for a part of the code. Hence, either MATLAB's or C's measurements are strongly inaccurate.
  2. The execution times measured in the C code are very scattered and exhibit very high st. deviation (coeff. of variation 44%, compared to just 13% for tic-toc).

What is going on with these timers?

Pantelis Sopasakis
  • 1,837
  • 4
  • 25
  • 44
  • What is the resolution of the clock? How do we know if `begin = clock();` is executed just before or just after a clock tick happended? Does that affect the result? Probably. – Bo Persson Jan 31 '13 at 23:03
  • @BoPersson So, you mean that `clock()` may miss a tick at most? – Pantelis Sopasakis Jan 31 '13 at 23:07
  • 4
    I mean that one tick might be large enough to affect the result. Like 18 ms. – Bo Persson Jan 31 '13 at 23:12
  • 3
    Simple test of this hypothesis would be to wrap `/* do stuff */` in a loop. Also, check out this post: http://stackoverflow.com/questions/588307/c-obtaining-milliseconds-time-on-linux-clock-doesnt-seem-to-work-properl about `clock()` resolution – s.bandara Jan 31 '13 at 23:16

1 Answers1

6

You're comparing apples to oranges.

Look at Matlab's documentation:

tic - http://www.mathworks.com/help/matlab/ref/tic.html
toc - http://www.mathworks.com/help/matlab/ref/toc.html

tic and toc let you measure real elapsed time.

Now look at the clock function http://linux.die.net/man/3/clock.

In particular,

The clock() function returns an approximation of processor time used by the program.

The value returned is the CPU time used so far as a clock_t; to get the number of seconds used, divide by CLOCKS_PER_SEC. If the processor time used is not available or its value cannot be represented, the function returns the value (clock_t) -1.

So what can account for your difference:

  • CPU time (measured by clock()) and real elapsed time (measured by tic and toc) are NOT the same. So you would expect that cpu time to be less than elapsed time? Well, maybe. What if within 0.0011s you're driving 10 cores at 100%? That would mean that clock() measurement is 10x that measured with tic and toc. Possible, unlikely.
  • clock(.) is grossly inaccurate, and consistent with the documentation, it is an approximate cpu time measurement! I suspect that it is pegged to the scheduler quantum size, but I didn't dig through the Linux kernel code to check. I also didn't check on other OSes, but this dude's blog is consistent with that theory.

So what to do... for starters, compare apples to apples! Next, make sure you take into account timer resolution.

thang
  • 3,220
  • 16
  • 30