Profiling from Mathematica

94

75

I've always wished I could do some profiling like you get in Wolfram Workbench, but directly from Mathematica, without using or having Workbench. If it is possible, how can I do it?

Rojo

Posted 2012-07-01T20:06:59.787

Reputation: 40 993

1

Related question.

– Leonid Shifrin – 2012-07-01T20:10:25.097

Answers

101

You can put your Mathematica session in debug mode by going to Evaluation->Debugger

Then, make some definitions and wrap the profiled code in RuntimeTools`Profile

For example, in debug mode, run

f[x_] := x^2

Table[f[x], {100000}]; // RuntimeTools`Profile

and you get a nice

Mathematica graphics

As @acl mentioned in the comments, clicking in the gray area in the output notebook's lines takes you to the related code

Rojo

Posted 2012-07-01T20:06:59.787

Reputation: 40 993

6Unfortunately this solution does not seem to work for more complicated constructs, like funcitons called within Module, etc.. – Wizard – 2014-10-17T11:40:55.340

3@Wizard Have you tried wrapping your entire code, definitions and all, in RuntimeTools`Profile? This seems to work for me. I suspect that certain profiling handles have to be silently inserted by this function for the timings to be gathered. Can you give me an example where this method fails? – Mr.Wizard – 2015-01-12T11:42:46.287

1Any idea, why test[] := Module[{}, Print["Here"]; Pause[0.1]; Print["There"]; Pause[1]; Return[2]] and test[] // RuntimeTools`Profile does not work, even though your example works correctly? – Ajasja – 2012-07-02T08:37:55.300

Also, do you happen to know what RuntimeTools`ProfileFunction does? – Ajasja – 2012-07-02T10:15:21.127

@Ajasja, sorry about the name ;). I am not sure. It don't think this profiler is without quirks. For starters, I think it doesn't account for Pauses, and without those pauses your code is too fast – Rojo – 2012-07-02T19:55:01.617

@Ajasja, I don't konw what that function does. It doesn't seem to be directly used by the profiler but, it seems to receive a matrix in which each row represents a function, the first column is the number of calls, the second the time taken overall, the third the code in question, and the fourth some number that relates either to the order of execution or something it uses to filter what to show. And returns the profiler notebook – Rojo – 2012-07-02T20:07:31.553

1My issues mentioned in the comment above seem to be resolved in Mathematica 10.1. I also think that Mr.Wizard's suggestion should work in older versions, but I am not sure if I recall that correctly. Sorry for the late reply. – Wizard – 2015-07-09T11:13:17.240

9@Wizard for the first time, I realize that there are at least two Wizards living on this site:-) – matheorem – 2015-10-11T08:47:02.397

I get rather inconsistent results with this example. The line with x^2 is sometimes printed, sometimes not. When it is, it lists 200,000 calls instead of 100,000 – Sjoerd C. de Vries – 2012-11-25T16:10:17.273

@SjoerdC.deVries, yes, I wasn't too attentive to that when I posted this. But I know I did it in MMA v8.0.4 Now I'm doing it in MMA v8.0.0 and I get the 200000 calls you tell me about. However, it doesn't seem to be inconsistent: they are not reported when the f definition cell wasn't evaluated in debug mode – Rojo – 2012-11-25T19:00:14.037

4

Not knowing about the built in functions for this, I compiled these two functions. Hope they help someone.

(* Test Performance of expression evaluation *)
benchmark[locals_,expr_,opts:OptionsPattern[]]:=Module[
{timeLst,funcs,stats,totalTime,times=OptionValue[times],run},
progressBar[Dynamic[run],times];
totalTime=AbsoluteTiming[
    timeLst=Table[
        Module[locals,
            ReleaseHold@AbsoluteTiming[expr]][[1]],
        {run,times}]][[1]];
If[OptionValue[printStats],
    styledPrint[{"Stats for ",times," runs of '", HoldForm[expr] ,"':"},Bold,20];
    statsSummary[timeLst];
    (styledPrint[{"Total Time: ", NumberForm[totalTime,3]},16])];
Return[{stats,timeLst}]
];

SetAttributes[benchmark,HoldAll];
Options[benchmark]={printStats->True,times->9};
benchmark::usage="benchmark[locals_,expr_,OptionsPattern[]] takes a list of localized var=val assignments (which are evaluated anew each run) (lexical, via Module). The expression is evaluated the given number of times, and statistics are printed about it.
The {list of statistics, list of individual runtimes} are returnd.

Example:
benchmark[{n=RandomInteger[10^3,10^5]},FactorInteger[n],times->10]

Options:
times:9 # to run the expression and collect runtime data
printStats:True Wether to print statistics about the distribution of times.
";

(* Compare performance of two expressions *)
compareRunTimes[locals_,base_,comp_,opts:OptionsPattern[]]:=Module[
{timeLst,baseTimeLst,compTimeLst,totalTime,ratio,times=OptionValue[times],runtimes=0,llocs},
progressBar[Dynamic[runtimes],times];
totalTime=AbsoluteTiming[
    timeLst=Map[
        With[locals,
            Evaluate[ReleaseHold@OptionValue[init]];runtimes=#;
            {ReleaseHold@AbsoluteTiming[base][[1]],
             ReleaseHold@AbsoluteTiming[comp][[1]]}]&,
        Range[times]]][[1]];
{baseTimeLst,compTimeLst}=Transpose@timeLst;
If[OptionValue[printStats],
    ratio=(Plus @@ compTimeLst)/(Plus @@ baseTimeLst);
    Quiet[styledPrint[{HoldForm[comp], Style[" (right)",Blue], " took ", Style[(ToString@NumberForm[100. ratio,3]) <> "%", If[ratio>1,Red,Green]], " as much time to evaluate as much as ", HoldForm[base], Style[" (left)", Blue], "!"},24,Bold],{NumberForm::sigz}];
    styledPrint[{"Stats for time ratios for ",times," runs of '", HoldForm[comp], "' and '", HoldForm[base] ,"':"},Bold,20];
    statsSummary[compTimeLst/baseTimeLst,total->False];
    styledPrint[{"Stats for ",times," runs of '", HoldForm[base] ,"':"},Bold,20];
    statsSummary[baseTimeLst];
    styledPrint[{"Stats for ",times," runs of '", HoldForm[comp] ,"':"},Bold,20];
    statsSummary[compTimeLst];];
Return[{baseTimeLst,compTimeLst}]
];

Options[compareRunTimes]={printStats->True,times->9,init->Null};
SetAttributes[compareRunTimes,HoldAll];
compareRunTimes::usage="compareRunTimes[locals_,base_,comp_,OptionsPattern[]] takes a list of localized var=val assignments (which are evaluated anew each run) (lexical, via Module). The expressions base and comp is evaluated the given number of times (with the same local calculated values for both), and statistics are printed about it.
The {list of statistics, list of individual runtimes} are returnd.

Example:
compareRunTimes[{s=RandomInteger[10^5,100000]},FactorInteger[s],FactorInteger[s (s+1)],times\[Rule]10]

Options:
times:9 # to run the expression and collect runtime data
printStats:True Wether to print statistics about the distribution of times.
";

Shwouchk

Posted 2012-07-01T20:06:59.787

Reputation: 477