Oracle Respones-Time Analysis Reports

Oracle響應時間分析報告分為系統級與會話級,報告相比awr報告更加直觀清楚有助於快速分析定位效能問題，這裡使用OSM工具來生成這兩種型別的報告，該工具是由Craig Shallahamer所寫。
在資料庫中建立osm使用者並安裝osm指令碼所需要使用的物件

[oracle@db1 ~]$ sqlplus / as sysdba
SQL*Plus: Release 11.2.0.4.0 Production on Wed Feb 27 15:43:54 2019
Copyright (c) 1982, 2013, Oracle.  All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
SQL> create user osm   identified by "osm" default tablespace sx temporary tablespace temp;
User created.
SQL> grant connect,resource,dba to osm;
Grant succeeded.
SQL> conn osm/osm
Connected.
SQL>  exec sys.dbms_lock.sleep(5);
PL/SQL procedure successfully completed.
SQL> @osmprep.sql
OraPub System Monitor - Interactive (OSM-I) installation script.
(c)1998,1999,2000,2001,2002,2003,2004,2005,2006,2007,2008 by OraPub, Inc.
(c)2009,2010,2011,2012,2013,2014,2015 by OraPub, Inc.
There is absolutely no guarantee with this software.  You may
use this software at your own risk, not OraPub's risk.
No value is implied or stated.
You may need to run $ORACLE_HOME/rdbms/admin/catblock.sql
Connect as the user who will be using the OSM.
Press ENTER to continue.
.....
To categorize wait events for OSM reports, run:
For pre-10g systems, run event_type_nc.sql
For 10g and beyond, run event_type.sql
Once you cateogrize the wait events, the installation is complete.
Menu is osm.sql
ENJOY!!
SQL> @event_type.sql
file: event_type.sql for Oracle 10g and beyond...
About to categorize wait events for OSM reports.
Press ENTER to re-create the o$event_type table.
.....
OraPub Categorization Summary
-----------------------------------------------
TYPE                   COUNT(*)
-------------------- ----------
bogus                       126
ior                          20
iow                          59
other                      1162
  COUNT(*)
----------
      1367
Oracle Categorization Summary
-----------------------------------------------
WAIT_CLASS             COUNT(*)
-------------------- ----------
Administrative               55
Application                  17
Cluster                      50
Commit                        2
Concurrency                  33
Configuration                24
Idle                         96
Network                      35
Other                       958
Queueing                      9
Scheduler                     8
WAIT_CLASS             COUNT(*)
-------------------- ----------
System I/O                   32
User I/O                     48
13 rows selected.
  COUNT(*)
----------
      1367

OSM工具包中的rtsess.sql是用來生成會話級報告，rtsysx.sql,rtpctx.sql用來生成例項級報告

例項級Oracle響應時間分析報告是基於rtsysx.sql指令碼，它將捕獲指定時間間隔內例項範圍內關於響應時間方面的詳細資訊。這個指令碼將對例項級統計資訊(v$sysstat,v$sys_time_model)與例項級等待事件統計資訊(v$system_event)生成快照。下面的例子在120秒的時間間隔內，指令碼每10秒被喚醒一次，從v$session檢視中查詢活動的SQL並儲存當前正在執行的SQL_ID。在報告生命週期結束後，其它的統計住處快照會生成，計算出時間差異並生成報告。幾乎報告中的所有資訊都可以從Statspack或AWR報告中進行收集。使用rtsysx.sql腳可以生成格式化的輸出可以快速的執行Oracle響應時間分析。使用指令碼rtsysx.sql指令碼生成的報告包括以下幾個組成部分:
.第一部分是關注工作量負載情況
.第二部分是高階別的響應時間分類資訊
.第三部分是IO與非IO情況
.第四部分是沒有使用繫結變數的SQL語句
.對於Oracle 10g及以上版本，第五部分是關於作業系統CPU利用率

下面執行rtsysx.sql指令碼，執行生命週期是120秒，指令碼每10秒被喚醒一次。

SQL> @rtsysx.sql 120 10
OraPub's Response Time Analysis (RTA) interactive system level delta report
Initializing response time delta objects...
Sleeping and probing active SQL for next 120 seconds...
Done sleeping...gathering and storing current values...
*** Response Time Ratio and Workload Metrics
RT Ratio  Ora Trx/s Block Changes/s User Calls/s      Execs/s
-------- ---------- --------------- ------------ ------------
   0.325       0.54           90.63        27.41       100.00
*** Response Time System Summary (delta - interactive - system level)
   Tot CPU   CPU SP   CPU BG CPU Parse CPU Recur         Tot Wait  IO Wait Other Wait
      Time     Time     Time      Time      Time Ora CPU     Time     Time       Time       %          %
     (sec)    (sec)    (sec)     (sec)     (sec)  Util %    (sec)    (sec)      (sec) IO Wait Other Wait
---------- -------- -------- --------- --------- ------- -------- -------- ---------- ------- ----------
        34       26        8         2        15     0.4       17       15          1      92          8
*** I/O Wait Time Summary w/Event Details (delta - interactive - system level)
 IO Wait  IO WRITE    IO READ
    Time Wait Time  Wait Time  % IO % IO
   (sec)     (sec)      (sec) Write Read
-------- --------- ---------- ----- ----
      15        10          5    66   34
                                                                          Tot Call    Avg Call
                                                                         Wait Time   Wait Time
IO Wait Event                                                R,W     %       (sec)        (ms) Tot Waits
------------------------------------------------------------ --- ----- ----------- ----------- ---------
LGWR real time apply sync                                    W      57        8.69       65.83       132
db file sequential read                                      R      31        4.67        4.97       940
LGWR-LNS wait on channel                                     W       5        0.71        1.74       408
*** Other Wait Time (non-I/O) Event Detail (delta - interactive - system level)
                                                                      Tot Call    Avg Call
                                                                     Wait Time   Wait Time
Non IO (other) Wait Event                                        %       (sec)        (ms) Tot Waits
------------------------------------------------------------ ----- ----------- ----------- ---------
gc current block 2-way                                          26        0.35        0.62       569
gc cr grant 2-way                                               17        0.23        0.48       484
reliable message                                                10        0.14        1.21       116
os thread startup                                               10        0.14       23.33         6
enq: US - contention                                             6        0.08        0.49       163
library cache pin                                                6        0.08        0.56       144
library cache lock                                               4        0.06        0.61        98
gc current grant 2-way                                           4        0.05        0.45       111
*** SQL Activity Details During Probe
                           Phys Rds  Log Rds  Tot Time   CPU Time                             Rows        Stmt
SQL ID             Sec/EXE      (k)      (k)     (sec)      (sec) Sec/PIO Sec/LIO     Runs     (k)  Sorts Type
---------------- --------- -------- -------- --------- ---------- ------- ------- -------- ------- ------ -----
gz5bfrcjq060u         0.01        0        0       0.3        0.3 #######   0.001       24       0     23 INSER
c77k33u5u7zgc         0.06        0       17       0.1        0.1 #######   0.000        2       0      2 SELEC
8fb44rrg8a5rh         0.13        0       15       0.1        0.1 #######   0.000        1       0      2 SELEC
98564h3vavfcm       -25.78       -0       -0     -51.6       -0.6  51.552   0.276        2       0      0 inser
*** SQL Similar Statements During Delta
SQL Statement (shown if first 10 chars)                                   Count
---------------------------------------------------------------------- --------
SELECT NVL                                                                    2
*** OS CPU Breakdown During Delta
Category                             Percent
----------------------------------- --------
Idle                                   96.51
IO Wait                                 0.44
Nice                                    0.00
System                                  0.38
User                                    2.47
Delta is 123.53 seconds
Number of CPU cores is 80

報告的第一部分:Response Time Ratio and Workload Metrics
報告的第一部分提供了與Statspack與AWR中Load Profile部分相同的Workload Metrics。這部分資訊在比較響應時間快照之間的差異時非常有用。如果工作負載減少那麼可以預期響應時間減少。

*** Response Time Ratio and Workload Metrics
RT Ratio  Ora Trx/s Block Changes/s User Calls/s      Execs/s
-------- ---------- --------------- ------------ ------------
   0.325       0.54           90.63        27.41       100.00

報告的第二部分:Response Time System Summary
這部分資訊顯示總的CPU時間為34秒，總的等待時間為17秒，也可以說是在120秒的時間間隔內，Oracle程式消耗的CPU時間只有34秒，消耗的等待時間只有17秒。而且還可以看到17秒的等待時間中IO等待時間為15秒，非IO等待時間為1秒。在120秒的時間間隔內，Oracle程式只消耗了總CPU可用時間的0.4%，這個資料是使用Oracle程式消耗的總CPU時間除以主機可用CPU時間。在120秒時間間隔的主機的CPU可用時間為CPU的核心數量乘以報告時間間隔。在這裡主機的CPU核心數量為80，報告時間間隔為120秒，所以Oracle所消耗的CPU時間為34/(120*80)=0.4%。如果主機上只執行該例項，那麼它也提供了作業系統CPU利用率給我們，因此也不用執行作業系統命令來檢視CPU利用情況了。

*** Response Time System Summary (delta - interactive - system level)
   Tot CPU   CPU SP   CPU BG CPU Parse CPU Recur         Tot Wait  IO Wait Other Wait
      Time     Time     Time      Time      Time Ora CPU     Time     Time       Time       %          %
     (sec)    (sec)    (sec)     (sec)     (sec)  Util %    (sec)    (sec)      (sec) IO Wait Other Wait
---------- -------- -------- --------- --------- ------- -------- -------- ---------- ------- ----------
        34       26        8         2        15     0.4       17       15          1      92          8

報告的第三部分:I/O Wait Time Summary w/Event Details
如果IO有問題，那麼你肯定想知道是讀還是寫有問題，管理員可以從瞭解IO負載型別來給出相關的解決方案。比如一個IO讀問題可以透過將常被訪問的資料塊儲存在Oracle Cache中來使用IO讀的影響降低到最小，如果一個IO寫問題可以透過配置，比如聯機重做日誌檔案的數量與大小來使IO寫的影響降低到最小。從報告中可以看到IO總等待時間為15秒，其中IO寫為10秒,IO讀為5秒。其中LGWR real time apply sync事件平均等待一次的時間是65.83毫秒，這是因為配置了ADG，對於同城異地容災來說這個等待時間也還是正常的，db file sequential read事件平均等待一次的時間為4.97毫秒也是正常的。

*** I/O Wait Time Summary w/Event Details (delta - interactive - system level)
 IO Wait  IO WRITE    IO READ
    Time Wait Time  Wait Time  % IO % IO
   (sec)     (sec)      (sec) Write Read
-------- --------- ---------- ----- ----
      15        10          5    66   34
                                                                          Tot Call    Avg Call
                                                                         Wait Time   Wait Time
IO Wait Event                                                R,W     %       (sec)        (ms) Tot Waits
------------------------------------------------------------ --- ----- ----------- ----------- ---------
LGWR real time apply sync                                    W      57        8.69       65.83       132
db file sequential read                                      R      31        4.67        4.97       940
LGWR-LNS wait on channel                                     W       5        0.71        1.74       408

報告的第四部分:Other Wait Time (non-I/O) Event Detail
這部分顯示了非IO等待事件的彙總與底層相關的等待事件詳細資訊，因為非IO等待時間總共才只有1秒，這並不影響效能。所以相關的等待事件我們也就不用檢視了。

*** Other Wait Time (non-I/O) Event Detail (delta - interactive - system level)
                                                                      Tot Call    Avg Call
                                                                     Wait Time   Wait Time
Non IO (other) Wait Event                                        %       (sec)        (ms) Tot Waits
------------------------------------------------------------ ----- ----------- ----------- ---------
gc current block 2-way                                          26        0.35        0.62       569
gc cr grant 2-way                                               17        0.23        0.48       484
reliable message                                                10        0.14        1.21       116
os thread startup                                               10        0.14       23.33         6
enq: US - contention                                             6        0.08        0.49       163
library cache pin                                                6        0.08        0.56       144
library cache lock                                               4        0.06        0.61        98
gc current grant 2-way                                           4        0.05        0.45       111

報告的第五部分:SQL Activity Details During Probe
為了幫助分析應用程式，報告捕獲了直接影響響應時間的SQL語句並顯示了資源消耗情況，以下面的資料來看，在捕獲的SQL語句所消耗的資源都是很少的不會影響效能，其中語句的物理讀為0，邏輯讀總大小也才32K。

*** SQL Activity Details During Probe
                           Phys Rds  Log Rds  Tot Time   CPU Time                             Rows        Stmt
SQL ID             Sec/EXE      (k)      (k)     (sec)      (sec) Sec/PIO Sec/LIO     Runs     (k)  Sorts Type
---------------- --------- -------- -------- --------- ---------- ------- ------- -------- ------- ------ -----
gz5bfrcjq060u         0.01        0        0       0.3        0.3 #######   0.001       24       0     23 INSER
c77k33u5u7zgc         0.06        0       17       0.1        0.1 #######   0.000        2       0      2 SELEC
8fb44rrg8a5rh         0.13        0       15       0.1        0.1 #######   0.000        1       0      2 SELEC
98564h3vavfcm       -25.78       -0       -0     -51.6       -0.6  51.552   0.276        2       0      0 inser

報告的第六部分:SQL Similar Statements During Delta
在執行rtsysx.sql指令碼所指定的第二個引數就與查詢類似SQL語句相關，類似SQL語句是除了where子句中的過濾與連線條件不同之外其它完全相同的語句。第二個引數我們指定的是10，也就是說類似語句會被統計且統計數大於1的語句的前10個字元才會被顯示。

*** SQL Similar Statements During Delta
SQL Statement (shown if first 10 chars)                                   Count
---------------------------------------------------------------------- --------
SELECT NVL                                                                    2

報告的第七部分:Operating System CPU Utilization
這部分顯示了作業系統使用的詳細情況。從Oracle 10g開始，Oracle捕獲作業系統CPU的使用的詳細資訊並且這些資訊可以透過v$osstat檢視來檢視。

*** OS CPU Breakdown During Delta
Category                             Percent
----------------------------------- --------
Idle                                   96.51
IO Wait                                 0.44
Nice                                    0.00
System                                  0.38
User                                    2.47
Delta is 123.53 seconds
Number of CPU cores is 80

會話級Oracle響應時間分析報告
執行指令碼rtsess9.sql來對指定會話1110來生成會話級Oracle響應時間分析報告，從下面的報告中可以看到會話的響應時間為699.29秒，其中佇列時間為608.20秒，非計數時間為91.09秒，而佇列時間中IO佇列時間只有0.3秒，Net+Client佇列時間佔了607.73秒。這說明會話一直在等待客戶端程式進行呼叫。

SQL> @rtsess9 1110
===================================================================
Session Level Response Time Profile
Oracle session 1110
CPU statistics number is 12
......
Session level response time details for SID 1110
*** Response Time Summary
      Response   Service     Queue Unaccount   % CPU % Queue    % UAT
     Time(sec) Time(sec) Time(sec) Time(sec)      RT      RT       RT
[rt=st+qt+uat]      [st]      [qt]     [uat] [st/rt] [qt/rt] [uat/rt]
-------------- --------- --------- --------- ------- ------- --------
        699.29      0.00    608.20     91.09    0.00   86.97    13.03
*** Queue Time Summary
                      QT              QT         QT
Queue Time(sec) I/O(sec) Net+Client(sec) Other(sec)
  [qio+qnc+qot]    [qio]           [qnc]      [qot]
--------------- -------- --------------- ----------
         608.20     0.03          607.73       0.44
*** Queue Time IO Timing Detail
           QT             QT            QT
     I/O(sec) Write I/O(sec) Read I/O(sec) % Writes Time % Read Time
[tio=wio+rio]          [wio]         [rio]     [wio/tio]   [rio/tio]
------------- -------------- ------------- ------------- -----------
         0.03           0.03          0.00         99.97        0.00
*** Queue Time IO Event Timing Detail
                                         Wait Time
Wait Event Name                              (sec)
---------------------------------------- ---------
direct path write                             0.01
log file sync                                 0.02
*** Queue Time Other Event Timing Detail
                                         Wait Time
Wait Event Name                              (sec)
---------------------------------------- ---------
gc cr block 2-way                             0.08
library cache pin                             0.01
gc current block congested                    0.01
gc current block 2-way                        0.31
row cache lock                                0.01
events in waitclass Other                     0.01
library cache lock                            0.01
*** Wait Event Time Not Categorized (for QA)
......

如果應用程式使用者與Oracle伺服器程式都在等待這是不正常的。如果使用者已經執行了命令並且正等待命令執行結束，同時，相關的Oracle伺服器程式正等待從客戶端程式接收資訊，那麼在這兩者之間存在問題。那麼大概問題區域就是網路與客戶端程式了。