Statspack的一些comments

STATSPACK report for
--数据库DB信息
Database    DB Id    Instance     Inst Num Startup Time    Release     RAC
~~~~~~~~ ----------- ------------ -------- --------------- ----------- ---
           323758096 esuite              1 15-3月 -08 18:3 10.2.0.1.0  NO
                                           4

Host  Name:   ora.linekong.com Num CPUs:    2        Phys Memory (MB):        0

--Statspacks采样时间纬度,时间的纬度很重要，任何的性能统计数据离开了时间的度量都会失去任何意义
这里我们只采样了60分钟左右。
Snapshot       Snap Id     Snap Time      Sessions Curs/Sess Comment
~~~~~~~~    ---------- ------------------ -------- --------- -------------------
Begin Snap:      11111 17-3月 -08 15:00:04      93      19.5
  End Snap:      11121 17-3月 -08 16:00:06      95      19.4
   Elapsed:               60.03 (mins)

Cache Sizes                       Begin        End
~~~~~~~~~~~                  ---------- ----------
               Buffer Cache:     1,840M             Std Block Size:         8K
           Shared Pool Size:       128M                 Log Buffer:    14,958K
   
--这里记录了负载概要信息:
这里通过Per Second和Per Transaction的形式出现。
通常每秒每个事务的负载越高，说明数据库的压力越大。 
这部分信息来自v$sysstat视图收集的统计信息里面。Statspack将这部分信息定时收集记录在stats$sysstat字典表里面，
然后通过前后对比，得出在报告时数据库的负载变化。这里的每一个值都是begin snap和end snap之间的采样差值,这个
差值就是通过spcpkg.sql文件中sysdif函数计算得出的结果。
Load Profile                            Per Second       Per Transaction
~~~~~~~~~~~~                       ---------------       ---------------
                  Redo size:             67,259.07              1,577.52
        这里单位是bytes，数据库每秒产生大约67KB左右的redo日志,每个事务大约产生1KB左右的redo日志,可以和后面的Instance Activity Stats关联.
        计算公式和方法：
        Per Second =  round[242,267,176 bytes / (60.03 (mins) * 60 secs)] = round[242,267,176 bytes /3601.8 seconds] = 67,262.81 bytes = 67KB
        其中Instance Activity Stats:redo size的total列为242,267,176 bytes
                           
              Logical reads:              3,711.07                 87.04
       这里的逻辑读一般都是对data block读取的逻辑读的请求次数，这里表示平均每秒逻辑读大约是3,711.07次，平均每个事务的逻辑读大约是87.04次 
       Logcial Reads = db block gets + consistent gets
        Logcial reads指标可以关联到Instance Activity Stats:Session logical reads.
        我们来看一下：
        consistent gets                           11,605,092        3,221.9         75.6
        db block gets                              1,762,183          489.2         11.5
        session logical reads                     13,367,273        3,711.1         87.0
        基本上我们可以理解为session logical reads = consistent gets + db block gets
       
              Block changes:                522.20                 12.25
       这里表示Block修改信息,也就是每秒和每事务期间修改了多少数据块    
             
             Physical reads:                132.14                  3.10
       这里的物理读是每秒132次，也就是说每秒大约有3.56%的逻辑读带动了物理读(132.14/3,711.07)
             
            Physical writes:                 42.81                  1.00
                 User calls:                126.68                  2.97
                     Parses:                 28.40                  0.67
       这里的Parses表示数据库在采样阶段每秒种总的解析次数(包括所有解析)，每秒是28.40次
        其对应Instance Activity Stats:parse count (total)

                Hard parses:                  0.34                  0.01
       这里的Hard parse表示数据库在采样阶段每秒种的硬解析次数，每秒是0.34次       
        其对应Instance Activity Stats:parse count (hard)
       
                      Sorts:                  5.23                  0.12
                     Logons:                  0.22                  0.01
                   Executes:                300.11                  7.04
               Transactions:                 42.64
       这里表示每秒产生多少个事务，这里是42.64 per Seconds
        我们知道数据库的事务量是由user commits+user rollbacks得来的，这两部分信息也可以从Instance Activity Stats得来
        总量分别是：
        user commits  = 146,930
        user rollbacks  =  6,645
        这样我们可以得出Transactions的总量=user commits + user rollbacks=146,930+6,645 = 153,575
        那么每秒的事务量(Transactions Per Seconds)= round(153,575 / 3601.8 seconds) = 42.64
        结果和上面的显示一样。
        同时对应于上面的Redo size也可以计算中Per Transaction的大小了：
        Redo size Per Transactions = round(242,267,176 bytes / 153,575) = 1577.52 bytes
              
              
  % Blocks changed per Read:   14.07    Recursive Call %:    76.90
这里Blocks changed per Read表示每一次逻辑读对于block的修改或者是改变，按照每秒计算取上面的采样就可以计算出来
%(Block changes / Logical reads) = %(522.20/3,711.07) = 14.07%,一般来讲这个数值不宜过大，block变化越频繁会给数据库带来很大的压力
从而会影响性能。

 Rollback per transaction %:    4.33       Rows per Sort:   118.44
回滚对于Oracle来讲是非常昂贵的操作，过多的回滚不仅仅表示数据库经历了过多的无用操作，同时也意味着增加了Undo segment的竞争
这里也是利用一些采样指标计算出来的：
%(User rollbacks/(user commits + user rollbacks)) = %(6,645/(146,930+6,645)) = 4.33%
其实更精确的计算方法应该是用Trasaction rollbacks来代替User rollbacks，意思是只有在事务真正回滚的时候才被计数：
%（Transaction rollbacks/(user commits + Transaction rollbacks) = %(379/(146,930+379)) = 0.26%
 
Instance Efficiency Percentages
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:   99.98
            Buffer  Hit   %:   96.44    In-memory Sort %:  100.00
   对于Buffer Hit
    这里在次强调一下精确的Buffer hit的计算公式：
    Buffer Hit% = 1 - [(physical reads-(physical reads directs + physical reads direct(lob)))
                       /
                       db block gets + consistent gets - (physical reads directs + physical reads direct(lob)) ]
    关于里面的每一值我们都可以到Instance Activity Stats区域找到.
    这里的buffer hit有点低了，需要引起注意.    但是命中率并不是全部要做为性能调优的依据，有的情况下，命中率高的时性能不一定好。
    比如大量的逻辑读

   对于In-memory Sort
    这里也强调一下，表示了SQL在PGA的私有工作区中的排序率。排序也是数据库中比较昂贵的操作之一，所以这里我们尽量希望Oracle的排序完全在
    内存中做完,这里的计算公式是：
    In - memory Sort % = (sort memory/(sort memory+sort disk))
    这里的指标说明我们所有的排序操作完全是在PGA中做完的，如果这个指标过低那么我们就要引起关注.
   
            Library Hit   %:   99.78        Soft Parse %:   98.79
   对于Sort Parse%这个比率就表示一个SQL语句直接共享了library cache中的执行计划，而不是或者latch重新生成执行计划。
    这个比率越高也好。
    计算公式是：
    Sort Parse % = 1 - (parse count(hard) / parse count(total))    = 1 - (1233/102,303) = 0.9879 * 100 = 98.79%
           
         Execute to Parse %:   90.54         Latch Hit %:  100.00
   对于Execute to Parse %表示分析和执行之间的百分比，计算的数据源也来自Instance Activity Stats区域
    计算公式为：
    Execute to Parse % = 1 - (parse count(total) / execute count) = 1 - (102,303/1,081,007) = 90.54%
    一般来说如果这个值要是为负或者很低，那就说名数据库的shared pool存在着性能问题。
         
Parse CPU to Parse Elapsd %:   84.67     % Non-Parse CPU:   98.13
   对于Prase CPU to Parse Elapsed %
    其计算公式为 100 * (parse time cpu / parse time elapsed) = 100 * ( 591/698) = 84.67%
    parse time CPU表示的是SQL解析过程中耗用的CPU时间，而parse time elapsed代表着整个SQL语句执行所耗用的时间。
    从优化角度来讲这个比率越高越好，期望值是100%，表示在SQL解析过程中所有的解析时间都放在了CPU上，而不是耗费
    在其他无用的等待上面。


 Shared Pool Statistics        Begin   End
                               ------  ------
             Memory Usage %:   87.21   88.17
    % SQL with executions>1:   73.15   86.31
  % Memory for SQL w/exec>1:   51.38   92.58


Top 10 Timed Events                                                   Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
log file sync                                  108,968       2,344     22   47.6
log file parallel write                        102,000       1,537     15   31.2
db file sequential read                         47,873         458     10    9.3
CPU time                                                       316           6.4
control file parallel write                      3,618          95     26    1.9
db file scattered read                          34,268          70      2    1.4
ARCH wait on SENDREQ                               336          43    127     .9
buffer exterminate                                  27          19    686     .4
buffer busy waits                                   75          13    179     .3
log file switch completion                          58           8    137     .2
          -------------------------------------------------------------
Host CPU  (CPUs: 2)
~~~~~~~~              Load Average
                      Begin     End      User  System    Idle     WIO     WCPU
                    ------- -------   ------- ------- ------- ------- --------
                       1.74    1.17      6.17    1.18   92.65

Note: There is a 29% discrepancy between the OS Stat total CPU time and
      the total CPU time estimated by Statspack
          OS Stat CPU time: 5079(s) (BUSY_TIME + IDLE_TIME)
        Statspack CPU time: 7204(s) (Elapsed time * num CPUs in end snap)

Instance CPU
~~~~~~~~~~~~
              % of total CPU for Instance:    8.39
              % of busy  CPU for Instance:  114.13
  %DB time waiting for CPU - Resource Mgr:

Memory Statistics                       Begin          End
~~~~~~~~~~~~~~~~~                ------------ ------------
                  Host Mem (MB):           .0           .0
                   SGA use (MB):      2,048.0      2,048.0
                   PGA use (MB):        386.9        339.9
    % Host Mem used for SGA+PGA:   15321729.0   15440866.7
          -------------------------------------------------------------

Time Model System Stats  DB/Inst: ESUITE/esuite  Snaps: 11111-11121
-> Ordered by % of DB time desc, Statistic name

Statistic                                       Time (s) % of DB time
----------------------------------- -------------------- ------------
sql execute elapsed time                           900.0         27.9
DB CPU                                             401.1         12.4
PL/SQL execution elapsed time                       19.9           .6
parse time elapsed                                   9.5           .3
hard parse elapsed time                              5.1           .2
connection management call elapsed                   3.6           .1
sequence load elapsed time                           0.9           .0
repeated bind elapsed time                           0.7           .0
PL/SQL compilation elapsed time                      0.6           .0
hard parse (sharing criteria) elaps                  0.3           .0
hard parse (bind mismatch) elapsed                   0.0           .0
failed parse elapsed time                            0.0           .0
DB time                                          3,224.9
background elapsed time                          2,484.2
background cpu time                                 24.9
          -------------------------------------------------------------
Wait Events  DB/Inst: ESUITE/esuite  Snaps: 11111-11121
-> s - second, cs - centisecond,  ms - millisecond, us - microsecond
-> %Timeouts:  value of 0 indicates value was < .5%.  Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)

                                                                    Avg
                                                %Time Total Wait   wait    Waits
Event                                    Waits  -outs   Time (s)   (ms)     /txn
--------------------------------- ------------ ------ ---------- ------ --------
log file sync                          108,968      0      2,344     22      0.7
log file parallel write                102,000      0      1,537     15      0.7
db file sequential read                 47,873      0        458     10      0.3
control file parallel write              3,618      0         95     26      0.0
db file scattered read                  34,268      0         70      2      0.2
ARCH wait on SENDREQ                       336      0         43    127      0.0
buffer exterminate                          27     52         19    686      0.0
buffer busy waits                           75      9         13    179      0.0
log file switch completion                  58      0          8    137      0.0
log file sequential read                   319      0          6     18      0.0
enq: TX - row lock contention              405      0          5     13      0.0
SGA: MMAN sleep for component shr          254     99          3     11      0.0
Log archive I/O                            813      0          1      2      0.0
os thread startup                           53      0          1     18      0.0
enq: CF - contention                        12      0          0     35      0.0
control file sequential read            15,584      0          0      0      0.1
latch: library cache                       233      0          0      1      0.0
log file single write                       24      0          0      8      0.0
read by other session                       18      0          0      5      0.0
SQL*Net more data to client                263      0          0      0      0.0
latch free                                  27      0          0      2      0.0
SQL*Net break/reset to client              174      0          0      0      0.0
enq: TX - index contention                   7      0          0      6      0.0
LGWR wait for redo copy                    161      0          0      0      0.0
latch: cache buffers chains                 16      0          0      1      0.0
latch: row cache objects                    12      0          0      1      0.0
latch: shared pool                          14      0          0      0      0.0
latch: In memory undo latch                 14      0          0      0      0.0
latch: cache buffers lru chain              13      0          0      0      0.0
latch: enqueue hash chains                  11      0          0      0      0.0
latch: object queue header operat            8      0          0      0      0.0
latch: library cache pin                    10      0          0      0      0.0
latch: session allocation                   17      0          0      0      0.0
SQL*Net message from client            394,676      0    229,568    582      2.6
virtual circuit status                     120    100      3,495  29126      0.0
jobq slave wait                          1,117     99      3,260   2919      0.0
SQL*Net message to client              394,677      0          1      0      2.6
SQL*Net more data from client               35      0          0      0      0.0
          -------------------------------------------------------------
Background Wait Events  DB/Inst: ESUITE/esuite  Snaps: 11111-11121
-> %Timeouts:  value of 0 indicates value was < .5%.  Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)

                                                                    Avg
                                                %Time Total Wait   wait    Waits
Event                                    Waits  -outs   Time (s)   (ms)     /txn
--------------------------------- ------------ ------ ---------- ------ --------
log file parallel write                102,008      0      1,537     15      0.7
control file parallel write              3,618      0         95     26      0.0
ARCH wait on SENDREQ                       336      0         43    127      0.0
log file sequential read                   319      0          6     18      0.0
SGA: MMAN sleep for component shr          254     99          3     11      0.0
Log archive I/O                            813      0          1      2      0.0
os thread startup                           53      0          1     18      0.0
db file sequential read                     22      0          1     33      0.0
events in waitclass Other                  190      0          0      2      0.0
db file scattered read                      20      0          0     17      0.0
control file sequential read            13,522      0          0      0      0.1
log file single write                       24      0          0      8      0.0
latch: library cache                         1      0          0      3      0.0
rdbms ipc message                       94,045     11     46,349    493      0.6
pmon timer                               1,260    100      3,514   2789      0.0
smon timer                                  15     67      3,347 ######      0.0
          -------------------------------------------------------------
Wait Event Histogram  DB/Inst: ESUITE/esuite  Snaps: 11111-11121
-> Total Waits - units: K is 1000, M is 1000000, G is 1000000000
-> % of Waits - column heading: <=1s is truly <1024ms, >1s is truly >=1024ms
-> % of Waits - value: .0 indicates value was <.05%, null is truly 0
-> Ordered by Event (idle events last)

                           Total ----------------- % of Waits ------------------
Event                      Waits  <1ms  <2ms  <4ms  <8ms <16ms <32ms  <=1s   >1s
-------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
ARCH wait on SENDREQ        336   66.1   5.4    .3          .6   1.2  24.7   1.8
LGWR wait for redo copy     161   96.9   1.2   1.9
Log archive I/O             813   34.6  40.6  23.2    .6   1.0
SGA: MMAN sleep for compon  254           .4          .4  99.2
SQL*Net break/reset to cli  174   96.0         2.3   1.7
SQL*Net more data to clien  263   95.8    .4    .8   1.9   1.1
buffer busy waits            75   48.0   1.3   4.0   1.3   1.3   5.3  38.7
buffer exterminate           27                                      100.0
control file parallel writ 3618                            1.7  86.7  11.6
control file sequential re   15K  99.9                .0    .0    .0
db file scattered read       34K  72.8  10.2   3.0   7.4   4.2   2.0    .3
db file sequential read      47K  22.2    .2    .4   6.0  65.2   5.7    .2
direct path read            228  100.0
direct path write           230  100.0
enq: CF - contention         12   25.0         8.3   8.3        25.0  33.3
enq: SQ - contention          1  100.0
enq: TX - index contention    7               28.6  57.1  14.3
enq: TX - row lock content  405   32.6   7.2   8.9  18.0  24.2   6.4   2.7
latch free                   27   74.1   7.4  11.1         3.7         3.7
latch: In memory undo latc   14   92.9               7.1
latch: cache buffers chain   16   75.0   6.3  12.5   6.3
latch: cache buffers lru c   13   92.3         7.7
latch: enqueue hash chains   11   90.9   9.1
latch: library cache        233   85.8   5.2   4.7   3.0    .4          .9
latch: library cache pin     10  100.0
latch: object queue header    8   75.0  25.0
latch: redo allocation       13  100.0
latch: redo writing           7  100.0
latch: row cache objects     12   83.3   8.3         8.3
latch: session allocation    17  100.0
latch: shared pool           13   76.9  23.1
latch: undo global data       4  100.0
log file parallel write     102K                .0   5.0  55.4  39.1    .4
log file sequential read    319   40.1   2.5   3.4   5.6   9.4  14.4  24.5
log file single write        24                8.3  37.5  54.2
log file switch completion   58    5.2                    13.8   5.2  75.9
log file sync               108K    .0    .0    .0   2.9  35.1  51.3  10.6
os thread startup            53                           24.5  75.5
rdbms ipc reply               3  100.0
read by other session        18   22.2  11.1  16.7  22.2  22.2   5.6
SQL*Net message from clien  394K  61.6    .9   1.4   2.1   2.6   4.4  24.3   2.7
SQL*Net message to client   394K 100.0
SQL*Net more data from cli   35   97.1               2.9
dispatcher timer             60                                            100.0
jobq slave wait            1117                                         .4  99.6
pmon timer                 1260    4.8                                  .1  95.2
rdbms ipc message            94K  30.6   1.8   2.9   6.3  10.2  14.6  26.6   7.0
smon timer                   15                                            100.0
virtual circuit status      120                                            100.0
          -------------------------------------------------------------

SQL ordered by CPU  DB/Inst: ESUITE/esuite  Snaps: 11111-11121
-> Resources reported for PL/SQL code includes the resources used by all SQL
   statements called by the code.
-> Total DB CPU (s):             401
-> Captured SQL accounts for  147.4% of Total DB CPU
-> SQL reported below exceeded  1.0% of Total DB CPU

    CPU                  CPU per             Elapsd                     Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)    Buffer Gets  Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
     81.71       19,561       0.00   20.4     169.43       4,337,235 3149343083
Module: eRatingServer@eRating (TNS V1-V3)
begin :1 := PKG_USER.enterGame(:2, :3, :4, :5, :6, :7, :8, :9, :
10, :11, :12, :13, :14);end;

     48.45       48,612       0.00   12.1     246.29         581,722   97521119
BEGIN :1 := pkg_eadmonitor_record.clickDirectly(:2,:3); END;

     46.80        1,876       0.02   11.7      56.93       3,755,675 3024237757
Module: eRatingServer@eRating (TNS V1-V3)
begin :1 := PKG_IB.buyProduct(:2, :3, :4, :5, :6, :7, :8, :9, :1
0, :11, :12, :13, :14, :15, :16, :17, :18, :19);end;

     42.61        1,781       0.02   10.6      43.50       3,678,612 3468525071
Module: eRatingServer@eRating (TNS V1-V3)
SELECT FUND_DETAIL_ID, LEFT_AMOUNT, CHANNEL_ID, DISCOUNT_RATIO F
ROM UMS_USER_FUND_DETAIL WHERE (RATING_ID = :B3 ) AND (USER_ID =
 :B2 ) AND (SUBJECT_ID = :B1 ) AND (LEFT_AMOUNT > 0) ORDER BY FU
ND_DETAIL_ID ASC FOR UPDATE

     40.53            4      10.13   10.1      52.84         476,638  791936117
Module: SQL