Performance tuning - finding CPU time

Hi -

I have a Matlab function (my code) that takes about 1.5ms to run most of the time, but every once in a while spikes up - 10ms, 15ms, 20ms, or even higher. I would like to figure out why.

I may have to do this with other functions in future - so my question is not about this specific piece of code, but rather about how to debug this type of a problem in Matlab.

1) tic/toc - Above timings were done using tic/toc. Natural question is - since I am measuring elapsed time, are my outlier purely due to things like thread switches, etc. etc.? If so, would setting processor affinity of the Matlab process help?

2) cputime - I tried using cputime - for a lot of my calls, the cputime returns zero even when tic/toc returns a non-zero value. Has anyone experienced this?

3) Profiler - Pretty useless in this case I think - it reports average times. Well, on average, the function performs just fine. I am trying to track down the outliers, and I don't quite see how the Profiler can be helpful here.

Thanks in advance! matal

Answer 1

[per isakson]

See

• TIMEIT Benchmarking Function and
• Buggy Profiler option

They link to other resources on timing.

BTW: Which OS do you use?

.

cputime

First time ever(?) I try cputime. The resolution is poor (0.0156s on Windows 7, R2012a 64bit). That's why you see ZERO.

    >> t = cputime; surf(peaks(40)); e = cputime-t
    e =
        0.2028
    >> t = cputime; surf(peaks(40)); e = cputime-t
    e =
        0.0624
    >> t = cputime; surf(peaks(40)); e = cputime-t
    e =
        0.0156
    >> t = cputime; surf(peaks(40)); e = cputime-t
    e =
        0.0156
    >> t = cputime; surf(peaks(40)); e = cputime-t
    e =
        0.0312
    >> t = cputime; surf(peaks(40)); e = cputime-t
    e =
        0.0156
    >> t = cputime; surf(peaks(40)); e = cputime-t
    e =
         0

[matal]

1) TIMEIT - Thanks I had seen this in my googling and I checked again after you suggested it - it uses tic/toc, i.e. elapsed time. I would have thought a way to measure cpu time / cycles would be the most accurate way to do this, no?

2) Is this bug still open?

FYI - I am using R2010b on Windows XP, but will deploy on R2009a/Linux (my current production environment).

[matal]

Also - just to be clear - my function is not stateless, so repeated calls change state and the spikes may be related to that too. Something like TIMEIT (i haven't read thru all the code yet, mind you) seems to be more of a fit for a stateless math function.

Seems to me if the profiler could provide me with a distribution of times per line along with a way of viewing execution times for selected iterations of my timing loop, that's what I am looking for.

I am currently having to put tic/toc around selected lines within the function, returning the times out of the function, and having the driver generate distributions and execution paths.... if you see what i mean?

[per isakson]

1) TIMEIT runs the function several times, excludes the first (few?) and report an average for the rest. More important than the code is the rational for TIMEIT.

2) AFAIK: Yes! (I'm not sure about the status of this "issue", whether it is a BUG with an ID and all that.)

The behavior, "spikes", you report is not typical - I dare to say. Have you seen it with many different m-files?

[matal]

And the problem is - when the spikes are due to tic/toc timing, i am not quite sure whether that's "real" or that's due to perhaps a task switch in the middle by the OS.

[matal]

1) Thanks - I am assuming the rationale is "warm up". I do one call to warm up and then do ~2000 calls and look at a chart of their times - so if there was a consistent pattern (early calls slow, later calls faster), I would know by now.

Further - I am calling out to mex files and external C++ libraries - the intermittent spike problem may well be with one of those calls.

But what I am hoping to do is this - scientifically establish the exact line(s) of code that are resulting in the spikes. Using tic/toc isn't precise in this case since they are elapsed time.....

2) Hmm. Let me check with Mathworks.

It seems to me now (given your point re profile above and cputime) that Matlab actually doesn't provide me with a precise way to measure CPU time - this will be tremendously disappointing to say the least.

[per isakson]

Regarding the "inner workings" Matlab is a black box and The Mathworks wants too keep it that way.

"scientifically establish the exact line(s) of code that are resulting in the spikes." Sounds difficult to me. Don't forget the accelerator and just-in-time-compiler.

See More undocumented timing features

Answer 2

[Yair Altman]

The Profiler DOES provide detailed information about specific call invocations, but you need to dig a bit in its undocumented raw data. This is explained here: http://undocumentedmatlab.com/blog/undocumented-profiler-options-part-3/

Naturally, the raw data begs for someone to write a utility that presents the info in a more human-readable manner. I would have done it myself if I had any time - maybe someone else will pick up the glove (Jan? Per? anyone?)

[matal]

Thank you much! This seems almost exactly what I am looking for - I will dig into this a bit later when I return to working on this portion of the code.

I say "almost exactly" because your link above says "we can run profile with the undocumented/unsupported –timestamp switch, which stores the CPU clock next to the history information".

Still not clear to me that a context/thread/process switch (what's the right term?) in the middle of my function will not bias the timings. Am I even right to worry about such external factors as being the potential cause for the spike?

And finally - why are these functionalities undocumented??? I am relatively new to Matlab - am I trying to push this product into areas where it's not meant to go (highly time critical, real-time processing)?

Answer 3

[Jan]

Measuring the timing can be influenced by other applications also. E.g. the garbage collection of the operating system's memory manager. Or the WLAN adapter checks the connection. I do not think that the source of the delays can be reliably determined in every case. So a strategy for measuring timings is to exclude the outliers from the statistics.

[matal]

Excluding outliers is not an option when spikes such as this in our calculation code may have material implications for production business logic. The production system will ensure no such external factors. However, in testing, I need to rule out our (internal) code being the cause of such spikes - hence my question about how to do accurate timing.