More undocumented timing features

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

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

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.

All these features return a numeric value, if requested:

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

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

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]

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. tic / toc – undocumented option Matlab's built-in tic/toc functions have an undocumented option enabling multiple nested clockings...
  2. 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....
  3. Undocumented feature() function Matlab's undocumented feature function enables access to some internal experimental features...
  4. Undocumented Profiler options part 2 Several undocumented features of the Matlab Profiler can make it much more useful - part 2 of series. ...
  5. Types of undocumented Matlab aspects This article lists the different types of undocumented/unsupported/hidden aspects in Matlab...
  6. Undocumented Profiler options part 3 An undocumented feature of the Matlab Profiler can report call history timeline - part 3 of series. ...

Categories: Medium risk of breaking in future versions, Stock Matlab function, Undocumented feature

Tags: , , ,

Bookmark and SharePrint Print

One Response to More undocumented timing features

  1. 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!!

Leave a Reply

Your email address will not be published. Required fields are marked *

*

<pre lang="matlab">
a = magic(3);
sum(a)
</pre>