Mercurial > hg > octave-terminal
changeset 12978:fb0f40cd8752
Add an example profiler session to the manual.
debug.txi: New section which walks through an example profiler session.
author | Daniel Kraft <d@domob.eu> |
---|---|
date | Fri, 19 Aug 2011 16:40:07 +0200 |
parents | 9db4e9b352d6 |
children | 6a9fbeff3368 |
files | doc/interpreter/debug.txi |
diffstat | 1 files changed, 193 insertions(+), 0 deletions(-) [+] |
line wrap: on
line diff
--- a/doc/interpreter/debug.txi +++ b/doc/interpreter/debug.txi @@ -36,6 +36,7 @@ * Debug Mode:: * Call Stack:: * Profiling:: +* Profiler Example:: @end menu @node Entering Debug Mode @@ -224,3 +225,195 @@ also found out that it is recursive. @DOCSTRING(profshow) + +@node Profiler Example +@section Profiler Example + +Below, we will give a short example of a profiler session. +See also @ref{Profiling} +for the documentation of the profiler functions in detail. +Consider the code: + +@example +global N A; + +N = 300; +A = rand (N, N); + +function xt = timesteps (steps, x0, expM) + global N; + + if (steps == 0) + xt = NA (N, 0); + else + xt = NA (N, steps); + x1 = expM * x0; + xt(:, 1) = x1; + xt(:, 2 : end) = timesteps (steps - 1, x1, expM); + endif +endfunction + +function foo () + global N A; + + initial = @@(x) sin (x); + x0 = (initial (linspace (0, 2 * pi, N)))'; + + expA = expm (A); + xt = timesteps (100, x0, expA); +endfunction + +function fib = bar (N) + if (N <= 2) + fib = 1; + else + fib = bar (N - 1) + bar (N - 2); + endif +endfunction +@end example + +If we execute the two ``main'' functions, we get: + +@example +tic; foo; toc; +@result{} Elapsed time is 2.37338 seconds. + +tic; bar (20); toc; +@result{} Elapsed time is 2.04952 seconds. +@end example + +But this does not give much information about where this time is spent; +for instance, whether the single call to @code{expm} is more expensive or +the recursive time-stepping itself. To get a more detailed picture, +we can use the profiler. + +@example +profile on; +foo; +profile off; + +data = profile ('info'); +profshow (data, 10); +@end example + +This prints a table like: + +@example + # Function Attr Time (s) Calls +--------------------------------------------- + 7 expm 1.034 1 + 3 binary * 0.823 117 + 41 binary \ 0.188 1 + 38 binary ^ 0.126 2 + 43 timesteps R 0.111 101 + 44 NA 0.029 101 + 39 binary + 0.024 8 + 34 norm 0.011 1 + 40 binary - 0.004 101 + 33 balance 0.003 1 +@end example + +The entries are the individual functions which have been executed (only the +10 most important ones), together with some information for each of them. +The entries like @samp{binary *} denote operators, while other +entries are ordinary functions --- they include both built-ins like @code{expm} +and our own routines (for instance @code{timesteps}). From this profile, we can +immediately deduce that @code{expm} uses up the largest proportion of the +processing time, even though it is only called once. The second expensive +operation is the matrix-vector product in the routine @code{timesteps}. +(We only know it is the binary multiplication operator, but fortunately this +operator appears only at one place in the code and thus we know which +occurance takes so much time. If there were multiple places, we would have +to use the hierarchical profile to find out the exact place which +uses up the time --- which is not covered in this example.) + +But timing is not the only information available from the profile --- the +attribute column shows us that @code{timesteps} calls itself recursively. +This may not be that exciting in this example (since it's clear anyway), +but could be helpful in a more complex setting. If you wonder why +there appears a @samp{binary \} in the output, we can easily shed some light +on that, too. Note that @code{data} is an Octave structure which contains +the field @code{FunctionTable}. This stores the ``raw data'' for the profile +shown. The number in the first column of the table gives the index under which +the shown function can be found there. Looking up @code{data.FunctionTable(41)} +gives: + +@example + scalar structure containing the fields: + + FunctionName = binary \ + TotalTime = 0.18765 + NumCalls = 1 + IsRecursive = 0 + Parents = 7 + Children = [](1x0) +@end example + +Here we see the information from the table again, but have additional fields +@code{Parents} and @code{Children}. Those are both arrays, which contain +the indices of functions which have directly called the function in question +(which is entry 7, @code{expm}, in this case) or been called by it (no +functions). Hence, the backslash operator has been used internally +by @code{expm}. + +Ok, now let's take a look at @code{bar}. For this, we start a fresh +profiling session (@code{profile on} does this, the old data is removed before +the profiler is restarted): + +@example +profile on; +bar (20); +profile off; + +profshow (profile ('info')); +@end example + +This gives: + +@example + # Function Attr Time (s) Calls +------------------------------------------------------- + 1 bar R 2.091 13529 + 2 binary <= 0.062 13529 + 3 binary - 0.042 13528 + 4 binary + 0.023 6764 + 5 profile 0.000 1 + 8 false 0.000 1 + 6 nargin 0.000 1 + 7 binary != 0.000 1 + 9 __profiler_enable__ 0.000 1 +@end example + +Unsurprisingly, @code{bar} is also recursive. It has been called 13,529 times +in the course of recursively calculating the Fibonacci number in a +not-that-optimal way, and most of the time was spent in @code{bar} itself. + +Finally, let's say we want to profile the execution of both @code{foo} +and @code{bar} together. Since we already have the runtime data collected +for @code{bar}, we can restart the profiler without clearing the existing +data and collect the missing statistics about @code{foo}. This is done by: + +@example +profile resume; +foo; +profile off; + +profshow (profile ('info'), 10); +@end example + +As you can see in the table below, now we have both profiles ``mixed together''. + +@example + # Function Attr Time (s) Calls +--------------------------------------------- + 1 bar R 2.091 13529 + 16 expm 1.122 1 + 12 binary * 0.798 117 + 46 binary \ 0.185 1 + 45 binary ^ 0.124 2 + 48 timesteps R 0.115 101 + 2 binary <= 0.062 13529 + 3 binary - 0.045 13629 + 4 binary + 0.041 6772 + 49 NA 0.036 101 +@end example