| 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 |
| 14 | asciidoc.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 |
| 32 | find out how much time is spent in each function over an entire run of\r |
| 33 | the program. To do so, compile your program with <span class="monospaced">-profile time</span>.\r |
| 34 | For 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">>=</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">>=</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">=></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">=></span><span class="w"> </span><span class="n">print</span><span class="w"> </span><span class="s">"this branch is not taken</span><span class="se">\n</span><span class="s">"</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">=></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 |
| 76 | 6.00 seconds of CPU time (0.00 seconds GC)\r |
| 77 | function cur\r |
| 78 | ------------- -----\r |
| 79 | Tak.tak1.tak2 75.8%\r |
| 80 | Tak.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 |
| 83 | sequence of period-separated names indicating the structures and\r |
| 84 | functions in which a function definition is nested. The profiling\r |
| 85 | data 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 |
| 91 | 6.00 seconds of CPU time (0.00 seconds GC)\r |
| 92 | function cur raw\r |
| 93 | ------------- ----- -------\r |
| 94 | Tak.tak1.tak2 75.8% (4.55s)\r |
| 95 | Tak.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 |
| 98 | its 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 |
| 102 | 6.00 seconds of CPU time (0.00 seconds GC)\r |
| 103 | function cur\r |
| 104 | ------------------------- -----\r |
| 105 | Tak.tak1.tak2 tak.sml: 5 75.8%\r |
| 106 | Tak.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 |
| 109 | However, in some cases there will be a run-time performance cost,\r |
| 110 | which may perturb the results. There is more likely to be an impact\r |
| 111 | with <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 |
| 113 | out 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 |
| 121 | a run-time error, since they would interfere with the profiler signal\r |
| 122 | handler.</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 |
| 136 | time</span>, it is best to have a long running program (at least tens of\r |
| 137 | seconds) 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 |