{"id":723,"date":"2018-05-16T22:08:26","date_gmt":"2018-05-16T22:08:26","guid":{"rendered":"http:\/\/second-tech.com\/wordpress\/?p=723"},"modified":"2018-11-02T13:33:17","modified_gmt":"2018-11-02T13:33:17","slug":"using-tbtk-to-time-c-code","status":"publish","type":"post","link":"https:\/\/second-tech.com\/wordpress\/index.php\/2018\/05\/16\/using-tbtk-to-time-c-code\/","title":{"rendered":"Using TBTK to time C++ code"},"content":{"rendered":"<p><i>Most recent TBTK release at the time of writing: v0.9.6<\/i><\/p>\n<p>When developing computationally intensive algorithms, it is important to be able to time the execution to find the main bottlenecks. TBTK therefore provides a flexible Timer class that allows for simple profiling of C++ code.<\/p>\n<div class=\"a-single a-4\"><script async src=\"\/\/pagead2.googlesyndication.com\/pagead\/js\/adsbygoogle.js\"><\/script>\r\n<ins class=\"adsbygoogle\"\r\n     style=\"display:block; text-align:center;\"\r\n     data-ad-layout=\"in-article\"\r\n     data-ad-format=\"fluid\"\r\n     data-ad-client=\"ca-pub-3756520172792312\"\r\n     data-ad-slot=\"9656949358\"><\/ins>\r\n<script>\r\n     (adsbygoogle = window.adsbygoogle || []).push({});\r\n<\/script><\/div>\n<h2>Include file<\/h2>\n<p>The Timer is made available through<\/p>\n<pre class=\"brush: cpp; title: ; notranslate\" title=\"\">\r\n#include &quot;TBTK\/Timer.h&quot;\r\n<\/pre>\n<h2>Stacked tick-tock calls<\/h2>\n<p>In its basic use case the Timer acts as a time stamp stack that allows a single time stamp to be pushed onto the stack through the call<\/p>\n<pre class=\"brush: cpp; title: ; notranslate\" title=\"\">\r\nTimer::tick(&quot;Optional tag.&quot;);\r\n<\/pre>\n<p>The latest time stamp can similarly be popped from the stack using<\/p>\n<pre class=\"brush: cpp; title: ; notranslate\" title=\"\">\r\nTimer::tock();\r\n<\/pre>\n<p>When a time stamp is popped, the time difference between the current time and the time that the time stamp was pushed onto the stack is printed to the standard output. In addition, the current stack depth and the optional tag is also printed. This allows for easy identification of which part of the code a specific time difference corresponds to.<\/p>\n<p>In the following example nested tick-tock calls are used to simultaneously measure the total calculation time of a nested loop as well as the time taken by a single iteration of the outer loop.<\/p>\n<pre class=\"brush: cpp; title: ; notranslate\" title=\"\">\r\nTimer::tick(&quot;Full calculation.&quot;)\r\ndouble sum = 0;\r\nfor(unsigned int i = 0; i &lt; 10; i++){\r\n    Timer::tick(&quot;Single iteration of the outer loop.&quot;);\r\n    for(unsigned int j = 0; j &lt; 10000000; j++)\r\n        sum += sqrt(i*j);\r\n    Timer::tock();\r\n}\r\nTimer::tock();\r\n<\/pre>\n<p>A typical output is<\/p>\n<pre class=\"brush: plain; title: ; notranslate\" title=\"\">\r\n(1) 23ms 356us 578ns \tSingle iteration of the outer loop.\r\n(1) 22ms 121us 595ns \tSingle iteration of the outer loop.\r\n(1) 20ms 894us 633ns \tSingle iteration of the outer loop.\r\n(1) 20ms 693us 151ns \tSingle iteration of the outer loop.\r\n(1) 20ms 753us 656ns \tSingle iteration of the outer loop.\r\n(1) 20ms 632us 406ns \tSingle iteration of the outer loop.\r\n(1) 20ms 693us 43ns \tSingle iteration of the outer loop.\r\n(1) 20ms 751us 261ns \tSingle iteration of the outer loop.\r\n(1) 20ms 420us 362ns \tSingle iteration of the outer loop.\r\n(1) 20ms 753us 927ns \tSingle iteration of the outer loop.\r\n(0) 211ms 272us 43ns \tFull calculation.\r\n<\/pre>\n<p>We can see that each iteration takes 20-23ms to execute while the full calculation takes 211ms. On the left we also see the stack depth, while the tag is displayed to the right.<\/p>\n<p>As a second example we consider the following recursive function call<\/p>\n<pre class=\"brush: cpp; title: ; notranslate\" title=\"\">\r\ndouble recursive(int depth){\r\n        Timer::tick(&quot;Recursive step &quot; + to_string(depth));\r\n\r\n        double answer;\r\n        if(depth == 10){\r\n                answer = 0;\r\n        }\r\n        else{\r\n                double sum = 0;\r\n                for(unsigned int i = 0; i &lt; 10000000; i++)\r\n                        sum += sqrt(depth*i);\r\n                answer = sum + recursive(depth+1);\r\n        }\r\n\r\n        Timer::tock();\r\n\r\n        return answer;\r\n}\r\n<\/pre>\n<p>Each time the recursive function is entered, a new time stamp is pushed onto the stack. After ten consecutive function calls the function begins to return and the time stamp stack is unwinded. The resulting output is<\/p>\n<pre class=\"brush: plain; title: ; notranslate\" title=\"\">\r\n(10) 501ns           \tRecursive step 10\r\n(9) 62ms 570us 861ns \tRecursive step 9\r\n(8) 125ms 299us 748ns \tRecursive step 8\r\n(7) 187ms 827us 863ns \tRecursive step 7\r\n(6) 250ms 704us 696ns \tRecursive step 6\r\n(5) 313ms 284us 290ns \tRecursive step 5\r\n(4) 376ms 373us 532ns \tRecursive step 4\r\n(3) 439ms 518us 286ns \tRecursive step 3\r\n(2) 502ms 852us 691ns \tRecursive step 2\r\n(1) 566ms 298us 567ns \tRecursive step 1\r\n(0) 617ms 420us 578ns \tRecursive step 0\r\n<\/pre>\n<h2>Accumulators<\/h2>\n<p>While the stacked mode allows for flexible measurements of multiple pieces of code at the same time, it is not suitable for a case like the following<\/p>\n<pre class=\"brush: cpp; title: ; notranslate\" title=\"\">\r\nfor(unsigned int i = 0; i &lt; 1000000; i++){\r\n    doA();\r\n    doB();\r\n}\r\n<\/pre>\n<p>Here both doA() and doB() are executed multiple times and we may want to figure out which one that is the bottleneck. Moreover, measuring doA() and doB() in single shot measurements may not be useful for figuring out the overall performance. For example, doA() and doB() may take widely different times to execute each time and the execution time for doB() may even depend on what the previous call of doA() did, and vice versa. In such cases it is only meaningful to measure the accumulated time taken by each function over the full loop.<\/p>\n<p>For this reason the Timer\u00a0 also has an accumulator mode. To use this mode we first create two new accumulators.<\/p>\n<pre class=\"brush: cpp; title: ; notranslate\" title=\"\">\r\nunsigned int idA = Timer::createAccumulator(&quot;Accumulator A&quot;);\r\nunsigned int idB = Timer::createAccumulator(&quot;Accumulator B&quot;);\r\n<\/pre>\n<p>The accumulators can then be used independently by supplying the corresponding ID to the tick-tock calls.<\/p>\n<pre class=\"brush: cpp; title: ; notranslate\" title=\"\">\r\nfor(unsigned int i = 0; i &lt; 1000000; i++){\r\n    Timer::tick(idA);\r\n    doA();\r\n    Timer::tock(idA);\r\n\r\n    Timer::tick(idB);\r\n    doB();\r\n    Timer::tock(idB);\r\n}\r\n<\/pre>\n<p>Since tick-tock pairs can be executed millions of times for any given accumulator, no information is printed by the tock calls in this mode. Instead the time accumulated so far can be printed at any time through the call<\/p>\n<pre class=\"brush: cpp; title: ; notranslate\" title=\"\">\r\nTimer::printAccumulators();\r\n<\/pre>\n<p>A typical output looks like<\/p>\n<pre class=\"brush: plain; title: ; notranslate\" title=\"\">\r\n============================== Accumulator table ==============================\r\nID        Time                                  Tag                                                                                            \r\n&#x5B;0]                       650ms 618us 220ns     Accumulator A                                                                                       \r\n&#x5B;1]                    2s 870ms 110us  19ns     Accumulator B                                                                                       \r\n===============================================================================\r\n<\/pre>\n<p>Note that time is added to the accumulators when the tock calls are made. Therefore, when printing the accumulator table, only completed time intervals contribute to the listed time. We also note that it is possible to use stacked tick-tock calls and accumulator calls simultaneously.<\/p>\n<h2>Learn more<\/h2>\n<p>For more information about the Timer class, see the <a href=\"http:\/\/www.second-quantization.com\/Timer.html\">corresponding manual page<\/a> and <a href=\"http:\/\/www.second-quantization.com\/classTBTK_1_1Timer.html\">API entry<\/a>.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>Most recent TBTK release at the time of writing: v0.9.6 When developing computationally intensive algorithms, it is important to be able to time the execution to find the main bottlenecks. TBTK therefore provides a flexible Timer class that allows for simple profiling of C++ code. Include file The Timer is made available through #include &quot;TBTK\/Timer.h&quot; &hellip; <\/p>\n<p class=\"link-more\"><a href=\"https:\/\/second-tech.com\/wordpress\/index.php\/2018\/05\/16\/using-tbtk-to-time-c-code\/\" class=\"more-link\">Continue reading<span class=\"screen-reader-text\"> &#8220;Using TBTK to time C++ code&#8221;<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[1],"tags":[],"_links":{"self":[{"href":"https:\/\/second-tech.com\/wordpress\/index.php\/wp-json\/wp\/v2\/posts\/723"}],"collection":[{"href":"https:\/\/second-tech.com\/wordpress\/index.php\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/second-tech.com\/wordpress\/index.php\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/second-tech.com\/wordpress\/index.php\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/second-tech.com\/wordpress\/index.php\/wp-json\/wp\/v2\/comments?post=723"}],"version-history":[{"count":75,"href":"https:\/\/second-tech.com\/wordpress\/index.php\/wp-json\/wp\/v2\/posts\/723\/revisions"}],"predecessor-version":[{"id":1204,"href":"https:\/\/second-tech.com\/wordpress\/index.php\/wp-json\/wp\/v2\/posts\/723\/revisions\/1204"}],"wp:attachment":[{"href":"https:\/\/second-tech.com\/wordpress\/index.php\/wp-json\/wp\/v2\/media?parent=723"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/second-tech.com\/wordpress\/index.php\/wp-json\/wp\/v2\/categories?post=723"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/second-tech.com\/wordpress\/index.php\/wp-json\/wp\/v2\/tags?post=723"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}