Doug's Oracle Blog

In his comment on the last post, John Beresniewicz mentioned the following property of DB CPU :-

"... 'DB time' fully contains 'DB CPU' and both are measured values (which means in particular that 'DB CPU' is not inflated by runq time)"

I'd like to talk about the end of that sentence in particular. About a year and a half ago, I wrote a paper (that's a PDF link) about building response time profiles for sessions that use Parallel Execution. One of the problems I highlighted in that paper was that PX jobs are prone to overload the available CPU resources simply because of the number of PX slave processes that are running concurrently. It's mentioned first in the section on "More Lost Time" on page 4 but most of the rest of the paper goes on to discuss this particular problem. I wasn't very successful coming up with any solutions beyond my usual approach of combining Oracle and O/S tools.

Essentially, as the queue of runnable processes that are waiting to execute on a CPU grows (I'll just refer to it as the run queue from now on), the Oracle server connection processes appear to lose time because they're unable to get on to a CPU in order to record the end time of an event. In the Response Time profilers I've seen, this time is recorded as unaccounted-for and it's what JB's referring to when he talks about runq time. Actually, time spent in the run queue is not the only cause of unaccounted-for time but it's the one I'll focus on here. (Here's another plug for Cary and Jeff's book - other reasons are discussed in chapter 7 on Oracle Kernel Timings.)

As JB stated, DB CPU does not include this time spent waiting in the run queue but the ASH samples for the session are aware that the server connection process is on the CPU or in the run queue. As a consequence, you can see apparently contradictory graphs in the various OEM (DB Control or Grid Control) Performance pages. Although I've tried this with the PX tests and confirmed the same behaviour, I'm going to use Swingbench for the examples here to continue the approach so far and so that you can try them out yourself if you want. (I might post PX examples later.)

Swingbench is supplied with several example applications, one of which is the Sales History (SH) application which uses the SH example schema supplied with recent versions of Oracle. The key attribute of this test for my purpose is that it's read only and CPU intensive, so that the limited I/O bandwidth on a home PC isn't the bottleneck.

I ran 8 concurrent sessions of the SH application for a total duration of 5 minutes with no delay between transactions, which was pretty unrealistic but I was only interested in over-loading the single dual-core CPU in the PC. Soon after the test started, this was how the database instance's home page looked.



CPU is at 100% and there are about 7 sessions active in the database on average, just under 2 of which are running on the CPU, while the rest are waiting. That looks about right. Now, if we look at the performance page at the end of the test, the results are quite different.



It looks like there were only ever about 2 sessions active on average! However, there are a couple of hints as to what's going on. If we look at the graph above as well as the Average Active Sessions graph, we can see that the Host's run queue is far in excess of the two available CPU cores.



Things become even more interesting if we look at the Top Activity screen for the same period.



In that view, the sessions waiting in the run queue are shown, so there's an average of about 7 active sessions during the test. Take a good look at the difference in the key text for the two graphs as well. The Average Active Sessions graph on the Performance Home page shows 'CPU Used', whereas the Top Activity page shows 'CPU'. It's a small but significant and appropriate difference. The first graph shows you the average number of sessions that are actually using CPU and is related to DB CPU in the Time Model Stats, but the Top Activity screen is really showing 'CPU + Wait for CPU', which is the event you'll see throughout an ASH report covering the same period. e.g.

Top Sessions

• '# Samples Active' shows the number of ASH samples in which the session was found waiting for that particular event. The percentage shown in this column is calculated with respect to wall clock time and not total database activity.
• 'XIDs' shows the number of distinct transaction IDs sampled in ASH when the session was waiting for that particular event
• For sessions running Parallel Queries, this section will NOT aggregate the PQ slave activity into the session issuing the PQ. Refer to the 'Top Sessions running PQs' section for such statistics.

Sid, Serial#	% Activity	Event	% Event	User	Program	# Samples Active	XIDs
136, 2716	12.75	CPU + Wait for CPU	12.16	SH	java.exe	227/300 [ 76%]	0
137, 120	12.64	CPU + Wait for CPU	12.32	SH	java.exe	230/300 [ 77%]	0
140, 164	12.59	CPU + Wait for CPU	12.00	SH	java.exe	224/300 [ 75%]	0
144, 240	12.53	CPU + Wait for CPU	11.94	SH	java.exe	223/300 [ 74%]	0
133, 29	12.37	CPU + Wait for CPU	11.62	SH	java.exe	217/300 [ 72%]	0

The more I think about this, the more I think that there's probably a Rule Of Thumb here (I'm joking, really, but maybe it's something I'll look for during further tests). Maybe when DB Time is much bigger than the sum of the wait times on various timed events plus CPU time, it's indicative of CPU overload? Then again, maybe it's just easier to check the process states and run queue?

Finally, I couldn't resist checking what ADDM makes of all this, specially for Graham Wood (that's another PDF link). Well, in this case, ADDM is smart enough to work out what's going on.

          DETAILED ADDM REPORT FOR TASK 'TASK_46' WITH ID 46
          --------------------------------------------------
 
              Analysis Period: 28-AUG-2008 from 23:22:54 to 23:27:56
         Database ID/Instance: 1533705496/1
      Database/Instance Names: TEST1020/TEST1020
                    Host Name: DESKTOP
             Database Version: 10.2.0.4.0
               Snapshot Range: from 26 to 27
                Database Time: 2006 seconds
        Average Database Load: 6.6 active sessions
 
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 
 
FINDING 1: 100% impact (2006 seconds)
-------------------------------------
Host CPU was a bottleneck and the instance was consuming 98% of the host CPU. 
All wait times will be inflated by wait for CPU.
 
   RECOMMENDATION 1: Host Configuration, 100% benefit (2006 seconds)
      ACTION: Consider adding more CPUs to the host or adding instances 
         serving the database on other hosts.
      ACTION: Also consider using Oracle Database Resource Manager to 
         prioritize the workload from various consumer groups.
 
   ADDITIONAL INFORMATION:
      Host CPU consumption was 99%.  CPU runqueue statistics are not available 
      from the host's OS. This disables ADDM's ability to estimate the impact 
      of this finding.  The instance spent significant time on CPU. However, 
      there were no predominant SQL statements responsible for the CPU load.

[In retrospect, the title of that first blog post might have suited the subject, but doesn't translate too well for subsequent related blog posts. That was a lack of planning or foresight on my part. These blog posts are tumbling out of my head in a fairly incoherent way. Maybe when they're finished, I could revisit them and write them up in a single, sensible article! In the meantime, I've retitled the previous post.]

The previous post might have given the impression that you shouldn't pay too much attention to the values in the "Time (S)" column of the Top 5 Timed Events section of a Statspack or AWR report*. That's not true, particularly when comparing system workload between two different periods. (I was just building up to this slowly ) In fact, although the values in that column are not "DB Time" they are nearly all components of it and, just as an increase in the values in that column indicate increased workload or decreased performance during the two different periods, so does an increase in an Instance's DB Time. (Edited later - see JB's comment below. Background Wait Events are *not* components of DB Time, just Foreground Wait Events. I knew that, but wasn't careful enough with this sentence.)

As Chen pointed out in her comment on the last blog, there's a direct relationship between the number of sessions that were running during the reporting period and the total time values. No matter how busy the system, the total time available can not exceed the maximum number of concurrent sessions * wall clock duration that they were running. That's a hard limit, but there are other relationships, too. If you think about it, as the number of active concurrent sessions increased from one to four so did the database instance's workload as more sessions were either working or waiting for something and, if the database is working on something then that implies the application is waiting for it to complete! In all likelihood on a small laptop with limited resources, the actual time spent waiting on individual events would increase as well, as contention for resources increases. Both an increase in the duration of events and an increase in the number of different sessions running or waiting on events will increase DB Time.

Here's a definition of DB Time that you'll see in various presentations from the Oracle guys who worked on this. (e.g. John Beresniewicz's excellent presentation "Average active sessions: the magic metric?" which is available on Kyle Hailey's website. I've never seen JB give the presentation, but I love the slides.)

Database time is total time spent by user processes either actively working or actively waiting in a database call

The same presentation describes the components of DB Time as

Time spent in the database by foreground sessions
Includes CPU time, IO time and wait time
Excludes idle wait time

In the context of a Statspack or AWR report, the top 5 timed events section is showing you the top 5 contributors to DB Time. (In fact, what I find most interesting about the latest versions of the Statspack report is the increased focus on time. For example, the first section of top SQL statements by resource consumption is ordered by DB CPU, followed by the SQL ordered by Elapsed Time, before we get anywhere near Logical or Physical Reads. Regardless of whether you're licensed for the Diagnostics Pack and have access to ASH, AWR and ADDM, you can still take advantage of some of the instrumentation improvements - Event Histograms, for example - and it's clear that Oracle is increasing its focus on time.)

Note that, although I'm choosing to write about aggregated system-wide values as a performance indicator because it's one convenient use of DB Time (particularly when comparing two different periods of time that might be seperated by months or when you have hundreds of systems to support or, most important, if you're writing a tool like ADDM.), I don't think there is anything inherently system-wide about DB Time. If you insist that the only valid performance analysis is that carried out at the session level then, make no mistake, DB Time is recorded for each individual session. It can be used as the input to response time tuning and is really just the Oracle Servers recording of the R in R=S+W. i.e. it's equally useful for Response Time tuning at the session level. In fact, I wish it had been called DB Response Time but I understand that even mentioning 'Response Time' might have led to the argument that the Database Server is only one component of the user's end-to-end response experience and that Response Time doesn't make sense as a term for data that's going to be aggregated for multiple sessions in some cases. (i.e. Can an entire instance have a aggregated Response Time?)

DB Time is the most important of the various Time Model Statistics, which break down the Service component of R = S + W into more detail. Here are the Time Model statistics from the Statspack report for the single-user test. (Don't forget that, as always, this is just reporting underlying statistics. In this case, these statistics are also exposed via v$sys_time_model and v$sess_time_model)

Time Model System Stats  DB/Inst: TEST1020/test1020  Snaps: 22-23
-> Ordered by % of DB time desc, Statistic name

Statistic                                       Time (s) % of DB time
----------------------------------- -------------------- ------------
sql execute elapsed time                           282.9         88.0
DB CPU                                              57.4         17.9
PL/SQL execution elapsed time                        7.8          2.4
parse time elapsed                                   6.2          1.9
hard parse elapsed time                              4.6          1.4
hard parse (sharing criteria) elaps                  2.3           .7
hard parse (bind mismatch) elapsed                   0.6           .2
PL/SQL compilation elapsed time                      0.4           .1
connection management call elapsed                   0.0           .0
repeated bind elapsed time                           0.0           .0
sequence load elapsed time                           0.0           .0
DB time                                     321.5
background elapsed time                            249.4
background cpu time                                  2.3

... and here are the Time Model stats from the Statspack report for the four-user test

Time Model System Stats  DB/Inst: TEST1020/test1020  Snaps: 24-25
-> Ordered by % of DB time desc, Statistic name

Statistic                                       Time (s) % of DB time
----------------------------------- -------------------- ------------
sql execute elapsed time                           779.5         64.8
DB CPU                                             107.7          9.0
PL/SQL execution elapsed time                       15.7          1.3
parse time elapsed                                   2.8           .2
hard parse elapsed time                              2.2           .2
hard parse (sharing criteria) elaps                  1.1           .1
hard parse (bind mismatch) elapsed                   1.1           .1
connection management call elapsed                   0.1           .0
repeated bind elapsed time                           0.0           .0
sequence load elapsed time                           0.0           .0
DB time                                   1,202.4
background elapsed time                            408.3
background cpu time                                  2.7

(For someone who asked me this question recently, DB CPU is just the value you would see in the CPU row of the existing top 5 timed events section although I understand that CPU measurement has been improved significantly in recent versions.)

In this case, there's a relationship between the number of people trying to do something and the total amount of DB Time consumed for a given wall clock duration. If we divide DB Time by the Wall Clock time, we're left with the average number of active sessions during the period. If I apply this first to the single-user test, using the values from the Statspack report :-

Elapsed Time (from report header) = 5.95 minutes = 357 seconds
DB Time (from Time Model Statistics) = 321 seconds
321/357 = 0.89 Average Active Sessions

and, for the four-session test :-

Elapsed Time = 5.5 minutes = 330 seconds
DB Time = 1202 seconds
1202/330 = 3.64 Average Active Sessions

Clearly, the instance was a lot busier during the four session test.

Why weren't the values exactly 1 and 4? Well, for starters, the Statspack reporting periods were slightly longer than the test run period as I executed snapshots manually in a sqlplus session. Therefore there was a period of time in both reports when the server was dead quiet. There is also the application overhead of Swingbench running the benchmarks and submitting the calls to Oracle. Oracle can only sensibly record the time when it's actually doing work on behalf of the application, not when the application is doing it's own thing, processing the results of the last database request. None of the database sessions in this test that were performing many small transactions was active for 100% of the time.

But that's only one part of the relationship. In this case, the instances workload has increased because more users are working at the same time, but there's more to performance problems than that. How about a different example? Imagine a single user is running a single query that takes 2 minutes to complete. The session has been connected for 20 minutes, most of which has been idle, waiting for the user to submit the query. If we look at the session-level information (using v$sess_time_model), we'd see something like this.

DB Time = 120 seconds

i.e. DB Time shows us 'the Oracle bit' that we might be able to tune. The goal of the DB Time Performance Method that Graham Wood presented at last year's UKOUG conference (amongst others) is to reduce the amount of DB Time taken to deliver the same results. So, how can we reduce DB Time here? By making the query run more quickly, whether it's through tuning it to do less work, or increasing the efficiency of that work by reducing bottlenecks. Regardless of *how* I improve the performance of the query, let's say I happen to make the query run in 50 seconds.

DB Time = 50 seconds

The end user's experience has improved.

There's a lot more I could say about DB Time. Like all of the best performance concepts or methods (e.g. YAPP, Method-R) it can seem so obvious as to not be worth saying, but contains an enormous amount of common sense and technical rigour. I suppose one important aspect of DB Time that I would highlight is that it's a common currency for ADDM. If you were to write an automatic performance diagnostic tool, what would be your goal? To reduce the time that any particular action takes, whether that's by eliminating a bottleneck at the server level, or in the instance configuration or a particular part of the application code. By combining ASH and AWR data using DB Time as the key measurement, ADDM can focus on the actions that will deliver the most significant response time reductions, whether they be more CPU or disk resource, tuning individual SQL statements or eliminating locking issues. Because DB Time can be aggregated at many levels (e.g. Session, Service, Instance) , it can be used in a number of different ways, depending on what data is available and what the goal of the optimisation exercise is.

DB Time - it's the future

In the meantime, here are the slides from a couple of other presentations that cover DB Time in much more depth than I have here. Until Graham Wood starts that blog of his (hint, hint) these are the next best thing.

http://www.oracle.com/technology/products/manageability/database/pdf/ow07/diag_techniques_presentation_ow07.pdf

http://doug.nl/downloads/OGH20080410_GRAHAM_WOOD.pdf

Updated later - this article from Chris Foot on dbazine.com looks at v$sys_time_model and v$sess_time_model in more detail.

* Of course, some people would say that you shouldn't pay too much attention to any values in Statspack reports, but they've worked so many times for me that I'll stick to my view that they're not worthless. In any case, you have a balancing contrary view.

When I was teaching the 10g Performance class at my last customer site, I remarked that the total number of seconds you see in the "Top 5 Timed Events" section of a Statspack or AWR report will often be greater than the total number of seconds between the snapshot intervals. For example, this is the "Top 5 Timed Events" section of a Statspack report covering two snapshots that are 5 minutes 30 seconds apart, either side of a 5 minute Sales Order Entry benchmark that I ran using Dominic Giles' Swingbench utility.

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
db file sequential read                          5,814         461     79   38.0
log file sync                                    4,246         421     99   34.7
log file parallel write                          3,222         109     34    9.0
CPU time                                                       108           8.9
db file parallel write                           1,718          60     35    4.9

(Note that this is from a 10.2.0.4 Statspack report, but you would see something similar in all AWR reports and Statspack reports that include CPU time in this section.)

Add up those seconds in the Time column and, even just for the top 5 events, the total is 1159 seconds or 19 minutes and 19 seconds. How can the system have spent 19 minutes and 19 seconds using CPU or waiting on various events when there were only 330 seconds in the reporting period?

The person who asked me to clarify this after the training has seen a few Statspack reports in his time and understood that there is more CPU time available in a given period than the Wall Clock period because servers often have multiple CPUs. But, in this case, I ran the test on my laptop which has a dual-core CPU. Therefore the maximum CPU time available between these snapshots was 660 seconds, or 11 minutes.

No, the real reason is that Statspack is reporting system-wide event timings for more than one session and then aggregating them. In this case, there were four user sessions running the SOE benchmark during the period. Given that each user and background session is instrumented and clocking up both service and wait time, aggregating the data for all of the sessions will record more time than has passed if you look at the clock on the wall.

This is such an intuitive idea to me that I hadn't thought to explain it properly during the course, so I set a mental reminder that I would blog about it soon. Having said that, this has been written about by others on many occasions (^*not least by Cary Millsap and Jeff Holt in Optimizing Oracle Performance. In fact, I stole the title of this blog post from their book - see page 215 for more information.) Therefore, if this post makes complete sense to you so far or you've read any of those sources before, continued reading will probably be a little boring. If not, this post is especially for you.

So let's revisit the tests. I ran two 5 minute tests using Swingbench's supplied Sales Order Entry benchmark, but I could have used anything for this. The important thing is that the first test consisted of one session running the SOE application, while four sessions were running during the second test.

Here is the top 5 timed events section of the Statspack report for the single session test.

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
db file sequential read                          4,818         175     36   46.3
CPU time                                                        57          15.2
db file parallel write                           1,085          42     39   11.2
log file sync                                      821          38     46   10.0
log file parallel write                          2,702          28     10    7.5

... and from the Statspack report for the four session test.

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
db file sequential read                          5,814         461     79   38.0
log file sync                                    4,246         421     99   34.7
log file parallel write                          3,222         109     34    9.0
CPU time                                                       108           8.9
db file parallel write                           1,718          60     35    4.9

So the two tests were running the same application, on the same hardware and for the same duration. Yet the values in the Time (s) column are much bigger when more sessions are running. The total for just the top 5 timed events is 340 seconds compared to 1159 seconds. (The average wait times have also increased in some cases, because the system is busier, and different events become more significant as concurrent sessions contend with each other. There are various things we could try to deduce from this section, particularly as this was a controlled test, but we'd need more supporting information. Let's just stick to the apparently increased time.)

The problem here, if you see it as a problem, is that aggregated data is being reported. Statspack is not the only example of this, though. Tracing Parallel Execution tasks and then aggregating the trace files using trcsess into one consolidated trace file will also result in variable timings, depending on the Degree of Parallelism. I talked about this in slides 33 to 37 of an earlier presentation. In fact, I can make the Time (s) values as big as I want to, just by running the SOE benchmark with more and more sessions.

That's why the % Total Call Time is a far more useful column. It tells you the system-wide percentage contribution of each event to any performance problem over the given period so that you can focus on the most significant contributors. It should go without saying that looking at session-level statistics is more specific and therefore more reliable but that's not always possible unless you're using ASH, Kyle Hailey's Simulated ASH, some other session history recorder or can recreate the problem session on demand, but that's another, bigger argument that I won't go into here.

So if wall clock time for those tests was about 300 seconds, then what is that bigger value being recorded in the Time (s) column? What I'm really talking about is DB Time, but I'll leave that for the next post.