Undocumented Matlab
  • SERVICES
    • Consulting
    • Development
    • Training
    • Gallery
    • Testimonials
  • PRODUCTS
    • IQML: IQFeed-Matlab connector
    • IB-Matlab: InteractiveBrokers-Matlab connector
    • EODML: EODHistoricalData-Matlab connector
    • Webinars
  • BOOKS
    • Secrets of MATLAB-Java Programming
    • Accelerating MATLAB Performance
    • MATLAB Succinctly
  • ARTICLES
  • ABOUT
    • Policies
  • CONTACT
  • SERVICES
    • Consulting
    • Development
    • Training
    • Gallery
    • Testimonials
  • PRODUCTS
    • IQML: IQFeed-Matlab connector
    • IB-Matlab: InteractiveBrokers-Matlab connector
    • EODML: EODHistoricalData-Matlab connector
    • Webinars
  • BOOKS
    • Secrets of MATLAB-Java Programming
    • Accelerating MATLAB Performance
    • MATLAB Succinctly
  • ARTICLES
  • ABOUT
    • Policies
  • CONTACT

Function call timeline profiling

June 16, 2014 9 Comments

Back in 2012, I wrote an article 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 now nearing publication (ETA: November 2014), I decided it’s finally time to finish the task. The result is my profile_history utility, 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; surf(peaks); profile_history

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



The function-call is displayed in a waterfall graph, where thick red lines mark the self (CPU-execution) time, and blue lines mark the calling (parent) functions. Dotted red lines connect the parent (calling) and child (called) functions, such that it is easy to see which function was called, when, and by whom. The graph is interactive: panning and zooming are possible, and clicking on any of the function labels or graph lines opens up the detailed (standard, builtin) profiler report for that function. In addition, an info-box is displayed whenever we move the mouse over the contents. This info-box displays information about the pointed-to call invocation, including its function name, start-time, self-time, time spent in children, total duration and the end time. If the function was called multiple times during the profiling session, then additional information about these other invocations is also displayed. The info-box, dotted waterfall lines, and the red execution lines can be turned on/off, using checkboxes at the bottom of the figure window.
We can also run profile_history on pre-stored profiling data:

profile on; myProgram(); profData=profile('info'); profile_history(profData)

profile on; myProgram(); profData=profile('info'); profile_history(profData)

Why is this important?

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

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.

Function call timeline profiling: focus on the first invocation (click for full-size image)
Function call timeline profiling: focus on the first invocation (click for full-size image)

For a detailed discussion of the profiling timing data that underlies profile_history, please refer to my aforementioned article.
Some ideas for potential future development:

  1. event markers (figure open/close, uicontrol actions, I/O, …)
  2. function labels color based on type (GUI/algo/internal/…)
  3. top-down vs. bottom-up presentation
  4. aggregated by function or not (i.e., full waterfall; duplicate function names on different rows)
  5. automatically highlight performance hotspots
  6. integrate in existing Profiler report (profview)
  7. additional info-box data

Let me know what you think of all this in a comment below!

Related posts:

  1. Viewing saved profiling results – We can easily use saved profiling results to analyze, view and compare profiling results of multiple runs. ...
  2. Profiling Matlab memory usage – mtic and mtoc were a couple of undocumented features that enabled users of past Matlab releases to easily profile memory usage. ...
  3. Undocumented Profiler options part 3 – An undocumented feature of the Matlab Profiler can report call history timeline - part 3 of series. ...
  4. ismembc – undocumented helper function – Matlab has several undocumented internal helper functions that can be useful on their own in some cases. This post presents the ismembc function....
  5. sprintfc – undocumented helper function – The built-in sprintfc function can be used to quickly generate a cell-array of formatted strings. ...
  6. Function definition meta-info – There are multiple ways to retrieve meta-info about functions in Matlab. ...
Performance Pure Matlab Undocumented feature
Print Print
« Previous
Next »
9 Responses
  1. Ali June 18, 2014 at 12:57 Reply

    Dear Yair,
    When I run the code

    profile on; surf(peaks); profile_history

    profile on; surf(peaks); profile_history

    I get the following error message:

    >> profile on; surf(peaks); profile_history
    Error using copyfile
    Cannot write to destination:
    /home/ali/Documents/MATLAB/@char/profile_orig.m.  Use the 'f' option to override.
     
    Error in char/profile (line 10)
        copyfile([matlabroot '/toolbox/matlab/codetools/profile.m'], [curFolder '/profile_orig.m']);
     
    Error in profile_history (line 42)
            profData = profile('info');

    >> profile on; surf(peaks); profile_history Error using copyfile Cannot write to destination: /home/ali/Documents/MATLAB/@char/profile_orig.m. Use the 'f' option to override. Error in char/profile (line 10) copyfile([matlabroot '/toolbox/matlab/codetools/profile.m'], [curFolder '/profile_orig.m']); Error in profile_history (line 42) profData = profile('info');

    However, when I removed @ from the @char folder’s name, it works like a charm.

    • Yair Altman June 18, 2014 at 14:01 Reply

      @Ali – thanks, I just updated the FEX utility with a fix to this edge-case.

  2. Wes Brodsky June 18, 2014 at 14:19 Reply

    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

    • Yair Altman June 18, 2014 at 15:12 Reply

      @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.

  3. Dan June 25, 2014 at 18:57 Reply

    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).

    • Yair Altman June 27, 2014 at 01:25 Reply

      @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.

  4. Andrea June 28, 2014 at 06:45 Reply

    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

    • Yair Altman June 28, 2014 at 10:49 Reply

      @Andrea – this is covered in my uitable customization report

  5. Class object tab completion & improper field names | Undocumented Matlab July 17, 2014 at 11:54 Reply

    […] 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. […]

Leave a Reply
HTML tags such as <b> or <i> are accepted.
Wrap code fragments inside <pre lang="matlab"> tags, like this:
<pre lang="matlab">
a = magic(3);
disp(sum(a))
</pre>
I reserve the right to edit/delete comments (read the site policies).
Not all comments will be answered. You can always email me (altmany at gmail) for private consulting.

Click here to cancel reply.

Useful links
  •  Email Yair Altman
  •  Subscribe to new posts (feed)
  •  Subscribe to new posts (reader)
  •  Subscribe to comments (feed)
 
Accelerating MATLAB Performance book
Recent Posts

Speeding-up builtin Matlab functions – part 3

Improving graphics interactivity

Interesting Matlab puzzle – analysis

Interesting Matlab puzzle

Undocumented plot marker types

Matlab toolstrip – part 9 (popup figures)

Matlab toolstrip – part 8 (galleries)

Matlab toolstrip – part 7 (selection controls)

Matlab toolstrip – part 6 (complex controls)

Matlab toolstrip – part 5 (icons)

Matlab toolstrip – part 4 (control customization)

Reverting axes controls in figure toolbar

Matlab toolstrip – part 3 (basic customization)

Matlab toolstrip – part 2 (ToolGroup App)

Matlab toolstrip – part 1

Categories
  • Desktop (45)
  • Figure window (59)
  • Guest bloggers (65)
  • GUI (165)
  • Handle graphics (84)
  • Hidden property (42)
  • Icons (15)
  • Java (174)
  • Listeners (22)
  • Memory (16)
  • Mex (13)
  • Presumed future risk (394)
    • High risk of breaking in future versions (100)
    • Low risk of breaking in future versions (160)
    • Medium risk of breaking in future versions (136)
  • Public presentation (6)
  • Semi-documented feature (10)
  • Semi-documented function (35)
  • Stock Matlab function (140)
  • Toolbox (10)
  • UI controls (52)
  • Uncategorized (13)
  • Undocumented feature (217)
  • Undocumented function (37)
Tags
AppDesigner (9) Callbacks (31) Compiler (10) Desktop (38) Donn Shull (10) Editor (8) Figure (19) FindJObj (27) GUI (141) GUIDE (8) Handle graphics (78) HG2 (34) Hidden property (51) HTML (26) Icons (9) Internal component (39) Java (178) JavaFrame (20) JIDE (19) JMI (8) Listener (17) Malcolm Lidierth (8) MCOS (11) Memory (13) Menubar (9) Mex (14) Optical illusion (11) Performance (78) Profiler (9) Pure Matlab (187) schema (7) schema.class (8) schema.prop (18) Semi-documented feature (6) Semi-documented function (33) Toolbar (14) Toolstrip (13) uicontrol (37) uifigure (8) UIInspect (12) uitable (6) uitools (20) Undocumented feature (187) Undocumented function (37) Undocumented property (20)
Recent Comments
Contact us
Captcha image for Custom Contact Forms plugin. You must type the numbers shown in the image
Undocumented Matlab © 2009 - Yair Altman
This website and Octahedron Ltd. are not affiliated with The MathWorks Inc.; MATLAB® is a registered trademark of The MathWorks Inc.
Scroll to top