Why does profiler include idle time?

The Matlab profiler is behaving in ways I do not expect. For example, I have a very simple function that looks like this:

function ptest(N)
  a=fftn(randn(N,N,N));

Now If I paste this text into the matlab command window:

profile on
tic
ptest(300);
toc
profile report

I get a profile report that tells me that the function ptest ran for 0.94 seconds (fairly consistent with toc) with the fft line taking nearly all the time and being called exactly once... so far so good!

However, if I then type this code into the profiler:

profile on
tic
ptest(300);
toc
pause(8)
toc
profile report

I have two toc lines... one gives 1.09 seconds and the other gives 9.10 seconds (all this makes sense). However, the profiler tells me that the function call took 8.923 seconds! In fact, if I wait another 10 seconds and type profile report again, it tells me the function call took 19 seconds!

[Jed]

One other oddity... If I change the function by adding a pause(10) above the main fftn line, I get this:

I have tried matlab 2012a and 2014a... dont have a newer version. My OS is linux:

Linux torb23 2.6.32-279.el6.x86_64 #1 SMP Wed Jun 13 18:24:36 EDT 2012 x86_64 x86_64 x86_64 GNU/Linux

I have tried in -nodesktop mode and regular (gui) mode

[per isakson]

With R2013b I cannot reproduce any of the behavior that you describe

[Jed]

Thanks for checking... something wrong with my specific configuration, I guess. A colleague running windows got the right answer like you did... I tried adding the (optional?) "end" statement, and still got the same weird result.

[Jed]

@per isakson: Thanks so much for checking this! The proposed answer by Philip below could explain this behavior if you are using windows. If he is correct, I would expect windows to still have the following problem, which I would try to verify if I had Matlab for windows:

type in the command window:

profile on
ptest(300)

Now wait 10 seconds and then type

profile report

If Philip is right, I would expect that even the windows version of matlab would give funny results because everything would be normalized to the wall clock time between the initial command "profile on" and the eventual command "profile report"

Answer 1

[Philip Borghesani]

This is a bug/feature in recent versions of the profiler through R2015a. On Mac/Linux the profiler times with processor time by default and on Windows it times with a wall clock timer. In both cases the time is normalized to the wall clock duration after profiling. Pause uses no processor time so on Linux you get 0 or nearly 0 time for the pause statement. The normalization process hides the fact that if you have 4 cores the fft statement might have used 4 seconds of processor time in 1 second of wall clock time.

Unfortunately the normalization also distorts the times in the presence of functions like pause that use no processor time.

To get the same results on both platforms issue the command:

profile -timer real

[Jed]

Thanks, Philip.

I guess your answer could explain the strange behavior. Certainly it can't be a feature, though!

I found this because I turned on the profiler, ran some code, then left for a meeting. An hour later I returned and ran profile report and it told me the run took an hour. In fact, the code was finished after 30 minutes (which I could verify using file timestamps). This can't be the desired behavior that Matlab intends, can it?

Edit: I now see from your profile that you are with MathWorks...so is this the desired behavior or is it a bug?

[Philip Borghesani]

I think the best explanation is that one bug was fixed by causing a new undesired behavior. Leaving the profiler on and coming back later was not a predicted usage model. I always use the profiler like:

profile on; mycode ; profile viewer

That way I can do it again with up arrow and you get the cleanest possible output.

When multi-core processors and power management were first appearing in computers these features made the timer used by the profiler unreliable and it was necessary to compensate the times returned to make times match expectations. This compensation is no longer needed but still exists in the code.

[Jed]

A friend of mine tested this out under windows and it did not behave this way. He ran code that took 10 seconds using cputime. Whether he asked for the profile report immediately or waited an additional 10 seconds before opening the report, the profiler gave the correct answer. If it can be fixed for windows, why not linux?

Anyway, I will use your suggestion and run the profiler like you suggest going forward. Thanks. I hope others benefit from your suggestion.

[Philip Borghesani]

Windows does not show the issue because sitting at the command prompt, though not visible in profiler output, is timed and added to the total for compensation purposes but on Linux it is timed with CPU time which will again be near zero.

The best I can say about any bug fix is point out the opening sentence of my answer: This is a bug/feature in recent versions of the profiler through R2015a