Undocumented Profiler options part 3

Today’s article continues my series on undocumented features of the Matlab Profiler. Past articles explained how to profile memory, improve timing resolution and fix a font issue. Today’s article will explain undocumented switches of the profile function that can be used to provide detailed history timeline of the function calls. Next week’s article will conclude the series by explaining undocumented switches of the profile function that can be used to profile built-in functions, to report and remove the profiling overhead, plus a couple of as-yet-unsolved mysteries.

Simple call history

One of the features that the programmatic profiling interface provides, and which is not represented in the Profiler GUI, is a report of the exact order in which different functions were called during the profiling session. This profiling history can be turned on using the –history switch. There is also an optional switch of –historysize, which enables us to modify the history size from a default maximum of 1 million function entry and exit items. Here is a sample usage of this history feature:

>> profile('on','-history'); surf(peaks); profile('off')
>> profData = profile('info');
>> history = profData.FunctionHistory
history =
  Columns 1 through 11
     0     0     0     1     0     1     0     1     1     1     0
    19     1    17    17    17    17    18    18     1    19     5
  ...

The history data is actually a numeric matrix, where the first row contains the values 0 (=function entry) or 1 (=function exit), and the second row is the corresponding index into profData.FunctionTable, indicating the called function. We can easily convert this matrix into human-readable form using the following code snippet:

offset = cumsum(1-2*history(1,:)) - 1;  % calling depth
entryIdx = history(1,:)==1;     % history items of function entries
funcIdx = history(2,entryIdx);  % indexes of relevant functions
funcNames = {profData.FunctionTable(funcIdx).FunctionName};
for idx = 1: length(funcNames);
   disp([repmat(' ',1,offset(idx)) funcNames{idx}]);
end

which generates the following calling list in the MATLAB Command Window:

isempty
 isempty
  transpose
 meshgrid
  peaks
 nargchk
  error
 ishg2parent
...

Unfortunately, the history information does not by default contain specific timing of each function entry/exit, but we can still make good use of it by looking at the sequence in which the functions were called from each other.

Detailed call history, with timing information

In order to retrieve actual history timing information, we can run profile with the undocumented/unsupported –timestamp switch, which stores the CPU clock next to the history information. The reported history matrix now has 4 rows rather than 2, where the extra rows represents the timestamp of each function entry/exit:

>> profile('on','-timestamp'); surf(peaks); profile('off')
>> profData = profile('info');
>> profData.FunctionHistory(:,1:3)
ans =
                0                0                1
                1                2                2
       1347473710       1347473710       1347473710
           453000           453000           468000

In this report, the 3rd row represents the timestamp in seconds, while the 4th row represents the fractional portion of the timestamp, in microseconds. In the example above, the first timestamp item corresponds to 1347473710.453 seconds.
The seconds value appears to be related to the number of seconds since midnight Jan 1, 1970 (so-called Epoch), which is a standard time representation in computing systems. However, the actual value appears to be off by slightly over a day from the expected value (which is retrievable via getTime(java.util.Date)) for some unknown reason. Since we are only interested in relative, rather than absolute times when profiling, this minor difference does not affect us.
The timeline of the profiling session can be visualized as follows:

histData = profData.FunctionHistory;
startTime     = histData(3,1) + histData(4,1)/1e6;
relativeTimes = histData(3,:) + histData(4,:)/1e6 - startTime;
plot(relativeTimes);

Invocation  #1 of func():  0.500 secs
Invocation  #2 of func():  0.013 secs
Invocation  #3 of func():  0.011 secs
   ...
Invocation #10 of func():  0.012 secs
_____________________________________
Total invocation time:     0.600 secs

In this simulation, we would not have known that the 0.6 secs invocation time of func() is not really evenly distributed across all 10 invocations, and this would lead us to incorrect conclusions. For example, we could spend time unnecessarily on tuning the steady-state run-time performance of the function, whereas we should really have concentrated on only the first invocation. By looking at the actual timestamps we could see the large run-time used by the first invocation and this information can possibly be used to tune this first invocation and significantly reduce the overall time taken by the function.
Note: instead of using profile -timestamp, we could also have used the undocumented built-in function callstats, which is the underlying profiling engine (the profile function is simply a convenient wrapper function to callstats – take a look within profile.m):

callstats('history',2);  % 0 = -nohistory, 1 = -history, 2 = -timestamp

History collection has an overhead, so if you don’t need it then you should turn it off:

profile -nohistory
profile('-nohistory')    % equivalent alternative
callstats('history',0);  % equivalent alternative

Addendum (June 16th, 2014): I have created a utility (profile_history, available on the Matlab File Exchange) that parses all this profile data and presents it in an interactive GUI. See this article for details.

Function call timeline profiling (click for full-size image)