常見問題:如何使用AWR報告來診斷數據庫性能問題 ID 1523048.1修改時間:2013-2-7類型:HOWTO狀態:PUBLISHED優先級:1In this DocumentGoal最佳實踐如何主動避免問題發生及做好診斷信息的收集FixInterpretationTop 5 Timed EventsSQL Statistics分析：Other SQL Statistic SectionsWaits for Cursor: mutex/pinLoad ProfileInstance EfficiencyLatch Activity值得注意的wait eventsCPU time eventsAnalysis:其他潛在的CPU相關的問題：檢查是否有其他等待事件與高CPU 事件同時出現數據庫以外的CPU使用率過高診斷CPU使用率Log file sync waitsBuffer busy waits診斷其他問題使用ADDM的報告其他的AWR參考文章StatspackReferencesApplies to: Oracle Database - Enterprise Edition - Version 10.2.0.1 and laterInformation in this document applies to any platform.適用于Oracle 數據庫企業版10.2.0.1及其之后的版本，適用于任何平臺。Goal本文旨在提供如何解釋跟數據庫性能問題息息相關的AWR信息。最佳實踐如何主動避免問題發生及做好診斷信息的收集有些問題是無法預見的，但大部分其它的問題如果及早發現一些征兆其實是可以避免的。同時，如果問題確實發生了，那么收集問題發生時的信息就非常重要。有關于如何主動避免問題及診斷信息的收集，請參見：Document 1482811.1 Best Practices: Proactively Avoiding Database and Query Performance IssuesDocument 1477599.1 Best Practices Around Data Collection For Performance IssuesFix對于數據庫整體的性能問題，AWR的報告是一個非常有用的診斷工具。一般來說，當檢測到性能問題時，我們會收集覆蓋了發生問題的時間段的AWR報告-但是最好只收集覆蓋1個小時時間段的AWR報告-如果時間過長，那么AWR報告就不能很好的反映出問題所在。還應該收集一份沒有性能問題的時間段的AWR報告，作為一個參照物來對比有問題的時間段的AWR報告。這兩個AWR報告的時間段應該是一致的，比如都是半個小時的，或者都是一個小時的。關于如何收集AWR報告，請參照如下文檔：Document 1363422.1 Automatic Workload Repository (AWR) Reports - Start Point注：最好一開始我們從ADDM報告入手，因為對應時間段的ADDM報告往往已經指出了問題所在。參見: Use of ADDM Reports alongside AWRInterpretation在處理性能問題時，我們最關注的是數據庫正在等待什么。當進程因為某些原因不能進行操作時，它需要等待。花費時間最多的等待事件是我們最需要關注的，因為降低它，我們能夠獲得最大的好處。AWR報告中的Top 5 Timed Events部分就提供了這樣的信息，可以讓我們只關注主要的問題。 Top 5 Timed Events正如前面提到的，Top 5 Timed Events是AWR報告中最重要的部分。它指出了數據庫的sessions花費時間最多的等待事件，如下：Top 5 Timed Events Avg %Total wait CallEvent Waits Time (s) (ms) Time Wait Class- - - - - -db file scattered read 10,152,564 81,327 8 29.6 User I/Odb file sequential read 10,327,231 75,878 7 27.6 User I/OCPU time 56,207 20.5read by other session 4,397,330 33,455 8 12.2 User I/OPX Deq Credit: send blkd 31,398 26,576 846 9.7 Other -Top 5 Events部分包含了一些跟Events（事件）相關的信息。它記錄了這期間遇到的等待的總次數，等待所花費的總時間，每次等待的平均時間；這一部分是按照每個Event占總體call time的百分比來進行排序的。根 據Top 5 Events部分的信息的不同，接下來我們需要檢查AWR報告的其他部分，來驗證發現的問題或者做定量分析。等待事件需要根據報告期的持續時間和當時數據 庫中的并發用戶數進行評估。如：10分鐘內1000萬次的等待事件比10個小時內的1000萬等待更有問題；10個用戶引起的1000萬次的等待事件比 10,000個用戶引起的相同的等待要更有問題。就像上面的例子，將近60%的時間是在等待IO相關的事件。o 事件db file scattered read一般表明正在做由全表掃描或者index fast full scan引起的多塊讀。o 事件db file sequential read一般是由不能做多塊讀的操作引起的單塊讀（如讀索引）其他20%的時間是花在使用或等待CPU time上。過高的CPU使用經常是性能不佳的SQL引起的（或者這些SQL有可能用更少的資源完成同樣的操作）；對于這樣的SQL，過多的IO操作也是一個癥狀。關于CPU使用方面，我們會在之后討論。在以上基礎上，我們將調查是否這個等待事件是有問題的。若有問題，解決它；若是正常的，檢查下個等待事件。過多的IO相關的等待一般會有兩個主要的原因：o 數據庫做了太多的讀操作o 每次的IO讀操作都很慢Top 5 Events部分的顯示的信息會幫助我們檢查：o 是否數據庫做了大量的讀操作：上面的圖顯示了在這段時間里兩類讀操作都分別大于1000萬，這些操作是否過多取決于報告的時間是1小時或1分鐘。我們可以檢查AWR報告的elapsed time如果這些讀操作確實是太多了，接下來我們需要檢查AWR報告中 SQL Statistics 部分的信息，因為讀操作都是由SQL語句發起的。o 是否是每次的IO讀操作都很慢：上面的圖顯示了在這段時間里兩類讀操作平均的等待時間是小于8ms的至于8ms是快還是慢取決于底層的硬件設備；一般來講小于20ms的都可以認為是可以接受的。我們還可以在AWR報告Tablespace IO Stats部分得到更詳細的信息o Tablespace IO Stats DB/Inst: VMWREP/VMWREP Snaps: 1-15oo - ordered by IOs (Reads + Writes) descoooo Tablespaceoo -oo Av Av Av Av Buffer Av Bufoo Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)oo - - - - - - - -oo TS_TX_DATAoo 14,246,367 283 7.6 4.6 145,263,880 2,883 3,844,161 8.3oo USERoo 204,834 4 10.7 1.0 17,849,021 354 15,249 9.8oo UNDOTS1oo 19,725 0 3.0 1.0 10,064,086 200 1,964 4.9oo AE_TSoo 4,287,567 85 5.4 6.7 932 0 465,793 3.7oo TEMPoo 2,022,883 40 0.0 5.8 878,049 17 0 0.0oo UNDOTS3oo 1,310,493 26 4.6 1.0 941,675 19 43 0.0oo TS_TX_IDXoo 1,884,478 37 7.3 1.0 23,695 0 73,703 8.3oo SYSAUXoo 346,094 7 5.6 3.9 112,744 2 0 0.0oo SYSTEMo 101,771 2 7.9 3.5 25,098 0 653 2.7如上圖，我們關心Av Rd(ms)的指標。如果它高于20ms并且同時有很多讀操作的，我們可能要開始從OS的角度調查是否有潛在的IO問題。注：對于一些比較空閑的tablespace/files,我們可能會得到一個比較大的Av Rd(ms)值；對于這樣的情況，我們應該忽略這樣的tablespace/files;因為這個很大的值可能是由于硬盤自旋(spin)引起的，沒有太大的參考意義。比如對于一個有1000萬次讀操作而且很慢的系統，引起問題的基本不可能是一個只有10次read的tablespace/file以下的文檔可以幫助我們進一步調查IO方面的問題：Note:223117.1 Troubleshooting I/O-related waits雖 然高db file scattered read和db file sequential read等待可以是I / O相關的問題，但是很多時候這些等待也可能是正常的；實際上，對一個已經性能很好的數據庫系統，這些等待事件往往在top 5待事件里，因為這意味著您的數據庫沒有那些真正的“問題”。訣竅是能夠評估引起這些等待的語句是否使用了最優的訪問路徑。如果db file scattered read比較高，那么相關的SQL語句可能使用了全表掃描而沒有使用索引（也許是沒有創建索引，也許是沒有合適的索引）；相應的，如果db file sequential read過多，則表明也許是這些SQL語句使用了selectivity不高的索引從而導致訪問了過多不必要的索引塊或者使用了錯誤的索引。這些等待可 能說明SQL語句的執行計劃不是最優的。接下來就需要通過AWR來檢查這些top SQL是否可以進一步的調優，我們可以查看AWR報告中 SQL Statistics 的部分.上面的例子顯示了20%的時間花在了等待或者使用CPU上，我們也需要檢查 SQL statistics 部分來進一步的分析。需要注意，接下來的分析步驟取決于我們在TOP 5部分的發現。在上面的例子里，3個top wait event表明問題可能與SQL語句執行計劃不好有關，所以接下來我們要去分析SQL Statistics部分。同樣的，因為我們并沒有看到latch相關的等待，latch在我們這個例子里并沒有引發嚴重的性能問題；那么我們接下來就完全不需要分析latch相關的信息。一 般來講，如果數據庫性能很慢，TOP 5等待事件里CPU， db file sequential read 和db file scattered read 比較明顯（不管它們之間的順序如何），我們總是需要檢查Top SQL (by logical and physical reads)部分；調用SQL Tuning Advisor或者手工調優這些SQL來確保它們是有效率的運行。 SQL StatisticsAWR包含了一些不同的SQL統計值：根據Top 5 部分的Top Wait Event不同，我們需要檢查不同的SQL statistic。在我們這個例子里，Top Wait Event是db file scattered read，db file sequential read和CPU；我們最需要關心的是SQL ordered by CPU Time, Gets and Reads。我們會從SQL ordered by gets入手，因為引起高buffer gets的SQL語句一般是需要調優的對象。SQL ordered by Gets - Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.- Total Buffer Gets: 4,745,943,815- Captured SQL account for 122.2% of Total Gets CPU Elapsed Buffer Gets Executions per Exec %Total Time (s) Time (s) SQL Id- - - - - - -1,228,753,877 168 7,314,011.2 25.9 8022.46 8404.73 5t1y1nvmwp2SELECT ADDRESSID,CURRENT$.ADDRESSTYPEID,CURRENT$URRENT$.ADDRESS3,CURRENT$.CITY,CURRENT$.ZIP,CURRENT$.STATE,CURRENT$.PHONECOUNTRYCODE,CURRENT$.PHONENUMBER,CURRENT$.PHONEEXTENSION,CURRENT$.FAXCOU1,039,875,759 62,959,363 16.5 21.9 5320.27 5618.96 grr4mg7ms81Module: DBMS_SCHEDULERINSERT INTO ADDRESS_RDONLY (ADDRESSID,ADDRESSTYPEID,CUSTOMERID,ADDRESS1,ADDRESS2,ADDRESS3,CITY,ZIP,STATE,PHONECOUNTRYCODE,PHONENU 854,035,223 168 5,083,543.0 18.0 5713.50 7458.95 4at7cbx8hnzSELECT CUSTOMERID,CURRENT$.ISACTIVE,CURRENT$.FIRSTNAME,CURRENT$.LASTNAME,CU Total Buffer Gets: 4,745,943,815假設這是一個一個小時的AWR報告，4,745,943,815是一個很大的值；所以需要進一步分析這個SQL是否使用了最優的執行計劃o Individual Buffer Gets上面的例子里單個的SQL的buffer get非常多，最少的那個都是8億5千萬。這三個SQL指向了兩個不同的引起過多buffers的原因： 單次執行buffer gets過多SQL_ID為5t1y1nvmwp2和4at7cbx8hnz的SQL語句總共被執行了168次，但是每次執行引起的buffer gets超過500萬。這兩個SQL應該是主要的需要調優的候選者。 執行次數過多SQL_ID grr4mg7ms81 每次執行只是引起16次buffer gets,減少這條SQL每次執行的buffer get可能并不能顯著減少總共的buffer gets。這條語句的問題是它執行的太頻繁了，6500萬次。改變這條SQL的執行次數可能會更有意義。這個SQL看起來是在一個循環里面被調用，如果可以讓它一次處理的數據更多也許可以減少它執行的次數。注意：對于某些非常繁忙的系統來講，以上的數字可能都是正常的。這時候我們需要把這些數字跟正常時段的數字作對比，如果沒有什么太大差別，那么這些SQL并不是引起問題的元兇（雖然通過調優這些SQL我們仍然可以受益）Other SQL Statistic Sections就像之前提到的那樣，AWR報告中有很多不同的部分用來分析各種不同的問題。如果特定的問題并沒有出現，那么分析AWR報告的這些部分并不能有很大的幫助。下面提到了一些可能的問題：o Waits for Cursor: mutex/pin如 果發現了一些像Cursor: pin S wait on X 或Cursor: mutex X 類的mutex等待，那么可能是由于parsing引起的問題。檢查SQL ordered by Parse Calls 和SQL ordered by Version Count部分的Top SQL，這些SQL可能引起這類的問題。以下文檔可以幫助我們分析這類問題：Document 1356828.1 FAQ: cursor: mutex . / cursor: pin . / library cache: mutex . Type Wait Events Note:1349387.1 Troubleshooting cursor: pin S wait on X waits. Load Profile根據Top 5等待事件的不同，Load Profile可以提供一些有用的背景資料或潛在問題的細節信息。Load Profile Per Second Per Transaction - - Redo size: 4,585,414.80 3,165,883.14 Logical reads: 94,185.63 65,028.07 Block changes: 40,028.57 27,636.71 Physical reads: 2,206.12 1,523.16 Physical writes: 3,939.97 2,720.25 User calls: 50.08 34.58 Parses: 26.96 18.61 Hard parses: 1.49 1.03 Sorts: 18.36 12.68 Logons: 0.13 0.09 Executes: 4,925.89 3,400.96 Transactions: 1.45 % Blocks changed per Read: 42.50 Recursive Call %: 99.19Rollback per transaction %: 59.69 Rows per Sort: 1922.64在這個例子里，Top 5 Events部分顯示問題可能跟SQL的執行有關，那么我們接下來檢查load profile部分。如果您檢查AWR report是為了一般性的性能調優，那么可以看到有比較多的redo activity和比較高的physical writes. Physical writes比physical read要高，并且有42%的塊被更改了.此外，hard parse的次數要少于soft parse.如果mutex等待事件比較嚴重，如library cache: mutex X，那么查看所有parse的比率會更有用。當然，如果把Load Profile部分跟正常時候的AWR報告做比較會更有用，比如，比較redo size, users calls, 和 parsing這些性能指標。 Instance EfficiencyInstance Efficiency部分更適用于一般性的調優，而不是解決某個具體問題（除非等待事件直接指向這些指標）。Instance Efficiency Percentages (Target 100%) Buffer Nowait %: 99.91 Redo NoWait %: 100.00 Buffer Hit %: 98.14 In-memory Sort %: 99.98 Library Hit %: 99.91 Soft Parse %: 94.48 Execute to Parse %: 99.45 Latch Hit %: 99.97Parse CPU to Parse Elapsd %: 71.23 % Non-Parse CPU: 99.00從我們的這個例子來看，最有用的信息是%Non-Parse CPU，它表明幾乎所有的CPU都消耗在了Execution而不是Parse上，所以調優SQL會對性能有改善。94.48 的soft parse比率顯示hard parse的比例很小，這是可取的。Execute to Parse %很高，說明cursor被很好的重用了。我們總是期望這里的值都是接近100%,但是因為應用的不同，如果這個部分的參數的某些值很小，也是可以認為沒 有問題的；如在數據倉庫環境，hard parse因為使用了物化視圖或histogram而變得很高。所以，重要的是，我們需要把這部分信息和正常時候的AWR報告做比較來判斷是否有問題。 Latch Activity在我們這個例子里，我們并沒有看到很高的latch相關的等待，所以這部分的信息可以忽略。但是如果latch相關的等待很嚴重，我們需要查看Latch Sleep Breakdown 部分sleeps很高的latchLatch Sleep Breakdown * ordered by misses desc Latch Name- Get Requests Misses Sleeps Spin Gets Sleep1 Sleep2 Sleep3- - - - - - -cache buffers chains2,881,936,948 3,070,271 41,336 3,031,456 0 0 0row cache objects 941,375,571 1,215,395 852 1,214,606 0 0 0object queue header operation 763,607,977 949,376 30,484 919,782 0 0 0cache buffers lru chain 376,874,990 705,162 3,192 702,090 0 0 0這 里top latch是cache buffers chains. Cache Buffers Chains latches是用來保護buffer caches中的buffers。在我們讀取數據時，這個latch是正常需要獲得的。Sleep的數字上升代表session在讀取buffers時開 始等待這個latch。爭用通常來自于不良的SQL要讀取相同的buffers。在我們這個例子里，雖然讀取buffer的操作發生了 28億次，但是只sleep了41,336次，可以認為是比較低的。Avg Slps/Miss（Sleeps/ Misses）也比較低。這表明當前Server有能力處理這樣多的數據，所以沒有發生Cache Buffers Chains latch的爭用。關于其他的latch free等待，請參照以下文檔：Note:413942.1 How to Identify Which Latch is Associated with a latch free wait值得注意的wait events CPU time eventsCPU變為top wait event并不總是代表出現了問題。但是如果同時數據庫性能比較慢，那么就需要進一步分析了。首先，檢查AWR報告的“ SQL ordered by CPU Time ”部分，看是否某個特定的SQL使用了大量的CPU。SQL ordered by CPU Time- Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.- % Total is the CPU Time divided into the Total CPU Time times 100- Total CPU Time (s): 56,207- Captured SQL account for 114.6% of Total CPU Elapsed CPU per % Total Time (s) Time (s) Executions Exec (s) % Total DB Time SQL Id- - - - - - - 20,349 24,884 168 121.12 36.2 9.1 7bbhgqykv3cm9Module: DBMS_SCHEDULERDECLARE job BINARY_INTEGER := :job; next_date TIMESTAMP WITH TIME ZONE := :mydate; broken BOOLEAN := FALSE; job_name VARCHAR2(30) := :job_name; job_subnameVARCHAR2(30) := :job_subname; job_owner VARCHAR2(30) := :job_owner; job_startTIMESTAMP WITH TIME ZONE := :job_start; job_scheduled_start TIMESTAMP WITH TIMEAnalysis:o - Total CPU Time (s): 56,207它代表了15分鐘的CPU time。但是這個數字是否有問題取決于整個報告的時間。o Top SQL使用的CPU是 20,349秒（大概5分鐘）o 整個CPU時間占DB Time的9.1%o 執行了168次，這個執行次數跟之前提到的幾個SQL是一樣的，說明這些SQL可能都是被同一個JOB調用的。其他潛在的CPU相關的問題：o 檢查是否有其他等待事件與高CPU 事件同時出現如cursor: pin S問題可能引起高CPU使用：Note:6904068.8 Bug 6904068 - High CPU usage when there are cursor: pin S waitso 數據庫以外的CPU使用率過高如果一個數據庫以外的進程使用了過多CPU，那么數據庫進程能夠獲得的CPU就會減少，數據庫性能就會受到影響。在這種情況下，運行OSWather或者其他的OS工具去發現是哪個進程使用了過多CPUNote:433472.1 OS Watcher For Windows (OSWFW) User Guideo 診斷CPU使用率下面的文檔進一步描述了如何進一步分析CPU問題:Note:164768.1 Troubleshooting: High CPU Utilization Log file sync waits當 一個user session commit或rollback時，log writer進程會把redo從log buffer中寫入redo logfile文件。AWR報告會幫助我們來確定是否存在這方面的問題，并且確認是否是由物理IO引起。如果”log file sync”事件比較嚴重，下面的文檔詳細描述了如何來處理:Document 1376916.1 Troubleshooting: Log File Sync Waits Note:34592.1WAITEVENT: log file sync Buffer busy waits當 一個session從buffer cache讀取一個buffer時，如果這個buffer處于busy的狀態（由于其它session正在向其中讀取數據，或者是由于這個buffer被 其它的session以不兼容模式持有），那么這個session就會等待這個事件。參照下面文檔來找出哪個block處于busy狀態和為什么：Document 155971.1 Resolving Intense and Random Buffer Busy Wait Performance Problems:Note:34405.1 WAITEVENT: buffer busy waits診斷其他問題關于其他性能問題，請參照文檔:Document 1377446.1 Troubleshooting Performance Issues使用ADDM的報告當分析性能問題時，除了AWR報告，我們還可以同時參照ADDM報告，對于潛在的性能問題，它同時提供了具體的解決方案建議。下面是從如下文檔拿到的一個ADDM報告示例：Note:250655.1How to use the Automatic Database Diagnostic Monitor:Example Output:DETAILED ADDM REPORT FOR TASK SCOTT_ADDM WITH ID 5-Analysis Period: 17-NOV-2003 from 09:50:21 to 10:35:47Database ID/Instance: 494687018/1Snapshot Range: from 1 to 3Database Time: 4215 secondsAverage Database Load: 1.5 active sessionsFINDING 1: 65% impact (2734 seconds)-PL/SQL execution consumed significant database time.RECOMMENDATION 1: SQL Tuning, 65% benefit (2734 seconds)ACTION: Tune the PL/SQL block with SQL_ID fjxa1vp3yhtmr. Refer to the Tuning PL/SQL Applications chapter of Oracles PL/SQL Users Guide and ReferenceRELEVANT OBJECT: SQL statement with SQL_ID fjxa1vp3yhtmrBEGIN EMD_NOTIFICATION.QUEUE_READY(:1, :2, :3); END;FINDING 2: 35% impact (1456 seconds)-SQL statements consuming significant database time were found.RECOMMENDATION 1: SQL Tuning, 35% benefit (1456 seconds)ACTION: Run SQL Tuning Advisor on the SQL statement with SQL_IDgt9ahqgd5fmm2.RELEVANT OBJECT: SQL statement with SQL_ID gt9ahqgd5fmm2 andPLAN_HASH 547793521UPDATE bigemp SET empno = ROWNUMFINDING 3: 20% impact (836 seconds)-The throughput of the I/O subsystem was significantly lower than expected.RECOMMENDATION 1: Host Configuration, 20% benefit (836 seconds)ACTION: Consider increasing the throughput of the I/O subsystem.Oracles recommended solution is to stripe all data file using the SAME methodology. You might also need to increase the number of disks for better performance.RECOMMENDATION 2: Host Configuration, 14% benefit (584 seconds)ACTION: The performance of file D:ORACLEORADATAV1010UNDOTBS01.DBF was significantly worse than other files. If striping all files using the SAME methodology is not possible, consider striping this file over multiple disks.RELEVANT OBJECT: database fileD:ORACLEORADATAV1010UNDOTBS01.DBFSYMPTOMS THAT LED TO THE FINDING:Wait class User I/O was consuming significant database time. (34% impact 1450 seconds)FINDING 4: 11% impact (447 seconds)-Undo I/O was a significant portion (33%) of the total database I/O.NO RECOMMENDATIONS AVAILABLESYMPTOMS THAT LED TO THE FINDING:The throughput of the I/O subsystem was significantly lower thanexpected. (20% impact 836 seconds)Wait class