How To Create Awesome Wait Event Based Histograms

Posted on 19-May-2015 by Craig Shallahamer, craig@orapub.com

You're not totally freaking out... not yet anyways. You know concurrency happens, which can explain why sometimes a single block Oracle read can take over a second.

But, how do you know if this is happening on your systems? How do you know if this is a problem? And, how do you easily demonstrate this to others?

The key to unlocking this mystery (and others) is the data found in v$event_histogram. And then you'll need to display it in a useful way and understand its story.

That's what this post is all about.

6ms Average Wait Time...Not The Whole Story

You may have heard about skewed data. I think it's so important for DBAs to know about this, I have blogged about it HERE and I created an online seminar entitled, Using Skewed Performance Data To Your Advantage . If you want to master this topic, you should take this seminar.

Just how easy is it to be misled and freak out? Read on...

Here's An Example Of How You Can Be Misled

Supposed you gathered 1000 sequential read wait times and 500 of the waits were 1ms, 496 of the waits were 2ms, 3 where 1000ms and the remaining sample was 2000ms. The average wait time would be 6.2ms.

For most production Oracle systems, an average single block read (wait time) of 6.2ms is not that bad. However, if I told you there were a few 1000ms reads and a 2000ms read, would that concern you? And what if over a five minute interval there were lots of 1000ms and few 2000ms reads. Would that concern you? This is when most DBAs start to freak out. But we have got to keep this in perspective.

How To Keep Perspective

In my example above the "slow" wait times occur less 5% of the time. Actually, 4% of the time. If you look at the single block read wait times on your IO intensive systems, don't be surprised if you see something similar.

If you have read books like The Black Swan or have thought about infrequent yet devastating events, you know that bad stuff can happen, just not that often.

Sometimes we care about these infrequent events, like an earthquake, a flood or a financial market crash. But sometimes, while we may care, there isn't much we can do. If so, we need to understand the risk and if necessary mitigate it.

A good example of, "there isn't much we can do" is with IO times. It is very rare for the business to invest in a 100% solid state IO subsystem or significantly alter the business workload to achieve 99.9% super fast and consistent IO times.

But before you even begin the budget discussion, we need to understand and put the "slow" IO times into perspective. A great way to better understand this type of situation is to create a histogram based on actual wait event values. Read on...

Gathering Wait Event Times To Create A Histogram

The key to unlocking this crazy single block IO time mystery is contained in the Oracle view v$event_histogram. There are other options. For example, we can manually gather the times from v$system_event or v$session. But usually, retrieving the values from v$event_histogram or DBA_HIST_EVENT_HISTOGRAM is a better solution for DBAs.

In my latest Firefighting Friday "How To" Webinar I demonstrated how to gather wait event times based on v$event_histogram resulting an series of helpful histograms. In this post, I'll do something similar.

Gathering Wait Event Times To Create A Histogram

In my OSM Toolkit there are a number of tools to gather/report Oracle wait event times. I am going to focus on gathering the data using the swEhVdGet.sql script and then copy/paste its output into the R script swEhCharts.r resulting in a magnificent two-page histogram montage. It's pretty cool.

All my wait event time SQL scripts are well documented and full of examples. Before I use them, I always check the script to remind myself of the options. If you want to really dive into this topic, I highly recommend you read the OSM event histogram readme file, osm/interactive/readmeEventHist.txt.

I created the swEhVdGet.sql script specifically so it contains no DML or DDL, and does not use DBMS_LOCK.SLEEP. Why? Because sometimes Oracle DBAs have super tight production system limitations placed on them. So, I wanted to create a script that could be simply copy and pasted directly into SQL*Plus or run from the command line.

If you look at the top of the script itself, you will notice it can be invoked a number of ways:

Like I said, you have options!

While this script is super flexible, there is one significant downside. Because DBMS_LOCK.SLEEP is not used and I don't know of another wait to "sleep" the script, when it gathers wait times it will likely consume an entire CPU core! Ouch!

Therefore, do NOT use swEhVdGet.sql unless you have the available CPU capacity.

Thankfully, I have even more options! Take a look the OSM interactive/swEhCharts.r R script. At the top of the script, I list multiple ways to gather wait event times. But I digress...

How To Use swEhVdGet.sql

To minimize the CPU impact, the script will exit if either of these two conditions are met. First, enough samples have been collected. Second, the script has looped a specific number of times. (The looping is what consumes the CPU cycles.)

For example, suppose you want 5000 log file sync wait time samples but never want the script to loop more than 1000 times. Having the script prompt you for the parameters, do this:

SQL> @swEhVdGet
Parameter 1 is the Maximum Number Of Sampling Loops (e.g., 100)
Enter value for 1: 1000
Parameter 2 is the Minimum Number of Samples To Collect (e.g., 200)
Enter value for 2: 5000
Parameter 3 is the Wait Event Name (e.g., db%file%seq%read)
Enter value for 3: db%file%seq%read
DEFINE MAXSAMPLELOOPS  = "1000" (CHAR)
DEFINE MINSAMPLECOUNT  = "5000" (CHAR)
DEFINE ENAME           = "log%file%sync" (CHAR)

Collecting event wait times...

Copy and paste the below R code directly into the swEhCharts.r
It must be the last entry in the #2 area of swEhCharts.r

### START ###

eName = "log%file%sync" 

### There were 1000 sampling loops completed and 3819 samples collected. 
### 
count0to1 = 0 
count1to2 = 281 
count2to4 = 1592 
count4to8 = 1368 
count8to16 = 385 
count16to32 = 99 
count32to64 = 68 
count64to128 = 30 
count128to256 = 9 
count256to512 = 0 
count512to1024 = 0 
count1024to2048 = 0 
count2048to4096 = 0 
count4096to8192 = 0 
count8192to16384 = 0 
count16384to32768 = 0 
count32768to65536 = 0 
count65536to131072 = 0 
count131072to262144 = 0 
PL/SQL procedure successfully completed.

### END : Do NOT COPY and PASTE the "PL/SQL procedure..." TEXT INTO R ###

Next, in a text editor open the OSM R script, interactive/swEhCharts.r and scroll down to below the last example. Then copy the above output starting from the "### START ###" to just above "### END" line, being careful to NOT include the "PL/SQL..." line. Now paste that into the R script.

Next, copy and paste the entire R script directly into R. Now press ENTER and you will see two pages of carefully thought out histograms displayed before your eyes!

If you have not installed R or have never used it before, I have some resources for you!

When you paste the R script into R and press ENTER, R will produce some basic statistics (i.e., mean and median) plus two pages of carefully crafted histograms, detailing the wait event activity. Below are the statistics followed by the histograms.

> summary(binValues)
   Min. 1st Qu.  Median    Mean 3rd Qu.    Max. 
  1.000   2.851   4.127   7.379   6.928 255.900 

 

Now you can easily create proper and beautiful Oracle wait event histograms based on v$event_histogram without any DML, DDL or using DBMS_LOCK.SLEEP.

What Are The Statistics And Histograms Telling Me?

Now that you have some statistics and some histograms, it's time to learn about the underlying data. While I'll provide some guidance, my online video seminar entitled, Using Skewed Performance Data To Your Advantage will teach you to be an expert!

Here are a few observations about the data:

If you want to understand the relationship between log file sync wait times and commit times, I did some very cool research on this topic and posted the results HERE.

Summary

My hope is you can calmly investigate shockingly large wait event times. Gathering some wait event data, generating the statistics, creating some histograms and taking the time to better understand the situation does not require that much effort, but the rewards are significant indeed!

To keep this post from getting to long, I did not mention how to get historical wait event data out of the AWR table, dba_hist_event_histogram. As you may have guessed, I do have a script for that. How to use that script will be the topic of my next post. But if you can't wait until next week, just watch my this OraPub "How To" Webinar .

Enjoy your work!

Craig.

If you have any questions or comments, feel free to email me directly at craig at orapub.com.

Comparing Oracle Database SQL Execution Times From Different Systems How To Solve A Similar SQL Statement Parsing Issue Oracle Database Buffer Cache Visualization And Tool