- Undocumented Matlab - https://undocumentedmatlab.com -
Function call timeline profiling
Posted By Yair Altman On June 16, 2014 | 9 Comments
Back in 2012, I wrote an article [1] about the Matlab profiler’s undocumented functionality of storing detailed information about the function-call history, including timing information. I intended to follow up on this with a utility that would bring the data to life, but I never found the time for this. With my upcoming book on Matlab performance [2] now nearing publication (ETA: November 2014), I decided it’s finally time to finish the task. The result is my profile_history utility [3], available for download on the Matlab File Exchange (open-source):
Usage of profile_history is very easy, based on the latest profiling session:
profile on; surf(peaks); profile_history
profile on; myProgram(); profData=profile('info'); profile_history(profData)
So yes, this is a cool utility, but does it really add information that was not already available if we dug down in the standard profiler report?
The answer is a definite YES. Let’s take the following simple example:
function perfTest
for idx = 1 : 10
pause(0.02);
nestedFunction();
subFunction(idx);
end
function nestedFunction
pause(0.03);
end
end
function subFunction(idx)
if idx > 1
pause(0.05);
else
pause(0.5);
end
end
The standard profiler report simply tells us that perfTest ran once, taking 1.69 secs, calling perfTest>subFunction 10 times running a total of 1.06 secs. There is no information, even in the detailed report, about which of the 10 invocations of subFunction was responsible for the majority of the run-time, or whether all 10 invocations took approximately ~0.1 secs each. Looking at the code above we can see that the first invocation was indeed significantly slower, but in general we do not know that a certain invocation is in fact much slower than the rest.
Enter profile_history: a single look at the output, possibly with a few mouse hovers over the relevant red invocation segments, immediately shows us that the first invocation of subFunction was responsible for the majority of the run-time. If we just improve this single invocation, rather than improve the general case, we achieve the maximal benefit from our performance-tuning effort.
Let me know what you think of all this in a comment below!
Categories: High risk of breaking in future versions, Stock Matlab function, Undocumented feature
Article printed from Undocumented Matlab: https://undocumentedmatlab.com
URL to article: https://undocumentedmatlab.com/articles/function-call-timeline-profiling
URLs in this post:
[1] an article: http://undocumentedmatlab.com/blog/undocumented-profiler-options-part-3
[2] book on Matlab performance: http://www.crcpress.com/product/isbn/9781482211290
[3] profile_history utility: http://www.mathworks.com/matlabcentral/fileexchange/46976-profile-history-display-graphical-profiling-timline-data
[4] Image: http://undocumentedmatlab.com/images/profile_history.png
[5] Image: http://undocumentedmatlab.com/images/profile_history2.png
[6] Viewing saved profiling results : https://undocumentedmatlab.com/articles/viewing-saved-profiling-results
[7] Profiling Matlab memory usage : https://undocumentedmatlab.com/articles/profiling-matlab-memory-usage
[8] Undocumented Profiler options part 3 : https://undocumentedmatlab.com/articles/undocumented-profiler-options-part-3
[9] ismembc – undocumented helper function : https://undocumentedmatlab.com/articles/ismembc-undocumented-helper-function
[10] sprintfc – undocumented helper function : https://undocumentedmatlab.com/articles/sprintfc-undocumented-helper-function
[11] Function definition meta-info : https://undocumentedmatlab.com/articles/function-definition-meta-info
[12] : https://undocumentedmatlab.com/blog/uitable-customization-report
Click here to print.
Copyright © Yair Altman - Undocumented Matlab. All rights reserved.
9 Comments To "Function call timeline profiling"
#1 Comment By Ali On June 18, 2014 @ 12:57
Dear Yair,
When I run the code
I get the following error message:
However, when I removed @ from the @char folder’s name, it works like a charm.
#2 Comment By Yair Altman On June 18, 2014 @ 14:01
@Ali – thanks, I just updated the FEX utility with a fix to this edge-case.
#3 Comment By Wes Brodsky On June 18, 2014 @ 14:19
Sounds great! I have not had a chance to try it yet. I look forward to the publication of your book;
MATLAB Performance Tuning: Making your MATLAB Program Fly
#4 Comment By Yair Altman On June 18, 2014 @ 15:12
@Wes – the title might change a bit by the time it actually gets published in a few months, but the ISBN and web link will remain unchanged.
#5 Comment By Dan On June 25, 2014 @ 18:57
It might be useful to be able to put a option to limit the number of function levels in view (i.e. How many sub-functions you delve down into for displaying their commands) … such that your not displaying so many commands. That could help visualize the general problem areas and let you dive down into those without getting so many display objects on the figure (which ultimately stops he usefulness).
#6 Comment By Yair Altman On June 27, 2014 @ 01:25
@Dan – I uploaded an update to the profile_history utility with the ability to programmatically and interactively control the number of displayed functions (default = 15), sorted by descending total time.
#7 Comment By Andrea On June 28, 2014 @ 06:45
Hi
I wont to apply a row filter like Excel to uitable to select multiple items contained in the column.
do you have any suggestion or example shopping how to do?
Thanks in advance
Andrea
#8 Comment By Yair Altman On June 28, 2014 @ 10:49
@Andrea – this is covered in my [12]
#9 Pingback By Class object tab completion & improper field names | Undocumented Matlab On July 17, 2014 @ 11:54
[…] This wrapper function can then be placed within a @char folder somewhere in the Matlab path. I used a similar trick for my profile_history utility last month. […]