Analysing Statspack(8)

[Further Reading on Statspack]

In an earlier article on Statpack I quoted some figures taken 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 since found on Burleson’s website the report from which this extract was taken.

The report is a Word document (dated 2nd June 2005) at this URL and it is referenced from this thread (dated 15th June 2005 – so the document was  published quite deliberately and has been on display for well over  two years) on the Burleson Consulting Oracle Forum; it would be a good idea to read both before carrying on with this blog item, which is going to discuss various statitistics in the report and suggest some preliminary observations you could draw from it. For cross-reference purposes, you might also find it useful to have the report available in a separate window as you read this blog item.

[Updated 14th Nov 2007: The document has been removed from the website although the forum thread that originally directed me to it is currently still available for review. The current version of the forum thread generates a 7 page pdf file, however, while the original version – currently still cached on Google – generates a 12 page pdf file – so just a tiny bit of history being rewritten there].

First of all we see (from the forum thread) that this is a Linux system with 4GB of RAM and a RAID-5 disk configuration. There is also a comment that this is a dedicated server – which in this context means that nothing else is running on the machine. It’s always useful to be aware of this type of information when reading through a Statspack report, as it gives us some extra hints about when some statistics are reasonable and when they might be suspect.

The report then tells us that the machine has 2 CPUs and the snapshot duration was one hour – which allows us to put the wait information into context. But before we worry about load profiles and waits, just take a look at the size of the buffer cache (124MB) and the shared pool (136MB) – that leaves use with about 3.7GB of “unused” memory. A quick check in the parameter list for the pga_aggregate_target shows that Oracle has been told to behave as if there is a (soft) limit of 92MB for process memory – and while we’re looking at the parameters we note that the sga_target has been set at 280MB. You then notice that the forum note says the database is only 300MB.

So – with 4GB of RAM, 300MB of database, and nothing running on the machine – why isn’t the buffer cache set to a value that makes the entire database operate in memory ? (This is a question I jotted down while reading through the AWR report – it’s something to follow up later. It won’t necessarily solve any performance problems but it looks like such an obvious configuration strategy that the question has to be asked).

So let’s take a look at the load profile: 7KB of redo per second, 464 logical I/Os per second, 52 block changes per second, 1 physical read per second, 2 physical writes per second, 2.66 transactions per second. On average this database is almost idle. Take a look at the the Top 5 timed events again in the light of a one hour snapshot (which, at 2 CPUs, means 7,200 CPU seconds – of which only 226 have been used) and again you can see that on average virtually nothing is happening.

But that’s one of the drawback of Statspack – you lose the detail in the average. Perhaps the problem with this system is that the activity comes in short bursts and when the system is trying to do something it does it too slowly. The report, however, was labelled as a health check – so it’s possible that the owner has simply asked for a general quality review without having any specific performance complaints. So, since we have no specific leads to follow, let’s just look for inefficiencies.

There’s not a lot to say really as we scan through the load profile and wait events. We’ve already picked up the fact that there isn’t much going on and the the average I/O times are very poor. (Probably something to do with that RAID-5 configuration).

As we hit page 6 (Service Statistics) we note that the DBA has set the system up to use database services – a nice touch with 10g – and a large fraction of the work is coming through the appropriate service.

Then we’re on to the system statistics – and nothing exciting stands out until we hit “index fast full scans (fast)”. If this is an OLTP system that’s a slightly unusual and resource-intensive execution path – and we have done 2,941 of them in an hour.

We take a brief pause at the parse count (total) – 72,000 in the hour, 20 per second – which is not a disaster (and only 627 required optimisation) but possibly some of them could be avoided. So we glance down the page to the figures for “session cursor cache hits” – and find there are none; so we look on down to the parameter list and find that the session_cached_cursors parameter is set to zero. That’s probably a mistake, and pretty safe to set to a value like 50. It will use a bit of memory (of which we have lots) and eliminate some of the CPU spent on parse calls.

The physical reads we already know are few and fast – but we do note that we have some “physical reads cache prefetch”. This is usually about pre-emptive readahead for tablescans and index fast full scans – so we want to look out for those (and, of course, we’ve already seen the index fast full scans) .

Working quickly through the redo figures: redo size + redo wastage is about 31M, and redo blocks written is 63,698 – so the redo block size is the very common 512 bytes. “redo synch writes” (the users’ calls to the log writer) is, at 9,280, very similar to the “redo writes” at 9,678 (and both are similar to “user commits” later on – so nothing of note going on there – and with an average of about 7 blocks per synch this looks like an OLTP type of system with quite small transactions.

It’s not until we get to the table scan section that there’s anything particularly striking – and there we see 138,713 rows fetched by rowid, and 75 million fetched by table scan (with 1.17 million blocks fetched by table scan). Most of the tablescans were short – so were probably constantly buffered – with a couple of “long” tablescans. (Ignoring special cases, a “short” table is anything up to 2% of the buffer cache – which means 26MB or about 3,300 blocks ).

If there’s anything in this report (apart from the slow disc configuration) that the client really needs to know it’s that they probably need to review their data and code to check that they have appropriate indexes to meet their requirements. And if the indexes are the correct indexes they need to look at the statistics to discover why Oracle isn’t using them.

The little bit about Instance Activity Stats on page 11 (combined with the redo size + redo wastage figures from earlier on) tells us that the redo log files are 10M – which is a little small for most systems. But maybe it’s going to stay a small system and the figure of 3 log switches per hour is in most people’s comfort zone. Possibly (glancing at the parameter list) we might mention the archive_lag_target parameter to the client, and explain how you can set that to ensure a log switch every N seconds.

The Buffer Pool Advisory on page 14 shows an interesting pattern – a very distinct step down in physical reads as the buffer cache changes from 60M to 72M. If you were just the wrong side of that step you’d almost certainly want to change the cache size. (Of course, we have such a large machine memory that it probably won’t make much difference to the performance since most of our reads are likely to be from local memory anyway) .

The PGA Aggr Histogram is always a useful little report – though in this case rather small. The figures we see here might prompt us to give a little warning about sorts/hashes that are a little large for a “real” OLTP system. But possible the 1M – 2M workareas were for small reports rather than for the OLTP side of the activity. We note, in passing, that the pga_aggregate_target is only 96M, which is a bit small given that processes is set to 150. A comfortable figure for an OLTP system would be in the 2M – 4M range per process. The advisories are basically then suggesting giving a bit more memory to the pga and sga – which is something we can easily afford to do.

The next interesting spot appears in the Undo Segment Summary (page 19) – do we really trust that “Max Qry Len” of 1,665 seconds? Better make a little comment about it, just in case. It might be indicative of an important report; it might be a bad piece of code.

The latch activity is too low key to be interesting.  The only slight anomaly is the relatively high value for get of the “row cache objects” latch relative to the “library cache latch”. This can be indicative of excessive optimization (a.k.a. “hard” parsing) – but since we aren’t doing much hard parsing we carry on down to the Dictionary Cache Stats and notice that the higher numbers come from the dc_global_oids, dc_object_ids, and dc_users caches. This may be the slightly undesirable side effect you get from using the cast() operator with object table types, perhaps in the guise of pipelined functions. For a high performance, highly concurrent system that’s a bit of Oracle’s technology that I’m not too keen to see in action.

The Library Cache Activity shows a small number of reloads – possibly an indication that we should increase the size of the shared pool – possibly a hint that there’s some literal string code arriving that’s kicking more useful information out a bit too enthusiastically. But at the current work rates it doesn’t seem to be much of a threat. A quick check of the parameter list also shows that cursor_sharing is set to force, so we might want to check if some of the code has mixed binds with literals – which is a code style for which this directive is inapplicable in later versions of Oracle. (It’s also a directive that, strategically, should be eliminated).

Looking at the parameters – we may want to get rid of the db_file_mulitblock_read_count as this is 10g, and ensure that the db_cache_size is always at least as large as 1M per process.

Summary

If you want a quick healthcheck on this database because you feel a little uneasy about the way it’s being developed then:

The disk write times are bad – possibly because it’s RAID-5.

Some of the queries are probably very inefficient because of indexing errors, or unsuitable statistics or code. You might as well use the machine memory you’ve got in the best place possble – which means putting more of it into the SGA and PGA. At present this probably won’t make much difference to performance because of the resources wasted in tablescans.

The session_cached_cursor parameter should probably be set to a non-zero value for a small win in CPU.

It would be a strategic target to make sure the coding strategies are correct, and then get rid of cursor_sharing = force.

Be a little cautious about using SQL that includes structures like cast(multiset(…) as user_defined_table_type)

That’s just a 90-minute review (including typing time) – so if you think there are other important things worth mentioning, or think I’ve mentioned something that’s irrelevant, then that’s what the comment section is for.

[Further Reading on Statspack]

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