Undocumented Profiler options part 4

Today’s article concludes my series on undocumented features of the Matlab Profiler. Past articles explained how to profile memory, improve timing resolution and fix a font issue, and display the call history. Today’s article will explain 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.

Profiling built-in functions

Built-in functions (e.g., isempty, length, find) are not monitored or displayed in the profiling summary by default. They are also not linkable to a detailed profiling report in the detailed report of any user function. So, if we have a code line such as the following, we cannot know how much time is spent in length, find as opposed to being spent in userFunction:

numResults = length(find(userFunction()));

However, we can tell the profile to monitor and display built-in functions using the undocumented optional -detail builtin switch of the profile function:

profile on –detail builtin
profile('on','-detail','builtin')   % an equivalent alternative

Alternately, we can use the undocumented built-in function callstats directly (as I already explained, the profile function is simply a convenient wrapper function to callstats):

callstats('level', 2);  % 1=mmex, 2=builtin

The built-in functions will now be reported in the profiling summary and detailed reports, and will be linkable within the code lines of the detailed report.
Note: old MATLAB releases also supported the ‘operator’ detail level, which provided profiling information about built-in operators such as +. However, this level of detail is no longer supported in the latest MATLAB releases.
The -detail switch can also be used with other profile switches. For example:

>> profile('on','-detail','builtin','-timestamp'); surf(peaks); profile('off')

To return to the standard profiling level (‘mmex’), run one of the following:

profile on –detail mmex
profile('on','-detail','mmex')   % an equivalent alternative
callstats('level', 1);           % an equivalent alternative

Profiling overhead removal

The -remove_overhead switch checks the profiler’s own overhead and knows to remove this overhead from all relevant timing values. This is normally off by default, and returns profData.overhead=0. When turned on, it stores the computed profiling overhead in profData.overhead:

profile -remove_overhead on
profile('-remove_overhead','on')        % equivalent alternative
callstats('remove_sample_overhead',1);  % equivalent alternative

We need to make a small fix to the profview function (%matlabroot%/toolbox/matlab/codetools/profview.m), otherwise the profiling report will croak on an error. The fix is simple: replace the following code segment (lines #351-355 in the profview.m file of R2012a)

if profileInfo.Overhead==0
    s{end+1} = sprintf(['<p><a name="selftimedef"></a>', getString(message('MATLAB:profiler:SelfTime1st')) ' ']);
else
    s{end+1} = sprintf(['<p><a name="selftimedef"></a>', getString(message('MATLAB:profiler:SelfTime2nd', profileInfo.Overhead))]);
end

with this (changed line highlighted – note the extra num2str):

if profileInfo.Overhead==0
    s{end+1} = sprintf(['<p><a name="selftimedef"></a>', getString(message('MATLAB:profiler:SelfTime1st')) ' ']);
else
    s{end+1} = sprintf(['<p><a name="selftimedef"></a>', getString(message('MATLAB:profiler:SelfTime2nd', num2str(profileInfo.Overhead)))]);end

Turning the overhead switch on causes the message at the bottom of the profiling summary report to change, from something that says:

Self time is the time spent in a function excluding the time spent in its child functions. Self time also includes overhead resulting from the process of profiling.

To this (the numeric value is the computed overhead, also reported in profData.overhead):

Self time is the time spent in a function excluding both the time spent in its child functions and most of the overhead resulting from the process of profiling.
In the present run, self time excludes 0.80601 seconds of profiling overhead. The amount of remaining overhead reflected in self time cannot be determined.

A similar customization needs to be done to fix an error arising from the use of the undocumented profile -timer none option. I don’t really see great value in running a Profiler without timing information, so I’ll skip this part here. If anyone has an idea what this could be used for, I’d be happy to hear.

[As-yet] unsolved mysteries

To conclude my series on undocumented profiling options, a couple of unsolved mysteries:

hardware profiling

The profview.m function has several references to hardware performance counter data, which, if available as fields in profData.FunctionTable, are displayed as separate columns to the left of the time column field in the code section, and also enabled for the sorting and highlighting drop-downs in the detailed profiling report. Separate monitored hardware events are stored in separate fields named profData.FunctionTable.HWevent (see the getHwFields() sub-function on lines 1557-1564). The mystery: how can we tell the Profiler to start hardware monitoring in a way that would add these HW fields to the collected profData.FunctionTable? Lines 1652-1653 give a hint:

hw_events = callstats('hw_events');
match = strcmpi(['hw_' str],hw_events);

Unfortunately, at least on my system, callstats('hw_events') returns an empty cell array:

>> hw_events = callstats('hw_events')
hw_events =
   Empty cell array: 1-by-0

So if anyone has an idea how to use these HW events, I’d be happy to hear – please leave a comment below.

parallel profiling

Another mystery relates to the question of how to profile parallel Matlab code. The underlying Java object of the Profiler tool (com.mathworks.mde.profiler.Profiler.getInstance) contains the following tell-tale methods:

I would have expected the parallel-enabled Profiler to be started using com.mathworks.mde.profiler.Profiler.getInstanceWithParallelOpts.invoke(). This does indeed start the Profiler, but I can’t see any difference between its output and that of the normal Profiler, even when I run parallel (parfor) code. It definitely does not look like output from the Parallel Computing Toolbox (PCT)’s mpiprofile function.
Perhaps these methods are used by mpiprofile internally? It could make sense for both profile and mpiprofile to share the same underlying profiler tool. On the other hand, if this were indeed the case then why would there be a reason for a separate mpiprofile function? Wouldn’t the standard profile function be sufficient?
Anyway, if anyone has an idea how to use these methods in the standard profiler, perhaps to profile parallel applications without the need for pmode, I’d be happy to hear – please leave a comment below.

Conclusion

The Matlab Profiler has quite a few important features, which for some unknown reason have not been made public. Matlab’s Profiler has remained stagnant since Matlab 7 was released last decade. In fact, some functionality, like the JIT information feature, was actually removed. Hopefully, future Matlab releases will improve the Profiler, by making these undocumented features officially supported, as well as by adding other important functionality.
This concludes my series on undocumented profiling features in Matlab. If anyone knows any other Profiler tricks, please share them in a comment below.