{"id":3264,"date":"2020-03-23T20:50:56","date_gmt":"2020-03-23T20:50:56","guid":{"rendered":"https:\/\/nenadnoveljic.com\/blog\/?p=3264"},"modified":"2023-06-29T07:08:09","modified_gmt":"2023-06-29T07:08:09","slug":"estimating-db-time-with-ash-logon-storm-pitfall","status":"publish","type":"post","link":"https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/","title":{"rendered":"Estimating DB Time With ASH: Logon Storm Pitfall"},"content":{"rendered":"

This blog post is inspired by John Beresniewicz’s<\/a> presentation DB Time, Average Active Sessions, and ASH Math<\/a>.<\/p>\n

In a nutshell, DB time can be estimated with the sum(usecs_per_row)<\/i> over an observed time period, where usecs_per_row<\/i> is the distance between the adjacent samples in active session history (ASH). Average active sessions (AAS)<\/i> can then be calculated as DB Time \/ elapsed time<\/i>.<\/p>\n

John also wrote two queries for estimating DB time and AAS based on ASH samples and comparing the result with more precise time model statistics: ASHmetricsAAS.sql<\/a> and ASH_TImeModel_AAS.sql<\/a>, respectively.<\/p>\n

Generally, I’ve got very good results while experimenting with John’s queries. For example, let’s consider a workload where multiple concurrent sessions are executing a SQL in a PL\/SQL loop:<\/p>\n

for i in {1..30}\ndo\nsqlplus \/nolog << EOD &\nconnect \/ as sysdba\ndeclare \n  l integer ;\nbegin\n  for i in 1..1e9\n  loop\n    select count(*) into l from dba_objects,dba_objects ;\n  end loop;\nend ;\n\/\nEOD\ndone<\/code><\/pre>\n
We can see that the estimate is perfect:<\/p>\n
@ASHmetricsAAS.sql\n\nEND_TIME               MDBTIME  ASHDBTIME   ASHCOUNT\n------------------- ---------- ---------- ----------\n2020-03-20 11:29:49 29.8652114         30<\/span>       1802\n2020-03-20 11:30:48 30.3782081         30<\/span>       1774\n2020-03-20 11:31:48 29.9119818         30<\/span>       1802\n\n@ASH_TImeModel_AAS.sql\n\nEND_TIME            DBTIME_PCTDIFF    ASH_AAS TIMEMODEL_AAS\n------------------- -------------- ---------- -------------\n2020-03-20 11:29:49              0<\/span>       29.9          29.9\n2020-03-20 11:30:48            1.6<\/span>       29.9          30.4\n2020-03-20 11:31:48              0<\/span>       29.9          29.9<\/code><\/pre>\n
(John’s scripts also estimate the CPU time, but I removed this part from the output.)<\/p>\n
However, I’ve also noticed some discrepancies, whose root cause could be tracked down to a large number of logon operations.<\/p>\n
I’ll demonstrate this by producing a logon storm:<\/p>\n
for j in {1..10000}\ndo\n  for i in {1..30}\n  do\nsqlplus \/nolog << EOD &\nconnect \/ as sysdba\nEOD\n  done\ndone<\/code><\/pre>\n
The ASH based estimate is completely unreliable – only around 1% of the total DB time is recorded in ASH:<\/p>\n
@ASHmetricsAAS.sql\n\nEND_TIME               MDBTIME  ASHDBTIME   ASHCOUNT\n------------------- ---------- ---------- ----------\n2020-03-20 11:38:54 95.5325744 .916666667<\/span>         57\n2020-03-20 11:39:53 70.7569325 .440677966<\/span>         31\n2020-03-20 11:40:54 57.5036575 .803278689<\/span>         54\n\n@ASH_TImeModel_AAS.sql\n\nEND_TIME            DBTIME_PCTDIFF    ASH_AAS TIMEMODEL_AAS\n------------------- -------------- ---------- -------------\n2020-03-20 11:38:54           99.1<\/span>         .9          95.5\n2020-03-20 11:39:53           99.4<\/span>         .4          70.8\n2020-03-20 11:40:54           98.6<\/span>         .8          57.5<\/code><\/pre>\n
Where does this discrepancy come from?<\/p>\n
Most of the time is consumed while the session hasn’t been created yet. This time will be added to the total DB time, but as the entry in v$session<\/i> exists only for a tiny fraction of the total logon time, there will be only very few ASH samples captured.<\/p>\n
I found a way to measure the exact fraction of the time during which the session exists and is active.<\/p>\n
\/* stop_forked.d *\/\n\n#pragma D option quiet\n\nproc:::exec\n\/ execname == \"sqlplus\" \/\n{\n  self->parent = pid ;\n}\n\nproc:::exec-success\n\/ self->parent &&\n  strtok(strtok(curpsinfo->pr_psargs,\" \"),\"oracle\") == $1 \/\n{\n  printf(\"DB: %s, pid: %d \\n\",\n    strtok(strtok(curpsinfo->pr_psargs,\" \"),\"oracle\"),\n    pid\n  );\n  stop();\n}<\/code><\/pre>\n
The script writes out the ID of the just forked dedicated server process.<\/p>\n
sudo -u root \/usr\/sbin\/dtrace -w -s stop_forked.d '\"DB1\"'\nDB: DB1, pid: 2083<\/code><\/pre>\n
The dedicated server process will resume after starting the script measure_login_time.d<\/i>.<\/p>\n
\/* measure_login_time.d *\/\n\n#pragma D option quiet\n\npid$target::main:entry\n{\n  self->started = timestamp;\n}\n\npid$target::kzsini1:entry\n{\n  self->session_started = timestamp;\n}\n\npid$target::kpoauth:return\n{\n  this->completed = timestamp;\n  printf(\"Total time [ns]: %d\\n\", this->completed -  self->started);\n  printf(\"Session time [ns]: %d\\n\", this->completed -  self->session_started);\n}<\/code><\/pre>\n
sudo -u root \/usr\/sbin\/dtrace -s measure_login_time.d -p 2083<\/code><\/pre>\n
The script above measures two elapsed times:<\/p>\n
    \n
  1. Total logon time, which is the elapsed time between entering main and kzsini1<\/i>. kzsini1<\/i> is the Oracle C function which initializes the session and creates the entry in v$session<\/i>.<\/li>\n
  2. Session time is the time during which the session exists and is marked as active. It is measured as the elapsed time between entering main and exiting kpoauth<\/i>. kpoauth<\/i> is the Oracle C function that handles authentication.<\/li>\n<\/ol>\n
    A sample output is below:<\/p>\n
    Total time [ns]: 337947071\nSession time [ns]: 4764305<\/code><\/pre>\n
    As you can see, the total time of the session is 1.4%, which matches the output of the ASH_TImeModel_AAS.sql<\/a> script and explains the difference between the time model and ASH.<\/p>\n
    In conclusion, a large positive difference between the actual DB time and its ASH estimate might indicate that a substantial amount of processing time is spent on logons, due to, for example, ill-configured connection pools, or even lack thereof.<\/p>\n
    This discrepancy isn’t an anomaly – it’s how ASH is designed to work, as it records just the active sessions. Therefore, it’s good to be aware of the activities that are contributing to the total DB time, but don’t result in ASH samples.<\/p>\n","protected":false},"excerpt":{"rendered":"
    Logon storms may substantionally contribute to DB time which isn’t captured in active session history. 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":[24,5],"tags":[],"class_list":["post-3264","post","type-post","status-publish","format-standard","hentry","category-dtrace","category-oracle"],"yoast_head":"\nEstimating DB Time With ASH: Logon Storm Pitfall - All-round Database Topics<\/title>\n<meta name=\"description\" content=\"Logon storms may substantially contribute to DB time which isn't captured in active session history.\" \/>\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\/estimating-db-time-with-ash-logon-storm-pitfall\/\" \/>\n<meta property=\"og:locale\" content=\"en_US\" \/>\n<meta property=\"og:type\" content=\"article\" \/>\n<meta property=\"og:title\" content=\"Estimating DB Time With ASH: Logon Storm Pitfall - All-round Database Topics\" \/>\n<meta property=\"og:description\" content=\"Logon storms may substantially contribute to DB time which isn't captured in active session history.\" \/>\n<meta property=\"og:url\" content=\"https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/\" \/>\n<meta property=\"og:site_name\" content=\"All-round Database Topics\" \/>\n<meta property=\"article:published_time\" content=\"2020-03-23T20:50:56+00:00\" \/>\n<meta property=\"article:modified_time\" content=\"2023-06-29T07:08:09+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\\\/estimating-db-time-with-ash-logon-storm-pitfall\\\/#article\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/estimating-db-time-with-ash-logon-storm-pitfall\\\/\"},\"author\":{\"name\":\"Nenad Noveljic\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#\\\/schema\\\/person\\\/51458d9dd86dbbdd19f5add451d44efa\"},\"headline\":\"Estimating DB Time With ASH: Logon Storm Pitfall\",\"datePublished\":\"2020-03-23T20:50:56+00:00\",\"dateModified\":\"2023-06-29T07:08:09+00:00\",\"mainEntityOfPage\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/estimating-db-time-with-ash-logon-storm-pitfall\\\/\"},\"wordCount\":548,\"commentCount\":0,\"articleSection\":[\"DTrace\",\"Oracle\"],\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"CommentAction\",\"name\":\"Comment\",\"target\":[\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/estimating-db-time-with-ash-logon-storm-pitfall\\\/#respond\"]}]},{\"@type\":\"WebPage\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/estimating-db-time-with-ash-logon-storm-pitfall\\\/\",\"url\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/estimating-db-time-with-ash-logon-storm-pitfall\\\/\",\"name\":\"Estimating DB Time With ASH: Logon Storm Pitfall - All-round Database Topics\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#website\"},\"datePublished\":\"2020-03-23T20:50:56+00:00\",\"dateModified\":\"2023-06-29T07:08:09+00:00\",\"author\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/#\\\/schema\\\/person\\\/51458d9dd86dbbdd19f5add451d44efa\"},\"description\":\"Logon storms may substantially contribute to DB time which isn't captured in active session history.\",\"breadcrumb\":{\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/estimating-db-time-with-ash-logon-storm-pitfall\\\/#breadcrumb\"},\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"ReadAction\",\"target\":[\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/estimating-db-time-with-ash-logon-storm-pitfall\\\/\"]}]},{\"@type\":\"BreadcrumbList\",\"@id\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/estimating-db-time-with-ash-logon-storm-pitfall\\\/#breadcrumb\",\"itemListElement\":[{\"@type\":\"ListItem\",\"position\":1,\"name\":\"Home\",\"item\":\"https:\\\/\\\/nenadnoveljic.com\\\/blog\\\/\"},{\"@type\":\"ListItem\",\"position\":2,\"name\":\"Estimating DB Time With ASH: Logon Storm Pitfall\"}]},{\"@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":"Estimating DB Time With ASH: Logon Storm Pitfall - All-round Database Topics","description":"Logon storms may substantially contribute to DB time which isn't captured in active session history.","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\/estimating-db-time-with-ash-logon-storm-pitfall\/","og_locale":"en_US","og_type":"article","og_title":"Estimating DB Time With ASH: Logon Storm Pitfall - All-round Database Topics","og_description":"Logon storms may substantially contribute to DB time which isn't captured in active session history.","og_url":"https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/","og_site_name":"All-round Database Topics","article_published_time":"2020-03-23T20:50:56+00:00","article_modified_time":"2023-06-29T07:08:09+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\/estimating-db-time-with-ash-logon-storm-pitfall\/#article","isPartOf":{"@id":"https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/"},"author":{"name":"Nenad Noveljic","@id":"https:\/\/nenadnoveljic.com\/blog\/#\/schema\/person\/51458d9dd86dbbdd19f5add451d44efa"},"headline":"Estimating DB Time With ASH: Logon Storm Pitfall","datePublished":"2020-03-23T20:50:56+00:00","dateModified":"2023-06-29T07:08:09+00:00","mainEntityOfPage":{"@id":"https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/"},"wordCount":548,"commentCount":0,"articleSection":["DTrace","Oracle"],"inLanguage":"en-US","potentialAction":[{"@type":"CommentAction","name":"Comment","target":["https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/#respond"]}]},{"@type":"WebPage","@id":"https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/","url":"https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/","name":"Estimating DB Time With ASH: Logon Storm Pitfall - All-round Database Topics","isPartOf":{"@id":"https:\/\/nenadnoveljic.com\/blog\/#website"},"datePublished":"2020-03-23T20:50:56+00:00","dateModified":"2023-06-29T07:08:09+00:00","author":{"@id":"https:\/\/nenadnoveljic.com\/blog\/#\/schema\/person\/51458d9dd86dbbdd19f5add451d44efa"},"description":"Logon storms may substantially contribute to DB time which isn't captured in active session history.","breadcrumb":{"@id":"https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/#breadcrumb"},"inLanguage":"en-US","potentialAction":[{"@type":"ReadAction","target":["https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/"]}]},{"@type":"BreadcrumbList","@id":"https:\/\/nenadnoveljic.com\/blog\/estimating-db-time-with-ash-logon-storm-pitfall\/#breadcrumb","itemListElement":[{"@type":"ListItem","position":1,"name":"Home","item":"https:\/\/nenadnoveljic.com\/blog\/"},{"@type":"ListItem","position":2,"name":"Estimating DB Time With ASH: Logon Storm Pitfall"}]},{"@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\/3264","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=3264"}],"version-history":[{"count":1,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/posts\/3264\/revisions"}],"predecessor-version":[{"id":3280,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/posts\/3264\/revisions\/3280"}],"wp:attachment":[{"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/media?parent=3264"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/categories?post=3264"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/nenadnoveljic.com\/blog\/wp-json\/wp\/v2\/tags?post=3264"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}
First, I’m stopping the dedicated server process immediately after forking. I’m using the stop_forked.d<\/i> script running in the background. I described this script in my blog post Debugging Session Creation<\/a>.<\/p>\n