A runstats poser

This week I ‘ave been mostly performance tuning.

As mentioned previously, I have a new client in the City. My remit is schema design and development, and performance tuning.

Tuning is a tricky thing, in the immediate short term at least. In most situations, you can be pretty darn sure that most performance gains are going to come from looking at the application SQL (and occasionally this is because of the schema design).

More than likely, there will be some quick wins. For example, look for slow row-by-row operations, non-set and non-bulk operations, inappropriate use of temporary tables, excessive updating of tables.

But the tricky thing about SQL tuning is that as Jonathan Lewis advocates, you have to know your data. For me at least, this takes time. Time to understand the application, time to understand where the application has come from and where the application is going, time to understand the schema design and time to get to grips with the data.

And one question to ask is what should you tune? And to a certain extent, I think you have to be led on that one. Statspack can help to identify some low hanging fruit but are those plums the ones that the business or the users or the rest of the technical team perceive as the main issues? And so, for example, in week one I had a good look through some Statspack reports from periods that were typically busy. I could see that CPU and IO was an issue (which is what we might expect, hope for even, in a system that is a target to be tuned). That Parsed CPU to Parsed Elapsed ratio, for what it’s worth, was very low into single figures in both reports – that means that every second of CPU time took nearly two seconds of clock time. The top SQL by CPU and IO has identified some initial “blind” tuning candidates (and I mean dumb in the sense that it’s sort of tuning in the dark without much understanding of the underlying business logic).

Second up has been a tuning review of areas that are perceived to be the main issues by the technical team and the business. And again, my approach is to look for quick wins that will lead into a better understanding of the data and the logic.

In the course of this activity, I’ve been using my usual approach of explain plans, extended tracing, wall clock speed, and runstats to find tuning targets and then compare possible changes. And this leads me on to the reason why I started this particular article.

With one particular procedure, I was proposing to replace one INSERT and two subsequent UPDATEs (to the same dataset just inserted), with one single INSERT statement.

Initial tests showed a reduction in clock speed of two thirds. But the picture from runstats threw me.
So, here’s what I was throwing at runstats, more or less:


begin
runstats_pkg.rs_start;
pkg_xyz.abc;
rollback;
runstats_pkg.rs_middle;
pkg_xyz.def;
rollback;
runstats_pkg.rs_stop;
end;

So, one routine was the original, one was my rewritten version. The arguments into both was the same. And I know from table counts that I’ve removed from this example that they were inserting the same number of rows. I also know that nothing significant was going on in the database at the same time.

This is an abridged version of what runstats had to say about the first run (well not the first but about the second so that everything was “warmed up”):


Run1 ran in 31542 hsecs
Run2 ran in 11489 hsecs
run 1 ran in 274.54% of the time
.....
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
14,049 398,035,535 398,021,486 .00%

So, in terms of time, looking good but oh my word, look at those latches.
I scratched my head for some time and reviewed my code several times.
Eventually, I reversed the order of the procs.

Run two revealed similar, note the reversed times “proving” that I had indeed swapped the calls around:


Run1 ran in 11501 hsecs
Run2 ran in 31257 hsecs
run 1 ran in 36.79% of the time
.....
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
14,049 263,512,363 263,498,314 .01%

So, my version is definitely significantly faster but what’s up with the latches. Whichever call is second is reporting massive latches. There’s an explicit rollback after a call to both versions to reset the data. The rollback is in the right place. They’re both inserting exactly the same number of rows. So….

Why do YOU think that might be?

More to follow at a later date.

About these ads

5 Responses to A runstats poser

  1. Mr. Ed says:

    Notice from Tom Kyte’s site:

    “You should note also that the LATCH information is collected on a SYSTEM WIDE basis.”

    But something else is going on here. Why do you have three rows of “table scan rows gotten”?

  2. dombrooks says:

    The latch information is collected on a system wide basis – thanks for highlighting that. I did mention that nothing else was happening on the database at the same time, and that was my point, but it’s better to be clear.
    Regarding the multiple rows of the same stat, that is a clear pointer of the problem. It took me a long time to notice that.
    My problem was that the rollbacks were also rolling back the runstats_pkg actions. Whilst the run_stats table is a global temporary table set up as “on commit preserve rows” the runstats_pkg was transactionally the same as the routines it is calling/testing. The addition of an AUTONOMOUS_TRANSACTION pragma declaration and a commit should resolve the situation.
    Anyway, something to be aware of if the thing that you’re testing is doing a rollback somewhere along the line.

  3. Mr. Ed says:

    Might also want to do the rollback after the call to runstats, so that you’re not measuring rollback performance.

  4. dombrooks says:

    The downside of that is that I want to rollback after both routines. Without the rollback, the second routine won’t do the same work.

    So, with the rollback within the call to runstats, whilst I am losing my measurement of the work of the standalone call away from my test harness, with both calls doing the same inserts and the same rollback, I am at least comparing like to like.

    Thanks for your comments.

  5. A Billington says:

    I’ve encountered this issue before, so I wrote a “resumeable runstats” to allow you to pause, rollback and restart the runstats. If it’s of any use to you, see http://www.oracle-developer.net/utilities.php for the download.

    Regards

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 72 other followers

%d bloggers like this: