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