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

The more I compare these two reports, the more the workload looks different. In particular, as Gary pointed out in his comment to the last blog<\/a>, our environment is committing a lot more transactions than the vendor’s. (Remember those log file sync waits? The extra redo per second?) <\/p>\n

Let’s take a look at the various SQL statements that are running during this batch job to see if the differences are apparent. (This is a long section of the report, so I’ll take it a few key statements at a time, focussing on the top 5 SQL statements ordered by Gets first.)<\/p>\n

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

\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 CPU\u00a0\u00a0\u00a0\u00a0\u00a0 Elapsd\u00a0 Buffer Gets\u00a0\u00a0\u00a0 Executions\u00a0 Gets per Exec\u00a0 %Total Time (s)\u00a0 Time (s) Hash Value--------------- ------------ -------------- ------ -------- --------- ----------\u00a0\u00a0\u00a0\u00a0 21,165,424\u00a0\u00a0\u00a0 1,777,416\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 11.9\u00a0\u00a0 14.6\u00a0\u00a0 188.42\u00a0\u00a0\u00a0 217.73 1081982467Module: dllhost.exeINSERT INTO W6FORECAST_UNITS_MEASURES (W6Key,W6SubKey_1,Name,RawValue,ActualValue,MinError,MaxError,TrendValue,FittedValue,Description) VALUES(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10)
<\/p>
\u00a0\u00a0\u00a0\u00a0 16,515,271\u00a0\u00a0\u00a0\u00a0\u00a0 444,354\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 37.2\u00a0\u00a0 11.4\u00a0\u00a0 119.72\u00a0\u00a0\u00a0 145.70 1221790051Module: dllhost.exeupdate W6FORECAST_UNITS set RelatedPlan=:1,PlanScenario=:2,Region=:3,District=:4,JobType=:5,ParentUnit=:6,JobCategory=:7 where W6Key = :8<\/p>
\u00a0\u00a0\u00a0\u00a0\u00a0 9,838,684\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 13,662\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 720.1\u00a0\u00a0\u00a0 6.8\u00a0\u00a0 370.97\u00a0\u00a0\u00a0 375.31\u00a0 302416274Module: dllhost.exeSELECT W6Key, Revision FROM W6FORECAST_UNITS WHERE ( ( ( History\u00a0= :1 AND Region = :2 AND District = :3 AND JobCategory = :4 ) )\u00a0AND ( ((StartTime <= :5) AND (FinishTime >= :6)) ) ) AND ( ( (RelatedPlan = :7 AND PlanScenario IS NULL ) ) OR ( ( RelatedPlan\u00a0IS NULL AND PlanScenario IS NULL ) ) ) ORDER BY History , Regio<\/p>
\u00a0\u00a0\u00a0\u00a0\u00a0 8,916,132\u00a0\u00a0\u00a0\u00a0\u00a0 444,354\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 20.1\u00a0\u00a0\u00a0 6.2\u00a0\u00a0\u00a0 55.49\u00a0\u00a0\u00a0\u00a0 52.92 3116000638Module: dllhost.exeINSERT INTO W6FORECAST_UNITS (W6Key,Revision,RelatedPlan,PlanScenario,Region,District,JobType,StartTime,FinishTime,History,TotalUnit,ParentUnit,JobCategory) VALUES(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13)<\/p>
\u00a0\u00a0\u00a0\u00a0\u00a0 4,011,657\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 693\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 5,788.8\u00a0\u00a0\u00a0 2.8\u00a0\u00a0\u00a0 18.64\u00a0\u00a0\u00a0\u00a0 18.77 3585738665Module: dllhost.exeSELECT W6ASSIGNMENTS.W6Key,W6ASSIGNMENTS.Revision,W6ASSIGNMENTS.CreatedBy,W6ASSIGNMENTS.TimeCreated,W6ASSIGNMENTS.CreatingProcess,W6ASSIGNMENTS.ModifiedBy,W6ASSIGNMENTS.TimeModified,W6ASSIGNMENTS.ModifyingProcess,W6ASSIGNMENTS.Task,W6ASSIGNMENTS.StartTime,W6ASSIGNMENTS.FinishTime,W6ASSIGNMENTS.CommentText,W6ASSIGNMENTS<\/p><\/code><\/pre>\n<\/p>\n
Vendor’s System<\/strong><\/code><\/p>\n
\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 CPU\u00a0\u00a0\u00a0\u00a0\u00a0 Elapsd\u00a0 Buffer Gets\u00a0\u00a0\u00a0 Executions\u00a0 Gets per Exec\u00a0 %Total Time (s)\u00a0 Time (s) Hash Value--------------- ------------ -------------- ------ -------- --------- ----------\u00a0\u00a0\u00a0\u00a0 50,736,460\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 13,870\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 3,658.0\u00a0\u00a0 45.5\u00a0 1016.56 ######### 3617180858SELECT W6Key, Revision FROM W6PLAN_ACTIONS\u00a0 WHERE (\u00a0 (\u00a0 RelatedPlan\u00a0 = :1\u00a0 AND PlanScenario IS NULL )\u00a0 )\u00a0 OR (\u00a0 (\u00a0 RelatedPlan IS NULL\u00a0 AND PlanScenario IS NULL )\u00a0 )\u00a0 ORDER BY\u00a0 RelatedPlan , PlanScenario<\/strong>
<\/p>
\u00a0\u00a0\u00a0\u00a0 23,867,527\u00a0\u00a0\u00a0 1,796,528\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 13.3\u00a0\u00a0 21.4\u00a0\u00a0 250.22\u00a0\u00a0\u00a0 374.91 2597570457INSERT INTO W6FORECAST_UNITS_MEASURES (W6Key,W6SubKey_1,Name,RawValue,ActualValue,MinError,MaxError,TrendValue,FittedValue,Description) VALUES(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10)<\/p>
\u00a0\u00a0\u00a0\u00a0 15,507,602\u00a0\u00a0\u00a0\u00a0\u00a0 449,132\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 34.5\u00a0\u00a0 13.9\u00a0\u00a0 120.33\u00a0\u00a0\u00a0 231.30 2081669994update W6FORECAST_UNITS set RelatedPlan=:1,PlanScenario=:2,Region=:3,District=:4,JobType=:5,ParentUnit=:6,JobCategory=:7 where W6Key = :8<\/p>
\u00a0\u00a0\u00a0\u00a0\u00a0 5,020,204\u00a0\u00a0\u00a0\u00a0\u00a0 449,132\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 11.2\u00a0\u00a0\u00a0 4.5\u00a0\u00a0\u00a0 49.48\u00a0\u00a0\u00a0\u00a0 77.33 2235729426INSERT INTO W6FORECAST_UNITS (W6Key,Revision,RelatedPlan,PlanScenario,Region,District,JobType,StartTime,FinishTime,History,TotalUnit,ParentUnit,JobCategory) VALUES(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13)<\/p>
\u00a0\u00a0\u00a0\u00a0\u00a0 4,701,942\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 13,662\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 344.2\u00a0\u00a0\u00a0 4.2\u00a0\u00a0 244.66\u00a0\u00a0\u00a0 271.37 1861931583SELECT W6Key, Revision FROM W6FORECAST_UNITS\u00a0 WHERE ( (\u00a0 (\u00a0 History\u00a0 = :1\u00a0 AND Region\u00a0 = :2\u00a0 AND District\u00a0 = :3\u00a0 AND JobCategory\u00a0= :4 )\u00a0 )\u00a0 AND ( ((StartTime <= :5) AND (FinishTime >= :6)) ))\u00a0 AND ( (\u00a0 (\u00a0 RelatedPlan\u00a0 = :7\u00a0 AND PlanScenario IS NULL )\u00a0 )\u00a0OR (\u00a0 (\u00a0 RelatedPlan IS NULL\u00a0 AND PlanScenario IS NULL )\u00a0 )\u00a0 )<\/p><\/pre>\n<\/p>\n
Most of the statements are duplicated in the two environments, but the bold statement in the vendor’s environment doesn’t appear in ours. As the top SQL by number of gets, that’s a little worrying. What’s even more confusing is that I expected to see more workload in *our* environment. Well, I’ve only looked at the top 5 SQL statements, so I’ll keep looking further down, but to save us all from a 12-part blog series I’ll narrow it down a bit.<\/p>\n
All the evidence so far is that our environment is experiencing a higher transaction throughput. so I’ll focus on INSERT, UPDATE and DELETE statements to try to work out where the additional activity is coming from. Note – the output below is limited to those statements.<\/p>\n
Our System<\/strong><\/p>\n
\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 CPU\u00a0\u00a0\u00a0\u00a0\u00a0 Elapsd\u00a0 Buffer Gets\u00a0\u00a0\u00a0 Executions\u00a0 Gets per Exec\u00a0 %Total Time (s)\u00a0 Time (s) Hash Value--------------- ------------ -------------- ------ -------- --------- ----------\u00a0\u00a0\u00a0\u00a0\u00a0 2,031,055\u00a0\u00a0\u00a0\u00a0\u00a0 219,574\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 9.2\u00a0\u00a0\u00a0 1.4\u00a0\u00a0\u00a0 47.75\u00a0\u00a0\u00a0\u00a0 48.39 2867215530Module: dllhost.exeinsert into W6GIS_CACHE (Origin_Lat,Origin_Long,Destination_Lat,Destination_Long,TravelTime,Distance,GISDataSource,UpdateStatus)values(:1,:2,:3,:4,:5,:6,:7,:8)
<\/p>
\u00a0\u00a0\u00a0\u00a0\u00a0 2,193,162\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 93,612\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 23.4\u00a0\u00a0\u00a0 1.5\u00a0\u00a0\u00a0 58.90\u00a0\u00a0\u00a0\u00a0 57.60\u00a0 713686856Module: dllhost.exeDELETE FROM W6OPERATION_LOG WHERE OperationTime < :1<\/p>
\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 CPU\u00a0\u00a0\u00a0\u00a0\u00a0 Elapsd\u00a0Physical Reads\u00a0 Executions\u00a0 Reads per Exec %Total Time (s)\u00a0 Time (s) Hash Value--------------- ------------ -------------- ------ -------- --------- ----------\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 976\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 23,254\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0.0\u00a0\u00a0\u00a0 0.0\u00a0\u00a0\u00a0\u00a0 7.23\u00a0\u00a0\u00a0\u00a0 23.81 4083657034Module: dllhost.exeINSERT INTO W6AGENTS_OPERATIONS (W6Key,Revision,CreatedBy,TimeCreated,CreatingProcess,ModifiedBy,TimeModified,ModifyingProcess,Server,AgentName,StartTime,Status,FinishTime,Integer1,Integer2,Integer3,Integer4,Integer5,String1,String2,String3,Boolean1,Boolean2,Boolean3,Boolean4,Boolean5,LastError,Integer6,Integer7,Intege<\/p><\/code><\/pre>\n
Vendor’s System<\/strong><\/p>\n
No statements<\/p>\n
Okay, so at this stage it looks like our environment is handling activity that the vendor’s system isn’t. I’d already told the vendor that it looked like our workload was higher and so we set up a conference call to discuss what those additional statements were doing. It turned out that when the vendor is performing the test, the database is working in isolation on this job (which is what we want) but when we’re running the job, our test environment has 10 application servers connected to it, performing normal maintenance activities. i.e. We’re handling the normal ‘background noise’ of this application, whereas the vendor’s test system is simplified.<\/p>\n
I could wade through the rest of the report but I think I’m going to leave it there for now. Problem solved, although this one probably took at least half a day of comparing the reports and sending out an analysis to the vendor, then a meeting and now we await their fixes to make our system perform better but the fixes won’t be to the main batch job, but the background processes.<\/p>\n","protected":false},"excerpt":{"rendered":"
The more I compare these two reports, the more the workload looks different. In particular, as Gary pointed out in his comment to the last blog, our environment is committing a lot more transactions than the vendor’s. (Remember those log file sync waits? The extra redo per second?) Let’s take a look at the various… Continue reading A More Complex Statspack Example – Part 3<\/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-1158","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1646,"url":"http:\/\/orcldoug.com\/blog\/2013\/08\/15\/real-time-sql-monitoring-retention\/","url_meta":{"origin":1158,"position":0},"title":"Real-Time SQL Monitoring – Retention","date":"August 15, 2013","format":false,"excerpt":"As I suggested in my last post, there's at least one more reason that your long-running SQL statements might not appear in SQL Monitoring views (e.g. V$SQL_MONITOR) or the related OEM screens. When the developers at my current site started to use SQL Monitoring more often, they would occasionally contact\u2026","rel":"","context":"With 8 comments","img":{"alt_text":"","src":"https:\/\/i0.wp.com\/18.133.199.212\/wp-content\/uploads\/recovered\/RTSM_1.png?resize=350%2C200","width":350,"height":200},"classes":[]},{"id":1506,"url":"http:\/\/orcldoug.com\/blog\/2009\/07\/02\/real-time-sql-monitoring-in-sql-developer\/","url_meta":{"origin":1158,"position":1},"title":"Real-Time SQL Monitoring in SQL Developer","date":"July 2, 2009","format":false,"excerpt":"Features in this post require both Diagnostics and Tuning Pack licenses.If you haven't seen 11g's Real Time SQL Monitoring feature, you need to. It's one of the most useful Oracle performance troubleshooting tools I've seen since I started working with Oracle too long ago. I was first aware of it\u2026","rel":"","context":"With 10 comments","img":{"alt_text":"","src":"\/serendipity\/uploads\/xsqldev1.png.pagespeed.ic.lI55QN9Yna.png","width":350,"height":200},"classes":[]},{"id":1320,"url":"http:\/\/orcldoug.com\/blog\/2007\/09\/23\/parallel-query-and-11g-part-2\/","url_meta":{"origin":1158,"position":2},"title":"Parallel Query and 11g – Part 2","date":"September 23, 2007","format":false,"excerpt":"Now, that's weird. A little surprising might be more accurate and maybe I'm missing something.During the various tests with and without parallel hints and different parallel_io_cap_enabled settings, I expected the runs that didn't use parallelism to show up \"db file scattered read\" events in the trace files. For example, here's\u2026","rel":"","context":"With 10 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1495,"url":"http:\/\/orcldoug.com\/blog\/2009\/05\/01\/diagnosing-locking-problems-using-ashlogminer-the-end\/","url_meta":{"origin":1158,"position":3},"title":"Diagnosing Locking Problems using ASH\/LogMiner \u2013 The End","date":"May 1, 2009","format":false,"excerpt":"Except\u00a0it's not the\u00a0end, of course. What I mean is\u00a0that I usually agree with\u00a0what Miladin Modrakovic said in one of his comments on his first deadlock blog post.\"There is always way around.\"As I keep saying, there are many different ways of diagnosing locking problems. Which one works best\u00a0depends on the situation\u2026","rel":"","context":"Similar post","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":999,"url":"http:\/\/orcldoug.com\/blog\/2012\/06\/18\/saving-optimiser-stats-9i\/","url_meta":{"origin":1158,"position":4},"title":"Saving Optimiser Stats – 9i","date":"June 18, 2012","format":false,"excerpt":"In a recent blog I described how a mis-timed optimiser statistics collection job led to a bad execution plan for one of the SQL statements in a regular batch jobIt's no coincidence that we were already in the process of implementing a change to our stats collection period to retain\u2026","rel":"","context":"With 4 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1642,"url":"http:\/\/orcldoug.com\/blog\/2011\/08\/10\/real-time-sql-monitoring-statement-not-appearing\/","url_meta":{"origin":1158,"position":5},"title":"Real-Time SQL Monitoring – Statement Not Appearing","date":"August 10, 2011","format":false,"excerpt":"Like Greg Rahn, I've looked at many SQL Monitoring reports over the past year or two. Possibly not as many as Greg, but it's become my default method of communicating* SQL performance issues to colleagues to the point that some might be finding it irritating by now, whilst others are\u2026","rel":"","context":"With 11 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1158","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=1158"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1158\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1158"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1158"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1158"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}