Profiler biases execution time of optimized code

Hi all,

I have got a problem with profile. It delivers some unexpected results when comparing two versions of the same algorithm, one written in Matlab and the other one invoked through a mex-file implementation.

I understand that profile measures the actual execution time and thus usually differs from the time measured when using for example tic and toc. That is not the problem.

What I observed first when profiling my script was that one particular function consumes about 63% (self time that is) of the entire execution time of the script. I went and optimized this function by implementing it in C and was happy to see that the execution time of the entire script according to profile was reduced from 170s down to 76s and the fraction of time that was spent in the optimized function was down to about 12% of the total execution time. Perfect, I thought, I overall gained more than 100% in performance.

Unfortunately the world looks different as soon as I turn off profile. Then, the script executes in about 24s with the original Matlab function and in about 21s with the optimized function, hence only 14% of performance gain. I would have expected the ratios of the execution times to be at least similar as to when profile was turned on.

That would mean, unless I have overseen something obvious, the results of profile are actually no indication whatsoever as to where the time in my code is really spent. Where am I mistaken?

Please help.

Thanks a lot in advance.

Olaf

Answer 1

[Jan]

The profiler disables the JIT acceleration of Matlab! This can lead to totally different timings.

Since Matlab 6.5 loops are optimized by the internal JIT-acceleration, such that the repeated calculations are performed much faster. To achieve this, the JIT can reorder the commands of the code. This would confuse the profiler, which looses the relation between code lines and time measurements. In consequence PROFILE disables the JIT completely.

The same behaviour appears, if you enable the debugger by setting a break point. To allow a line-by-line execution, the order of commands/lines must not be modified, and therefore the JIT is disabled, too.

Therefore the PROFILEr, the standard tool for speed optimizations, has a very limited use for optimizing code, which profits from the JIT. Strange, isn't it?

Inserting TIC/TOCs is more reliable.

[Daniel Shub]

I thought I had read a discussion about the profiler and JIT accelerator, but I couldn't find it. Yair's blog has something which made me think the JIT acceleration is in effect during profiling: http://undocumentedmatlab.com/blog/undocumented-profiler-options/

[Olaf]

Thanks to you both. That sheds some light on the issue. It makes the choice of default options for the profiler, to say the least, questionable :(

[Jan]

In former releases the profiler showed messages about lines, which could not be optimized by the JIT, but the JIT itself did not run.

Answer 2

[Daniel Shub]

In order to profile your code MATLAB needs to do a little extra work. In general, I think this extra work is minimal. In your case before optimization your code takes 170 seconds with the profiler and 24 seconds without. I think this indicates something unusual (not necessarily wrong) about your code. It is quite possible that the mex file changes the overhead associated with profiling.

I would suspect that the portion of your code that you optimized is called many times and for some reason the overhead of profiling is a significant portion of the task.

[Olaf]

Hi Daniel,

thanks for your reply. In fact, the function in question is called many times, but so are also some of the other functions in the script that took less time to compute. This would thus not explain the minimal reduction of overall execution time of the script with profile disabled. I would expect the overhead of profile to be the same on all the functions.

[Daniel Shub]

I wouldn't expect this. At some point the profiler stops digging down into the code. I think when it hits a mex file, but maybe when it hits java or private functions. I wouldn't expect running the code with the profiler turned on to take 7.5 times as long.

[Olaf]

The mex file shows up in the results page, hence it is not excluded by the profiler.

Thanks for your reply in any case.