Let’s Pretend

Here’s a summary of a question that appeared on the Oracle Forum some time ago:

I had been seeing frequent log file switching (resulting in “checkpoint not complete” reports) at night when some export dumps have to occur simultaneously, so I increased my redo log file sizes from 5MB to 10MB.

I now have a user who complains that the system is slow, and I see that the buffer cache hit ratio (BCHR) has dropped to about 90% from what was usually 95% or higher.

Can anyone tell me whether increasing the log file size could cause a performance decrease (and thus buffer cache hit ratio decrease)?

Now the intuitive response to this question is “surely not”. And, of course, the immediate association between poor performance and a lower “buffer cache hit ratio” (BCHR) is inviting a lecture on the general irrelevance of hit ratios.

BUT – there are two important points to consider in this case: (i) a user has reported a performance problem after the change in the log file size and (ii) the hit ratio did drop after the change in log file size. So the question, and the association, should not be dismissed out of hand.

First, of course, we have to recite the dictum: “correlation is not causation”. In other words when two events occur together it isn’t necessarily the case that one caused the other – and when you do start to think about cause and effect, don’t jump to any conclusions about which is cause and which the effect.

Secondly we have to remember the mantra of Greg House M.D.: “Everybody lies”. In its friendlier form we might word this as “there are likely to be important details that haven’t been mentioned”. Most significantly, do we believe that the user’s process started running more slowly the moment the redo log file size was changed; but also: is it just one task that goes more slowly – is it always slower, or just slower sometimes – is it a read-intensive process or a write-intensive process – and do we believe that the user’s process has been examined to see if there is a more obvious reason for why it is running more slowly.

Finally, since we aren’t on the spot and able to apply a proper inquisition, let’s just assume that there really is a link between the resizing operation and the slow-down of the user process and try to work out how that could happen.

This is a situation I find myself in a little too often – I have to diagnose a problem hands-off and blind-folded while someone else tells me what’s going on, so my only option is to trust what I’m hearing and create a reasonable explanation for the given symptoms. It’s slightly more difficult in this case, because I can’t even ask any questions.

So we’re going to play: “Let’s pretend”. What could possibly be going on that could make a process slow down because the redo log file size has been increased and, incidentally, make the BCHR drop at the same time.

One obvious thought, of course, is that you can’t resize log files – you create new ones and drop the old ones. So the new log files might be on a slower disc or on a hot bit of the SAN, and if the log file writes are slower then a job that does lots of commits might run noticeable slower.  (Bong 0/10 – because that wouldn’t, at first sight, cause the BCHR to drop; moreover, if this were the case, wouldn’t the process have been blocked by the ‘checkpoint not complete’ anyway).

Second thoughts, then. The log files were made bigger to avoid ‘checkpoint not complete’ problems. This suggests that the other user’s process was a read-intensive one rather than a write-intensive one otherwise it, too, would have been waiting on ‘checkpoint not complete’ and should have been able to work faster when the log file sizes were increased. But that means something is going faster because of the change in log file size, but it’s not this other user.

Take a side step for a moment – what makes the BCHR down ? If you follow the typical formula it’s either a drop in the rate of buffer gets or an increase in the rate of disc reads. So why should the BCHR go down when some jobs can go faster ? Here’s one easy answer:

I have a batch update job that needs to do a lot of disc I/O; but it keeps stopping because of the checkpoints. You have a big report that gets through a lot of buffer visits, and keeps running even when the checkpoints are stopping my batch. Because your job is running, you can keep revisiting buffers, promoting them in memory and pushing the BCHR up.

As soon as I am allowed to work for longer periods, I can get through more disc I/O in a given interval and revisit the blocks I am interested in at a higher rate. So I push the BCHR down because of the extra reads, I knock your blocks out of the buffer because of my increased read rate, and I protect my blocks better because I can revisit them more often.

At the same time, you have less success in re-visiting buffered blocks because I have a better chance of kicking them out before they are promoted, and you end up doing more physical reads – pushing the BCHR down even further.

So, a fix that allows me to work harder (visiting the disc more, and disrupting the cache more) slows you down and increases the BCHR. It’s just the old problem of local vs. global optimisation. If I can work harder I may cause you more pain – that’s the way it is in a multi-user system.

It took me some time to write all this down – but it took just a couple of minutes to sit back and ask myself if there was a scenario that could reasonably fit the facts supplied. It’s an approach I often take:

• What are the known facts ?
• What reasonable hypothesis will explain the known facts ?
• What further facts should be present if the hypothesis is correct ?

It’s called the scientific method. It’s a good methodology to follow. Work at it and you’ll end up wasting less time chasing round in circles; you get to the right answer more often, more rapidly.

(Readers are invited to join in the game – can you suggest a possible cause, and then say what other indications you would expect to see, and where you’d see them, if your suggestion is correct.)