MLton MLTONWIKIVERSION

ProfilingTime

Home Index

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

Last edited on 2006-11-02 17:38:19 by MatthewFluet.