[hcoop/debian/mlton.git] / doc / guide / src / ProfilingTime.adoc

ProfilingTime
=============

With MLton and `mlprof`, you can <:Profiling: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.

[source,sml]
----
sys::[./bin/InclGitFile.py mlton master doc/examples/profiling/tak.sml]
----

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
Commit	Line	Data
7f918cf1 CE	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