doc/guide/localhost/ProfilingTime

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