Discover MakerZone

MATLAB and Simulink resources for Arduino, LEGO, and Raspberry Pi

Learn more

Discover what MATLAB® can do for your career.

Opportunities for recent engineering grads.

Apply Today

To resolve issues starting MATLAB on Mac OS X 10.10 (Yosemite) visit: http://www.mathworks.com/matlabcentral/answers/159016

Performance tuning - finding CPU time

Asked by matal on 19 Jul 2013

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

0 Comments

matal

Products

3 Answers

Answer by per isakson on 19 Jul 2013
Edited by per isakson on 19 Jul 2013

See

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

6 Comments

matal on 19 Jul 2013

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 on 19 Jul 2013

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 on 19 Jul 2013

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

per isakson
Answer by Yair Altman on 20 Jul 2013
Edited by Yair Altman on 20 Jul 2013

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?)

1 Comment

matal on 22 Jul 2013

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)?

Yair Altman
Answer by Jan Simon on 19 Jul 2013

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.

1 Comment

matal on 22 Jul 2013

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.

Jan Simon

Contact us