During my work on the recent series of articles on undocumented Profiler options, I came across a very odd bug. Apparently, a major documented Profiler functionality has been dysfunctional since at least R2008a (and probably earlier), and AFAIK was not reported until now.
The functionality in question is the Profiler’s documented ability to display results in either wall-clock (profile -timer real) or CPU-time (profile -timer cpu) modes. In fact, at least since R2008a and possibly sooner (I’m unsure about earlier releases), at least on Windows (I’m unsure about other platforms), both of these Profiler options provide wall-clock measurements – CPU-time measurements is not available. The irony is that CPU mode is stated in the documentation to be the Profiler’s default mode, and has been this way ever since this option was introduced about a decade ago.
I used a very simple test harness – prepare the following function in test.m:
function test pause(2) end
And now run it in the Profiler:
>> profile on -timer cpu >> test >> profile off; profile report
If everything had worked as documented, the Profiler report would show the test function as taking no time at all, or maybe only a few millisecs of overhead. In fact, this is exactly what we see in Matlab release R14 SP3 (7.1, dated 2005):
Unfortunately, on R2008a and later (and possibly also some earlier releases), the same profiling run reports the timing as taking 2 full seconds (=wall-clock time):
You might assume that the built-in pause function has a bug that causes it to churn the CPU, and in that case the Profiler’s report would be correct. However, a quick check in the Task Manager (I actually use Process Explorer that I find much better) proves that this is not the case – no discernible CPU-time is used by the Matlab process during the pause.
Somewhere between R2006a and R2008a a bug was introduced that caused the Profiler to only use wall-clock mode.
Note that even in R14 SP3 the situation is not perfect: I have found that the default mode (i.e., when not specifying the -timer mode explicitly) is sometimes wall-clock and sometimes CPU, with no apparent consistency. However, if we explicitly use the -timer option, it works ok.
It is strange that such a feature has escaped everyone’s attention (the community’s no less than MathWorks’) for so many years. It is true that this is not an often-used functionality, and it is also true that the profile function itself it way under-utilized by the general public. Still, anyone who needs to do serious performance tuning must have used this feature at some point in time. When performance-tuning code, it is very important to be aware of both the wall-clock and the CPU-time of the profiled program. Different tuning strategies apply to these two modes. Relying only on wall-clock timing can lead to incorrect conclusions about the application’s hotspots, and therefore to sub-optimal tuning. So I am very surprised that this bug was not reported until now. I’ve reported it (1-K1I06V) lately, and I really hope that it will be fixed in R2013a.
From the command line:
works as expected giving:
No profile information to display.
But making test.m a script gives the same result as the function.
Yair, from what I remember hearing from a TMWer, the ability to measure CPU time has become more and more meaningless over time as things such as hyperthreading, complex pipelining, and multi-core/CPU technologies have been developed. I wouldn’t be surprised if CPUTIME went away in a future version (or just returned wall time), and the same thing could happen with the profiler. See the note at the end of the following doc page: http://www.mathworks.com/help/matlab/matlab_prog/analyzing-your-programs-performance.html
Maybe you could post a question on CSSM or email one of the blog owners to see if they can clarify all of this 🙂