input on statspack report

From: <bordenm_at_methodisthealth.org>
Date: 27 Jan 2004 08:20:07 -0800
Message-ID: <db50b9a0.0401270820.3c52e9e1@posting.google.com>

I'm trying to get a grasp on something here. We are seeing a high I/O wait using vmstat on our AIX5L server. It is connected to an IBM shark with two fibre channel cards. I look at the statspack and there are high Average read times, and the documentation on statspack says if you have anything over 20ms Average read times we might need to redistribute the datafiles. However, I'm trying to correalate high average read times to certain vpaths/luns using NMON, and I really do not see any. I want to post a few snippets of the statspack snaps and see what you guys think. I do see some buffer busy waits, I know how to resolve these, however, are those going to cause high I/O waits? Here is a snippet of a vmstat

$ vmstat 2 10
kthr memory page faults cpu

----- ----------- ------------------------ ------------ -----------

 r b avm fre re pi po fr sr cy in sy cs us sy id wa  1 1 1062374 481 0 0 0 298 713 0 4417 12921 6436 8 4 72 16
 3 0 1062378 510 0 0 0 16 16 0 7110 34132 13725 38 7 31 24
 4 0 1063011 657 0 0 2 390 434 0 7225 36281 13898 36 7 35 21
 2 0 1063013 655 0 0 0 0 0 0 8028 39802 15276 35 6 34 24
 3 0 1063017 651 0 0 0 0 0 0 7920 40754 15370 37 7 32 24
 3 0 1063016 652 0 0 0 0 0 0 7622 34952 15280 38 8 29 25
 3 0 1063064 604 0 0 0 0 0 0 5842 24820 11775 36 5 28 30
 4 0 1063065 603 0 0 0 0 0 0 6806 27467 13759 45 6 19 30
 3 0 1063902 490 0 0 0 362 372 0 7890 30898 16121 21 9 42 29
 4 0 1063902 490 0 0 0 0 0 0 7938 29780 17398 10 7 40 43
I would think since we are on a SAN that there should be less I/O wait here than there is CPU utilization.

Here are a few snippets of the statspack.

Cache Sizes

---

           db_block_buffers: 61035 log_buffer: 1048576

              db_block_size: 8192 shared_pool_size: 475000000

Load Profile

~~~~~~~~~~~~                            Per Second       Per
Transaction
                                   ---------------      
---------------
                  Redo size:            201,595.63            
16,468.40
              Logical reads:             16,644.18             
1,359.67
              Block changes:                680.04                
55.55
             Physical reads:                824.76                
67.38
            Physical writes:                 61.14                 
4.99
                 User calls:              1,398.30               
114.23
                     Parses:                192.81                
15.75
                Hard parses:                  0.09                 
0.01
                      Sorts:                 37.32                 
3.05
                     Logons:                  0.98                 
0.08
                   Executes:                716.89                
58.56
               Transactions:                 12.24



  % Blocks changed per Read:    4.09    Recursive Call %:    5.49

 Rollback per transaction %:    2.50       Rows per Sort:   68.12

Instance Efficiency Percentages (Target 100%)

---

            Buffer Nowait %:   99.91       Redo NoWait %:  100.00
            Buffer  Hit   %:   95.04    In-memory Sort %:   99.98
            Library Hit   %:   99.96        Soft Parse %:   99.95
         Execute to Parse %:   73.10         Latch Hit %:   99.93
Parse CPU to Parse Elapsd %:   87.05     % Non-Parse CPU:   98.28

 Shared Pool Statistics        Begin   End
                               ------  ------
             Memory Usage %:   49.58   76.90

    % SQL with executions>1: 57.12 63.39
% Memory for SQL w/exec>1: 79.24 77.33

Top 5 Wait Events

~~~~~~~~~~~~~~~~~                                             Wait    
% Total
Event                                               Waits  Time (cs)  

Wt Time

-------------------------------------------- ------------ ------------
-------
db file sequential read                        49,541,904    8,414,230
  89.74
db file scattered read                          1,248,946      287,366
   3.06
buffer busy waits                               1,185,869      275,561
   2.94
log file sync                                     958,900       91,690
    .98
log file sequential read                          259,712       78,650
    .84
          -------------------------------------------------------------


Here are the datafiles I have in question about the High read times. 
Tablespace               Filename
------------------------
----------------------------------------------------
                 Av      Av     Av                    Av        Buffer
Av Buf
         Reads Reads/s Rd(ms) Blks/Rd       Writes Writes/s      Waits

Wt(ms)
-------------- ------- ------ ------- ------------ -------- ----------

---

D_CN_OMF                 /dev/rprod_0016_126
           146       0  108.0     1.0           39        0          0
D_CPO                    /dev/rprod_0016_023
             40       0  333.5     1.0           40        0         
0
D_DISCERN                /dev/rprod_0256_013
           120       0  137.3     1.0           40        0          0

Now, could it be the reason these have high read times is because it is on a SAN and these particular files have not been read into the CACHE? Mike Received on Tue Jan 27 2004 - 10:20:07 CST