{"id":1988,"date":"2018-06-03T17:29:32","date_gmt":"2018-06-03T17:29:32","guid":{"rendered":"http:\/\/nenadnoveljic.com\/blog\/?p=1988"},"modified":"2018-06-03T17:29:32","modified_gmt":"2018-06-03T17:29:32","slug":"negative-unaccounted-for-pitfalls","status":"publish","type":"post","link":"https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/","title":{"rendered":"Negative Unaccounted-for (2) – Pitfalls"},"content":{"rendered":"

In my previous blog post<\/a> I described boundary conditions that cause negative unaccounted-for time. The main point is – the CPU time consumed by the code instrumented with a wait event is double counted. To begin with, it’s contained in the CPU time of its parent database call. And then, it’s entailed in the wait event duration. The negative duration of this CPU time is unaccounted-for.<\/p>\n

Although I’ve been was focusing only on SQL extended trace so far, there are more performance diagnostic features where you shouldn’t take the reported elapsed and CPU times at face value. In fact, I’d like to make you aware of a few pitfalls related to the negative unaccounted-for in SQL Monitor and ASH.<\/p>\n

In doing so, I’m using synchronous IO on ZFS for demonstration purposes. On top of that, I’ve now configured the file system cache, that is ZFS ARC, to make pread completely CPU-bound. The database release is 12.2.0.1.180116 on Solaris 11.3. <\/p>\n

tkprof<\/h1>\n

As you can see in the tkprof output below, the sum of the CPU time (19.34s) and wait events duration (13.26s) exceeds the elapsed time (19.34s).<\/p>\n

\r\ncall     count       cpu    elapsed       disk      query    current        rows\r\n------- ------  -------- ---------- ---------- ---------- ----------  ----------\r\nParse        1      0.02       0.02          0         63          0           0\r\nExecute      1      0.00       0.00          0          0          0           0\r\nFetch        1     19.34      19.34    3408598    3408626          0           1\r\n------- ------  -------- ---------- ---------- ---------- ----------  ----------\r\ntotal        3     19.36      19.36<\/span>    3408598    3408689          0           1\r\n\r\n...\r\n\r\nElapsed times include waiting on following events:\r\n  Event waited on                             Times   Max. Wait  Total Waited\r\n  ----------------------------------------   Waited  ----------  ------------\r\n  SQL*Net message to client                       2        0.00          0.00\r\n  SQL*Net message from client                     1        0.00          0.00\r\n  PGA memory operation                            2        0.00          0.00\r\n  direct path read                            26669        0.00         13.26<\/span>\r\n********************************************************************************<\/code><\/pre>\n
unaccounted-for can be calculated as follows:<\/p>\n
unaccounted-for = elapsed – cpu – total_waited = 19.36s – 19.36s – 13.26s = -13.26s<\/p>\n
In other words, the whole execution (19.34s) was on the CPU. Besides that, it took 13.26 s (entirely on the CPU) to execute the code instrumented by the wait event “direct path read”, which was double counted. <\/p>\n
In conclusion, in the case of a non-zero unaccounted-for, it’s wrong to think of elapsed time as the sum of the CPU time and wait event durations.<\/b><\/p>\n
By the way, sophisticated profilers, such as Method-R Profiler<\/a>, report the unaccounted-for.<\/p>\n
SQL Monitor<\/h1>\n
Below is the excerpt from the corresponding SQL Monitor report:<\/p>\n
...\r\nGlobal Information\r\n------------------------------\r\n...\r\nDuration            :  20s<\/span>\r\n...\r\nGlobal Stats\r\n=================================================================\r\n| Elapsed |   Cpu   |    IO    | Fetch | Buffer | Read  | Read  |\r\n| Time(s) | Time(s) | Waits(s) | Calls |  Gets  | Reqs  | Bytes |\r\n=================================================================\r\n|      33<\/span> |      19 |       13 |     1 |     3M | 26669 |  26GB |\r\n=================================================================\r\n...<\/code><\/pre>\n
Obviously, “Elapsed Time(s)” in the “Global Stats” section is calculated as the sum of “CPU Time(s)” and “IO Wait(s)” and therefore misleading. Use “Duration” in the “Global Information” instead.<\/b><\/p>\n
ASH<\/h1>\n
With the following query we’ll verify how the samples are categorized in v$active_session_history:<\/p>\n
column event format a18                                                                                                               \r\nselect session_state,event, count(*) \r\n  from v$active_session_history \r\n  where sql_id = '4hqv20rbt8dck' and\r\n    sql_exec_id = ( \r\n     select max(sql_exec_id) from v$active_session_history \r\n       where sql_id = '4hqv20rbt8dck'\r\n   )\r\n  group by event,session_state ;                                                                                                       \r\n\r\nSESSION EVENT                COUNT(*)\r\n------- ------------------ ----------\r\nWAITING direct path read           14<\/span>\r\nON CPU                              5<\/code><\/pre>\n
Expectedly, there isn’t double counting, as there’s just one sample per second whose session state can be either WAITING or ON CPU. It’s worth noting that the samples taken during the execution of the code instrumented by a wait event were categorized as WAITING, whether the process was on the CPU or not.
\nConsequently, the CPU time based on v$active_session_history can’t be calculated correctly in the case of a negative unaccounted-for.<\/b><\/p>\n","protected":false},"excerpt":{"rendered":"
Find out which information in SQL Monitor report and ASH becomes unreliable in the case of a negative unaccounted-for. Continue Reading →<\/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":[5],"tags":[],"class_list":["post-1988","post","type-post","status-publish","format-standard","hentry","category-oracle"],"yoast_head":"\nNegative Unaccounted-for (2) - Pitfalls - All-round Database Topics<\/title>\n<meta name=\"description\" content=\"Find out which information in SQL Monitor report and ASH becomes unreliable in the case of a negative unaccounted-for.\" \/>\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\/negative-unaccounted-for-pitfalls\/\" \/>\n<meta property=\"og:locale\" content=\"en_US\" \/>\n<meta property=\"og:type\" content=\"article\" \/>\n<meta property=\"og:title\" content=\"Negative Unaccounted-for (2) - Pitfalls - All-round Database Topics\" \/>\n<meta property=\"og:description\" content=\"Find out which information in SQL Monitor report and ASH becomes unreliable in the case of a negative unaccounted-for.\" \/>\n<meta property=\"og:url\" content=\"https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/\" \/>\n<meta property=\"og:site_name\" content=\"All-round Database Topics\" \/>\n<meta property=\"article:published_time\" content=\"2018-06-03T17:29:32+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\\\/negative-unaccounted-for-pitfalls\\\/#article\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/negative-unaccounted-for-pitfalls\\\/\"},\"author\":{\"name\":\"Nenad Noveljic\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#\\\/schema\\\/person\\\/51458d9dd86dbbdd19f5add451d44efa\"},\"headline\":\"Negative Unaccounted-for (2) – Pitfalls\",\"datePublished\":\"2018-06-03T17:29:32+00:00\",\"mainEntityOfPage\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/negative-unaccounted-for-pitfalls\\\/\"},\"wordCount\":431,\"commentCount\":1,\"articleSection\":[\"Oracle\"],\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"CommentAction\",\"name\":\"Comment\",\"target\":[\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/negative-unaccounted-for-pitfalls\\\/#respond\"]}]},{\"@type\":\"WebPage\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/negative-unaccounted-for-pitfalls\\\/\",\"url\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/negative-unaccounted-for-pitfalls\\\/\",\"name\":\"Negative Unaccounted-for (2) - Pitfalls - All-round Database Topics\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#website\"},\"datePublished\":\"2018-06-03T17:29:32+00:00\",\"author\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#\\\/schema\\\/person\\\/51458d9dd86dbbdd19f5add451d44efa\"},\"description\":\"Find out which information in SQL Monitor report and ASH becomes unreliable in the case of a negative unaccounted-for.\",\"breadcrumb\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/negative-unaccounted-for-pitfalls\\\/#breadcrumb\"},\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"ReadAction\",\"target\":[\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/negative-unaccounted-for-pitfalls\\\/\"]}]},{\"@type\":\"BreadcrumbList\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/negative-unaccounted-for-pitfalls\\\/#breadcrumb\",\"itemListElement\":[{\"@type\":\"ListItem\",\"position\":1,\"name\":\"Home\",\"item\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/\"},{\"@type\":\"ListItem\",\"position\":2,\"name\":\"Negative Unaccounted-for (2) – Pitfalls\"}]},{\"@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":"Negative Unaccounted-for (2) - Pitfalls - All-round Database Topics","description":"Find out which information in SQL Monitor report and ASH becomes unreliable in the case of a negative unaccounted-for.","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\/negative-unaccounted-for-pitfalls\/","og_locale":"en_US","og_type":"article","og_title":"Negative Unaccounted-for (2) - Pitfalls - All-round Database Topics","og_description":"Find out which information in SQL Monitor report and ASH becomes unreliable in the case of a negative unaccounted-for.","og_url":"https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/","og_site_name":"All-round Database Topics","article_published_time":"2018-06-03T17:29:32+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\/negative-unaccounted-for-pitfalls\/#article","isPartOf":{"@id":"https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/"},"author":{"name":"Nenad Noveljic","@id":"https:\/\/nenadnoveljic.com\/blog\/#\/schema\/person\/51458d9dd86dbbdd19f5add451d44efa"},"headline":"Negative Unaccounted-for (2) – Pitfalls","datePublished":"2018-06-03T17:29:32+00:00","mainEntityOfPage":{"@id":"https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/"},"wordCount":431,"commentCount":1,"articleSection":["Oracle"],"inLanguage":"en-US","potentialAction":[{"@type":"CommentAction","name":"Comment","target":["https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/#respond"]}]},{"@type":"WebPage","@id":"https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/","url":"https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/","name":"Negative Unaccounted-for (2) - Pitfalls - All-round Database Topics","isPartOf":{"@id":"https:\/\/nenadnoveljic.com\/blog\/#website"},"datePublished":"2018-06-03T17:29:32+00:00","author":{"@id":"https:\/\/nenadnoveljic.com\/blog\/#\/schema\/person\/51458d9dd86dbbdd19f5add451d44efa"},"description":"Find out which information in SQL Monitor report and ASH becomes unreliable in the case of a negative unaccounted-for.","breadcrumb":{"@id":"https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/#breadcrumb"},"inLanguage":"en-US","potentialAction":[{"@type":"ReadAction","target":["https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/"]}]},{"@type":"BreadcrumbList","@id":"https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for-pitfalls\/#breadcrumb","itemListElement":[{"@type":"ListItem","position":1,"name":"Home","item":"https:\/\/nenadnoveljic.com\/blog\/"},{"@type":"ListItem","position":2,"name":"Negative Unaccounted-for (2) – Pitfalls"}]},{"@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\/1988","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=1988"}],"version-history":[{"count":1,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/posts\/1988\/revisions"}],"predecessor-version":[{"id":2007,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/posts\/1988\/revisions\/2007"}],"wp:attachment":[{"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/media?parent=1988"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/categories?post=1988"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/tags?post=1988"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}