I have recently discussed undocumented features in Matlab’s built-in profiler. Another tool often used for ad-hoc performance profiling of Matlab code are the built-in duo functions tic and toc:
>> tic; magic(500); toc Elapsed time is 0.474647 seconds.
Both tic and toc are documented functions, but they contain an undocumented option (at least until R2008b – see history below) that enables nested clocking. The problem that is solved using this undocumented option is that if we try to use tic/toc in external function parentFcn and also in the internal function childFcn, we get unexpected results. This happens because our childFcn‘s invocation of tic has reset the clock and so parentFcn‘s clock is now obviously incorrect:
function parentFcn % Start clocking tic; % Do something long... m1 = magic(1500); % Call nested function toc1 = childFcn; % Present clock timing toc2 = toc; fprintf('Elapsed time for childFcn: %0.3f secs\n',toc1) fprintf('Elapsed time for parentFcn: %0.3f secs\n',toc2) % Nested function with separate clocking function t = childFcn tic; m = magic(800); t = toc; end % childFcn end % parentFcn
>> parentFcn Elapsed time for childFcn: 1.063 secs Elapsed time for parentFcn: 1.068 secs
The solution: use a separate handle for each clock. The format is very simple:
>> t = tic; >> toc(t)
This format ensures independent clocking of the clocks. Clockings can now be safely nested and even partial overlap is possible:
function parentFcn % Start clocking t1 = tic; % Do something long... m1 = magic(1500); % Call nested function toc1 = childFcn; % Present clock timing toc2 = toc(t1); fprintf('Elapsed time for childFcn: %0.3f secs\n',toc1) fprintf('Elapsed time for parentFcn: %0.3f secs\n',toc2) % Nested function with separate clocking function t = childFcn tic; m = magic(800); t = toc; end % childFcn end % parentFcn
>> parentFcn Elapsed time for childFcn: 1.123 secs Elapsed time for parentFcn: 4.992 secs
For the record, this undocumented option was first presented by the MathWorks support team as an official workaround for the aforementioned problem. The solution was originally posted for Matlab R2006b, but actually the option was supported by Matlab versions at least as early as R14SP3 (7.1) – perhaps even earlier (I don’t have ready access to earlier versions). I do know that it was not supported on release R12 aka 6.0, but I don’t know whether it was introduced in 6.5, 7.0 or 7.1. This option has only been documented since R2008b, although it has existed in many earlier releases.
Now here’s a puzzle for all you undoc fans out there: toc has a really undocumented option of using an uninitialized uint64 value, rather than an actual tic handle. It seems that whichever value is passed will always result in the same result, but this result is uncorrelated to any possible event (start of Matlab, midnight etc.). It even works without any prior tic invocation! I would love to hear your thoughts on what you think this strange toc result might represent:
>> toc(uint64(1)) Elapsed time is 72825.947547 seconds. >> toc(uint64(1234)) Elapsed time is 72826.538296 seconds.