Import Upstream version 20180207
[hcoop/debian/mlton.git] / doc / guide / localhost / ProfilingTime
CommitLineData
7f918cf1
CE
1<!DOCTYPE html>\r
2<html lang="en">\r
3<head>\r
4<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">\r
5<meta name="generator" content="AsciiDoc 8.6.9">\r
6<title>ProfilingTime</title>\r
7<link rel="stylesheet" href="./asciidoc.css" type="text/css">\r
8<link rel="stylesheet" href="./pygments.css" type="text/css">\r
9\r
10\r
11<script type="text/javascript" src="./asciidoc.js"></script>\r
12<script type="text/javascript">\r
13/*<![CDATA[*/\r
14asciidoc.install();\r
15/*]]>*/\r
16</script>\r
17<link rel="stylesheet" href="./mlton.css" type="text/css">\r
18</head>\r
19<body class="article">\r
20<div id="banner">\r
21<div id="banner-home">\r
22<a href="./Home">MLton 20180207</a>\r
23</div>\r
24</div>\r
25<div id="header">\r
26<h1>ProfilingTime</h1>\r
27</div>\r
28<div id="content">\r
29<div id="preamble">\r
30<div class="sectionbody">\r
31<div class="paragraph"><p>With MLton and <span class="monospaced">mlprof</span>, you can <a href="Profiling">profile</a> your program to\r
32find out how much time is spent in each function over an entire run of\r
33the program. To do so, compile your program with <span class="monospaced">-profile time</span>.\r
34For example, suppose that <span class="monospaced">tak.sml</span> contains the following.</p></div>\r
35<div class="listingblock">\r
36<div class="content"><div class="highlight"><pre><span class="k">structure</span><span class="w"> </span><span class="n">Tak</span><span class="w"> </span><span class="p">=</span><span class="w"></span>\r
37<span class="w"> </span><span class="k">struct</span><span class="w"></span>\r
38<span class="w"> </span><span class="k">fun</span><span class="w"> </span><span class="n">tak1</span><span class="w"> </span><span class="p">(</span><span class="n">x</span><span class="p">,</span><span class="w"> </span><span class="n">y</span><span class="p">,</span><span class="w"> </span><span class="n">z</span><span class="p">)</span><span class="w"> </span><span class="p">=</span><span class="w"></span>\r
39<span class="w"> </span><span class="k">let</span><span class="w"></span>\r
40<span class="w"> </span><span class="k">fun</span><span class="w"> </span><span class="n">tak2</span><span class="w"> </span><span class="p">(</span><span class="n">x</span><span class="p">,</span><span class="w"> </span><span class="n">y</span><span class="p">,</span><span class="w"> </span><span class="n">z</span><span class="p">)</span><span class="w"> </span><span class="p">=</span><span class="w"></span>\r
41<span class="w"> </span><span class="k">if</span><span class="w"> </span><span class="n">y</span><span class="w"> </span><span class="n">&gt;=</span><span class="w"> </span><span class="n">x</span><span class="w"></span>\r
42<span class="w"> </span><span class="k">then</span><span class="w"> </span><span class="n">z</span><span class="w"></span>\r
43<span class="w"> </span><span class="k">else</span><span class="w"></span>\r
44<span class="w"> </span><span class="n">tak1</span><span class="w"> </span><span class="p">(</span><span class="n">tak2</span><span class="w"> </span><span class="p">(</span><span class="n">x</span><span class="w"> </span><span class="n">-</span><span class="w"> </span><span class="mi">1</span><span class="p">,</span><span class="w"> </span><span class="n">y</span><span class="p">,</span><span class="w"> </span><span class="n">z</span><span class="p">),</span><span class="w"></span>\r
45<span class="w"> </span><span class="n">tak2</span><span class="w"> </span><span class="p">(</span><span class="n">y</span><span class="w"> </span><span class="n">-</span><span class="w"> </span><span class="mi">1</span><span class="p">,</span><span class="w"> </span><span class="n">z</span><span class="p">,</span><span class="w"> </span><span class="n">x</span><span class="p">),</span><span class="w"></span>\r
46<span class="w"> </span><span class="n">tak2</span><span class="w"> </span><span class="p">(</span><span class="n">z</span><span class="w"> </span><span class="n">-</span><span class="w"> </span><span class="mi">1</span><span class="p">,</span><span class="w"> </span><span class="n">x</span><span class="p">,</span><span class="w"> </span><span class="n">y</span><span class="p">))</span><span class="w"></span>\r
47<span class="w"> </span><span class="k">in</span><span class="w"></span>\r
48<span class="w"> </span><span class="k">if</span><span class="w"> </span><span class="n">y</span><span class="w"> </span><span class="n">&gt;=</span><span class="w"> </span><span class="n">x</span><span class="w"></span>\r
49<span class="w"> </span><span class="k">then</span><span class="w"> </span><span class="n">z</span><span class="w"></span>\r
50<span class="w"> </span><span class="k">else</span><span class="w"></span>\r
51<span class="w"> </span><span class="n">tak1</span><span class="w"> </span><span class="p">(</span><span class="n">tak2</span><span class="w"> </span><span class="p">(</span><span class="n">x</span><span class="w"> </span><span class="n">-</span><span class="w"> </span><span class="mi">1</span><span class="p">,</span><span class="w"> </span><span class="n">y</span><span class="p">,</span><span class="w"> </span><span class="n">z</span><span class="p">),</span><span class="w"></span>\r
52<span class="w"> </span><span class="n">tak2</span><span class="w"> </span><span class="p">(</span><span class="n">y</span><span class="w"> </span><span class="n">-</span><span class="w"> </span><span class="mi">1</span><span class="p">,</span><span class="w"> </span><span class="n">z</span><span class="p">,</span><span class="w"> </span><span class="n">x</span><span class="p">),</span><span class="w"></span>\r
53<span class="w"> </span><span class="n">tak2</span><span class="w"> </span><span class="p">(</span><span class="n">z</span><span class="w"> </span><span class="n">-</span><span class="w"> </span><span class="mi">1</span><span class="p">,</span><span class="w"> </span><span class="n">x</span><span class="p">,</span><span class="w"> </span><span class="n">y</span><span class="p">))</span><span class="w"></span>\r
54<span class="w"> </span><span class="k">end</span><span class="w"></span>\r
55<span class="w"> </span><span class="k">end</span><span class="w"></span>\r
56\r
57<span class="k">val</span><span class="w"> </span><span class="k">rec</span><span class="w"> </span><span class="n">f</span><span class="w"> </span><span class="p">=</span><span class="w"></span>\r
58<span class="w"> </span><span class="k">fn</span><span class="w"> </span><span class="mi">0</span><span class="w"> </span><span class="p">=&gt;</span><span class="w"> </span><span class="p">()</span><span class="w"></span>\r
59<span class="w"> </span><span class="p">|</span><span class="w"> </span><span class="mi">~1</span><span class="w"> </span><span class="p">=&gt;</span><span class="w"> </span><span class="n">print</span><span class="w"> </span><span class="s">&quot;this branch is not taken</span><span class="se">\n</span><span class="s">&quot;</span><span class="w"></span>\r
60<span class="w"> </span><span class="p">|</span><span class="w"> </span><span class="n">n</span><span class="w"> </span><span class="p">=&gt;</span><span class="w"> </span><span class="p">(</span><span class="n">Tak</span><span class="p">.</span><span class="n">tak1</span><span class="w"> </span><span class="p">(</span><span class="mi">18</span><span class="p">,</span><span class="w"> </span><span class="mi">12</span><span class="p">,</span><span class="w"> </span><span class="mi">6</span><span class="p">)</span><span class="w"> </span><span class="p">;</span><span class="w"> </span><span class="n">f</span><span class="w"> </span><span class="p">(</span><span class="n">n-</span><span class="mi">1</span><span class="p">))</span><span class="w"></span>\r
61\r
62<span class="k">val</span><span class="w"> </span><span class="p">_</span><span class="w"> </span><span class="p">=</span><span class="w"> </span><span class="n">f</span><span class="w"> </span><span class="mi">5000</span><span class="w"></span>\r
63\r
64<span class="k">fun</span><span class="w"> </span><span class="n">uncalled</span><span class="w"> </span><span class="p">()</span><span class="w"> </span><span class="p">=</span><span class="w"> </span><span class="p">()</span><span class="w"></span>\r
65</pre></div></div></div>\r
66<div class="paragraph"><p>Compile with time profiling and run the program.</p></div>\r
67<div class="listingblock">\r
68<div class="content monospaced">\r
69<pre>% mlton -profile time tak.sml\r
70% ./tak</pre>\r
71</div></div>\r
72<div class="paragraph"><p>Display the profiling data.</p></div>\r
73<div class="listingblock">\r
74<div class="content monospaced">\r
75<pre>% mlprof tak mlmon.out\r
766.00 seconds of CPU time (0.00 seconds GC)\r
77function cur\r
78------------- -----\r
79Tak.tak1.tak2 75.8%\r
80Tak.tak1 24.2%</pre>\r
81</div></div>\r
82<div class="paragraph"><p>This example shows how <span class="monospaced">mlprof</span> indicates lexical nesting: as a\r
83sequence of period-separated names indicating the structures and\r
84functions in which a function definition is nested. The profiling\r
85data shows that roughly three-quarters of the time is spent in the\r
86<span class="monospaced">Tak.tak1.tak2</span> function, while the rest is spent in <span class="monospaced">Tak.tak1</span>.</p></div>\r
87<div class="paragraph"><p>Display raw counts in addition to percentages with <span class="monospaced">-raw true</span>.</p></div>\r
88<div class="listingblock">\r
89<div class="content monospaced">\r
90<pre>% mlprof -raw true tak mlmon.out\r
916.00 seconds of CPU time (0.00 seconds GC)\r
92 function cur raw\r
93------------- ----- -------\r
94Tak.tak1.tak2 75.8% (4.55s)\r
95Tak.tak1 24.2% (1.45s)</pre>\r
96</div></div>\r
97<div class="paragraph"><p>Display the file name and line number for each function in addition to\r
98its name with <span class="monospaced">-show-line true</span>.</p></div>\r
99<div class="listingblock">\r
100<div class="content monospaced">\r
101<pre>% mlprof -show-line true tak mlmon.out\r
1026.00 seconds of CPU time (0.00 seconds GC)\r
103 function cur\r
104------------------------- -----\r
105Tak.tak1.tak2 tak.sml: 5 75.8%\r
106Tak.tak1 tak.sml: 3 24.2%</pre>\r
107</div></div>\r
108<div class="paragraph"><p>Time profiling is designed to have a very small performance impact.\r
109However, in some cases there will be a run-time performance cost,\r
110which may perturb the results. There is more likely to be an impact\r
111with <span class="monospaced">-codegen c</span> than <span class="monospaced">-codegen native</span>.</p></div>\r
112<div class="paragraph"><p>You can also compile with <span class="monospaced">-profile time -profile-branch true</span> to find\r
113out how much time is spent in each branch of a function; see\r
114<a href="ProfilingCounts">ProfilingCounts</a> for more details on <span class="monospaced">-profile-branch</span>.</p></div>\r
115</div>\r
116</div>\r
117<div class="sect1">\r
118<h2 id="_caveats">Caveats</h2>\r
119<div class="sectionbody">\r
120<div class="paragraph"><p>With <span class="monospaced">-profile time</span>, use of the following in your program will cause\r
121a run-time error, since they would interfere with the profiler signal\r
122handler.</p></div>\r
123<div class="ulist"><ul>\r
124<li>\r
125<p>\r
126<span class="monospaced">MLton.Itimer.set (MLton.Itimer.Prof, ...)</span>\r
127</p>\r
128</li>\r
129<li>\r
130<p>\r
131<span class="monospaced">MLton.Signal.setHandler (MLton.Signal.prof, ...)</span>\r
132</p>\r
133</li>\r
134</ul></div>\r
135<div class="paragraph"><p>Also, because of the random sampling used to implement <span class="monospaced">-profile\r
136time</span>, it is best to have a long running program (at least tens of\r
137seconds) in order to get reasonable time</p></div>\r
138</div>\r
139</div>\r
140</div>\r
141<div id="footnotes"><hr></div>\r
142<div id="footer">\r
143<div id="footer-text">\r
144</div>\r
145<div id="footer-badges">\r
146</div>\r
147</div>\r
148</body>\r
149</html>\r