{"id":1826,"date":"2018-05-17T18:40:12","date_gmt":"2018-05-17T18:40:12","guid":{"rendered":"http:\/\/nenadnoveljic.com\/blog\/?p=1826"},"modified":"2018-05-17T18:40:12","modified_gmt":"2018-05-17T18:40:12","slug":"wait-events-dtrace","status":"publish","type":"post","link":"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/","title":{"rendered":"Tracking Wait Events with DTrace"},"content":{"rendered":"<h1>Wait Interface Internals<\/h1>\n<p>This blog post describes the DTrace script I came up with while analyzing wrong data in an Oracle SQL Extended SQL Trace file. In particular, the purpose of the script mentioned is to calculate the wait event durations by tracing Oracle database functions and crosschecking the result with the trace data. Although the script is still experimental, it has been producing correct results on my test cases so far. I&#8217;ve been using it on 12.2.0.1.180116 databases and Solaris 11.3.<\/p>\n<p>First of all, let me mention that the script is entirely based on the information presented in Stefan Koehler&#8217;s blog post  <a href=\"https:\/\/blogs.sap.com\/2015\/12\/10\/oracle-understanding-the-oracle-code-instrumentation-wait-interface-a-deep-dive-into-what-is-really-measured\/\">Understanding the Oracle code instrumentation (wait interface) \u2013 A deep dive into what is really measured<\/a>. <\/p>\n<p>Before jumping to the DTrace script, I&#8217;d like summarize (and partially paraphrase) the most relevant information in Stefan&#8217;s article.<\/p>\n<p>1. Oracle function kslwtbctx represents the start of a wait event.<br \/>\n2. Oracle function kslwtbctx calls the function kskthbwt to get\/store the corresponding wait event (number).<br \/>\n3. Oracle function kslwtectx represents the end of a wait event.<br \/>\n4. The Solaris kernel function get_cur_hrtime returns the current time in nanoseconds relative to some arbitrary point in the past.<br \/>\n5. The Solaris kernel function get_cur_hrtime gets called before and after the wait event. Subsequently, the difference between two captured values is reported as the wait event elapsed time.<\/p>\n<h1>DTrace Script<\/h1>\n<pre><code>1  #!\/usr\/sbin\/dtrace\r\n2  \r\n3  #pragma D option quiet\r\n4  \r\n5  pid$target::kslwtbctx:entry\r\n6  {\r\n7    self->start_event = 1 ;\r\n8  }\r\n9  \r\n10 pid$target::kslwtectx:entry\r\n11 {\r\n12   self->end_event = 1 ;\r\n13 }\r\n14 \r\n15 pid$target::kskthbwt:entry\r\n16 {\r\n17   self->event_code = arg2 ;\r\n18 }\r\n19 \r\n20 pid$target::get_cur_hrtime:return\r\n21 \/ self->start_event \/\r\n22 {\r\n23   self->start_ts = timestamp ;\r\n24   self->start_event = 0 ;\r\n25 }\r\n26 \r\n27 pid$target::get_cur_hrtime:return\r\n28 \/ self->end_event \/\r\n29 {\r\n30   printf(\"duration: %d ns\\n\", arg1 - self->start_ts);\r\n31   printf(\"event code: %d\\n\", self->event_code );\r\n32   self->end_event = 0 ;\r\n33   self->start_ts = 0 ;\r\n34 }\r\n35 \r\n36 pid$target::write:entry\r\n37 \/\r\n38   strstr(fds[arg0].fi_pathname,\".trc\") != 0 && \\\r\n39   strstr(copyinstr(arg1),\"WAIT\") != 0\r\n40 \/\r\n41 {\r\n42   printf(\"%s\",copyinstr(arg1));\r\n43   printf(\"------------------------\\n\");\r\n44 }<\/code><\/pre>\n<p>The variable self->start_ts stores the timestamp in nanosecondes returned by the Solaris kernel function get_cur_hrtime (line 23). Since the function get_cur_hrtime gets called in different places in the code, conditions on the lines 21 and 28 filter the executions made in the wait event start and end context, respectively. Later on, the duration is callculated and printed on the line 30. Besides that, the variable self->event_code on the line 17 stores the wait event code, which is then printed on the line 31. Last but not least, the Oracle SQL Extended Trace information is printed on the line 42.<\/p>\n<h1>Output<\/h1>\n<p>Here&#8217;s a sample output:<\/p>\n<pre><code>\r\n...\r\n------------------------\r\n<span style=\"color: #ff0000;\">duration: 4786884 ns<\/span>\r\n<span style=\"color: #0000ff;\">event code: 228<\/span>\r\nWAIT #18446604434613714256: <span style=\"color: #0000ff;\">nam='direct path write'<\/span> <span style=\"color: #ff0000;\">ela= 4787<\/span> file number=1 first dba=453248 block cnt=128 obj#=74 tim=17223120819779\r\n------------------------\r\n...\r\n------------------------\r\n<span style=\"color: #ff0000;\">duration: 581623 ns<\/span>\r\n<span style=\"color: #0000ff;\">event code: 164<\/span>\r\nWAIT #18446604434566192160: <span style=\"color: #0000ff;\">nam='db file sequential read'<\/span> <span style=\"color: #ff0000;\">ela= 582<\/span> file#=1 block#=120860 blocks=1 obj#=423 tim=17223125714073\r\n------------------------\r\n...<\/code><\/pre>\n<p><span style=\"color: #ff0000;\">&#8220;Duration&#8221;<\/span> (in nanoseconds) calculated by the script corresponds to the <span style=\"color: #ff0000;\">&#8220;ela&#8221;<\/span> (in microseconds) in the SQL trace. The <span style=\"color: #0000ff;\">&#8220;event code&#8221;<\/span> captured in the Oracle function kskthbwt refers to the name of the wait event (<span style=\"color: #0000ff;\">&#8220;nam&#8221;<\/span>) in the trace file. <\/p>\n<p>Finally, their relationship can be queried as follows:<\/p>\n<pre><code> select EVENT#,NAME from V$EVENT_NAME where NAME in\r\n  ('db file sequential read','direct path write');\r\n    EVENT# NAME\r\n---------- ----------------------------------------------------------------\r\n       <span style=\"color: #0000ff;\">164 db file sequential read<\/span>\r\n       <span style=\"color: #0000ff;\">228 direct path write<\/span><\/code><\/pre>\n","protected":false},"excerpt":{"rendered":"<p>Measuring Oracle database wait event durations with DTrace <a href=\"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/\" 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":[24,5],"tags":[],"class_list":["post-1826","post","type-post","status-publish","format-standard","hentry","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>Tracking Wait Events with DTrace - All-round Database Topics<\/title>\n<meta name=\"description\" content=\"Measuring Oracle database wait event durations with DTrace\" \/>\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\/wait-events-dtrace\/\" \/>\n<meta property=\"og:locale\" content=\"en_US\" \/>\n<meta property=\"og:type\" content=\"article\" \/>\n<meta property=\"og:title\" content=\"Tracking Wait Events with DTrace - All-round Database Topics\" \/>\n<meta property=\"og:description\" content=\"Measuring Oracle database wait event durations with DTrace\" \/>\n<meta property=\"og:url\" content=\"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/\" \/>\n<meta property=\"og:site_name\" content=\"All-round Database Topics\" \/>\n<meta property=\"article:published_time\" content=\"2018-05-17T18:40:12+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=\"3 minutes\" \/>\n<script type=\"application\/ld+json\" class=\"yoast-schema-graph\">{\"@context\":\"https:\\\/\\\/schema.org\",\"@graph\":[{\"@type\":\"Article\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/wait-events-dtrace\\\/#article\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/wait-events-dtrace\\\/\"},\"author\":{\"name\":\"Nenad Noveljic\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#\\\/schema\\\/person\\\/51458d9dd86dbbdd19f5add451d44efa\"},\"headline\":\"Tracking Wait Events with DTrace\",\"datePublished\":\"2018-05-17T18:40:12+00:00\",\"mainEntityOfPage\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/wait-events-dtrace\\\/\"},\"wordCount\":385,\"commentCount\":0,\"articleSection\":[\"DTrace\",\"Oracle\"],\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"CommentAction\",\"name\":\"Comment\",\"target\":[\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/wait-events-dtrace\\\/#respond\"]}]},{\"@type\":\"WebPage\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/wait-events-dtrace\\\/\",\"url\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/wait-events-dtrace\\\/\",\"name\":\"Tracking Wait Events with DTrace - All-round Database Topics\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#website\"},\"datePublished\":\"2018-05-17T18:40:12+00:00\",\"author\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#\\\/schema\\\/person\\\/51458d9dd86dbbdd19f5add451d44efa\"},\"description\":\"Measuring Oracle database wait event durations with DTrace\",\"breadcrumb\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/wait-events-dtrace\\\/#breadcrumb\"},\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"ReadAction\",\"target\":[\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/wait-events-dtrace\\\/\"]}]},{\"@type\":\"BreadcrumbList\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/wait-events-dtrace\\\/#breadcrumb\",\"itemListElement\":[{\"@type\":\"ListItem\",\"position\":1,\"name\":\"Home\",\"item\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/\"},{\"@type\":\"ListItem\",\"position\":2,\"name\":\"Tracking Wait Events with DTrace\"}]},{\"@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":"Tracking Wait Events with DTrace - All-round Database Topics","description":"Measuring Oracle database wait event durations with DTrace","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\/wait-events-dtrace\/","og_locale":"en_US","og_type":"article","og_title":"Tracking Wait Events with DTrace - All-round Database Topics","og_description":"Measuring Oracle database wait event durations with DTrace","og_url":"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/","og_site_name":"All-round Database Topics","article_published_time":"2018-05-17T18:40:12+00:00","author":"Nenad Noveljic","twitter_card":"summary_large_image","twitter_creator":"@NenadNoveljic","twitter_misc":{"Written by":"Nenad Noveljic","Est. reading time":"3 minutes"},"schema":{"@context":"https:\/\/schema.org","@graph":[{"@type":"Article","@id":"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/#article","isPartOf":{"@id":"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/"},"author":{"name":"Nenad Noveljic","@id":"https:\/\/nenadnoveljic.com\/blog\/#\/schema\/person\/51458d9dd86dbbdd19f5add451d44efa"},"headline":"Tracking Wait Events with DTrace","datePublished":"2018-05-17T18:40:12+00:00","mainEntityOfPage":{"@id":"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/"},"wordCount":385,"commentCount":0,"articleSection":["DTrace","Oracle"],"inLanguage":"en-US","potentialAction":[{"@type":"CommentAction","name":"Comment","target":["https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/#respond"]}]},{"@type":"WebPage","@id":"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/","url":"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/","name":"Tracking Wait Events with DTrace - All-round Database Topics","isPartOf":{"@id":"https:\/\/nenadnoveljic.com\/blog\/#website"},"datePublished":"2018-05-17T18:40:12+00:00","author":{"@id":"https:\/\/nenadnoveljic.com\/blog\/#\/schema\/person\/51458d9dd86dbbdd19f5add451d44efa"},"description":"Measuring Oracle database wait event durations with DTrace","breadcrumb":{"@id":"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/#breadcrumb"},"inLanguage":"en-US","potentialAction":[{"@type":"ReadAction","target":["https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/"]}]},{"@type":"BreadcrumbList","@id":"https:\/\/nenadnoveljic.com\/blog\/wait-events-dtrace\/#breadcrumb","itemListElement":[{"@type":"ListItem","position":1,"name":"Home","item":"https:\/\/nenadnoveljic.com\/blog\/"},{"@type":"ListItem","position":2,"name":"Tracking Wait Events with DTrace"}]},{"@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\/1826","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=1826"}],"version-history":[{"count":1,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/posts\/1826\/revisions"}],"predecessor-version":[{"id":1842,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/posts\/1826\/revisions\/1842"}],"wp:attachment":[{"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/media?parent=1826"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/categories?post=1826"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/tags?post=1826"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}