statspack分析报告急在线等

jeffreyli

抓取相关内容为早上9-10一个小时的:

Begin Snap:       496 03-Oct-06 09:00:04       62     323.8
  End Snap:       497 03-Oct-06 10:00:05       63     319.4
   Elapsed:               60.02 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
               Buffer Cache:     1,536M      Std Block Size:          8K
           Shared Pool Size:       512M          Log Buffer:     10,240K

Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            569,631.79              2,210.82
              Logical reads:              6,365.71                 24.71
              Block changes:              3,917.92                 15.21
             Physical reads:                572.27                  2.22
            Physical writes:                 82.13                  0.32
                 User calls:                931.98                  3.62
                     Parses:                322.05                  1.25
                Hard parses:                  0.01                  0.00
                      Sorts:                237.63                  0.92
                     Logons:                  0.10                  0.00
                   Executes:                441.11                  1.71
               Transactions:                257.66

  % Blocks changed per Read:   61.55    Recursive Call %:     54.04
Rollback per transaction %:    0.00       Rows per Sort:      2.40

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:    100.00
            Buffer  Hit   %:   91.01    In-memory Sort %:    100.00
            Library Hit   %:  100.03        Soft Parse %:    100.00
         Execute to Parse %:   26.99         Latch Hit %:     99.10
Parse CPU to Parse Elapsd %:    3.93     % Non-Parse CPU:     99.53

Shared Pool Statistics        Begin   End
                               ------  ------
             Memory Usage %:   91.40   91.36
    % SQL with executions>1:    1.65    1.71
  % Memory for SQL w/exec>1:    2.27    2.34

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~                                                     % Total
Event                                               Waits    Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
log file sync                                   1,143,542      48,685    89.62
db file scattered read                            130,666       2,147     3.95
db file sequential read                            74,154       1,231     2.27
db file parallel write                              5,864       1,016     1.87
CPU time                                                          928     1.71
          -------------------------------------------------------------
Wait Events for DB: test  Instance: test  Snaps: 496 -497
-> s  - second
-> cs - centisecond -     100th of a second
-> ms - millisecond -    1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

                                                                   Avg
                                                     Total Wait   wait    Waits
Event                               Waits   Timeouts   Time (s)   (ms)     /txn
---------------------------- ------------ ---------- ---------- ------ --------
log file sync                   1,143,542      1,025     48,685     43      1.2
db file scattered read            130,666          0      2,147     16      0.1
db file sequential read            74,154          0      1,231     17      0.1
db file parallel write              5,864          0      1,016    173      0.0
control file parallel write         1,213          0        142    117      0.0
row cache lock                     79,258          0         64      1      0.1
SQL*Net message from dblink           113          0         40    350      0.0
log file switch completion            158          0         26    164      0.0
control file sequential read          619          0         13     21      0.0
latch free                          6,074      3,728         12      2      0.0
log file parallel write           156,175          0         12      0      0.2
single-task message                     8          0          7    888      0.0
buffer busy waits                     303          0          1      3      0.0
direct path read                      164          0          1      3      0.0
direct path write                     164          0          0      2      0.0
process startup                         3          0          0     75      0.0
enqueue                                 9          0          0     21      0.0
log file single write                   8          0          0     15      0.0
LGWR wait for redo copy               717          0          0      0      0.0
SQL*Net break/reset to clien           10          0          0      3      0.0
log file sequential read                8          0          0      4      0.0
db file parallel read                   1          0          0     22      0.0
SQL*Net more data to client           360          0          0      0      0.0
SQL*Net message to dblink             113          0          0      0      0.0
undo segment extension                  1          1          0      0      0.0
SQL*Net message from client     3,354,102          0     99,373     30      3.6
virtual circuit status                120        120      3,492  29100      0.0
wakeup time manager                   116        116      3,384  29168      0.0
jobq slave wait                        66         63        191   2889      0.0
SQL*Net message to client       3,354,105          0          8      0      3.6
          -------------------------------------------------------------


以下为晚上18到19的相关信息
Begin Snap:       505 03-Oct-06 18:00:05       65     314.4
  End Snap:       506 03-Oct-06 19:00:01       64     320.0
   Elapsed:               59.93 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
               Buffer Cache:     1,536M      Std Block Size:          8K
           Shared Pool Size:       512M          Log Buffer:     10,240K

Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:            233,834.30              2,155.26
              Logical reads:              3,189.30                 29.40
              Block changes:              1,600.69                 14.75
             Physical reads:                741.23                  6.83
            Physical writes:                 30.01                  0.28
                 User calls:                410.25                  3.78
                     Parses:                143.64                  1.32
                Hard parses:                  0.03                  0.00
                      Sorts:                107.45                  0.99
                     Logons:                  0.26                  0.00
                   Executes:                190.19                  1.75
               Transactions:                108.49

  % Blocks changed per Read:   50.19    Recursive Call %:     52.70
Rollback per transaction %:    0.00       Rows per Sort:      3.45

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:    100.00
            Buffer  Hit   %:   76.76    In-memory Sort %:    100.00
            Library Hit   %:  100.01        Soft Parse %:     99.98
         Execute to Parse %:   24.48         Latch Hit %:     99.68
Parse CPU to Parse Elapsd %:    4.34     % Non-Parse CPU:     99.73

Shared Pool Statistics        Begin   End
                               ------  ------
             Memory Usage %:   91.44   91.44
    % SQL with executions>1:    1.82    1.94
  % Memory for SQL w/exec>1:    2.58    2.90

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~                                                     % Total
Event                                               Waits    Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
log file sync                                     477,560      14,391    80.63
db file scattered read                            185,231       2,061    11.55
CPU time                                                          661     3.70
db file parallel write                              2,524         384     2.15
db file sequential read                            27,470         292     1.63
          -------------------------------------------------------------
Wait Events for DB: test  Instance: test  Snaps: 505 -506
-> s  - second
-> cs - centisecond -     100th of a second
-> ms - millisecond -    1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

                                                                   Avg
                                                     Total Wait   wait    Waits
Event                               Waits   Timeouts   Time (s)   (ms)     /txn
---------------------------- ------------ ---------- ---------- ------ --------
log file sync                     477,560          0     14,391     30      1.2
db file scattered read            185,231          0      2,061     11      0.5
db file parallel write              2,524          0        384    152      0.0
db file sequential read            27,470          0        292     11      0.1
control file parallel write         1,210          0         34     28      0.0
log file parallel write           213,549          0         11      0      0.5
row cache lock                     10,671          0          6      1      0.0
single-task message                     6          0          4    633      0.0
control file sequential read          586          0          2      3      0.0
log file switch completion             17          0          2    109      0.0
SQL*Net message from dblink            72          0          0      5      0.0
latch free                            236        176          0      1      0.0
process startup                         3          0          0     71      0.0
direct path read                       82          0          0      2      0.0
direct path write                      84          0          0      2      0.0
db file parallel read                   1          0          0     94      0.0
log file single write                   2          0          0     14      0.0
LGWR wait for redo copy               666          0          0      0      0.0
SQL*Net more data to client           433          0          0      0      0.0
log file sequential read                2          0          0      9      0.0
SQL*Net break/reset to clien           14          0          0      0      0.0
buffer busy waits                      97          0          0      0      0.0
SQL*Net message to dblink              72          0          0      0      0.0
undo segment extension                  1          1          0      0      0.0
SQL*Net message from client     1,473,483          0    138,444     94      3.8
virtual circuit status                120        120      3,515  29294      0.0
wakeup time manager                   116        116      3,378  29121      0.0
jobq slave wait                        66         63        191   2889      0.0
SQL*Net message to client       1,473,484          0          3      0      3.8
          -------------------------------------------------------------
Background Wait Events for DB: test  Instance: test  Snaps: 505 -506
-> ordered by wait time desc, waits desc (idle events last)

                                                                   Avg
                                                     Total Wait   wait    Waits
Event                               Waits   Timeouts   Time (s)   (ms)     /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file parallel write              2,524          0        384    152      0.0
control file parallel write         1,210          0         34     28      0.0
log file parallel write           213,547          0         11      0      0.5
control file sequential read          505          0          2      4      0.0
db file scattered read                 48          0          0     10      0.0
direct path read                       82          0          0      2      0.0
direct path write                      82          0          0      2      0.0
db file sequential read                 7          0          0     16      0.0
rdbms ipc reply                       140          0          0      1      0.0
log file single write                   2          0          0     14      0.0
LGWR wait for redo copy               666          0          0      0      0.0
log file sequential read                2          0          0      9      0.0
latch free                              1          0          0      0      0.0
buffer busy waits                       1          0          0      0      0.0
rdbms ipc message                  37,479      2,304      9,661    258      0.1
smon timer                             41          4      3,519  85824      0.0
pmon timer                          1,199      1,199      3,511   2928      0.0
          -------------------------------------------------------------


数据库的log  文件建立在raid 5上,所以log file sync 事件比较多.但是已经把group加大,每个group只有一个member.
哪位大虾帮忙分析一下还有没有其它原因?

[ 本帖最后由 jeffreyli 于 2006-10-4 08:14 编辑 ]

numenhuang

1. redo log size多大，在一个小时中log switch的次数很多，特别是早上9:00-10:00,建议增大redo log size和增加redo log group
2. redo log和data file是否放在同一raid 5上，已经发生了磁盘I/O读写瓶颈了，一般不建议把redo log放在raid 5,并且和data file放在一起，可以单独使用一组raid 0+1存放redo log。
3. 这个报告没有包含user statistics信息，要监测以下user commits是否过于频繁？
4. db file scattered read，latch free，buffer busy waits, db file sequential read,enqueue几个事件的数值都不小（在一个小时的采样时间），建议你根据stackspace的TOP sql，结合v$session_longops察看一下这些sql的统计信息，是否没有创建合适的索引，索引有没有得到合理的应用？

jeffreyli

谢谢兄弟的关注.

Statistic                                      Total     per Second    per Trans
--------------------------------- ------------------ -------------- ------------
enqueue timeouts                                   1            0.0          0.0
enqueue waits                                      9            0.0          0.0
exchange deadlocks                                 0            0.0          0.0
execute count                              1,588,445          441.1          1.7
free buffer inspected                            628            0.2          0.0
free buffer requested                      2,180,966          605.7          2.4
hot buffers moved to head of LRU             130,783           36.3          0.1
immediate (CR) block cleanout app             30,312            8.4          0.0
immediate (CURRENT) block cleanou            987,374          274.2          1.1
index fast full scans (rowid rang                  0            0.0          0.0
index fetch by key                           216,232           60.1          0.2
index scans kdiixs1                          450,348          125.1          0.5
leaf node 90-10 splits                           562            0.2          0.0
leaf node splits                               9,742            2.7          0.0
logons cumulative                                350            0.1          0.0
messages received                            162,340           45.1          0.2
messages sent                                162,340           45.1          0.2
no buffer to keep pinned count                     0            0.0          0.0
no work - consistent read gets             2,314,106          642.6          2.5
opened cursors cumulative                    219,284           60.9          0.2
parse count (failures)                             4            0.0          0.0
parse count (hard)                                47            0.0          0.0
parse count (total)                        1,159,685          322.1          1.3
parse time cpu                                   433            0.1          0.0
parse time elapsed                            11,015            3.1          0.0
physical reads                             2,060,736          572.3          2.2
physical reads direct                            164            0.1          0.0
physical writes                              295,767           82.1          0.3
physical writes direct                           164            0.1          0.0
physical writes non checkpoint               155,808           43.3          0.2
pinned buffers inspected                           0            0.0          0.0
prefetch clients - default                         0            0.0          0.0
prefetched blocks                          1,855,753          515.3          2.0
prefetched blocks aged out before                 26            0.0          0.0
process last non-idle time                     3,601            1.0          0.0
queries parallelized                               0            0.0          0.0
recursive calls                            3,946,052        1,095.8          4.3
recursive cpu usage                            1,999            0.6          0.0
redo blocks written                        4,214,377        1,170.3          4.5
redo buffer allocation retries                    73            0.0          0.0
redo entries                               7,600,869        2,110.8          8.2
redo log space requests                          164            0.1          0.0
redo log space wait time                       2,658            0.7          0.0
redo ordering marks                                0            0.0          0.0
redo size                              2,051,244,068      569,631.8      2,210.8
redo synch time                            4,989,392        1,385.6          5.4
redo synch writes                          1,142,523          317.3          1.2
redo wastage                              38,350,268       10,649.9         41.3
redo write time                              357,376           99.2          0.4
redo writer latching time                          6            0.0          0.0
redo writes                                  156,184           43.4          0.2
rollback changes - undo records a                 16            0.0          0.0
rows fetched via callback                      1,301            0.4          0.0
session connect time                               0            0.0          0.0
session logical reads                     22,922,921        6,365.7         24.7
session pga memory                         1,665,400          462.5          1.8
Instance Activity Stats for DB: test  Instance: test  Snaps: 496 -497

Statistic                                      Total     per Second    per Trans
--------------------------------- ------------------ -------------- ------------
session pga memory max                    20,079,592        5,576.1         21.6
session uga memory                     4,300,003,128    1,194,113.6      4,634.5
session uga memory max                    43,879,808       12,185.5         47.3
shared hash latch upgrades - no w            424,394          117.9          0.5
shared hash latch upgrades - wait                 10            0.0          0.0
sorts (disk)                                       0            0.0          0.0
sorts (memory)                               855,698          237.6          0.9
sorts (rows)                               2,057,690          571.4          2.2
summed dirty queue length                      1,594            0.4          0.0
switch current to new buffer                     342            0.1          0.0
table fetch by rowid                         457,936          127.2          0.5
table fetch continued row                          7            0.0          0.0
table scan blocks gotten                   2,223,258          617.4          2.4
table scan rows gotten                   142,660,573       39,616.9        153.8
table scans (direct read)                          0            0.0          0.0
table scans (long tables)                         14            0.0          0.0
table scans (rowid ranges)                         0            0.0          0.0
table scans (short tables)                   215,616           59.9          0.2
transaction rollbacks                             18            0.0          0.0
transaction tables consistent rea                  0            0.0          0.0
transaction tables consistent rea                  0            0.0          0.0
user calls                                 3,356,061          932.0          3.6
user commits                                 927,821          257.7          1.0
user rollbacks                                     0            0.0          0.0
workarea executions - onepass                      0            0.0          0.0
workarea executions - optimal              1,629,151          452.4          1.8
write clones created in backgroun                  0            0.0          0.0
write clones created in foregroun                679            0.2          0.0
          -------------------------------------------------------------


我的redo log buffer 已经设为10M.
我的1个小时的采样时间,log file sync是不是累计等待用了8个多小时.正常情况下应该是多少呢?
索引看了一下都没有问题.都有有效状态.


依兄弟的意思是与主机存储有关还是与数据库有关呢?

[ 本帖最后由 jeffreyli 于 2006-10-4 11:45 编辑 ]

numenhuang

这个还是跟你的redo log和data file在磁盘上的分布有关，还有所在的磁盘所采用的raid方式。
log buffer增大解决不了你的问题。增大redo log file的大小，增加log file group以减小，以减小log switch次数。将redo log file单独分配到raid0+1的磁盘阵列上。redo log在正常情况是只写不读的，所以分布在raid 5上是得不偿失的。（对于繁忙的oltp应用来说）。
索引状态有效并不代表索引得到了有效的利用，还是要通过top sql的信息来分析sql语句的execute plan来确认索引是不是得到了合理有效的使用。同时要看高耗资源的sql语句是否写的合理。

rollingpig

1。 log file sync wait 无疑是最大的问题，解决这个问题可以从两方面入手
A. 看看程序的逻辑，是否存在过量的commit, 比如说，在一个loop 里面commit ?
B. 保证log file 放在快速的存储介质上，尽量不要放在RAID 5 上

2.db file scattered read  不小，估计有不恰当的全表扫描，Tune Top SQL

3. 以附件形式上传整个statspack report 更有利于解决问题，提供OS 的配置，如存储设置，内存总数及现有的free memory, OS 版本,以及CPU 个数等也有利于决问题