| 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 |