Help with statspack report comparison

From: Martin T. <0xCDCDCDCD_at_gmx.at>
Date: Sun, 23 Sep 2007 13:16:14 +0200
Message-ID: <46f64be8$0$1340$834e42db@reader.greatnowhere.com>

Hello,
[Oracle 9i2, Windows XP / Windows Server 2003]

I am currently trying to figure out why one of our sites has such a horrible performance. To this end I took statspack snapshots over the last few days from the "bad" site and from one "good" site and now I'm trying to compare two reports for both sites.

Both sites are running the same software with the same usage patterns.

The *good* (marked AT10) site is running on XPsp2 with one 7200RPM HD with a dual core P4 (3,4 GHz) and 1GB of RAM

The *bad* site (marked DE30) is running Win2003r2 with one 7200RPM HD with a dual core Xeon (2,13 GHz) and 2GB of RAM.

The most striking figure (for me, at this time at least) seems to be the <db file scattered read> timed events. The problem is that I am not too sure what to make of this.

It would be great if you could take a quick look at the infos below and just throw a few suggestions at me what might get me on the right track to find the problem and a solution for it.

Thanks!
- Martin

Good Site = *** AT10 ***
Bad Site = *** DE30 ***

( I hope the formatting won't get messed up. )

STATSPACK COMPARISON NUMBER 1

Basic Info

AT10 *** Snap Id Snap Time Sessions Curs/Sess Comment
- ------------------ -------- ---------
  Begin Snap: 31 20-Sep-07 16:49:04 34 29.5 End Snap: 32 20-Sep-07 17:09:02 34 29.5 Elapsed: 19.97 (mins)

Cache Sizes (end)

                Buffer Cache:        48M      Std Block Size:         8K
            Shared Pool Size:        48M          Log Buffer:       512K



*** DE30 ***

             Snap Id     Snap Time      Sessions Curs/Sess Comment
             ------- ------------------ -------- --------- 
-------------------
Begin Snap:       7 20-Sep-07 16:41:06       35      29.7
   End Snap:       8 20-Sep-07 17:01:12       33      28.3
    Elapsed:               20.10 (mins)

Cache Sizes (end)

                Buffer Cache:        24M      Std Block Size:         8K
            Shared Pool Size:        48M          Log Buffer:       512K

Load profile

AT10 *** Load Profile ~~~~~~~~~~~~ Per Second Per Transaction
- --------------- Redo size: 18,430.47 1,644.79 Logical reads: 22,854.65 2,039.62 Block changes: 49.10 4.38 Physical reads: 197.40 17.62 Physical writes: 0.81 0.07 User calls: 143.22 12.78 Parses: 43.85 3.91 Hard parses: 4.68 0.42 Sorts: 45.64 4.07 Logons: 0.17 0.02 Executes: 423.02 37.75 Transactions: 11.21

% Blocks changed per Read: 0.21 Recursive Call %: 82.26 Rollback per transaction %: 0.00 Rows per Sort: 775.87

DE30 *** Load Profile ~~~~~~~~~~~~ Per Second Per Transaction
- --------------- Redo size: 4,023.79 1,731.87 Logical reads: 52,318.99 22,518.45 Block changes: 20.08 8.64 Physical reads: 1,749.80 753.12 Physical writes: 43.25 18.62 User calls: 36.41 15.67 Parses: 12.55 5.40 Hard parses: 1.59 0.68 Sorts: 9.47 4.08 Logons: 0.18 0.08 Executes: 328.37 141.33 Transactions: 2.32

% Blocks changed per Read: 0.04 Recursive Call %: 92.57 Rollback per transaction %: 0.00 Rows per Sort: 682.38

Instance Efficiency Percentages

AT10 *** Instance Efficiency Percentages (Target 100%)
Buffer Nowait %: 99.99 Redo NoWait %: 100.00 Buffer Hit %: 99.14 In-memory Sort %: 100.00 Library Hit %: 99.19 Soft Parse %: 89.33 Execute to Parse %: 89.63 Latch Hit %: 99.97 Parse CPU to Parse Elapsd %: 92.59 % Non-Parse CPU: 93.03

  Shared Pool Statistics        Begin   End
                                ------  ------
              Memory Usage %:   93.44   92.32
     % SQL with executions>1:   24.39   26.09

% Memory for SQL w/exec>1: 23.05 24.63

DE30 *** Instance Efficiency Percentages (Target 100%)
Buffer Nowait %: 99.97 Redo NoWait %: 100.00 Buffer Hit %: 96.78 In-memory Sort %: 99.98 Library Hit %: 99.47 Soft Parse %: 87.35 Execute to Parse %: 96.18 Latch Hit %: 99.20 Parse CPU to Parse Elapsd %: 27.09 % Non-Parse CPU: 99.06

  Shared Pool Statistics        Begin   End
                                ------  ------
              Memory Usage %:   93.08   89.06
     % SQL with executions>1:   23.79   26.42

% Memory for SQL w/exec>1: 24.90 27.77

Top 5 Timed Events

[Note: 20 min == 1200 sec * 34 sess = 40,800 sec]

AT10 *** Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time -------------------------------------------- ------------ -----------
SQL*Net more data to client 9,224 1,576 78.73 CPU time 226 11.29 db file scattered read 31,453 109 5.46 db file sequential read 51,028 61 3.05 log file parallel write 13,107 14 .70
DE30 *** Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time -------------------------------------------- ------------ -----------
db file scattered read 262,952 8,778 76.29 db file sequential read 47,490 1,483 12.89 CPU time 325 2.82 direct path read 10,995 295 2.57 enqueue 189 254 2.21

Top 5 SQL Stmts by GET

AT10 *** CPU Elapsd Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value --------------- ------------ -------------- ------ -------- ---------
18,446,371 1,640 11,247.8 67.4 50.80 51.76 395610491 SELECT MDT.ID , MB.Time_stamp TS_START , ME.Time_stamp TS_ END , VALIDATED_REASON , DECODE( SIGN(MB.Time_stamp - NVL (:b4, sysdate)), -1,-- Zeit vor Setup-Ende DECODE( SIGN(900 - MDT.Validated_Reason), 1, -- manuelle Down times DECODE(MDT.Validated_Reason, 0, 0, 1, 0, 1),

18,420,632 160 115,129.0 67.3 59.56 60.43 979285868
begin MONITOR.GET_VALUES_ON_SHIFT_CHANGE(:1,:2,:3,:4, :5); end;

3,578,182 1,057 3,385.2 13.1 133.70 136.14 3172615181
BEGIN MONITOR.COLLECT_CYCLIC_MACHINE_DATA; END; 1,719,956 22,636 76.0 6.3 83.83 84.29 1952305027

SELECT ID, STARTED, FINISHED   FROM SHIFTS   WHERE         machi
ne = :b2     AND STARTED <= :b1   ORDER BY STARTED desc

       1,539,784           72       21,385.9    5.6    19.55     61.11

1163642282
select ((sysdate - :1/24)- TO_DATE('1970-01-01', 'YYYY-MM-DD')) * 24 * 60 * 60 * 1000 time_stamp, 'M' event, m.order_id, NULL or der_type, mechanical_speed, machine_speed, output_count, ma chine_status, NULL production_number, NULL target_speed, NULL mi nimum_run_speed, DECODE(mdt.validated_reason,NULL,NULL,DEC

DE30 *** Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value --------------- ------------ -------------- ------ -------- ---------
48,577,464 227 213,997.6 77.0 136.63 654.59 979285868 begin MONITOR.GET_VALUES_ON_SHIFT_CHANGE(:1,:2,:3,:4, :5); end;

47,854,480 6,286 7,612.9 75.8 120.13 127.97 395610491
SELECT MDT.ID , MB.Time_stamp TS_START , ME.Time_stamp TS_ END , VALIDATED_REASON , DECODE( SIGN(MB.Time_stamp - NVL

(:b4, sysdate)),     -1,-- Zeit vor Setup-Ende     DECODE(
    SIGN(900 - MDT.Validated_Reason),         1, -- manuelle Down
times         DECODE(MDT.Validated_Reason, 0, 0, 1, 0, 1),

       8,351,896          214       39,027.6   13.2    57.36   3202.14

2,317,372 216 10,728.6 3.7 14.84 1087.68 452266749
SELECT /*+ INDEX(mdt IX_MDT_1) */ DECODE(mdt.validated_reaso n,NULL,NULL,DECODE(mdt.validated_reason,0,'U','A')) error_type,

     t.text error_text,     DECODE(mdt.validated_reason,NULL,NULL
,         DECODE(             SIGN(NVL(po.end_setup, sysdate) -
m.time_stamp),             1, -- in setup             DECODE(

       2,317,372          214       10,828.8    3.7    14.91   1087.86

1909573811
begin MONITOR.GET_DOWN_TIME_REASON(:1,:2,:3, :4,:5,:6); end; Received on Sun Sep 23 2007 - 06:16:14 CDT