Analysing Statspack (6)

[Back to Part 5][Forward to Part 7]

Here’s an extract of an AWR (automatic workload repository) snapshot published some time ago on the Internet, along with the text describing (apparently) why it’s worth seeing. The extract comes from an article by Don Burleson:

Here is an an example of an Oracle 10g database with an undersized log buffer, in this example 512k:

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~                                        % Total 
Event                                 Waits    Time (s)   DB Time  Wait Class 
log file parallel write               9,670         291     55.67 System I/O
log file sync                         9,293         278     53.12 Commit
CPU time                                            225     43.12
db file parallel write                4,922         201     38.53 System I/O
control file parallel write           1,282          65     12.42 System I/O                          

I have a problem with this data set, though: there’s nothing in the data to point to the explanation – is it intended to give us a clue of what to look for when the log buffer is too small, and if that’s not the intention why bother printing it. (And there’s nothing in any of the surrounding text to explain how you could discover that the problem was the log buffer).

The other problem with this data set is that there is no scope information – how many CPU’s are there on the box, and how long was the snapshot.

Of course, the fact that the “log buffer space” wait doesn’t appear in the top 5 might make you suspect that it’s not really the most important problem with this database; the fact that the author didn’t even print the “log buffer space” wait line from the next section of the AWR report is even more irritating.

So what could you glean from this extract ? Can you find anything in it that tells you that the log buffer might be too small ?

We are told that the buffer is 512KB – if we assume that the DBA hasn’t configured this deliberately and that this is the default log buffer size, then we have one to four CPUs. That doesn’t give us much extra information though.

We can see that (apart from the CPU time) most of the reported time is for background processes – only the log file sync time is a foreground wait. Conveniently it happens to be similar to the log file parallel write time – which tends to suggest that this is a low-concurrency system (When we do a write there seems to be, on average, just one process waiting for that write to complete and it waits about the same amount of time as the write takes to complete). This still doesn’t give us much to go on.

We note that the average times for writes are:

• log file parallel write – 30.1 m/s
• db file parallel write – 40.8 m/s
• control file parallel write – 50.7 m/s

These figures are not particularly good – so if there are complaints about performance we have an indication that slow disk devices are our most obvious root cause.

Of course, log buffer space waits usually need systems with some degree of concurrent activity – if I’ve issued a commit and made the log writer write I’ll be waiting on a log file sync, so someone else has to fill the log buffer to get a log buffer space wait.

There is one exception to this – if I keep generating fairly large redo records then the log writer could be triggered into writing by one of the “non-commit” events … such as seeing the log buffer one-third full.  That could explain why I have more log file parallel write waits than log file sync waits - and why my sync waits total 13 seconds less than my write waits. It would have been so nice to see the stats about the log buffer space waits following a claim that we were looking at a database with an undersized log buffer.

No matter – maybe there are 13 seconds of log buffer space waits. What’s the problem with this machine. We spent 278 seconds waiting on log file sync waits which were dependent on slow log file parallel writes. If we increased the log buffer size we would probably spend an extra 13 seconds in log file sync waiting for slow log file parallel writes. This machine’s problem is probably slow disks.

Of course I wouldn’t normally diagnose a performance problem from just the “Top 5″ events – but if that’s all that’s on offer and it doesn’t agree with the offered diagnosis – then you have to ask for more information. I’d want to check the load profile (how much work was actually happening – such as user calls, executes, transactions), then see what other time was lost just below the “Top 5″ – where, for example, are the disk read times ?

Provisionally: this looks like a small single-user run on a single-CPU box with a slow disk drive; maybe it’s just a testbed Windows laptop.

Practically: if you thought the statistics were supposed to tell you the symptons that would help you spot an undersized log buffer, they don’t.

Example 2:

Here’s another sample from the same author which also seems to suggest that the statistics are supposed to be symptomatic of an undersized log buffer. For the present I’ll leave them to you to think about. I may come back and let you know what I think they show at some future date.

Here is a AWR report showing a database with an undersized log_buffer, in this case where the DBA did not set the log_buffer parameter in their init.ora file:

                                                                Avg
                                                  Total Wait   wait    Waits
Event                            Waits   Timeouts   Time (s)   (ms)     /txn 
log file sequential read         4,275          0        229     54      0.0
log buffer space                    12          0          3    235      0.0                  

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~                                           % Total
Event                                     Waits    Time (s) Ela Time 
CPU time                                            163,182    88.23
db file sequential read               1,541,854       8,551     4.62
log file sync                         1,824,469       8,402     4.54
log file parallel write               1,810,628       2,413     1.30
SQL*Net more data to client          15,421,202         687      .37                  

For further reading, here’s a reference to a thread on the Oracle Forum which prompted me to review and examine these samples.

[Edited 2nd Aug 2007]  The reference of the forum thread was originally followed by a link to Don Burleson’s response to my comments. The response has recently been removed from his website, so I have deleted the link.
[Back to Part 5][Forward to Part 7]

Footnote: Any advice about reading AWR reports is almost always relevant when reading Statspack reports (and vice versa).