{"id":1155,"date":"2006-12-06T12:00:00","date_gmt":"2006-12-06T12:00:00","guid":{"rendered":"http:\/\/orcldoug.com\/blog\/?p=1155"},"modified":"2006-12-06T12:00:00","modified_gmt":"2006-12-06T12:00:00","slug":"a-more-complex-statspack-example-part-1","status":"publish","type":"post","link":"http:\/\/orcldoug.com\/blog\/2006\/12\/06\/a-more-complex-statspack-example-part-1\/","title":{"rendered":"A More Complex Statspack Example – Part 1"},"content":{"rendered":"

Following on from the last Statspack example<\/a>, up popped an example at work this week of another common reason I use Statspack – comparing the performance of different environments. It’s also a nice illustration of some of Statspack’s limitations.<\/p>\n

Because a Statspack report contains a lot of information and this particular exercise threw up a fewcommon problems, I’m going to break it up into several postings. In fact, my overall analysis was prefixed with the following.<\/p>\n

“I’m sorry this reply is so long and sprawling and doesn’t contain any easy answers.”<\/i><\/p><\/blockquote>\n

Mmmm, quite<\/i>. <\/p>\n

When you’re a DBA for a large organisation, it’s only a matter of time before one of your software suppliers claims that the performance they’re getting in their test environment is substantially better than your test environment. The initial stages of this discussion usually involve sending them lists of init.ora parameters (this is *very* important 😉), lists of indexes, export dumps of your schema and so it goes on. <\/p>\n

Eventually, though, the only sensible solution is to analyze the performance of the same job in the two different environments. My preference here is to use event 10046 or DBMS_MONITOR\/DBMS_SESSION to trace the actions and wait events (in fact, there’s an example from the same application here<\/a>) but that can be a little tricky if the application isn’t instrumented and uses connection pools. Sometimes it’s difficult to narrow down which session you should be tracing. Without wanting to be too disparaging, I also need to think about how experienced the vendor’s technical people are with tracing. Bitter experience leans towards ‘not very’.<\/p>\n

In those cases Statspack can be useful, particularly if we’re using test environments and we can guarantee that the only job running is the one we’re interested in. This is what Mogens Norgaard means when he says :-<\/p>\n

“The one exception is when only one thing was running 🙂 … then the
\nsummary becomes just a summary of that one form, report or whatever.” <\/i><\/p><\/blockquote>\n

in this blog<\/a> which focusses on the limitations of Statspack. That’s what I suggested to the vendor – we would both enable Statspack snapshot collection, run the same job with a before and after snapshot and compare the resulting reports.<\/p>\n

Anyway, let’s start delving into these reports. I usually open the pair in different windows and work my way through them, flicking back and forward between the two. Most of the information in this blog will be obfuscated, but I’ve kept the important details intact.<\/p>\n

The first thing I noticed about the reports was that we’re running Oracle 9.2.0.7 and the vendor is running 9.2.0.1. That difference might turn out to be minor, but I’ve hit enough 9.2.0.x bugs to know that it might not be. Having looked through both reports completely, I don’t think it’s the cause of the performance difference in this case but I’ve suggested they might want to upgrade to a later version.<\/p>\n

Here’s the next section that shows the report period. At first I was a little confused by this because we have 15-minute snapshots, so I took a snapshot before the job was running and then the nearest 15 minutes after it finished. On our system the job took about 12 hours.<\/p>\n

Our System<\/b><\/p>\n

              Snap Id     Snap Time      Sessions Curs\/Sess Comment            --------- ------------------ -------- --------- -------------------Begin Snap:       346 22-Nov-06 08:53:55       62        .7  End Snap:       395 22-Nov-06 21:00:02       46       1.0   Elapsed:              726.12 (mins)<\/code><\/pre>\n
The job took 6 hours 44 minutes on the vendor’s system, but the report is for a longer period of time.<\/p>\n
Vendor System<\/b><\/p>\n
            Snap Id     Snap Time      Sessions Curs\/Sess Comment            ------- ------------------ -------- --------- -------------------Begin Snap:       4 03-Dec-06 17:30:11       18       2.8  End Snap:       7 04-Dec-06 08:05:45       14       4.6   Elapsed:              875.57 (mins)<\/code><\/pre>\n
The reason for the anomaly was that they had left the job running and had run a closing snapshot hours after the job finished, the next morning. However, as their system was running nothing after the job completed, I could make allowances for this. I would have preferred them to have a report covering the exact period of the job, though.<\/p>\n
In fact, you might think at this point that I’ve broken one of the cardinal rules of sensible Statspack use. A 12 hour report?!? What good could that be? Think of the detail hidden in those 12 hours! Well, not really because the job cycles round a few different sections multiple times and, even though it’s a very long business task, it is a single business task and I want to compare the entire task running on two different environments. If I do want to drill down to a narrower period, I can use the multiple 15 minute snapshots.<\/p>\n
Next the Cache Sizes. This section is one of a few (including the list of non-default parameters at the end of the report) that don’t help me solve any performance problem, but offer a quick sanity check of the two environments.<\/p>\n
Our System<\/b><\/p>\n
Cache Sizes (end)~~~~~~~~~~~~~~~~~               Buffer Cache:     1,968M      Std Block Size:          8K           Shared Pool Size:       576M          Log Buffer:     20,480K<\/code><\/pre>\n

Vendor’s System<\/b><\/p>\n
Cache Sizes (end)~~~~~~~~~~~~~~~~~               Buffer Cache:       512M      Std Block Size:         8K           Shared Pool Size:       128M          Log Buffer:    20,480K<\/code><\/pre>\n
Why are our caches so much bigger than the vendor’s? Because we’ve been working on this problem for a little while now and the vendors just keep asking us to increase cache sizes in the hope that everything will magically perform better. If in doubt, bump everything up a bit! (I’ll leave it to the reader to guess how successful this has proved.)<\/p>\n
On to the Load Profiles<\/p>\n
Our System<\/b>
<\/code><\/p>\n
Load Profile~~~~~~~~~~~~                            Per Second       Per Transaction                                   ---------------       ---------------                  Redo size:             95,650.78              9,958.63              Logical reads:              3,317.07                345.35              Block changes:                650.44                 67.72             Physical reads:                 45.52                  4.74            Physical writes:                 11.59                  1.21                 User calls:                423.49                 44.09                     Parses:                188.57                 19.63                Hard parses:                  0.46                  0.05                      Sorts:                 15.96                  1.66                     Logons:                  0.06                  0.01                   Executes:                118.06                 12.29               Transactions:                  9.60  % Blocks changed per Read:   19.61    Recursive Call %:     10.37 Rollback per transaction %:    0.00       Rows per Sort:      7.61<\/pre>\n

Vendor’s System<\/b>
<\/code><\/p>\n
Load Profile~~~~~~~~~~~~                            Per Second       Per Transaction                                   ---------------       ---------------                  Redo size:             63,599.53            433,182.61              Logical reads:              2,124.32             14,468.98              Block changes:                433.31              2,951.29             Physical reads:                100.97                687.73            Physical writes:                  6.52                 44.39                 User calls:                253.44              1,726.23                     Parses:                106.31                724.09                Hard parses:                  0.01                  0.04                      Sorts:                  1.17                  7.94                     Logons:                  0.01                  0.05                   Executes:                 55.26                376.40               Transactions:                  0.15  % Blocks changed per Read:   20.40    Recursive Call %:     1.12 Rollback per transaction %:    0.00       Rows per Sort:     7.12<\/pre>\n
This is the stage where I started to have doubts. Look at the difference in redo size per second and per transaction. <\/p>\n
Now that I’m writing down how I tend to use Statspack, I realise that Redo size is a figure I tend to focus on because I think it gives a pretty good indication of workload. If both these databases are running the same job, why the difference, particularly the massive difference in redo size per transaction? (In fact, it looks like our system is doing about 50% more work than the vendors when you look at the various load profile values)<\/p>\n
More on that in the next blog.<\/p>\n","protected":false},"excerpt":{"rendered":"
Following on from the last Statspack example, up popped an example at work this week of another common reason I use Statspack – comparing the performance of different environments. It’s also a nice illustration of some of Statspack’s limitations. Because a Statspack report contains a lot of information and this particular exercise threw up a… Continue reading A More Complex Statspack Example – Part 1<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[1],"tags":[],"class_list":["post-1155","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1159,"url":"http:\/\/orcldoug.com\/blog\/2006\/12\/11\/a-more-complex-statspack-example-summary\/","url_meta":{"origin":1155,"position":0},"title":"A More Complex Statspack Example – Summary","date":"December 11, 2006","format":false,"excerpt":"Looking back at the three blogs (and hopefully the comments, where others have made some very useful contributions), it's all quite unsatisfactory, isn't it? We haven't solved the problem. All we've proved is that the tests aren't equivalent, although I think there's value in that negative result because I was\u2026","rel":"","context":"With 3 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1156,"url":"http:\/\/orcldoug.com\/blog\/2006\/12\/07\/a-more-complex-statspack-example-part-2\/","url_meta":{"origin":1155,"position":1},"title":"A More Complex Statspack Example – Part 2","date":"December 7, 2006","format":false,"excerpt":"So far we're barely into the comparison of the Statspack reports from the two different test environments and they look quite different already.Next up, the Instance Efficiency Percentages. I have to confess that I rarely find these very useful because the numbers are always near 100% on most databases I\u2026","rel":"","context":"With 13 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1428,"url":"http:\/\/orcldoug.com\/blog\/2008\/08\/14\/time-matters-an-infinite-capacity-for-waiting\/","url_meta":{"origin":1155,"position":2},"title":"Time Matters – An Infinite Capacity for Waiting*","date":"August 14, 2008","format":false,"excerpt":"When I was teaching the 10g Performance class at my last customer site, I remarked that the total number of seconds you see in the \"Top 5 Timed Events\" section of a Statspack or AWR report will often be greater than the total number of seconds between the snapshot intervals.\u2026","rel":"","context":"With 6 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1153,"url":"http:\/\/orcldoug.com\/blog\/2006\/12\/01\/a-small-statspack-success\/","url_meta":{"origin":1155,"position":3},"title":"A Small Statspack Success","date":"December 1, 2006","format":false,"excerpt":"I'll warn you up front that this is going to be spectacularly lacking in detail but it's a simple and true example from the other week of the kind of thing I find Statspack useful for.One of the developers scuttled round to my desk one late shift very concerned about\u2026","rel":"","context":"With 7 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1050,"url":"http:\/\/orcldoug.com\/blog\/2006\/08\/10\/historical-perspective-part-2\/","url_meta":{"origin":1155,"position":4},"title":"Historical Perspective (Part 2)","date":"August 10, 2006","format":false,"excerpt":"Let's look at items 2 and 3 from the list in my previous blog1) You know you have a performance problem and can re-create it by running a specific part of the application, be it a user interaction or batch job.2) You have an intermittent but recurring performance problem which\u2026","rel":"","context":"Similar post","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1429,"url":"http:\/\/orcldoug.com\/blog\/2008\/08\/20\/time-matters-db-time\/","url_meta":{"origin":1155,"position":5},"title":"Time Matters – DB Time","date":"August 20, 2008","format":false,"excerpt":"[In retrospect, the title of that first blog post might have suited the subject, but doesn't translate too well for subsequent related blog posts. That was a lack of planning or foresight on my part. These blog posts are tumbling out of my head in a fairly incoherent way. Maybe\u2026","rel":"","context":"With 13 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1155","targetHints":{"allow":["GET"]}}],"collection":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/comments?post=1155"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1155\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1155"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1155"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1155"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}