{"id":1858,"date":"2018-05-27T17:18:45","date_gmt":"2018-05-27T17:18:45","guid":{"rendered":"http:\/\/nenadnoveljic.com\/blog\/?p=1858"},"modified":"2019-04-04T15:50:32","modified_gmt":"2019-04-04T15:50:32","slug":"negative-unaccounted-for","status":"publish","type":"post","link":"https:\/\/nenadnoveljic.com\/blog\/negative-unaccounted-for\/","title":{"rendered":"Negative Unaccounted-for"},"content":{"rendered":"

Unaccounted-for<\/h1>\n

In this blog post I\u2019ll be sharing the insights obtained from analyzing a negative unaccounted-for time in an Oracle extended SQL trace profile. <\/p>\n

Ideally, the time elapsed in a fetch database call is the sum of the cpu time and the total duration of the wait events during the fetch:<\/p>\n

<\/a><\/p>\n

(1) <\/span>   <\/span>\"\begin{equation*} <\/p>\n

If that’s not the case, unaccounted-for is the magnitude of the discrepancy:<\/p>\n

<\/a><\/p>\n

(2) <\/span>   <\/span>\"\begin{equation*} <\/p>\n

In other words, unaccounted-for is the adjustment that needs to be made to the right side of the equation 1<\/a> in the case of a mismatch. <\/p>\n

Wait Events<\/h1>\n

Wait event duration (a.k.a time waited) is the time it took to execute a part of Oracle database code instrumented by a wait event. Therefore, the naming “wait event” is somewhat confusing, because it implies that the server process is solely waiting on something. As we shall see later, that\u2019s not necessarily true. For this reason, Cary Millsap prefers to use the term “syscall” instead of “wait” in his excellent book The Method R Guide to Mastering Oracle Trace Data<\/a> . Cary’s naming convention describes the reality much better.<\/p>\n

Anyway, the primary goal of a wait event is to instrument OS kernel functions executed within the Oracle database code. Generally, for any given wait event i<\/i> the time spent in an OS kernel function consists of the time spent on the CPU and the time spent waiting on something:<\/p>\n

<\/a><\/p>\n

(3) <\/span>   <\/span>\"\begin{equation*} <\/p>\n

After combining the equations 1<\/a> and 3<\/a> we get the following:<\/p>\n

<\/a><\/p>\n

(4) <\/span>   <\/span>\"\begin{equation*} <\/p>\n

Finally, we can apply commutative law<\/a> to the previous equation 4<\/a> to isolate the terms:<\/p>\n

<\/a><\/p>\n

(5) <\/span>   <\/span>\"\begin{equation*} <\/p>\n

Usually, the instrumented OS kernel calls, such as IO operations, spend substantially more time waiting on something than consuming CPU. In fact, more often than not the CPU time consumed by such OS kernel functions is close to zero. In such case, the entire wait event duration is the time waited:<\/p>\n

(6) <\/span>   <\/span>\"\begin{equation*}<\/p>\n

CPU Intensive OS Kernel Functions<\/h1>\n

But what will happen if an instrumented OS kernel function spends a considerable amount of time on the CPU? <\/p>\n

First, let\u2019s take a look at the oversimplified pseudocode below to understand how fetch database call is instrumented:<\/p>\n

begin_cpu_ts = slcpums\r\n\r\n# BEGIN FETCH\r\nloop \r\n  non-instrumented code\r\n  code instrumented with a wait event\r\nend loop\r\n# END FETCH\r\n\r\nend_cpu_ts = slcpums\r\n\r\nfetch_cpu = end_cpu_ts - begin_cpu_ts<\/code><\/pre>\n
slcpums is an Oracle database function for getting total CPU time consumed by the process so far. As a consequence, the difference betweeen two consecutive returned values is the total amount of CPU time that the server proces consumed between two slcpums calls. By the way, I provided more details on that topic in my blog post Database Call CPU Instrumentation<\/a>.<\/p>\n
The key point here is that the cpu_time of the instrumented OS kernel function is counted twice in the equation 5<\/a>. To begin with, it is inherently entailed in the wait event duration. And then, it is contained in the fetch_cpu, simply because the wait events are the children of the fetch call. As a result, the sum of the CPU time and the total time spent in the instrumented code needs to be decreased by the amount of time the instrumented code spent on the CPU in order to match the elapsed time. This negative adjustment is unaccounted-for. Simply put, the amount of time that the code instrumented by a wait event spent on the CPU is a negative unaccounted-for:<\/b><\/p>\n
<\/a><\/p>\n
 (7) <\/span>   <\/span>\"\begin{equation*} <\/p>\n
DTrace<\/h1>\n
I put together an experiment to prove the theory expressed with the equation 7<\/a>.<\/p>\n
First, I had to find an instrumented OS kernel function which is consuming CPU. pread qualifies when using ZFS. Therefore, the database needed to be configured for synchronous IO during this experiment (disk_asynch_io = FALSE). <\/p>\n
Then I had to figure out the methodology for measuring the CPU time in the code instrumented by wait events, as Oracle database doesn’t provide that. So, I wrote a DTrace script for this purpose:<\/p>\n
#pragma D option quiet \r\n\r\npid$target:oracle:kslwt_start_snapshot:entry\r\n{\r\n  self->start_ts_cpu = vtimestamp ;\r\n}\r\n\r\npid$target:oracle:kslwt_end_snapshot:entry\r\n\/ self->start_ts_cpu \/\r\n{\r\n  @time[\"cpu by wait events\"] = sum( vtimestamp - self->start_ts_cpu ) ;\r\n}\r\n\r\nEND\r\n{\r\n  normalize(@time, 1000000);\r\n  printa(\"%s: %@d ms\\n\",@time);\r\n}<\/code><\/pre>\n
The server process calls Oracle functions kslwt_start_snapshot and kslwt_end_snapshot before and after the instrumented code, respectively, to take the current timestamp. The difference of both captured values is the time elapsed in the wait event. Accordingly, the DTrace script measures the CPU time consumed between these two points. By the way, I wrote more on wait event internals in the blog post Tracking Wait Events with DTrace<\/a>.<\/p>\n
The DTrace script above measured 42.848 s CPU time consumed by the Oracle code instrumented with wait events:<\/p>\n
cpu by wait events: 42848 ms<\/span><\/code><\/pre>\n
The corresponding tkprof output is below:<\/p>\n
\r\ncall     count       cpu    elapsed       disk      query    current        rows\r\n------- ------  -------- ---------- ---------- ---------- ----------  ----------\r\nParse        1      0.00       0.00          0          0          0           0\r\nExecute      1      0.00       0.00          0          0          0           0\r\nFetch        1     53.39     175.76<\/span>    3408598    3408626          0           1\r\n------- ------  -------- ---------- ---------- ---------- ----------  ----------\r\ntotal        3     53.39     175.76    3408598    3408626          0           1\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  Disk file operations I\/O                       59        0.00          0.00\r\n  direct path read                            26669        0.04        164.69<\/span>\r\n<\/code><\/pre>\n
Next, I’m going to apply the values from the tkprof output above to the equation 2<\/a>:<\/p>\n
unaccounted-for = 175.76 – 53.39 – 164.69<\/span> = -42.32 s<\/span>\t<\/p>\n
As you can see, the DTrace script measured unaccounted-for fairly accurately.<\/p>\n
Test Environment<\/h1>\n