{"id":2320,"date":"2018-12-12T15:30:50","date_gmt":"2018-12-12T15:30:50","guid":{"rendered":"https:\/\/nenadnoveljic.com\/blog\/?p=2320"},"modified":"2018-12-12T15:30:52","modified_gmt":"2018-12-12T15:30:52","slug":"enriching-trace-with-call-stacks","status":"publish","type":"post","link":"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/","title":{"rendered":"Enriching Trace with Call Stacks"},"content":{"rendered":"<p>I developed a little DTrace script which captures the call stack whenever a line containing a predefined string gets written into the trace file.<\/p>\n<pre><code>#!\/usr\/sbin\/dtrace\n\n\/*\n\n(c) 2018 Nenad Noveljic All Rights Reserved\n\nUsage: dtrace -p PID -s call_stack_trace.d '\"STRING\"'\n\nWARNING:  The script can dramatically slow down the observed process!!!\n\n*\/\n\n#pragma D option quiet\n\nsyscall::write:entry\n\/ \n  pid == $target &amp;&amp; \n  strstr(fds[arg0].fi_pathname,\".trc\") != 0  &amp;&amp; \n  strstr(copyinstr(arg1),$1) != 0  \n\/\n{\n  printf(\"\\n\\n%s\",copyinstr(arg1));\n  ustack();\n}<\/code><\/pre>\n<p>Although this script is generic and can be used with any software, I originally wrote it to understand which Oracle C functions are participating in a particular query transformation.<\/p>\n<p>Its usage is trivial: to begin with, turn on the optimizer trace and then invoke the script as follows to get the call stacks for, for example, the join predicate push-down (<span style=\"color: #ff0000;\">JPPD<\/span>) transformation:<\/p>\n<pre><code>dtrace -p PID -s call_stack_trace.d '\"<span style=\"color: #ff0000;\">JPPD<\/span>:\"'<\/code><\/pre>\n<p>You can see the sample output below:<\/p>\n<pre><code><span style=\"color: #ff0000;\">JPPD<\/span>: Performing join predicate push-down (final phase) from query block SEL$A1EEA789 (#1) to query block SEL$2 (#2)\n\nlibc.so.1`__write+0xa\na.out`sdbgrfuwf_write_file+0x46\na.out`sdbgrfwf_write_file+0x3a\na.out`dbgtfdFileWrite+0x28c\na.out`dbgtfdFileAccessCbk+0x154\na.out`dbgtfWriteRec+0x529\na.out`dbgtRecVAWriteDisk+0xad\na.out`dbgtGrpBVaList_int+0xd8b\na.out`dbgtGrpB_int+0x9d\na.out`kkq<span style=\"color: #ff0000;\">jpd<\/span>pvpd+0x1cec\na.out`kkq<span style=\"color: #ff0000;\">jpd<\/span>pdp+0x320\na.out`kkq<span style=\"color: #ff0000;\">jpd<\/span>ctr+0x4b3\t\t\t  \na.out`qksqbApplyToQbcLoc+0x256\na.out`qksqbApplyToQbc+0x34\na.out`kkq<span style=\"color: #ff0000;\">jpd<\/span>drv+0x199\na.out`kkqdrv+0x1f53\na.out`kkqctdrvIT+0x3e3\na.out`apadrv+0xcba\na.out`opitca+0x966\na.out`kksFullTypeCheck+0x4c<\/code><\/pre>\n<p>The functions containing &#8220;dbg&#8221; in their names are just some low-level debugging functions for writing the output into the trace file.<\/p>\n<p>The functions actually doing the <span style=\"color: #ff0000;\">JPPD<\/span> transformation are the ones with &#8220;<span style=\"color: #ff0000;\">jpd<\/span>&#8221; in their name.<\/p>\n<p>Similarly, below is a captured stack for the OR-Expansion (<span style=\"color: #ff0000;\">ORE<\/span>) transformation:<\/p>\n<pre><code>dtrace -p PID -s call_stack_trace.d '\"ORE:\"'\n\n<span style=\"color: #ff0000;\">ORE<\/span>: # conjunction chain - 3\n\nlibc.so.1`__write+0xa\na.out`sdbgrfuwf_write_file+0x46\na.out`sdbgrfwf_write_file+0x3a\na.out`dbgtfdFileWrite+0x28c\na.out`dbgtfdFileAccessCbk+0x154\na.out`dbgtfWriteRec+0x529\na.out`dbgtRecVAWriteDisk+0xad\na.out`dbgtTrcVaList_int+0xa0f\na.out`dbgtTrc_int+0xa6\na.out`kkq<span style=\"color: #ff0000;\">ore<\/span>GetDNFCount+0xb11\na.out`kkq<span style=\"color: #ff0000;\">ore<\/span>InitStateSpace+0x214\na.out`kkqctiss+0x408\na.out`kkqctdrv<span style=\"color: #ff0000;\">ORE<\/span>+0x13e\na.out`kkqoregdtr+0x94\na.out`qksqbApplyToQbcLoc+0x256\na.out`qksqbApplyToQbc+0x34\na.out`kkqctdrvTD+0x570\na.out`kkqoredrv+0x4a\na.out`kkqdrv+0xf35<\/code><\/pre>\n<p>As you can see, there are indeed a couple of functions containing &#8220;<span style=\"color: #ff0000;\">ore<\/span>&#8221; in their name.<\/p>\n<p>In conclusion, the DTrace script above provides the call stacks and hence a clue for further analysis.<\/p>\n<p>After getting the functions names, I usually go to <a href=\"http:\/\/orafun.info\/\">Frits Hooglands&#8217; Oracle C functions annotations<\/a> for more information.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>A DTrace script for capturing the call stack when a line gets written into the trace file. It&#8217;s useful, for example, for finding out the functions participating in a particular query transformation.  <a href=\"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/\" class=\"more-link\">Continue Reading <span class=\"meta-nav\">&rarr;<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"inline_featured_image":false,"footnotes":""},"categories":[11,24,5],"tags":[],"class_list":["post-2320","post","type-post","status-publish","format-standard","hentry","category-cost-based-optimizer","category-dtrace","category-oracle"],"yoast_head":"<!-- This site is optimized with the Yoast SEO plugin v27.4 - https:\/\/yoast.com\/product\/yoast-seo-wordpress\/ -->\n<title>Enriching Trace with Call Stacks - All-round Database Topics<\/title>\n<meta name=\"description\" content=\"A DTrace script for capturing the call stack when a line gets written into the trace file. It&#039;s useful, for example, for finding out the functions participating in a particular query transformation.\" \/>\n<meta name=\"robots\" content=\"index, follow, max-snippet:-1, max-image-preview:large, max-video-preview:-1\" \/>\n<link rel=\"canonical\" href=\"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/\" \/>\n<meta property=\"og:locale\" content=\"en_US\" \/>\n<meta property=\"og:type\" content=\"article\" \/>\n<meta property=\"og:title\" content=\"Enriching Trace with Call Stacks - All-round Database Topics\" \/>\n<meta property=\"og:description\" content=\"A DTrace script for capturing the call stack when a line gets written into the trace file. It&#039;s useful, for example, for finding out the functions participating in a particular query transformation.\" \/>\n<meta property=\"og:url\" content=\"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/\" \/>\n<meta property=\"og:site_name\" content=\"All-round Database Topics\" \/>\n<meta property=\"article:published_time\" content=\"2018-12-12T15:30:50+00:00\" \/>\n<meta property=\"article:modified_time\" content=\"2018-12-12T15:30:52+00:00\" \/>\n<meta name=\"author\" content=\"Nenad Noveljic\" \/>\n<meta name=\"twitter:card\" content=\"summary_large_image\" \/>\n<meta name=\"twitter:creator\" content=\"@NenadNoveljic\" \/>\n<meta name=\"twitter:label1\" content=\"Written by\" \/>\n\t<meta name=\"twitter:data1\" content=\"Nenad Noveljic\" \/>\n\t<meta name=\"twitter:label2\" content=\"Est. reading time\" \/>\n\t<meta name=\"twitter:data2\" content=\"2 minutes\" \/>\n<script type=\"application\/ld+json\" class=\"yoast-schema-graph\">{\"@context\":\"https:\\\/\\\/schema.org\",\"@graph\":[{\"@type\":\"Article\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/enriching-trace-with-call-stacks\\\/#article\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/enriching-trace-with-call-stacks\\\/\"},\"author\":{\"name\":\"Nenad Noveljic\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#\\\/schema\\\/person\\\/51458d9dd86dbbdd19f5add451d44efa\"},\"headline\":\"Enriching Trace with Call Stacks\",\"datePublished\":\"2018-12-12T15:30:50+00:00\",\"dateModified\":\"2018-12-12T15:30:52+00:00\",\"mainEntityOfPage\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/enriching-trace-with-call-stacks\\\/\"},\"wordCount\":196,\"commentCount\":0,\"articleSection\":[\"cost based optimizer\",\"DTrace\",\"Oracle\"],\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"CommentAction\",\"name\":\"Comment\",\"target\":[\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/enriching-trace-with-call-stacks\\\/#respond\"]}]},{\"@type\":\"WebPage\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/enriching-trace-with-call-stacks\\\/\",\"url\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/enriching-trace-with-call-stacks\\\/\",\"name\":\"Enriching Trace with Call Stacks - All-round Database Topics\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#website\"},\"datePublished\":\"2018-12-12T15:30:50+00:00\",\"dateModified\":\"2018-12-12T15:30:52+00:00\",\"author\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#\\\/schema\\\/person\\\/51458d9dd86dbbdd19f5add451d44efa\"},\"description\":\"A DTrace script for capturing the call stack when a line gets written into the trace file. It's useful, for example, for finding out the functions participating in a particular query transformation.\",\"breadcrumb\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/enriching-trace-with-call-stacks\\\/#breadcrumb\"},\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"ReadAction\",\"target\":[\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/enriching-trace-with-call-stacks\\\/\"]}]},{\"@type\":\"BreadcrumbList\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/enriching-trace-with-call-stacks\\\/#breadcrumb\",\"itemListElement\":[{\"@type\":\"ListItem\",\"position\":1,\"name\":\"Home\",\"item\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/\"},{\"@type\":\"ListItem\",\"position\":2,\"name\":\"Enriching Trace with Call Stacks\"}]},{\"@type\":\"WebSite\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#website\",\"url\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/\",\"name\":\"All-round Database Topics\",\"description\":\"Nenad Noveljic\",\"potentialAction\":[{\"@type\":\"SearchAction\",\"target\":{\"@type\":\"EntryPoint\",\"urlTemplate\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/?s={search_term_string}\"},\"query-input\":{\"@type\":\"PropertyValueSpecification\",\"valueRequired\":true,\"valueName\":\"search_term_string\"}}],\"inLanguage\":\"en-US\"},{\"@type\":\"Person\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#\\\/schema\\\/person\\\/51458d9dd86dbbdd19f5add451d44efa\",\"name\":\"Nenad Noveljic\",\"image\":{\"@type\":\"ImageObject\",\"inLanguage\":\"en-US\",\"@id\":\"https:\\\/\\\/secure.gravatar.com\\\/avatar\\\/a97b796613ea48ec8a7b79c8ffe1c685dcffc920c68121f6238d5caab5070670?s=96&d=mm&r=g\",\"url\":\"https:\\\/\\\/secure.gravatar.com\\\/avatar\\\/a97b796613ea48ec8a7b79c8ffe1c685dcffc920c68121f6238d5caab5070670?s=96&d=mm&r=g\",\"contentUrl\":\"https:\\\/\\\/secure.gravatar.com\\\/avatar\\\/a97b796613ea48ec8a7b79c8ffe1c685dcffc920c68121f6238d5caab5070670?s=96&d=mm&r=g\",\"caption\":\"Nenad Noveljic\"},\"sameAs\":[\"nenad-noveljic-9b746a6\",\"https:\\\/\\\/x.com\\\/NenadNoveljic\"],\"url\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/author\\\/nenad\\\/\"}]}<\/script>\n<!-- \/ Yoast SEO plugin. -->","yoast_head_json":{"title":"Enriching Trace with Call Stacks - All-round Database Topics","description":"A DTrace script for capturing the call stack when a line gets written into the trace file. It's useful, for example, for finding out the functions participating in a particular query transformation.","robots":{"index":"index","follow":"follow","max-snippet":"max-snippet:-1","max-image-preview":"max-image-preview:large","max-video-preview":"max-video-preview:-1"},"canonical":"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/","og_locale":"en_US","og_type":"article","og_title":"Enriching Trace with Call Stacks - All-round Database Topics","og_description":"A DTrace script for capturing the call stack when a line gets written into the trace file. It's useful, for example, for finding out the functions participating in a particular query transformation.","og_url":"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/","og_site_name":"All-round Database Topics","article_published_time":"2018-12-12T15:30:50+00:00","article_modified_time":"2018-12-12T15:30:52+00:00","author":"Nenad Noveljic","twitter_card":"summary_large_image","twitter_creator":"@NenadNoveljic","twitter_misc":{"Written by":"Nenad Noveljic","Est. reading time":"2 minutes"},"schema":{"@context":"https:\/\/schema.org","@graph":[{"@type":"Article","@id":"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/#article","isPartOf":{"@id":"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/"},"author":{"name":"Nenad Noveljic","@id":"https:\/\/nenadnoveljic.com\/blog\/#\/schema\/person\/51458d9dd86dbbdd19f5add451d44efa"},"headline":"Enriching Trace with Call Stacks","datePublished":"2018-12-12T15:30:50+00:00","dateModified":"2018-12-12T15:30:52+00:00","mainEntityOfPage":{"@id":"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/"},"wordCount":196,"commentCount":0,"articleSection":["cost based optimizer","DTrace","Oracle"],"inLanguage":"en-US","potentialAction":[{"@type":"CommentAction","name":"Comment","target":["https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/#respond"]}]},{"@type":"WebPage","@id":"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/","url":"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/","name":"Enriching Trace with Call Stacks - All-round Database Topics","isPartOf":{"@id":"https:\/\/nenadnoveljic.com\/blog\/#website"},"datePublished":"2018-12-12T15:30:50+00:00","dateModified":"2018-12-12T15:30:52+00:00","author":{"@id":"https:\/\/nenadnoveljic.com\/blog\/#\/schema\/person\/51458d9dd86dbbdd19f5add451d44efa"},"description":"A DTrace script for capturing the call stack when a line gets written into the trace file. It's useful, for example, for finding out the functions participating in a particular query transformation.","breadcrumb":{"@id":"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/#breadcrumb"},"inLanguage":"en-US","potentialAction":[{"@type":"ReadAction","target":["https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/"]}]},{"@type":"BreadcrumbList","@id":"https:\/\/nenadnoveljic.com\/blog\/enriching-trace-with-call-stacks\/#breadcrumb","itemListElement":[{"@type":"ListItem","position":1,"name":"Home","item":"https:\/\/nenadnoveljic.com\/blog\/"},{"@type":"ListItem","position":2,"name":"Enriching Trace with Call Stacks"}]},{"@type":"WebSite","@id":"https:\/\/nenadnoveljic.com\/blog\/#website","url":"https:\/\/nenadnoveljic.com\/blog\/","name":"All-round Database Topics","description":"Nenad Noveljic","potentialAction":[{"@type":"SearchAction","target":{"@type":"EntryPoint","urlTemplate":"https:\/\/nenadnoveljic.com\/blog\/?s={search_term_string}"},"query-input":{"@type":"PropertyValueSpecification","valueRequired":true,"valueName":"search_term_string"}}],"inLanguage":"en-US"},{"@type":"Person","@id":"https:\/\/nenadnoveljic.com\/blog\/#\/schema\/person\/51458d9dd86dbbdd19f5add451d44efa","name":"Nenad Noveljic","image":{"@type":"ImageObject","inLanguage":"en-US","@id":"https:\/\/secure.gravatar.com\/avatar\/a97b796613ea48ec8a7b79c8ffe1c685dcffc920c68121f6238d5caab5070670?s=96&d=mm&r=g","url":"https:\/\/secure.gravatar.com\/avatar\/a97b796613ea48ec8a7b79c8ffe1c685dcffc920c68121f6238d5caab5070670?s=96&d=mm&r=g","contentUrl":"https:\/\/secure.gravatar.com\/avatar\/a97b796613ea48ec8a7b79c8ffe1c685dcffc920c68121f6238d5caab5070670?s=96&d=mm&r=g","caption":"Nenad Noveljic"},"sameAs":["nenad-noveljic-9b746a6","https:\/\/x.com\/NenadNoveljic"],"url":"https:\/\/nenadnoveljic.com\/blog\/author\/nenad\/"}]}},"_links":{"self":[{"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/posts\/2320","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/comments?post=2320"}],"version-history":[{"count":1,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/posts\/2320\/revisions"}],"predecessor-version":[{"id":2326,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/posts\/2320\/revisions\/2326"}],"wp:attachment":[{"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/media?parent=2320"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/categories?post=2320"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/tags?post=2320"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}