[intro music]
[theme music]
Hi. Today we are going to talk about
the data, the Database Log Writer and the impact on
OLTP response times and
also the impact it tends to happen on the effective, the total system
associated with going through middleware layers and
just show you some examples of what can happen in a real-world system,
and we do see in real world systems, ah, but are
very rarely correctly diagnosed. And it's important to you do actually look at
these things
because a lot of variability in your response time
may be an impact of just basically the Log Writer not being able to perform
correctly.
So, let's think about how the Oracle database is structured
and, and what the Log Writer does.
Well, the Log Writer's role is to basically write commit
records and write enough information to recover transactions.
This is done to, by the redo log. And there's just one process that does this
and it's called the Log Writer, and
when a....use this process wants to commit,
it posts the Log Writer to write away the
redo information associated with the transaction and a commit record.
With that in mind, it means that the user process is
often in a wait state, waiting for the Log Writer to do that write.
The Log Writer, umm, will do that write as fast as possible
And whilst that's going on, the, ahh, user processes is in a state
and a wait event to known as log file sync. Now many people say that
log file sync is their most common wait event.
And they try and fix the log file sync wait event,
rather than looking at the root cause of the problem. And
usually the problem is one of twofolds. There's two reasons why they're in log file synch.
One is the Log Writer is taking a long time to write the log
to disk. And the second thing is
is if the Log Writer has to wake up a lot of processes having done the log write,
you may find that your waking up more processes than there are CPUs on the
system.
In which case, we get into an over subscriptions case which we demonstrate
in another
Real World videos. So with that in mind,
I'd like you to look at a system that has got some pathological logging
problems.
And let's look at the demo screen that we have here. You'll notice that we've got
almost a square-shaped wave and this is not an accident. We've manufactured this
for you.
And what's happening is we're running a workload
and at points of time, time the workload is running just fine.
And then appointed time, the workload almost falls down to zero.
What you will also notice in the application performance, when the
response time gets high is correlated with the time of the throughput drops.
Now what I really wanted to show to you is what we can see in the red.
The red is the database response time increasing, and that's as a result
we're seeing high log file synchs. But what I'd like to show you, you see
is is what's happening in the Application Server. We're getting this
multiplication or amplification effect,
that a small increase in response time that the database
gets multiplied through the app server. So
being at the bottom of the stack, like the Log Writer is,
if it basically gets slow
i/o write or struggles to get scheduled, there's a fair chance that any response
time
changes or degradations or deltas
at the bottom of the stack, by the time you've got out to the web browser
this will have been multiplied through. And this is because we have just
series of loosely coupled systems cuing requests
at all layers of the application all waiting for something to happen.
Now if the thing at the bottom is delayed,
everybody gets delayed. And so this is why we get
this amplification effect. And this is seen very often
umm, in real-world systems where we have shared storage, where the storage is being
shared
amongst multiple databases. In fact may be shared between
database applications. It may be shared amongst
Microsoft Exchange servers. It may be other applications that are logging data.
It may be a file system.
Because today, the reality is that in many large corporations
storage is just seen as a space to store things.
It, it is administered by storage administrators
who do the allocations on the basis of
space. They allocate space for a database. Or they allocate space for log files.
And that allocating space, they very rarely make the decisions
on the basis of performance. So let's have a look and see
what happens when the impact is when we share storage
particularly when we share the storage associated with our redo log files.
So in this workload, where we're getting this square-shaped workload
you can see that when there's a performance problem in CPU
we're all stuck in log file synch. It also teaches us another important lesson
that if we actually start looking at the Log Writer statistics, that
the log file sync, the time spent in log file sync,
is usually the time spent on a log file write
times the number of users on the system.
So here, you can see with a millisecond,
we have approximately 100, or in fact 96, 100 connections
just over 100 connections to the database. And you can see that approximately
the log file sync is approximately a hundred times that we have on the log file
write.
And sometimes as we get into the situation where
the log file write becomes more variable and in fact we've got log
writes that are taking more than a second you, can see this gets, tends to get,
multiplied through. However the thing to also note about this system, that the log
file write
statistical average is really good. It's
under a millisecond but we know we still got a system in trouble.
So the statistical average times for log file sync,
and write times are very good. And this is another thing to be wary of, if you
read your AWR reports,
that you may have a race condition or something going on
in that error report that the AWR report pertaining.
But it maybe, you may have a statistical outlier
that happens for five minutes out of that hour, but that will all get rounded down by
the averaging process when you look at an AWR report.
So it's important to get up on Enterprise Manager look at the ASH
reports,
and look at the spikes. Now in this workload that we've got here
we've artificially made the Log Writer slow
by having another database continually checkpoint and do a lot of i/o
to the same discs that we write redo to.
As a result the log writes are getting slower and slower,
and in fact some of the log writes, and you can see we've got
ten of them over a second, so whilst I've been running
10 of the seconds, the database has been effectively stalled.
On a high-volume OLTP system, this is
pretty much close, as close to an outage, as you are going to get.
Now let's think about what actually happens in real world systems on shared
storage.
Basically the storage administrator will have given the DBA a series of LUNs
not based on the performance requirements but based on disk space.
Now those LUNs may be sharing disks with all sorts of other applications.
Now those applications may check point from time-to-time,
They may be dumping, writing a load of log files. They may be periodically.
So very often we see on real-world systems at the top of the hour when
people are running reports or check points and things like that,
the Log Writer slows down. This is because literally the Log Writer
slows down because the writes are slowing down.
And we see higher log file sync at the top of the hour,
because the writes have slowed down. And this is exactly what we're seeing here.
This is not really a good way to run an OLTP system, but it's something what we
see a lot of.
Now to actually solve this problem, there's multiple ways to solve it.
Some we would not recommend. Some
are inevitable--to--ways to solve the problem.
One of the first ways we can actually solve the problem, and it is not
something we would recommend,
is to, umm, not actually
synchronize with your commit, and do
an asynchronous commit. We see a lot of people doing this in benchmarks, in PSE's
because they want to raise the throughput level. But when we start doing
asynchronous commits,
it means that we tell the application we've committed but there's no guarantee
that we will have actually committed the log. So you'll notice I've just
put in asynchronous committing, and you can see the
we can't even trust log file sync or log file parallel write
because it doesn't actually mean anything to us at this point in time. Because the user processes
are not waited on log file sync. They're just going to write the commit
record into the redo buffer, and then just hope the Log Writer catches up.
And as a result, you can see on this trace, there are no log file synch wait
events, because nobody's waiting on it.
We're keeping the CPU busy. Now in a minute,
what we're going to do is we're going to see the i/o storm created by the other
database.
So it's still actually starts slow the workload down,
but the reason it starts to slow down now at this point in time
is that we're actually seeing the redo log buffer filling up,
Okay? And so we're backing up on the redo buffer,
log buffer space, okay, so it's not exactly solve the problem
at this point in time. But it's certainly made it less
bad than it was before. But potentially
we are affecting the transactional integrity of the application.
Other solutions would be to just put the redo logs
on their own dedicated disks. Now
my experience when asking this from storage administrators is usually
one of ridicule and being laughed out of the room.
"You say you want me to allocate specific disk drives for you?"
And they are not really very keen on doing that. In fact it's got so ludicrous
within our industry, in many cases the DBAs can raise a PO
to get dedicated storage for the redo logs
quicker than they can get the storage administrators to give dedicated
storage.
So in many cases we find that the DBA teams
are raising POs for flash devices, and solid-state devices,
to put their redo logs on. Now, they say "Oh! All our performance problems went away
because we got flash devices." And he goes no,
you didn't get it because it was flash devices, it was because it was exclusively
your device. You never had to share it, okay.
Flash devices are fast, but
in many cases they're not the reason why things went on. It was because they can
get predictable write performance
from their Log Writer, and that was the key to the performance.
And as you can see, you know, asynchronous techniques are not working
here.
So let's turn off the asynchronous commit.
And let's talk about other options within Oracle,
to get fast log times. Now one of the challenges
and the reasons why storage administrators don't like to give
exclusive storage to redo logs,
is that they're very often incentived
about maximizing utilization of all the disks
getting the space filled optimally, okay.
And because that impacts the cost of storage and the cost of operations.
We have the same concept also within exit data,
where people are actually using the exit data storage for both logging
and database files. And their sharing and striping everything across all the
volumes and all the cells.
And within exit data, we can actually manifest the same problem.
But within exit data, we've been able to innovate
a way around the problem, because exit data storage has
both disk drives but it also has flash devices inside it.
So the way exit data solves a problem of erratic log performance
is to write to both the log disk
as well as the flash device at the same time.
And take the write back from the one that comes back first.
So if we think about that, we basically get the best of both worlds. If the log
write
to disk is fast, we come back quickly.
If, however, it's an outlier because the disc is so busy
the write to flash memory it'll return suitably quickly as well.
So let's apply flash logging to this workload.
And see what the impact on performance is. You can see that we've gone back
and we're back in their erratic state. So let's turn flash logging on.
I'm going to apply it now. And turn that on.
And what I'm also gonna do, is I'm going to clear, [silent pause]
I'm gonna clear down some statistics so I can find a number.
[typing]
Okay. So I've now turned on
um, flash logging and we've now...
I've zeroed out all the statistics that we had
on the right-hand side here. And what the first thing to notice is we're not
seeing
when the i/o storms come in. We're not seeing
the outliers in the right times. So
let's wait for the next i/o storm to come along and see what happens.
You'll notice that basically the log write time is now in just over
a quarter of a millisecond, and the log file sync time is under millisecond.
And we are now approaching the point where the next log storm, this
i/o storm is going to hit us from the other database.
But the thing to notice is we're not generating
many outliers where their log times are
either in a quarter of a second, there's a few.
But we're not seeing the ones at one second. As a result we barely seeing a
glitch
at all. And in fact what we're starting to see is transactions starting to
degrade
because the reads are taking longer.
So at this point we started to smooth out
all the performance problems associated with
erratic log times. And if we actually look at the response time when we had
erratic log times, you can see we,
in each iteration, we are smoothing these things out over and over again.
So in a second we're going to kind of get the next i/o storm
and you'll notice it's coming a lot smoother. [silent pause]
And it's barely detectable at this point.
The fact that there is an i/o storm taking place
but it's not impacting the system there can just see a tiny.