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

More undocumented timing features

July 6, 2011 3 Comments

Two years ago, I posted about a previously-undocumented feature of the built-in tic/toc functions that enables using them in nested operations. Apparently, tStart=tic returns a uint64 value that represents the number of cpu cycles since the last computer restart (as several people have commented in that post).
Since that time I have found a few additional related titbits that I would like to share:

cpucount

It appears that the CPU count value returned by tic is also returned by the internal executable application cpucount (or cpucount.exe), which is located beneath the bin folder of the Matlab installation (for example: C:\Program Files\Matlab\R2011a\bin\win32\cpucount.exe or /bin/matlab/R2011a/bin/glnx86/cpucount):

>> !cpucount
7144479469070
>> uint64(str2num(evalc('!cpucount')))
ans =
        7144486156548
>> tStart = tic
tStart =
        7144497276916
>> uint64(str2num(evalc('!cpucount'))) - tic
ans =
                    0

>> !cpucount 7144479469070 >> uint64(str2num(evalc('!cpucount'))) ans = 7144486156548 >> tStart = tic tStart = 7144497276916 >> uint64(str2num(evalc('!cpucount'))) - tic ans = 0

Note that the cpucount application should not be confused with the built-in cputime function, which returns the total CPU time (in seconds) used by the current Matlab process.

>> cputime
ans =
                 210.15625

>> cputime ans = 210.15625

Note that the CPU count value itself should typically not be used to profile performance, but rather as a unique seed for random numbers and for multiple independent tic/toc invocations. This reminds me of a discussion that arose a decade ago, about the flops function’s removal in Matlab 6.0, when LAPACK was introduced. There are far better ways today for code profiling.
Anyway, the value reported by both cpucount and tic, is also returned by feature('timing','winperfcount'). Which brings us to:

feature(‘timing’)

A related tidbit is the ‘timing’ option of the built-in undocumented feature function, which I explored last year:

>> feature('timing')
??? Error using ==> feature
Choose second argument from:
    'resolution_tictoc'  - Resolution of Tic/Toc clock in sec (double)
    'overhead_tictoc'    - Overhead of Tic/Toc command in sec (double)
    'cpucount'           - Current CPU cycles used (uint64) [Using utCPUcount]
    'getcpuspeed_tictoc' - Stored CPU cycles/sec (double) [Used by tic/toc]
    'cpuspeed'           - Current CPU cycles/sec (double) [Simple MathWorks]
    'winperfcount'       - Current CPU cycles used (uint64) [Windows call]
    'winperfspeed'       - Current CPU cycles/sec (double) [Windows call]
    'wintime'            - Current Windows time (uint32) [Windows call]
                           units: msec since startup [Wraps]
    'wintimeofday'       - Current time of day converted to file time (unit64)[Windows call]
                           units: 100 nsec since 01-Jan-1601 (UTC)
    'clocks_per_sec'     - clock() speed in cycles/sec [CLOCKS_PER_SEC]
Choose second and third arguments from:
    'cpuspeed', double num             - Current CPU cycles/sec (double) [MathWorks - num iterations]
    'setcpuspeed_tictoc', double speed - Set the CPU cycles/sec [Used by tic/toc]
     uint64 arg2, uint64 arg3          - uint64 difference = arg2 - arg3 (uint64)
>> feature('timing','resolution_tictoc')
Resolution of Tic/Toc clock is 1.676191e-006 sec.
>> feature('timing','overhead_tictoc')
Overhead of Tic/Toc command is 1.676191e-006 sec.
>> feature('timing','cpucount')
CPU counter is 17548354355882 cycles.
>> feature('timing','getcpuspeed_tictoc')
tic/toc CPU speed is 2.533333e+009 cycles/sec.
>> feature('timing','cpuspeed')
Current CPU speed is 2.535690e+009 cycles/sec.
>> feature('timing','winperfcount')
Counter is 7150537513228 cycles.
>> feature('timing','winperfspeed')
Speed is 3.579545e+006 cycles/sec.
>> feature('timing','wintime')
Time is 1997625531 msec.
>> feature('timing','wintimeofday')
Time is 129543477454370000 units (100 nsec).
>> feature('timing','clocks_per_sec')
clock() speed is 1.000000e+003 cycles/sec.
>> feature('timing','cpuspeed')
Current CPU speed is 2.535746e+009 cycles/sec.

>> feature('timing') ??? Error using ==> feature Choose second argument from: 'resolution_tictoc' - Resolution of Tic/Toc clock in sec (double) 'overhead_tictoc' - Overhead of Tic/Toc command in sec (double) 'cpucount' - Current CPU cycles used (uint64) [Using utCPUcount] 'getcpuspeed_tictoc' - Stored CPU cycles/sec (double) [Used by tic/toc] 'cpuspeed' - Current CPU cycles/sec (double) [Simple MathWorks] 'winperfcount' - Current CPU cycles used (uint64) [Windows call] 'winperfspeed' - Current CPU cycles/sec (double) [Windows call] 'wintime' - Current Windows time (uint32) [Windows call] units: msec since startup [Wraps] 'wintimeofday' - Current time of day converted to file time (unit64)[Windows call] units: 100 nsec since 01-Jan-1601 (UTC) 'clocks_per_sec' - clock() speed in cycles/sec [CLOCKS_PER_SEC] Choose second and third arguments from: 'cpuspeed', double num - Current CPU cycles/sec (double) [MathWorks - num iterations] 'setcpuspeed_tictoc', double speed - Set the CPU cycles/sec [Used by tic/toc] uint64 arg2, uint64 arg3 - uint64 difference = arg2 - arg3 (uint64) >> feature('timing','resolution_tictoc') Resolution of Tic/Toc clock is 1.676191e-006 sec. >> feature('timing','overhead_tictoc') Overhead of Tic/Toc command is 1.676191e-006 sec. >> feature('timing','cpucount') CPU counter is 17548354355882 cycles. >> feature('timing','getcpuspeed_tictoc') tic/toc CPU speed is 2.533333e+009 cycles/sec. >> feature('timing','cpuspeed') Current CPU speed is 2.535690e+009 cycles/sec. >> feature('timing','winperfcount') Counter is 7150537513228 cycles. >> feature('timing','winperfspeed') Speed is 3.579545e+006 cycles/sec. >> feature('timing','wintime') Time is 1997625531 msec. >> feature('timing','wintimeofday') Time is 129543477454370000 units (100 nsec). >> feature('timing','clocks_per_sec') clock() speed is 1.000000e+003 cycles/sec. >> feature('timing','cpuspeed') Current CPU speed is 2.535746e+009 cycles/sec.

All these features return a numeric value, if requested:

>> cpuspeed = feature('timing','cpuspeed')
cpuspeed =
          2535702174.31193

>> cpuspeed = feature('timing','cpuspeed') cpuspeed = 2535702174.31193

In fact, feature('timing','cpucount') is used internally by the built-in tempname function, to generate a unique temporary filename:

if usejava('jvm')
    tmp_name = fullfile(dirname, ['tp' strrep(char(java.util.UUID.randomUUID),'-','_')]);
else
    tmp_name = fullfile(dirname, ['tp' num2str(feature('timing','cpucount'))]);
end

if usejava('jvm') tmp_name = fullfile(dirname, ['tp' strrep(char(java.util.UUID.randomUUID),'-','_')]); else tmp_name = fullfile(dirname, ['tp' num2str(feature('timing','cpucount'))]); end

feature('timing','wintime') returns the system time in nano-seconds, that can also be gotten directly via Java:

>> uint64(java.lang.System.nanoTime)
ans =
     1997449616528637

>> uint64(java.lang.System.nanoTime) ans = 1997449616528637

It may be interesting to learn the nuances between ‘wintime’, ‘wintimeofday’ and java.lang.System.currentTimeMillis, which returns yet another value. If anyone knows, please post a comment.

-timing startup option

Finally, note that Matlab has had a startup (command-line) option of -timing for a long time. This was documented up to R2009a, but removed from the documentation in R2009b, although the functionality remains to this day.
If Matlab is started with the -timing command-line option, it creates a log file of the time it took different segments of its startup process. Matlab displays the log file contents in the Matlab Command Window when initialization is done. This could help debug the numerous startup problems that users on a variety of platforms and system configurations report:

  Toolbox Path Cache read in 0.08 seconds.
  MATLAB Path initialized in 1.27 seconds.
Opening timing log C:\DOCUME~1\Yair\LOCALS~1\Temp\timing_log.9104 ..
    MATLAB Startup Performance Metrics (In Seconds)
total   item     gap      description         % Yair's comments/hunches
=====================================         % =================================
 0.00   0.00    0.00   MATLAB script          % A: Starting point
 5.70   5.70    0.00   main                   % B: (??? - why so long after the initial Matlab script started?)
 6.14   0.08    0.36   LM Startup             % C: License-manager check of the license validity (from B: 5.70+0.36+0.08=6.14)
 6.21   0.00    0.07   splash                 % D: Matlab splash screen (can be bypassed with the '-nosplash' startup option) - (from C: 6.14+0.07=6.21)
 6.32   0.00    0.11   mnSigInit              % E: (start the initialization part ???) - (from D: 6.21+0.11=6.32)
 7.84   1.49    0.02      InitSunVM           % F: Start the Java Virtual Machine (JVM) used by Matlab GUI (from E: 6.32+0.02+1.49=7.84)
12.66   1.79    3.03      PostVMInit          % G: End of JVM initialization (from F: 7.84+3.03+1.79=12.66)
12.67   6.35    0.01     mljInit              % H: Initialization of Matlab's Java portion (from E: 6.32+0.01+6.35=12.67)
13.64   0.97    0.00     StartDesktop         % I: Start to prepare & initialize the Matlab Desktop (workspace, editor etc.) - (from H: 12.67+0.97=13.64)
13.64   7.31    0.01   Java initialization    % J: ??? (from E: 6.32+0.01+7.31=13.64)
14.04   0.40    0.00   hgInitialize           % K: Handle-Graphics initialization (from J: 13.64+0.40=14.04)
15.13   0.98    0.12   psParser               % L: ??? (from K: 14.04+0.12+0.98=15.13)
15.67   0.07    0.46   cachepath              % M: Toolbox Path Cache initialization (from L: 15.13+0.46+0.07=15.67)
18.53   1.27    1.60     matlabpath           % N: Matlab path initialization (from M: 15.67+1.60+1.27=18.53)
21.54   0.00    3.01     matlabpath           % O: ??? (from N: 18.53+3.01=21.52)
36.78  23.14   13.64   Init Desktop           % P: I believe this indicates the end of the Desktop's init (from I: 13.64+23.14=36.78)
37.05  21.38    0.00   matlabrc               % Q: indicates the end (?) of the m-file (matlabrc.m) initialization process (from M: 15.67+21.38=37.05)
=====================================
Items shown account for 159.4% of total startup time [TIMER: 3 MHz]

Toolbox Path Cache read in 0.08 seconds. MATLAB Path initialized in 1.27 seconds. Opening timing log C:\DOCUME~1\Yair\LOCALS~1\Temp\timing_log.9104 .. MATLAB Startup Performance Metrics (In Seconds) total item gap description % Yair's comments/hunches ===================================== % ================================= 0.00 0.00 0.00 MATLAB script % A: Starting point 5.70 5.70 0.00 main % B: (??? - why so long after the initial Matlab script started?) 6.14 0.08 0.36 LM Startup % C: License-manager check of the license validity (from B: 5.70+0.36+0.08=6.14) 6.21 0.00 0.07 splash % D: Matlab splash screen (can be bypassed with the '-nosplash' startup option) - (from C: 6.14+0.07=6.21) 6.32 0.00 0.11 mnSigInit % E: (start the initialization part ???) - (from D: 6.21+0.11=6.32) 7.84 1.49 0.02 InitSunVM % F: Start the Java Virtual Machine (JVM) used by Matlab GUI (from E: 6.32+0.02+1.49=7.84) 12.66 1.79 3.03 PostVMInit % G: End of JVM initialization (from F: 7.84+3.03+1.79=12.66) 12.67 6.35 0.01 mljInit % H: Initialization of Matlab's Java portion (from E: 6.32+0.01+6.35=12.67) 13.64 0.97 0.00 StartDesktop % I: Start to prepare & initialize the Matlab Desktop (workspace, editor etc.) - (from H: 12.67+0.97=13.64) 13.64 7.31 0.01 Java initialization % J: ??? (from E: 6.32+0.01+7.31=13.64) 14.04 0.40 0.00 hgInitialize % K: Handle-Graphics initialization (from J: 13.64+0.40=14.04) 15.13 0.98 0.12 psParser % L: ??? (from K: 14.04+0.12+0.98=15.13) 15.67 0.07 0.46 cachepath % M: Toolbox Path Cache initialization (from L: 15.13+0.46+0.07=15.67) 18.53 1.27 1.60 matlabpath % N: Matlab path initialization (from M: 15.67+1.60+1.27=18.53) 21.54 0.00 3.01 matlabpath % O: ??? (from N: 18.53+3.01=21.52) 36.78 23.14 13.64 Init Desktop % P: I believe this indicates the end of the Desktop's init (from I: 13.64+23.14=36.78) 37.05 21.38 0.00 matlabrc % Q: indicates the end (?) of the m-file (matlabrc.m) initialization process (from M: 15.67+21.38=37.05) ===================================== Items shown account for 159.4% of total startup time [TIMER: 3 MHz]

In the above list, note the unexplained gaps between the items. I’m not sure I understand them correctly. I posted my hunches as comments next to the relevant lines. I am not sure in some items whether they refer to the start or the end of their associated functionality. If anyone has other ideas or insight that will improve understanding of this list, please share.

Related posts:

  1. Undocumented feature() function – Matlab's undocumented feature function enables access to some internal experimental features...
  2. Undocumented Profiler options part 2 – Several undocumented features of the Matlab Profiler can make it much more useful - part 2 of series. ...
  3. Undocumented Profiler options part 3 – An undocumented feature of the Matlab Profiler can report call history timeline - part 3 of series. ...
  4. Undocumented scatter plot behavior – The scatter plot function has an undocumented behavior when plotting more than 100 points: it returns a single unified patch object handle, rather than a patch handle for each specific point as it returns with 100 or less points....
  5. tic / toc – undocumented option – Matlab's built-in tic/toc functions have an undocumented option enabling multiple nested clockings...
  6. HG's undocumented parameters interface – Some HG functions also accept inputs parameters in a struct fields rather than the normal P-V pairs format. ...
Java Performance Pure Matlab Undocumented feature
Print Print
« Previous
Next »
3 Responses
  1. Aurélien July 7, 2011 at 00:48 Reply

    Hi Yair,

    As the Release Notes of R2011b Prerelease state:
    “MATLAB: Startup Accelerator for faster startup on Windows®
    Startup Accelerator for faster MATLAB startup on Windows, especially on Windows XP, and for network installations”

    I have tried starting different ML versions using your flag trick -timing, I am really disappointed the results given by 10b or 11a are better than 11b Prerelease!!

  2. Daan Willemsen March 14, 2017 at 19:04 Reply

    I have a hunch that PsParser has to do with printers. My PsParser timing had a 15 second gap and by changing the default printer to PDF (as opposed to a network one), I was able to shorten my start-up time by 15 seconds.

    • Dave Laurenson November 22, 2018 at 23:38 Reply

      I think you must be right! I had an issue that psParser was taking 9 minutes to run, but 0.22 seconds when the network was disconnected. Setting the printer to a local PDF printer reduced the time to a mere 0.02 seconds with the network switched back on.

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