{"id":5735,"date":"2020-03-23T08:49:39","date_gmt":"2020-03-23T15:49:39","guid":{"rendered":"https:\/\/visualgdb.com\/w\/?p=5735"},"modified":"2020-03-23T08:49:39","modified_gmt":"2020-03-23T15:49:39","slug":"tracking-separate-callers-when-profiling","status":"publish","type":"post","link":"https:\/\/visualgdb.com\/documentation\/profiler\/separate_callers\/","title":{"rendered":"Tracking Separate Callers when Profiling"},"content":{"rendered":"<p>VisualGDB can record profiling information for Linux projects in one of 2 modes:<\/p>\n<ul>\n<li>One entry per each function<\/li>\n<li>One entry per each unique call stack<\/li>\n<\/ul>\n<p>The first option generally requires less overhead and allows quickly pinpointing the slowest functions. However if those functions are called from multiple locations, it doesn&#8217;t easily allow locating the call stack associated with the most consumed time. We will illustrate this with a basic example.<\/p>\n<p>Consider the following program:<\/p>\n<pre class=\"\">void delay(int iter)\r\n{\r\n    for (int i = 0; i &lt; iter; i++)\r\n        asm(\"nop\");\r\n}\r\n\r\nvoid fast()\r\n{\r\n    delay(1);\r\n}\r\n\r\nvoid slow()\r\n{\r\n    delay(10000000);\r\n}\r\n\r\nint main(int argc, char *argv[])\r\n{\r\n    fast();\r\n    slow();\r\n    return 0;\r\n}<\/pre>\n<p>Most of the time will be spent in the delay() function called with an argument of 10000000 from the slow() function. However the regular profiling report will only show that the function was called twice consuming ~ 60M cycles:<\/p>\n<p><a href=\"https:\/\/visualgdb.com\/w\/wp-content\/uploads\/2020\/03\/01-altogether.png\"><img loading=\"lazy\" decoding=\"async\" class=\"aligncenter size-full wp-image-5736\" src=\"https:\/\/visualgdb.com\/w\/wp-content\/uploads\/2020\/03\/01-altogether.png\" alt=\"\" width=\"653\" height=\"137\" \/><\/a><\/p>\n<p>In this example it is obvious from the inclusive time of <strong>fast()<\/strong> and <strong>slow()<\/strong> that most of the time comes from the <strong> slow()<\/strong> function, however if those functions would call other functions affecting the runtime, or were themselves called from different locations, tracking down the critical path for the delay() function could be tricky.<\/p>\n<p>To track the individual contexts of each functions responsible for the most delay, enable the &#8220;Distinguish up to &lt;&#8230;&gt; parent frames&#8221; option:\u00a0<a href=\"https:\/\/visualgdb.com\/w\/wp-content\/uploads\/2020\/03\/02-distinguish.png\"><img loading=\"lazy\" decoding=\"async\" class=\"aligncenter size-full wp-image-5737\" src=\"https:\/\/visualgdb.com\/w\/wp-content\/uploads\/2020\/03\/02-distinguish.png\" alt=\"\" width=\"574\" height=\"434\" \/><\/a>This will change the way the profiling report looks. You can now view all contexts of the &#8216;delay&#8217; function (i.e. call stacks) by expanding the &#8220;[all contexts]&#8221; node:<a href=\"https:\/\/visualgdb.com\/w\/wp-content\/uploads\/2020\/03\/03-2calls.png\"><img loading=\"lazy\" decoding=\"async\" class=\"aligncenter size-full wp-image-5738\" src=\"https:\/\/visualgdb.com\/w\/wp-content\/uploads\/2020\/03\/03-2calls.png\" alt=\"\" width=\"648\" height=\"292\" \/><\/a><\/p>\n<p>See how the slow call from <strong>slow()<\/strong> is now shown separately from the fast call from <strong>fast()<\/strong>.<\/p>\n<p>If you now look at the functions called from the <strong>fast()<\/strong> or <strong>slow() <\/strong>function, VisualGDB will be able to distinguish different instances of delay() and will show them correctly (e.g. the call to delay() from fast() won&#8217;t be confused with a much slower call from slow():<a href=\"https:\/\/visualgdb.com\/w\/wp-content\/uploads\/2020\/03\/04-annotate.png\"><img loading=\"lazy\" decoding=\"async\" class=\"aligncenter size-full wp-image-5739\" src=\"https:\/\/visualgdb.com\/w\/wp-content\/uploads\/2020\/03\/04-annotate.png\" alt=\"\" width=\"364\" height=\"201\" \/><\/a>You can view the sum of all execution times for all contexts of a certain function by expanding the [totals] node in the report viewer. It will also let you see other contexts via expanding the &#8220;[all contexts]&#8221; node:\u00a0<a href=\"https:\/\/visualgdb.com\/w\/wp-content\/uploads\/2020\/03\/05-all.png\"><img loading=\"lazy\" decoding=\"async\" class=\"aligncenter size-full wp-image-5740\" src=\"https:\/\/visualgdb.com\/w\/wp-content\/uploads\/2020\/03\/05-all.png\" alt=\"\" width=\"649\" height=\"268\" \/><\/a><\/p>\n","protected":false},"excerpt":{"rendered":"<p>VisualGDB can record profiling information for Linux projects in one of 2 modes: One entry per each function One entry<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[200],"tags":[],"_links":{"self":[{"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/posts\/5735"}],"collection":[{"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/comments?post=5735"}],"version-history":[{"count":1,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/posts\/5735\/revisions"}],"predecessor-version":[{"id":5741,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/posts\/5735\/revisions\/5741"}],"wp:attachment":[{"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/media?parent=5735"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/categories?post=5735"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/tags?post=5735"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}