A More Complex Statspack Example - Part 3

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 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.)

Our System

                                                     CPU      Elapsd
  Buffer Gets    Executions  Gets per Exec  %Total Time (s)  Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
     21,165,424    1,777,416           11.9   14.6   188.42    217.73 1081982467
Module: dllhost.exe
INSERT INTO W6FORECAST_UNITS_MEASURES (W6Key,W6SubKey_1,Name,Raw
Value,ActualValue,MinError,MaxError,TrendValue,FittedValue,Descr
iption) VALUES(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10)
     16,515,271      444,354           37.2   11.4   119.72    145.70 1221790051
Module: dllhost.exe
update W6FORECAST_UNITS set RelatedPlan=:1,PlanScenario=:2,Regio
n=:3,District=:4,JobType=:5,ParentUnit=:6,JobCategory=:7 where W
6Key = :8
      9,838,684       13,662          720.1    6.8   370.97    375.31  302416274
Module: dllhost.exe
SELECT W6Key, Revision FROM W6FORECAST_UNITS WHERE ( ( ( History
 = :1 AND Region = :2 AND District = :3 AND JobCategory = :4 ) )
 AND ( ((StartTime <= :5) AND (FinishTime >= :6)) ) ) AND ( ( (
RelatedPlan = :7 AND PlanScenario IS NULL ) ) OR ( ( RelatedPlan
 IS NULL AND PlanScenario IS NULL ) ) ) ORDER BY History , Regio
      8,916,132      444,354           20.1    6.2    55.49     52.92 3116000638
Module: dllhost.exe
INSERT INTO W6FORECAST_UNITS (W6Key,Revision,RelatedPlan,PlanSce
nario,Region,District,JobType,StartTime,FinishTime,History,Total
Unit,ParentUnit,JobCategory) VALUES(:1,:2,:3,:4,:5,:6,:7,:8,:9,:
10,:11,:12,:13)
      4,011,657          693        5,788.8    2.8    18.64     18.77 3585738665
Module: dllhost.exe
SELECT W6ASSIGNMENTS.W6Key,W6ASSIGNMENTS.Revision,W6ASSIGNMENTS.
CreatedBy,W6ASSIGNMENTS.TimeCreated,W6ASSIGNMENTS.CreatingProces
s,W6ASSIGNMENTS.ModifiedBy,W6ASSIGNMENTS.TimeModified,W6ASSIGNME
NTS.ModifyingProcess,W6ASSIGNMENTS.Task,W6ASSIGNMENTS.StartTime,
W6ASSIGNMENTS.FinishTime,W6ASSIGNMENTS.CommentText,W6ASSIGNMENTS

Vendor's System

                                                     CPU      Elapsd
  Buffer Gets    Executions  Gets per Exec  %Total Time (s)  Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
     50,736,460       13,870        3,658.0   45.5  1016.56 ######### 3617180858
SELECT W6Key, Revision FROM W6PLAN_ACTIONS  WHERE (  (  RelatedP
lan  = :1  AND PlanScenario IS NULL )  )  OR (  (  RelatedPlan I
S NULL  AND PlanScenario IS NULL )  )  ORDER BY  RelatedPlan , P
lanScenario
     23,867,527    1,796,528           13.3   21.4   250.22    374.91 2597570457
INSERT INTO W6FORECAST_UNITS_MEASURES (W6Key,W6SubKey_1,Name,Raw
Value,ActualValue,MinError,MaxError,TrendValue,FittedValue,Descr
iption) VALUES(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10)
     15,507,602      449,132           34.5   13.9   120.33    231.30 2081669994
update W6FORECAST_UNITS set RelatedPlan=:1,PlanScenario=:2,Regio
n=:3,District=:4,JobType=:5,ParentUnit=:6,JobCategory=:7 where W
6Key = :8
      5,020,204      449,132           11.2    4.5    49.48     77.33 2235729426
INSERT INTO W6FORECAST_UNITS (W6Key,Revision,RelatedPlan,PlanSce
nario,Region,District,JobType,StartTime,FinishTime,History,Total
Unit,ParentUnit,JobCategory) VALUES(:1,:2,:3,:4,:5,:6,:7,:8,:9,:
10,:11,:12,:13)
      4,701,942       13,662          344.2    4.2   244.66    271.37 1861931583
SELECT W6Key, Revision FROM W6FORECAST_UNITS  WHERE ( (  (  Hist
ory  = :1  AND Region  = :2  AND District  = :3  AND JobCategory
 = :4 )  )  AND ( ((StartTime <= :5) AND (FinishTime >= :6)) )
)  AND ( (  (  RelatedPlan  = :7  AND PlanScenario IS NULL )  )
 OR (  (  RelatedPlan IS NULL  AND PlanScenario IS NULL )  )  )

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.

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.

Our System

                                                     CPU      Elapsd
  Buffer Gets    Executions  Gets per Exec  %Total Time (s)  Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
      2,031,055      219,574            9.2    1.4    47.75     48.39 2867215530
Module: dllhost.exe
insert into W6GIS_CACHE (Origin_Lat,Origin_Long,Destination_Lat,
Destination_Long,TravelTime,Distance,GISDataSource,UpdateStatus)
values(:1,:2,:3,:4,:5,:6,:7,:8)
      2,193,162       93,612           23.4    1.5    58.90     57.60  713686856
Module: dllhost.exe
DELETE FROM W6OPERATION_LOG WHERE OperationTime < :1
                                                     CPU      Elapsd
 Physical Reads  Executions  Reads per Exec %Total Time (s)  Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
            976       23,254            0.0    0.0     7.23     23.81 4083657034
Module: dllhost.exe
INSERT INTO W6AGENTS_OPERATIONS (W6Key,Revision,CreatedBy,TimeCr
eated,CreatingProcess,ModifiedBy,TimeModified,ModifyingProcess,S
erver,AgentName,StartTime,Status,FinishTime,Integer1,Integer2,In
teger3,Integer4,Integer5,String1,String2,String3,Boolean1,Boolea
n2,Boolean3,Boolean4,Boolean5,LastError,Integer6,Integer7,Intege

No statements

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.

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.