<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN" "http://www.w3.org/TR/html4/strict.dtd">
<html>
<head>
<meta name="robots" content="index,nofollow">
<title>ProfilingTime - MLton Standard ML Compiler (SML Compiler)</title>
<link rel="stylesheet" type="text/css" charset="iso-8859-1" media="all" href="common.css">
<link rel="stylesheet" type="text/css" charset="iso-8859-1" media="screen" href="screen.css">
<link rel="stylesheet" type="text/css" charset="iso-8859-1" media="print" href="print.css">
<link rel="Start" href="Home">
</head>
<body lang="en" dir="ltr">
<script src="http://www.google-analytics.com/urchin.js" type="text/javascript">
</script>
<script type="text/javascript">
_uacct = "UA-833377-1";
urchinTracker();
</script>
<table bgcolor = lightblue cellspacing = 0 style = "border: 0px;" width = 100%>
<tr>
<td style = "
border: 0px;
color: darkblue;
font-size: 150%;
text-align: left;">
<a class = mltona href="Home">MLton MLTONWIKIVERSION</a>
<td style = "
border: 0px;
font-size: 150%;
text-align: center;
width: 50%;">
ProfilingTime
<td style = "
border: 0px;
text-align: right;">
<table cellspacing = 0 style = "border: 0px">
<tr style = "vertical-align: middle;">
</table>
<tr style = "background-color: white;">
<td colspan = 3
style = "
border: 0px;
font-size:70%;
text-align: right;">
<a href = "Home">Home</a>
<a href = "TitleIndex">Index</a>
</table>
<div id="content" lang="en" dir="ltr">
With MLton and <tt>mlprof</tt>, you can <a href="Profiling">profile</a> 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 <tt>-profile time</tt>. For example, suppose that <tt>tak.sml</tt> contains the following. <p>
<pre class=code><B><FONT COLOR="#0000FF">structure</FONT></B> Tak =
<B><FONT COLOR="#0000FF">struct</FONT></B>
<B><FONT COLOR="#A020F0">fun</FONT></B> tak1 (x, y, z) =
<B><FONT COLOR="#A020F0">let</FONT></B>
<B><FONT COLOR="#A020F0">fun</FONT></B> tak2 (x, y, z) =
<B><FONT COLOR="#A020F0">if</FONT></B> y >= x
<B><FONT COLOR="#A020F0">then</FONT></B> z
<B><FONT COLOR="#A020F0">else</FONT></B>
tak1 (tak2 (x - <B><FONT COLOR="#5F9EA0">1</FONT></B>, y, z),
tak2 (y - <B><FONT COLOR="#5F9EA0">1</FONT></B>, z, x),
tak2 (z - <B><FONT COLOR="#5F9EA0">1</FONT></B>, x, y))
<B><FONT COLOR="#A020F0">in</FONT></B>
<B><FONT COLOR="#A020F0">if</FONT></B> y >= x
<B><FONT COLOR="#A020F0">then</FONT></B> z
<B><FONT COLOR="#A020F0">else</FONT></B>
tak1 (tak2 (x - <B><FONT COLOR="#5F9EA0">1</FONT></B>, y, z),
tak2 (y - <B><FONT COLOR="#5F9EA0">1</FONT></B>, z, x),
tak2 (z - <B><FONT COLOR="#5F9EA0">1</FONT></B>, x, y))
<B><FONT COLOR="#A020F0">end</FONT></B>
<B><FONT COLOR="#0000FF">end</FONT></B>
<B><FONT COLOR="#A020F0">val</FONT></B> <B><FONT COLOR="#A020F0">rec</FONT></B> f =
<B><FONT COLOR="#A020F0">fn</FONT></B> <B><FONT COLOR="#5F9EA0">0</FONT></B> => ()
| ~<B><FONT COLOR="#5F9EA0">1</FONT></B> => print <B><FONT COLOR="#BC8F8F">"this branch is not taken\n"</FONT></B>
| n => (Tak.tak1 (<B><FONT COLOR="#5F9EA0">18</FONT></B>, <B><FONT COLOR="#5F9EA0">12</FONT></B>, <B><FONT COLOR="#5F9EA0">6</FONT></B>) ; f (n-<B><FONT COLOR="#5F9EA0">1</FONT></B>))
<B><FONT COLOR="#A020F0">val</FONT></B> _ = f <B><FONT COLOR="#5F9EA0">5000</FONT></B>
<B><FONT COLOR="#A020F0">fun</FONT></B> uncalled () = ()
</PRE>
</p>
<p>
Compile with time profiling and run the program.
<pre>% mlton -profile time tak.sml
% ./tak
</pre>
</p>
<p>
Display the profiling data.
</p>
<pre>% 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%
</pre><p>
This example shows how <tt>mlprof</tt> 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 <tt>Tak.tak1.tak2</tt> function, while the rest is spent in <tt>Tak.tak1</tt>.
</p>
<p>
Display raw counts in addition to percentages with <tt>-raw true</tt>.
<pre>% 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)
</pre>
</p>
<p>
Display the file name and line number for each function in addition to its name with <tt>-show-line true</tt>.
<pre>% 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%
</pre>
</p>
<p>
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 <tt>-codegen c</tt> than <tt>-codegen native</tt>.
</p>
<p>
You can also compile with <tt>-profile time -profile-branch true</tt> to find out how much time is spent in each branch of a function; see <a href="ProfilingCounts">ProfilingCounts</a> for more details on <tt>-profile-branch</tt>.
</p>
<h2 id="head-bcaa33a7ae44bd5042c37a9cdbea7f843b1cf7c8">Caveats</h2>
<p>
With <tt>-profile time</tt>, use of the following in your program will cause a run-time error, since they would interfere with the profiler signal handler.
</p>
<ul>
<li>
<p>
<tt>MLton.Itimer.set (MLton.Itimer.Prof, ...)</tt>
</p>
</li>
<li>
<p>
<tt>MLton.Signal.setHandler (MLton.Signal.prof, ...)</tt>
</p>
</li>
</ul>
<p>
Also, because of the random sampling used to implement <tt>-profile time</tt>, it is best to have a long running program (at least tens of seconds) in order to get reasonable time
</p>
</div>
<p>
<hr>
Last edited on 2006-11-02 17:38:19 by <span title="76.16.241.4"><a href="MatthewFluet">MatthewFluet</a></span>.
</body></html>
