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:

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:

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:

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)

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:

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:

getHtmlTextParallel(), setHtmlTextParallel()

getInstanceWithParallelOpts()

getSelectedLabsFromHtml()

setNumLabs()

setNumLabsParallel()

setSelectedLab()

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.

One Response to Undocumented Profiler options part 4

Useful article! I discovered that calls to load() on a very small file take up a third of the entire processing time on my function. On a side note, the fix to profview.m doesn’t seem to be necessary for 2011b and perhaps earlier versions, as the (presumably) entire message is hard-coded into the sprintf call and so profileInfo.Overhead is converted through sprintf, as shown:

s{end+1} = sprintf(['<a></a><strong>Self time</strong> 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 %4.3f seconds of profiling overhead. ', ...'The amount of remaining overhead reflected in self time cannot be determined.'], profileInfo.Overhead);

Recent Comments

Yair Altman (1 day 9 hours ago): yes, this post was originally posted in 2011, more than 5 years ago – Matlab has changed a lot since then, including an entirely revised graphics system (HG2). The current...

Andrew (1 day 9 hours ago): I figured it out…actually found it elsewhere but then realized it is mentioned in this original post as well. You can still use getcursorinfo(dcmObject) to get a list of all...

Andrew (1 day 10 hours ago): Hello, Did MATLAB recently change the syntax to this? I am trying to get access to the current list of datacursors programatically, but nothing I have tried seems to work. >>...

Yair Altman (2 days 12 hours ago): @Alex – there is no immediate answer. If you want me to look at your specific code, then email me (altmany at gmail) for a dedicated consulting session.

Yair Altman (2 days 12 hours ago): Perhaps you have an outdated version of export_fig. Try to download the latest version from https://github.com/altmany/exp ort_fig

mimi sam (2 days 13 hours ago): I have “GPL Ghostscript” installed on my PC and I get this : In export_fig at 660 export_fig error. Please ensure: that you are using the latest version of export_fig...

Jaap Nienhuis (3 days 7 hours ago): I frequently make images in Matlab. Is it possible, to render the raster component of the image as a bitmap (image in illustrator) and to render the axes labels etc as vector...

Yair Altman (6 days 9 hours ago): @DavidB + @Guillaume + @TheBlackCat – if I remember correctly, my client wanted the code to continue processing only when the 2 inputs were both vectors, although possibly...

David B (6 days 16 hours ago): @TheBlackCat From the limited information we have available we are assuming the data is a vector. If that is the case then I think something like this code snippet would work nicely...

TheBlackCat (7 days 9 hours ago): It is hard to say without seeing more code. It may very well be that the data can only come in a few formats, so transposing it is the correct thing to do.

Guillaume (7 days 10 hours ago): Well, presumably, the code is operating on vectors, so the alternative could be dataA(:) + dataB(:) But really, the proper alternative would have been to find out why the data...