JL Computer Consultancy

Statspack timed events

Mar 2005


Important Update: 9th Sept 2005


It’s very easy to be fooled by a summary – take a look at this ‘Top 5 Timed Events’ report from an Oracle 9i system:

Top 5 Timed Events

~~~~~~~~~~~~~~~~~~ % Total

Event Waits Time (s) Ela Time

-------------------------------------------- ------------ ----------- --------

CPU time 11,330 81.95

log file sync 163,725 1,012 7.32

enqueue 4,486 615 4.45

latch free 28,786 236 1.71

db file sequential read 1,420,355 149 1.08

-------------------------------------------------------------

Is there a performance problem, and if so what is it?

Think about that question for a minute before you scroll down the page to see the answer.


 

 

 

 

 

 

 


Top 5 Timed Events

~~~~~~~~~~~~~~~~~~ % Total

Event Waits Time (s) Ela Time

-------------------------------------------- ------------ ----------- --------

CPU time 11,330 81.95

log file sync 163,725 1,012 7.32

enqueue 4,486 615 4.45

latch free 28,786 236 1.71

db file sequential read 1,420,355 149 1.08

-------------------------------------------------------------

Even though the numbers look unusual, the first thing you should notice is that I haven’t supplied enough information for you to make a sensible decision.

What was the time interval – wouldn’t that make some difference to your interpretation of the figures? The total CPU time reported is a little over 3 hours – would that be significant if the report covered a 12 hour, or 24 hour period? Maybe, maybe not.

Okay, so the time interval was 15 minutes – does this give you a better clue about the performance problem ?

Think about it, then scroll down the page.


 

 

 

 

 

 

 


Top 5 Timed Events

~~~~~~~~~~~~~~~~~~ % Total

Event Waits Time (s) Ela Time

-------------------------------------------- ------------ ----------- --------

CPU time 11,330 81.95

log file sync 163,725 1,012 7.32

enqueue 4,486 615 4.45

latch free 28,786 236 1.71

db file sequential read 1,420,355 149 1.08

-------------------------------------------------------------

How many CPUs do you think the system has? I’ve recorded about three and a quarter hours of CPU in 15 minutes. If I had 13 CPUs, I could get that by running them all at 100% - then I probably would say that CPU was my bottleneck. In fact, this system is running with 48 CPUs, so it’s only been using about 27% of the available CPU – which means CPU probably isn’t a threat.

Of course, it is possible that in that 15 minutes interval two or three critical processes (or even 12 of them) had each been flogging a single CPU to death – so there could be 12 processes that are CPU bound whilst every other user of the system is perfectly content with their own performance. Life is like that with big systems, the issues can be a little more subtle than you might think at first sight. In some ways, it’s a nuisance that Oracle Corp. has put the CPU time into the same list as the wait events – there is a critical difference between waiting and working, namely the amount of CPU available in an interval is strictly limited by “no of CPUs * number of seconds in interval”. (Actually, even that is subject to a type of overlap problem. If a single call has been consuming CPU non-stop for the last 30 minutes, and the call finishes in the current fifteen-minute snapshot, then that’s 30 minutes worth of CPU in one snapshot that should have been spread over two or three snapshots. It’s a bit rare, but you may have to examine a few consecutive reports if you suspect that this type of event could have occurred).

So should we look at the first wait event on the list – the log file sync – as the source of a performance problem; after all, we’ve lost 1,012 seconds (16 minutes 52 seconds) in a fifteen minute period. Think about the implications of that, and then scroll down.


 

 

 

 

 

 

 

 

 


Top 5 Timed Events

~~~~~~~~~~~~~~~~~~ % Total

Event Waits Time (s) Ela Time

-------------------------------------------- ------------ ----------- --------

CPU time 11,330 81.95

log file sync 163,725 1,012 7.32

enqueue 4,486 615 4.45

latch free 28,786 236 1.71

db file sequential read 1,420,355 149 1.08

-------------------------------------------------------------

A log file sync occurs when a session sends a call to the log writer (lgwr) to write the log buffer up to a certain point and waits for acknowledgement from the log writer. In a highly concurrent system with lots of very small transactions, dozens of sessions could do this more or less simultaneously – and then they would all have to wait for lgwr to complete one large write – up to the highest marker it discovered waiting when it woke up – before continuing.

A single write by lgwr taking just one hundredth of a second, could satisfy literally dozens of these ‘piggyback’ commits, and it is quite possible that no one session ever has to wait very long for a log file sync. (The average wait is about 6.2 milliseconds in this example, which seems quite harmless but we need to check whether lgwr is having trouble with writing. It’s cases like this that make the 10g view v$event_histogram useful as it would be nice to know something about the variation in wait times).

Just like CPU time, the wait for log file sync is a bit of an oddity. Every single session could be waiting on, and freed simultaneously by, exactly one action. Despite the apparently large numbers, there really is only one critical wait going on at any one moment.

You will notice, of course, that we have done about 11,000 transactions per minute for the 15 minutes (A log file sync is almost synonymous with the completion of a transaction). That’s quite a busy rate of work – and it could be work that is being done very badly. It could, for example, indicate that we have a 3GL (or generated program) trying to updates thousands of rows of data one row at a time and committing on each row. But if it were, we would probably see lgwr suffering thousands of waits for log file parallel write and the same 1,000 second time loss. (But see important update below.)


I won’t go on with the ‘scroll down and see’ approach as the next three events are the ones that have some significance.

The enqueue waits were a bit of a problem, although it’s not really visible from the summary. As you can see, the average wait is about 13.7 centiseconds (137 milliseconds) – but the range of wait times varied between zero and 0.5 seconds and in this application, the intermittent long waits can have a serious knock-on effect.


The latch free waits weren’t really very much of a problem. Given the vast amount of work going on (which also isn’t totally obvious from the summary) we have a relatively small number of waits, and the average wait time is only one hundredth of a second. But these latch waits are largely split between library cache and shared pool latch waits (not cache buffers chains). The system was getting close to the edge of its scaling limit – a little more stress on the library cache and shared pool latches, and the latch contention is likely to escalate dramatically and become a serious bottleneck. (A couple of code changes eliminating this stress point were implemented just a couple of days after I reviewed the system).


The db file sequential read waits are extraordinary: the average wait time is 100 microseconds. Almost all of these reads are being satisfied from the file system buffer. The time loss isn’t great overall but there’s clearly a little warning that something might be waiting to go wrong. We are doing nine “physical” reads per transaction – what’s going to happen to transaction times if just a couple of those reads really do turn into real trips to disc?

It’s possible, of course, to move memory from the file system to the Oracle buffer cache – there is a slight chance that this may give a slight performance benefit; there is a slight chance that it may result in an increase in latch contention (cache buffers chains latch). More significantly, it’s worth looking at options for reducing the I/O requirement for critical parts of the code.


Finally, there’s one problem that is invisible, and will always remain invisible in this report. We are doing 11,000 (real) transactions per minute, and a lot of statement executions that you can’t see. We are doing about 100,000 “physical” reads per minute, and a lot of logical I/O that you can’t see.

You don’t know how many network round-trips are going on, and how much time is being lost on them – even though the report gives you a very small hint that there may be a lot of them. This system happens to be one of those where the various “SQL*Net message” wait events could be rather important – and it’s deliberately excluded from the summary.


Conclusion:

When you look at a Top 5 report, there are usually several other things you have to keep in mind at the same time. At a minimum these would be:

         the time between snapshots

         the number of CPUs

         the typical level of concurrency

         and the nature of the application.

As this example shows, not only is it possible for the top (or even top 2) of the Top 5 report to be totally misleading; sometimes you may even have to think about that’s implied by the summary, but not in the summary. Be careful when you use Statspack – it’s very easy to look at the headline numbers and be totally fooled.


Addendum 4th April 2005

Shortly after completing this article, I noticed that a relevant thread had popped to the top of the list on AskTom. “Statspack: Who waits on logfile sync …”. In that thread, the most recent poster had supplied part of a fifteen minute statspack snapshot from an Oracle 8.1 system – including the following “Top 5” section.

(Note – although the original sample included the Heading that identifies the database and version, you can tell that the following extract is from Oracle 8i because its title is “Top 5 Wait Events” rather than “Top 5 Timed Events”, and the times are in centiseconds rather than seconds; the column headings also change with the version of Oracle).

Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
-------------------------------------------- ------------ ------------ -------
log file sync 1,108 30,766 37.11
log file parallel write 890 22,068 26.62
control file parallel write 224 21,963 26.49
db file sequential read 4,903 4,367 5.27
db file parallel write 69 1,825 2.20

I’ve picked up this example because it happens to reflect my comments above about log file sync and log file parallel write. In this case we see that log file sync (the user session event) is at the top of the list, but it is followed closely by log file parallel write (the background event from lgwr). Not only that, but we can also see that there is nearly a one to one match between the numbers of waits on these two events.

In this case, it is probably the case that the log file sync wait time is high as a direct consequence of a problem that lgwr has – nearly every time a user session commits it has to wait a (long) time for the log writer to write. Solve the log writer problem, and the log file sync wait time is likely to vanish as a consequence.

In fact, something strange seems to be going on. Looking more closely at the numbers, you notice that the average log file parallel write is taking about a quarter of a second; the average control file parallel write is taking nearly one second, and the average db file parallel write is taking about a quarter of a second. (The only I/O event that isn’t extremely bad is the db file sequential read averaging just under 1 hundredth of a second). Based purely on this set of numbers, you might want to ask more questions about the I/O activity – it looks as if there may be a hardware problem with the I/O subsystem, possibly a real physical glitch, perhaps a configuration issue).

(I was just about to post this update when I decided to check the link, and found that Tom Kyte had added a link to his article to point to my article – a case of the dreaded circular reference. Still, we can safely say that neither of us is attempting proof by circular reference).


Important Update – 9th Sept 2005:

There is a bug in Oracle 9.2 that results in the wait time for event log file parallel write being under-recorded. This bug is not present in 8i, and has been fixed in 10g. A critical consequence of this bug is that you may see lots of time lost on log file sync and only a little time lost on log file parallel write waits, yet still have an I/O problem on log file parallel write.

My comments above about log file sync and log file parallel write are true for 8i and 10g, but not conclusive for 9.2.

In 9.2, a high log file sync time with a low log file parallel write time may simply mean that lgwr is not reporting time properly. You may be able to guess what’s going on is (a) the average time for log file sync is about right for a file I/O time, and (b) the average time for log file parallel write is impossibly small for a file I/O. If this set of circumstances look likely, then take some snapshots over very short time intervals to see if you aren’t missing something due to averaging effects.

I have produced a separate note describing this issue in more detail.


Back to Index of Topics