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 osmidentified 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 ----------------------------------------------- TYPECOUNT(*) -------------------- ---------- bogus126 ior20 iow59 other1162 COUNT(*) ---------- 1367 Oracle Categorization Summary ----------------------------------------------- WAIT_CLASSCOUNT(*) -------------------- ---------- Administrative55 Application17 Cluster50 Commit2 Concurrency33 Configuration24 Idle96 Network35 Other958 Queueing9 Scheduler8 WAIT_CLASSCOUNT(*) -------------------- ---------- System I/O32 User I/O48 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 RatioOra Trx/s Block Changes/s User Calls/sExecs/s -------- ---------- --------------- ------------ ------------ 0.3250.5490.6327.41100.00 *** Response Time System Summary (delta - interactive - system level) Tot CPUCPU SPCPU BG CPU Parse CPU RecurTot WaitIO Wait Other Wait TimeTimeTimeTimeTime Ora CPUTimeTimeTime%% (sec)(sec)(sec)(sec)(sec)Util %(sec)(sec)(sec) IO Wait Other Wait ---------- -------- -------- --------- --------- ------- -------- -------- ---------- ------- ---------- 342682150.417151928 *** I/O Wait Time Summary w/Event Details (delta - interactive - system level) IO WaitIO WRITEIO READ Time Wait TimeWait Time% IO % IO (sec)(sec)(sec) Write Read -------- --------- ---------- ----- ---- 151056634 Tot CallAvg Call Wait TimeWait Time IO Wait EventR,W%(sec)(ms) Tot Waits ------------------------------------------------------------ --- ----- ----------- ----------- --------- LGWR real time apply syncW578.6965.83132 db file sequential readR314.674.97940 LGWR-LNS wait on channelW50.711.74408 *** Other Wait Time (non-I/O) Event Detail (delta - interactive - system level) Tot CallAvg Call Wait TimeWait Time Non IO (other) Wait Event%(sec)(ms) Tot Waits ------------------------------------------------------------ ----- ----------- ----------- --------- gc current block 2-way260.350.62569 gc cr grant 2-way170.230.48484 reliable message100.141.21116 os thread startup100.1423.336 enq: US - contention60.080.49163 library cache pin60.080.56144 library cache lock40.060.6198 gc current grant 2-way40.050.45111 *** SQL Activity Details During Probe Phys RdsLog RdsTot TimeCPU TimeRowsStmt SQL IDSec/EXE(k)(k)(sec)(sec) Sec/PIO Sec/LIORuns(k)Sorts Type ---------------- --------- -------- -------- --------- ---------- ------- ------- -------- ------- ------ ----- gz5bfrcjq060u0.01000.30.3 #######0.00124023 INSER c77k33u5u7zgc0.060170.10.1 #######0.000202 SELEC 8fb44rrg8a5rh0.130150.10.1 #######0.000102 SELEC 98564h3vavfcm-25.78-0-0-51.6-0.651.5520.276200 inser *** SQL Similar Statements During Delta SQL Statement (shown if first 10 chars)Count ---------------------------------------------------------------------- -------- SELECT NVL2 *** OS CPU Breakdown During Delta CategoryPercent ----------------------------------- -------- Idle96.51 IO Wait0.44 Nice0.00 System0.38 User2.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 RatioOra Trx/s Block Changes/s User Calls/sExecs/s -------- ---------- --------------- ------------ ------------ 0.3250.5490.6327.41100.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 CPUCPU SPCPU BG CPU Parse CPU RecurTot WaitIO Wait Other Wait TimeTimeTimeTimeTime Ora CPUTimeTimeTime%% (sec)(sec)(sec)(sec)(sec)Util %(sec)(sec)(sec) IO Wait Other Wait ---------- -------- -------- --------- --------- ------- -------- -------- ---------- ------- ---------- 342682150.417151928
報告的第三部分: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 WaitIO WRITEIO READ Time Wait TimeWait Time% IO % IO (sec)(sec)(sec) Write Read -------- --------- ---------- ----- ---- 151056634 Tot CallAvg Call Wait TimeWait Time IO Wait EventR,W%(sec)(ms) Tot Waits ------------------------------------------------------------ --- ----- ----------- ----------- --------- LGWR real time apply syncW578.6965.83132 db file sequential readR314.674.97940 LGWR-LNS wait on channelW50.711.74408
報告的第四部分:Other Wait Time (non-I/O) Event Detail
這部分顯示了非IO等待事件的彙總與底層相關的等待事件詳細資訊，因為非IO等待時間總共才只有1秒，這並不影響效能。所以相關的等待事件我們也就不用查看了。
*** Other Wait Time (non-I/O) Event Detail (delta - interactive - system level) Tot CallAvg Call Wait TimeWait Time Non IO (other) Wait Event%(sec)(ms) Tot Waits ------------------------------------------------------------ ----- ----------- ----------- --------- gc current block 2-way260.350.62569 gc cr grant 2-way170.230.48484 reliable message100.141.21116 os thread startup100.1423.336 enq: US - contention60.080.49163 library cache pin60.080.56144 library cache lock40.060.6198 gc current grant 2-way40.050.45111
報告的第五部分:SQL Activity Details During Probe
為了幫助分析應用程式，報告捕獲了直接影響響應時間的SQL語句並顯示了資源消耗情況，以下面的資料來看，在捕獲的SQL語句所消耗的資源都是很少的不會影響效能，其中語句的物理讀為0，邏輯讀總大小也才32K。
*** SQL Activity Details During Probe Phys RdsLog RdsTot TimeCPU TimeRowsStmt SQL IDSec/EXE(k)(k)(sec)(sec) Sec/PIO Sec/LIORuns(k)Sorts Type ---------------- --------- -------- -------- --------- ---------- ------- ------- -------- ------- ------ ----- gz5bfrcjq060u0.01000.30.3 #######0.00124023 INSER c77k33u5u7zgc0.060170.10.1 #######0.000202 SELEC 8fb44rrg8a5rh0.130150.10.1 #######0.000102 SELEC 98564h3vavfcm-25.78-0-0-51.6-0.651.5520.276200 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 NVL2
報告的第七部分:Operating System CPU Utilization
這部分顯示了作業系統使用的詳細情況。從Oracle 10g開始，Oracle捕獲作業系統CPU的使用的詳細資訊並且這些資訊可以通過v$osstat檢視來檢視。
*** OS CPU Breakdown During Delta CategoryPercent ----------------------------------- -------- Idle96.51 IO Wait0.44 Nice0.00 System0.38 User2.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 ResponseServiceQueue Unaccount% CPU % Queue% UAT Time(sec) Time(sec) Time(sec) Time(sec)RTRTRT [rt=st+qt+uat][st][qt][uat] [st/rt] [qt/rt] [uat/rt] -------------- --------- --------- --------- ------- ------- -------- 699.290.00608.2091.090.0086.9713.03 *** Queue Time Summary QTQTQT Queue Time(sec) I/O(sec) Net+Client(sec) Other(sec) [qio+qnc+qot][qio][qnc][qot] --------------- -------- --------------- ---------- 608.200.03607.730.44 *** Queue Time IO Timing Detail QTQTQT 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.030.030.0099.970.00 *** Queue Time IO Event Timing Detail Wait Time Wait Event Name(sec) ---------------------------------------- --------- direct path write0.01 log file sync0.02 *** Queue Time Other Event Timing Detail Wait Time Wait Event Name(sec) ---------------------------------------- --------- gc cr block 2-way0.08 library cache pin0.01 gc current block congested0.01 gc current block 2-way0.31 row cache lock0.01 events in waitclass Other0.01 library cache lock0.01 *** Wait Event Time Not Categorized (for QA) ......
如果應用程式使用者與Oracle伺服器程序都在等待這是不正常的。如果使用者已經執行了命令並且正等待命令執行結束，同時，相關的Oracle伺服器程序正等待從客戶端程序接收資訊，那麼在這兩者之間存在問題。那麼大概問題區域就是網路與客戶端程序了。