Ouch! Log File Switch Checkpoint Incomplete
Users are screaming. They say their screen freezes for multiple seconds, and it makes no difference where they are in the application.
I run my Oracle time-based analysis report and staring me in the face is the Oracle wait event - log file switch checkpoint incomplete. I also noticed that Oracle processes are consuming more CPU time than log file switch time!
What does this mean, what can be done, and how should I move forward? How to fix an Oracle log file switch checkpoint incomplete wait event situation is what this article is all about.
Listening To The Users
Ah yes... music to my ears. As I mentioned, the application users are upset... really upset. When they save their work anywhere in the application, their screen can freeze up to 20 seconds. But it appears random to them. The only consistent part of their experience is the freeze only happens when they save their work.
When I hear a story like this, I am immediately thinking block or lock.
The lock could be something like a table level or row level lock. But regardless, it is related to a relational object. I would expect the associated wait event would be either a TM or a TX enqueue wait.
When a user experiences a frozen screen when they save their work and it's not about an enqueue wait, it is probably more Oracle redo specific as opposed to an application object (e.g., table) related. It's like something is preventing Oracle processes from moving forward after the user saves their work. An Oracle checkpoint related wait event fits this scenario perfectly.
Once I see the Oracle time-based report, I will know whether it's locking or blocking related. And when I look at the operating system situation and a more SQL perspective, I should have everything I need to devise multiple solutions. So, let's get started!
Oracle Time Baseline
In my OSM toolkit the script, ttpctx.sql is a basic Oracle time-based (think: db time) analysis report. This script works like this: You run the script once to gather the initial statistics, pause for a while and then run it again. What is displayed is the delta. As long as you remain connected to Oracle, each subsequent run will display another delta based on the previous run and the present.
As you can see, the output is very similar to the "Top 5 Events" table we see on any AWR or Statspack report. Notice my "delta" or sample time was 264 seconds, which is about 4 1/2 minutes.
SQL> @ttpctx DB/Inst: prod30/prod30 27-Apr 05:54am Report: ttpctx.sql OSM by OraPub, Inc. Page 1 Total Time Activity (264 sec interval) Avg Time Time Wait Time Component % TT % WT Waited (ms) (sec) Count(k) -------------------------------------- ------- ------- ----------- ----------- -------- CPU consumption: Oracle SP + BG procs 45.55 0.00 0.000 837.416 0 log file switch (checkpoint incomplete 29.16 53.56 642.024 536.090 1 db file async I/O submit 7.55 13.87 325.892 138.830 0 db file scattered read 5.29 9.71 0.490 97.180 198 control file parallel write 2.80 5.14 20.924 51.410 2 log file parallel write 2.43 4.46 33.192 44.610 1 log file switch completion 1.70 3.12 157.626 31.210 0 enq: CI - contention 1.58 2.91 539.074 29.110 0 enq: CF - contention 1.40 2.56 113.040 25.660 0 db file single write 0.86 1.58 12.547 15.860 1 db file sequential read 0.41 0.75 0.050 7.530 152 ...
What Is A Log File Switch (Checkpoint Incomplete) Event?
Just what is an Oracle Database log file switch checkpoint incomplete wait event? I'll try to explain this as quickly and as best I can. When an Oracle session change an Oracle buffer in the buffer cache, their process copies just enough redo information into the redo buffer. For a number of reasons, a log writer will write their redo from the redo buffer to an online redo log file. The online redo log files are connected serially one to the next creating a closed loop. When the log writer is writing to an online redo log, eventually it will fill and the log writer must switch to the next online redo log and then begin writing. This switchis the "log file switch" in the wait event "log file switch (checkpoint incomplete)."
When the log writer wants to switch to the next online redo log, a checkpoint is initiated. This checkpoint is the "checkpoint" in the wait event "log file switch (checkpoint incomplete)."
The Oracle session is waiting, literally frozen, waiting for the checkpoint to complete.
This type of checkpoint requires all the changed buffers related to the redo in the switched-into-redo-log to be written into their associated Oracle database file (DBF). This waiting is absolutely necessary.
Here's why: Supposed this next redo log contained committed data and the only other place this committed data currently resides is in Oracle's buffer cache. Therefore, if the log writer was to switch into this next online redo log and then overwrites the committed AND there was an instance failure resulting in the buffer cache vanishing into thin air... the committed data would be lost. Truly a DBAs nightmare situation and a situation Oracle will try very hard to never ever allow.
Once the database writer(s) is done writing all the checkpoint related buffers to their DBF file and a few housekeeps chores are done, the checkpoint is now complete. And the log writer is allowed to complete the log switch and begin writing into this next online redo log.
Once the log writer has finished writing the user's redo to the online redo log file, their commit is essentially finished and they can continue with the work.
Very cool stuff from technical perspective! But let's get back to solving the problem...
Get A Performance Baseline
Before we continue diagnosing the situation, we need to create a baseline. Here's my thinking: I need to know if my performance have done any good. And I want this numerically quantified. I want to document the workload, the wait event situation and in this case, the online redo log switch rate. I'll detail each of these.
Baseline: Log file switch rate
Usually in a log file switch checkpoint incomplete situation, the online redo logs are switching every few minutes or even every few seconds! One way to get the switch rate is to time how many switches occurs within a single minute. Take at least three samples. If they differ more than say 5 switches per minutes, take a few more samples.
Here is how I did this:
SQL> show parameter background_dump_dest NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ background_dump_dest string /home/oracle/base/diag/rdbms/p rod30/prod30/trace SQL> !tail -f /home/oracle/base/diag/rdbms/prod30/prod30/trace/alert*log | grep "advanced to log sequence" Thread 1 advanced to log sequence 335098 (LGWR switch) Thread 1 advanced to log sequence 335099 (LGWR switch) Thread 1 advanced to log sequence 335100 (LGWR switch) Thread 1 advanced to log sequence 335101 (LGWR switch) ...
On my system, I collected three one-minute samples. The values where 37, 38 and 34 log switches per minute. So, the average is 36.33 switches/minute. I will record this because it is part of my baseline. When I implement my solutions, I'm hoping the log switch rate will dramatically reduce.
Baseline: Wait Event Percentage
Referencing my total time report (ttpctx.sql) report above, from a total time perspective (cpu and non-idle wait time), log file switch checkpoint incomplete time accounts for 29.16% of the total time. From a wait time only perspective, the event time accounts for 53.56% of all the wait time.
When I implement my solutions, I'm hoping the log file switch checkpoint incomplete wait time percentage will dramatically decrease.
Baseline: Workload Rate
Normally, I would pick a few users and time how long it takes to commit transactions. If that is not possible, I'll pick an Oracle workload related statistics that incapsulate buffer changes. One perfect statistics is, db block changes. What I really want is change rate, such as block changes per second.
Here's how I can get this statistic over a 60 second interval.
set serveroutput on variable bogus_v number; begin select value into :bogus_v from v$sysstat where name='db block changes'; dbms_lock.sleep(60); select (value-:bogus_v)/60 into :bogus_v from v$sysstat where name='db block changes'; dbms_output.put_line('block changes per sec = '||round(:bogus_v,2)); end; /
On my system, I ran the above script three times. The block changes per second where 13680.85, 13223.25 and 11930.93. So, the average is 12945.01 block changes per second.
When I implement my solutions, I'm hoping the block change rate will dramatically increase. I want there to be absolutely no question the system is processing a lot more work. If I am not convinced my chosen workload statistic will allow me to demonstrate this, I'll find another statistic or use multiple statistics.
I have now completed gathering the baseline performance statistics. This is what we have collected:
After the chosen solution is implemented, I will gather the performance statistics again... hopefully seeing a significant improvement!
Take A Breath
So far we have listened closely to our users, gathered baseline performance statistics and took a quick look at the Oracle timing situation (@ttpctx.sql). This is my starting point.
Next I will look closely at Oracle, the operating system and also the application. For each of these subsystems, I will derive at least one solution, rank them and select one to implement, implement it and then re-run my baseline hoping to see a marvelous improvement.
That's too much for a single blog post. So, I'm going to end this post and make another post in a week or two.
Thanks for reading and enjoy your work!
If you have any questions or comments, feel free to email me directly at craig at orapub.com.
|Hmm... Better Oracle Database Tools Are the Answer To Increased Complexity?||How To Change The Priority Of Oracle Database Background Processes||IOUG 2016 Is Different: Here's How To Get Your Abstract Accepted|