ProfilingTime

With MLton and mlprof, you can profile your program to find out how much time is spent in each function over an entire run of the program. To do so, compile your program with -profile time. For example, suppose that tak.sml contains the following.

structure Tak =
   struct
      fun tak1 (x, y, z) =
         let
            fun tak2 (x, y, z) =
               if y >= x
                  then z
               else
                  tak1 (tak2 (x - 1, y, z),
                        tak2 (y - 1, z, x),
                        tak2 (z - 1, x, y))
         in
            if y >= x
               then z
            else
               tak1 (tak2 (x - 1, y, z),
                     tak2 (y - 1, z, x),
                     tak2 (z - 1, x, y))
         end
   end

val rec f =
   fn 0 => ()
    | ~1 => print "this branch is not taken\n"
    | n => (Tak.tak1 (18, 12, 6) ; f (n-1))

val _ = f 5000

fun uncalled () = ()

Compile with time profiling and run the program.

% mlton -profile time tak.sml
% ./tak

Display the profiling data.

% mlprof tak mlmon.out
6.00 seconds of CPU time (0.00 seconds GC)
function     cur
------------- -----
Tak.tak1.tak2 75.8%
Tak.tak1      24.2%

This example shows how mlprof indicates lexical nesting: as a sequence of period-separated names indicating the structures and functions in which a function definition is nested. The profiling data shows that roughly three-quarters of the time is spent in the Tak.tak1.tak2 function, while the rest is spent in Tak.tak1.

Display raw counts in addition to percentages with -raw true.

% mlprof -raw true tak mlmon.out
6.00 seconds of CPU time (0.00 seconds GC)
  function     cur    raw
------------- ----- -------
Tak.tak1.tak2 75.8% (4.55s)
Tak.tak1      24.2% (1.45s)

Display the file name and line number for each function in addition to its name with -show-line true.

% mlprof -show-line true tak mlmon.out
6.00 seconds of CPU time (0.00 seconds GC)
        function           cur
------------------------- -----
Tak.tak1.tak2  tak.sml: 5 75.8%
Tak.tak1  tak.sml: 3      24.2%

Time profiling is designed to have a very small performance impact. However, in some cases there will be a run-time performance cost, which may perturb the results. There is more likely to be an impact with -codegen c than -codegen native.

You can also compile with -profile time -profile-branch true to find out how much time is spent in each branch of a function; see ProfilingCounts for more details on -profile-branch.

Caveats

With -profile time, use of the following in your program will cause a run-time error, since they would interfere with the profiler signal handler.

MLton.Itimer.set (MLton.Itimer.Prof, ...)
MLton.Signal.setHandler (MLton.Signal.prof, ...)

Also, because of the random sampling used to implement -profile time, it is best to have a long running program (at least tens of seconds) in order to get reasonable time