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.