doc/guide/src/ProfilingTime.adoc

   1 ProfilingTime
   2 =============
   3
   4 With MLton and `mlprof`, you can <:Profiling:profile> your program to
   5 find out how much time is spent in each function over an entire run of
   6 the program.  To do so, compile your program with `-profile time`.
   7 For example, suppose that `tak.sml` contains the following.
   8
   9 [source,sml]
  10 ----
  11 sys::[./bin/InclGitFile.py mlton master doc/examples/profiling/tak.sml]
  12 ----
  13
  14 Compile with time profiling and run the program.
  15 ----
  16 % mlton -profile time tak.sml
  17 % ./tak
  18 ----
  19
  20 Display the profiling data.
  21 ----
  22 % mlprof tak mlmon.out
  23 6.00 seconds of CPU time (0.00 seconds GC)
  24 function     cur
  25 ------------- -----
  26 Tak.tak1.tak2 75.8%
  27 Tak.tak1      24.2%
  28 ----
  29
  30 This example shows how `mlprof` indicates lexical nesting: as a
  31 sequence of period-separated names indicating the structures and
  32 functions in which a function definition is nested.  The profiling
  33 data shows that roughly three-quarters of the time is spent in the
  34 `Tak.tak1.tak2` function, while the rest is spent in `Tak.tak1`.
  35
  36 Display raw counts in addition to percentages with `-raw true`.
  37 ----
  38 % mlprof -raw true tak mlmon.out
  39 6.00 seconds of CPU time (0.00 seconds GC)
  40   function     cur    raw
  41 ------------- ----- -------
  42 Tak.tak1.tak2 75.8% (4.55s)
  43 Tak.tak1      24.2% (1.45s)
  44 ----
  45
  46 Display the file name and line number for each function in addition to
  47 its name with `-show-line true`.
  48 ----
  49 % mlprof -show-line true tak mlmon.out
  50 6.00 seconds of CPU time (0.00 seconds GC)
  51         function           cur
  52 ------------------------- -----
  53 Tak.tak1.tak2  tak.sml: 5 75.8%
  54 Tak.tak1  tak.sml: 3      24.2%
  55 ----
  56
  57 Time profiling is designed to have a very small performance impact.
  58 However, in some cases there will be a run-time performance cost,
  59 which may perturb the results.  There is more likely to be an impact
  60 with `-codegen c` than `-codegen native`.
  61
  62 You can also compile with `-profile time -profile-branch true` to find
  63 out how much time is spent in each branch of a function; see
  64 <:ProfilingCounts:> for more details on `-profile-branch`.
  65
  66
  67 == Caveats ==
  68
  69 With `-profile time`, use of the following in your program will cause
  70 a run-time error, since they would interfere with the profiler signal
  71 handler.
  72
  73 * `MLton.Itimer.set (MLton.Itimer.Prof, ...)`
  74 * `MLton.Signal.setHandler (MLton.Signal.prof, ...)`
  75
  76 Also, because of the random sampling used to implement `-profile
  77 time`, it is best to have a long running program (at least tens of
  78 seconds) in order to get reasonable time