How The Oracle Database Determines Wait Time When It's Not Set

This page has been permanently moved. Please CLICK HERE to be redirected.

Thanks, Craig.

Have you ever wondered how the Oracle Database 12c (and earlier versions) determines the wait time when it has absolutely no control over how long the wait will take? If so, then read on!

The Back Story

Using wait time is part of an Oracle Time Based Analysis (OTBA). While Oracle process CPU consumption is a big part of the analysis, the other category is non-idle wait time.

You can see the two categories of time clearly "in action" with my Real-Time Session Sampler script, rss.sql. It's part of my OraPub System Monitor (OSM) toolkit, that can be downloaded for free. Here's an example of the output:

I need to  explain a little more about CPU time and then Oracle wait time.

An Oracle processes wants to burn CPU. Without consuming CPU an Oracle process, can well...not process work! Oracle keeps track of the CPU consumption time. It's the actual CPU time consumed, for example, 500 ms or 3 seconds.

When an Oracle process can not burn CPU, the process, in Oracle terms, it must wait. For example, when an Oracle process waits, it's like it yells out details about why it's waiting. We call this yell a wait event. Each wait event has a name. And the name provides clues about why the process can't burn CPU and is therefore waiting.

There Are Different Reasons Why An Oracle Process Waits

There are three broad categories Oracle must time, when a process is not consuming CPU:

1. When the wait time is predetermined and not interruptible. Perhaps when a latch can not be acquired through repeated attempts so the process takes a break (i.e., sleeps) for a fix period of time, say 10ms.
2. When the wait time is predetermined but the process can be woken by another process. Perhaps a log writer is in the middle of its three second sleep and then a server process commits. The log writer will be signaled to wake and do some work.
3. When Oracle has no idea how long the wait may last. Perhaps a process submitted a block to the IO subsystem for a synchronous read. Oracle has no idea how long this may take. This situation is what I'm focusing on in this posting and I show in the video below.

Exploring When Oracle Has No Idea How Long The Wait Will Take

Let's say when I work it's like an Oracle process consuming CPU. And if I have to stop working to drive to a meeting, it's like an Oracle process waiting. And in this situation,  I really don't know how long the wait will take. It's out of my control. There could be an accident along the way (think: table level lock)! An Oracle process can experience this same kind of thing.

If I'm an Oracle server process and I discover a block I need is not in the buffer cache, I'm going to need to make a call to the OS for that block. When I make the synchronous IO call, I really do not know how long it will take and I have to wait, that is, the Oracle process must wait.

From a DBA perspective, when I perform an Oracle Time Based Analysis (OTBA) I need know how long the IO, that is, the wait took. How does Oracle figure this out? It's pretty simple actually. It's basiclly like this:

• Get the current time, start time
• Make the synchronous IO call and wait until IO received
• Get the current time, end time
• Calculate the delta, end time - start time

The "delta" is the wait time for the single block read. If the single block read is a synchronous read and then placed into the buffer cache, Oracle will tag or name the wait time calling it a "db file sequential read".

Actually Watching An Oracle Process Figuring Out the Wait Time

Some say that seeing is believing. For sure it helps one to learn quickly. If you want to see with your own eyes an Oracle server process determine wait time for a multiple block synchronous read (event name is, db file scattered read), watch the below video.

Pretty cool, eh? By the way, the processing of timing processes and events has a special name, called instrumentation. As we can see, Oracle has instrumented its kernel code.

Enjoy your work and thanks for reading!

Craig.

The LGWR Three Second Rule. Really?

This page has been permanently moved. Please CLICK HERE to be redirected.

Thanks, Craig.

Does the Oracle Database 12c Log Writer Really Sleep For Three Seconds?

I have learned the part of Oracle Database performance tuning is checking if what you have been taught is actually true. What I'm writing about today has been done before in Oracle Database 10g and 11g, but I wanted to document this using 12c.

When I was first learning about the Oracle Database process architecture, the instructor said there are a number of reasons the log writer (LGWR) background process will wake up and do "something." In addition to this, if the LGWR was not signaled to wake up, every three seconds it would wake up by itself and check if there was something it needed to do.

Is this "three second rule" really true? That's what this posting is all about.

If you don't want to read the details below, I created a short video for you to watch.

Here is what you just saw in static text. First let's get the LGWR process PID. Here's one way to do this.

$ ps -eaf | grep lgwr
oracle   41977     1  0 May16 ?        00:00:50 ora_lgwr_prod35
oracle   46294 46110  0 07:39 pts/0    00:00:00 grep lgwr
oracle   60264     1  0 Jan13 ?        00:14:14 ora_lgwr_prod30

My Oracle Database 12c instance is prod35, so the process I'm interested in 41977.

Note: Since this is a 12c instance, there are also two additional log writers, lg00 and lg01. But that's a topic for another posting!

At this point, for simplicity sake it's important there be little instance activity. It will make it much simpler to find what we are looking for... the three second sleep

To watch the LGWR process, I'm going to use the Linux strace command. To easily see the system call timing, I'm going to use the -r option. I'm also going to redirect the output, using the -o option to the out.txt file. I'll let the below strace run for about 15 seconds. OK... here we go:

$ strace -rp 41977 -o out.txt
Process 41977 attached - interrupt to quit
^CProcess 41977 detached

To break out of the strace, I simply did a control-c and the result is what you see above. Let's look at the first three lines of the out.txt file so I can tell you what we will be looking for.

$ head -3 out.txt
     0.000000 clock_gettime(CLOCK_MONOTONIC, {19940373, 720653971}) = 0
     0.000186 gettimeofday({1401979552, 853214}, NULL) = 0
     0.000207 gettimeofday({1401979552, 853444}, NULL) = 0

With the -r option, the first column (far left) shows how long the system call took the for call directly above. For example, in the snipped above, the first clock_gettime call took 0.000186 seconds. The first gettimeofday call took 0.000207 seconds. Got it? Read on!

You may wonder why the system call time is the next line down? It actually makes since, because strace displays information as it becomes available. When the call starts obviously it does not know the call duration, so it just displays the call itself. When the call completes and therefore has the time, it shows return details (e.g., "= 0"), line feeds, prints the call time, the next call is displayed, and repeat. OK, back to our objective.

What we are looking for is a three second sleep. In other words, we are looking for a call that takes three seconds. And since a call's duration shown in the first column of the next line down, we want to look for values in the first column that start with 3.0.

Below is an example of what I found in the out.txt file.

...
     0.000033 clock_gettime(CLOCK_MONOTONIC, {19940376, 746821505}) = 0
     0.000033 semtimedop(7503875, {{16, -1, 0}}, 1, {3, 0}) = -1 EAGAIN

                   (Resource temporarily unavailable)
     3.000436 clock_gettime(CLOCK_MONOTONIC, {19940379, 747351774}) = 0
     0.000188 gettimeofday({1401979558, 879922}, NULL) = 0
     0.000171 clock_gettime(CLOCK_MONOTONIC, {19940379, 747708976}) = 0
...

Looking at the above output snippet, notice the time of 3.000436. Then look at the call directly above it. It's the semtimedop call. This call can be used to put a process to sleep, but the process can be woken up. In other words, the LGWR can set an alarm for three seconds, go to sleep, and if it is not disturbed, it will wake up in three seconds. Shown above is an example of the LGWR setting the alarm for three seconds, not being woken up until the alarm fired. This is an example of the three second rule!

If you do what I did and look at your output file, you'll see lots of these "three seconds." If you do this on a pretty-much idle Oracle Database 12c instance's LG01 process (one of the two default LGWR children), it may contain mostly semtimedop calls, each with a three second sleep.

As you might have guessed, the sleep time is part of the system call. Look closely at the semtimedop call below:

semtimedop(7503875, {{16, -1, 0}}, 1, {3, 0})

Notice the "{3, 0}" near the far right? The defines the maximum delay, that is, the sleep. The 3 is the seconds and the 0 is the number of nanoseconds. If you're interested in other sleep options and the actual code to make this work, check out this posting.

Oracle could have used the select system call (not "select * from...") but that would have been a bad idea because then the process could not be woken before the three seconds limit. This topic touches very closely on Oracle Time Based Analysis and more specifically about Oracle's wait interface. I really get into this, including sample C code in my online video seminar entitled, Introduction To Oracle Time Based Analysis.

So there you go! The Oracle kernel code developers set the default sleep time to three seconds along with the ability for the process to be awoken, should the need arise.

Give It A Try

Check this out for yourself on a test or QA system. Once you see it for yourself, you'll never forget about it!

But it gets even better! If you really want to dig into this, do the same but on your database writer (DBWR). Does the DBWR have a three second rule? Does Oracle use the same system call? I'm not going to tell you the answer. You'll have to figure that out for yourself!

Always A Three Second Delay?

You may have noticed that sometimes the process does not sleep the entire three seconds and at other times Oracle sets the sleep time less than three seconds. What up with that? That will be my next posting!

Thanks for reading,

Craig.