1、1 編寫目的介紹在現場出現Oracle故障和性能問題時的診斷流程，讓項目支撐人員在解決Oracle問題時有據可依。2 適用場景當現場出現以下問題時，可依照本文檔進行處理：1） Oracle異常關閉、重啟、Hang住等故障。2） PM相關程序出現性能急劇下降的情況。3） PM相關程序出現Hang住等故障。3 分析流程3.1 信息收集及初步診斷本節介紹以下知識點：1） 出現問題時，需要收集什么樣的信息？2） 這些信息的作用是什么？3） 如何進行收集？4） 如何對這些信息進行分析，從而得到初步診斷結論？初步診斷結論是指引起問題的原因，但不是根因。例如，初步診斷結論是內存問題、IO問題、等待事件的問題

2、、執行計劃的問題、統計信息的問題。3.1.1 PM運行情況（黃）反映PM運行情況的數據主要包括運行日志以及存儲運行數據的表（例如COUNTERLOADMESSAGE、SUM_SUMMARYTASKQUEUE表等）。從以上內容中，可以分析出PM在運行過程中是否有錯誤發生，以及是否存在性能問題。以下內容均以C03版本為準，C02和V4.5可能有變化，需結合實際情況作相應調整。1) 如何收集：a) 運行日志：加載環境變量后，使用cd $PM4H_LOG進入日志目錄b) 運行數據表：Table NameSchema NameDescriptionCOUNTERLOADMESSAGEpm4h_db反映入

3、庫程序的運行狀態PILOADMESSAGEpm4h_db反映PIMapping程序的運行狀態SUM_SUMMARYTASKQUEUEpm4h_ad反映匯總程序的運行狀態SUM_BHTASKQUEUEpm4h_ad反映忙時程序的運行狀態2) 如何分析：a) 運行日志：i. 可以使用cat <logfilename> | grep ERROR的方式，搜索指定日志中是否存在錯誤信息。<logfilename>可以是具體的日志文件名，也可以是使用了通配符的表達式。例如搜索所有的匯總日志中是否存在錯誤，可使用如下命令：cat Summarize* | grep ERRORii.

4、如果某個日志文件中存在ERROR信息，可以使用vi命令編輯該文件，依次輸入/ERROR和回車，搜索ERROR信息，查看詳細的錯誤信息。（/是vi編輯器中的搜索命令）iii. 對于性能分析，可以分為兩種情況，一種是程序出現Hang住的情況，表現為日志長時間無內容輸出；另一種是程序沒有Hang住，但在單位周期內無法處理完一周期的性能數據。iv. 出現Hang住的情況時，可以使用兩種方式找到Hang住的任務。一種是通過日志分析出當前正在執行的任務。以匯總執行日志為例，可以分析Hang住時那一輪的日志中，哪些任務只有start日志，沒有end日志，這些任務就是Hang住的任務；另一種是在DB服務器上使

5、用top命令查看當前正在運行的Oracle進程，找到進程運行時間長的進程，并找到進程對應的SQL，進而分析出Hang住的任務。v. 出現整體性能下降時，可以通過其它方面的信息來查找問題。b) 運行數據表：i. 運行數據表的數據主要用于分析核心模塊的運行效率以及工作量的變化。ii. 分析COUNTERLOADMESSAGE表中每天產生的MSG數量，可以得出入庫程序的工作量和性能情況。PILOADMESSAGE和COUNTERLOADMESSAGE類似。iii. 分析SUM_SUMMARYTASKQUEUE表中每小時執行完成的TASK數量，可以得出匯總執行程序的工作量和性能情況。SUM_BHTAS

6、KQUEUE和SUM_SUMMARYTASKQUEUE類似。3.1.2 操作系統資源情況（孫）l CPUu 信息收集登錄系統后，使用top、vmstat、iostat、mpstat等命令，都可以查看到操作系統的CPU使用情況。相關的解釋如下。top命令（CPU部分）load averageCPU負載。1分鐘、5分鐘、15分鐘前到現在的平均值% us用戶進程占用CPU百分比% sy內核空間占用CPU百分比% ni用戶進程空間內改變過優先級的進程占用CPU百分比% id空閑CPU百分比% wa等待輸入輸出的CPU時間百分比% hi硬件中斷CPU時間百分比% si軟件中斷CPU時間百分比% st虛擬

7、CPU等待實際CPU的時間的百分比(Steal Time)表1-1 TOP命令中的CPU信息vmstat命令（CPU部分）usCPU 用戶進程使用CPU時間百分比syCPU 系統進程使用CPU時間百分比idCPU 閑置時間百分比waCPU 等待輸入輸出的CPU時間百分比stCPU虛擬CPU等待實際CPU的時間的百分比(Steal Time)表1-2 vmstat命令中的CPU信息iostat命令（CPU部分）%user用戶進程占用CPU百分比%nice用戶進程空間內改變過優先級的進程占用CPU百分比%system內核空間占用CPU百分比%iowait等待輸入輸出的CPU時間百分比%steal虛

8、擬CPU等待實際CPU的時間的百分比(Steal Time)%idle空閑CPU百分比表1-2 iostat命令中的CPU信息u 初步診斷使用CPU利用率和負載來進行CPU的初步診斷。1. CPU利用率的參考值： 正常情況下<=70%1） 如果CPU的利用率長期大約70%，說明CPU的已經比較繁忙；2） 如果故障時刻，連續超過95%以上，說明可能是CPU存在瓶頸。2. CPU負載的參考值范圍：CPU核數*0 - CPU核數*31） CPU負載越小越好；如果負載=CPU核數，還可以接受；2） 如果負載>= CPU核數*3，則說明系統負載非常高。u 更詳細的資料，見附錄一TOP命令詳解

9、、附錄二iostat命令詳解、附錄三vmstat命令詳解。l 內存u 信息收集登錄系統后，使用top、vmstat、free等命令，都可以查看到操作系統的CPU使用情況。相關的解釋如下（以free命令為例）。total總計物理內存的大小used已使用多大free可用有多少Shared多個進程共享的內存總額Buffers磁盤緩存之：Buffer Cache內存數cached磁盤緩存之：Page Cache內存數表1-3 free命令中的內存信息l 更詳細的資料，見附錄四free命令詳解。u 初步診斷診斷內存是是否是瓶頸的標準：swap和+buffers/cache。1） 只要不用swap的交換空

10、間，就不用擔心自己的內存太少。如果常常swap用很多，可能你就要考慮加物理內存了。這也是linux看內存是否夠用的標準。2） 如果是應用服務器的話，一般只看第二行，+buffers/cache，即對應用程序來說free的內存太少了，也是該考慮優化程序或加內存了。l IOu 信息收集登錄系統后，使用iostat命令獲取服務器的I/O使用情況。如下：iostat命令rrqm/s每秒進行merge的讀操作數目。即delta(rmerge)/swrqm/s每秒進行merge的寫操作數目。即delta(wmerge)/sr/s每秒完成的讀I/O設備次數。即delta(rio)/sw/s每秒完成的寫I/O

11、設備次數。即delta(wio)/srsec/s每秒讀扇區數。即delta(rsect)/swsec/s每秒寫扇區數。即delta(wsect)/srkB/s每秒讀K字節數。是rsect/s的一半，因為每扇區大小為512字節。wkB/s每秒寫K字節數。是wsect/s的一半。avgrq-sz平均每次設備I/O操作的數據大小(扇區)。即delta(rsect+wsect)/delta(rio+wio)avgqu-sz平均I/O隊列長度。即delta(aveq)/s/1000(因為aveq的單位為毫秒)。await平均每次設備I/O操作的等待時間(毫秒)。即delta(ruse+wuse)/del

12、ta(rio+wio)svctm平均每次設備I/O操作的服務時間(毫秒)。即delta(use)/delta(rio+wio)%util一秒中有百分之多少的時間用于I/O操作，或者說一秒中有多少時間I/O隊列是非空的。即delta(use)/s/1000(因為use的單位為毫秒)表1-4 iostat命令中的I/O信息u 初步診斷表1-4中是最主要的I/O參數，使用他們來進初步的診斷：1） 如果 %util 接近 100%，說明產生的I/O請求太多，I/O系統已經滿負荷，該磁盤可能存在瓶頸。2） 如果%util接近100%，表明I/O請求太多，I/O系統已經滿負荷，磁盤可能存在瓶頸，一 般%u

13、til大于70%，I/O壓力就比較大，讀取速度有較多的wait.同時可以結合vmstat查看查看b參數(等待資源的進程數)和wa參數(IO 等待所占用的CPU時間的百分比，高過30%時IO壓力高)。3） await 的大小一般取決于服務時間(svctm) 以及 I/O 隊列的長度和 I/O 請求的發出模式。如果 svctm 比較接近 await，說明 I/O 幾乎沒有等待時間；如果 await 遠大于 svctm，說明 I/O 隊列太長，應用得到的響應時間變慢。l 持續收集資源信息u 信息收集需要在系統上部署NMON軟件。具體的部署方法見附錄五NMON的部署方法。u 初步診斷見附錄六NMON的

14、診斷方法3.1.3 Alert日志和Trace文件（孫）u 信息收集收集方法：第一步：ftp到alert日志的目錄，將alert日志收集下來。方法一：Alert日志的目錄可以通過oracle的參數background_dump_dest找到。如圖1-1所示。方法二：使用這個語句select value from v$diag_info where name ='Diag Trace'得到alert日志的位置。另外，RAC節點下的日志文件結構和普通的日志文件結構不一樣。請參考附件附錄五：Oracle RAC集群環境下日志文件結構。第二步：找到故障發生時的時間段的log日志進行分析

15、。第三步：如果通過alert日志看不到具體的信息，可以通過alert日志的提示，轉到相應的trace文件，進行信息收集。示例如下：其中：“/opt/oracle/db/diag/rdbms/vmos5200/vmos52001/trace/vmos52001_ora_8723.trc”和“/opt/oracle/db/diag/rdbms/vmos5200/vmos52001/incident/incdir_28441/vmos52001_ora_8723_i28441.trc”就是trace文件。第四步：也可以登錄網站，查找具體的錯誤代碼。例如：錯誤代碼：kksfbc-wrong-kkscs

16、flgs。u 初步診斷在alert日志中能夠看到大部分嚴重錯誤、警告，以及一些重要的操作產生的日志。從ORACLE的角度來看，alert日志的信息可以分為如下幾類：Ø 所有的內部錯誤（ORA-00600），塊損壞錯誤（ORA-01578），死鎖（ORA-00060）。Ø 管理性的操作，如create，alter，drop語句和start，shutdown，archivelog語句Ø MTS模式（多線程服務器。區別于專用服務器）下共享服務器進程和調度進程的信息和錯誤Ø 自動刷新物化視圖時發生的錯誤Ø 非默認的啟動參數Ø 各個后臺進程運行

17、產生的錯誤。Oracle的后臺進程見附錄六Oracle的后臺進程。同時用戶也可以使用Oracle的DBMS_SYSTEM包的KSDWRT過程向alert日志書寫自定義信息Ø Job執行失敗錯誤從用戶的角度，或者DBA的角度來看，alert日志的信息可以分為如下幾類：1） 故障級錯誤：這種信息需要優先定位；故障類信息如：Sat Nov 05 10:13:37 2011Errors in file /opt/oracle/db/diag/rdbms/vmos5200/vmos52001/trace/vmos52001_ora_8723.trc (incident=28441):ORA-0

18、0600: internal error code, arguments: kksfbc-wrong-kkscsflgs, 10327733560, 45, , , , , , , , , Incident details in: /opt/oracle/db/diag/rdbms/vmos5200/vmos52001/incident/incdir_28441/vmos52001_ora_8723_i28441.trc2） 警告級信息。如：TNS-12535: TNS:operation timed out ns secondary err code: 12606 nt main err c

19、ode: 0 nt secondary err code: 0 nt OS err code: 0 Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=8)(PORT=2243)WARNING: inbound connection timed out (ORA-3136)3） 操作級信息：Errors in file /opt/oracle/db/diag/rdbms/vmos5200/vmos52001/trace/vmos52001_ora_8480.trc:ORA-00942: table or view does not ex

20、ist更詳細的信息請參見：1） 附錄七：讀懂alert日志2） 附錄八：讀懂trace文件3.1.4 AWR報告（房）3.1.5 ADDM報告（張）（1）出現問題時，需要收集什么樣的信息？ADDM(Automatic Database Diagnostic Monitor) 是植入Oracle數據庫的一個自診斷引擎。ADDM 通過檢查和分析AWR獲取的數據來判斷Oracle數據庫中可能的問題。ADDM會找到數據庫當前的瓶頸，找出等待時間或占用CPU處理時間較長的事件（比如不合理的SQLID等），并可以給出相應的建議，達到減小系統吞吐量的目的。（2）這些信息的作用是什么？通過ADDM我們可以找到

21、當前占用數據庫資源的事件，并根據Oracle自動給出這些事件的建議來降低對系統資源的占用。（3）如何進行收集？收集方法：用sqlplus登陸Oracle。輸入?/rdbms/admin/addmrpt準備生成ADDM報告SQL> ?/rdbms/admin/addmrptOracle會把最近的snapshotID號及對應的時間段顯示出來，并提示輸入snapshotID。根據需要診斷的時間段，輸入需要的snapshotID開始號和結束號。Enter value for begin_snap: 191Enter value for end_snap: 194輸入ADDM報告的名字，沒有的話O

22、racle會默認為addmrpt_1_（起始snapshot）_（終止snapshot）.txt；這里就用默認的，敲回車即可。Oracle會把ADDM報告輸出到屏幕上并同時寫入addmrpt_1_（起始snapshot）_（終止snapshot）.txt文件。生成的文件默認在$ORACLE_HOME/rdbms/admin下。這樣ADDM報告就生成完畢了。（4）如何對這些信息進行分析，從而得到初步診斷結論？Oracle 11G的ADDM報告分為3部分：ADDM報告的生成環境概述：Analysis Period-AWR snapshot range from 191 to 194.Time pe

23、riod starts at 07-DEC-11 07.00.35 AMTime period ends at 07-DEC-11 10.00.16 AMAnalysis Target-Database 'MOS5200' with DB ID 3304876993.Database version .0.ADDM performed an analysis of instance mos5200, numbered 1 and hosted atcreede.Activity During the Analysis Period-Total database

24、time was 437 seconds.The average number of active sessions was .04.Analysis Period說明ADDM生成的snapshot范圍和時間段；Analysis Target說明ADDM生成的Oracle實例、主機及版本；Activity During the Analysis Period說明ADDM生成的數據庫消耗時間，活動回話信息。問題列表（這是ADDM的主要部分）：Summary of Findings- Description Active Sessions Recommendations Percent of Ac

25、tivity - - -1 Top SQL by DB Time .02 | 37.36 52 Hard Parse 0 | 10.74 03 "User I/O" wait Class 0 | 7.81 04 Soft Parse 0 | 4.82 25 Undersized SGA 0 | 4.81 16 Java Execution 0 | 4.3 17 CPU Usage 0 | 2.24 1Summary of Findings是ADDM找出的Oracle存在的瓶頸總覽。下面Description每一行代表一個導致系統瓶頸的事件、對系統的影響比例，以及Oracle

26、自己給出建議的條數。下面就是對每個事件的具體分析，拿Top SQL by DB Time這個首要問題為例： Findings and Recommendations -Finding 1: Top SQL by DB TimeImpact is .02 active sessions, 37.36% of total activity.-SQL statements consuming significant database time were found. Recommendation 1: SQL Tuning Estimated benefit is .01 active sessio

27、ns, 23.39% of total activity. - Action Investigate the SQL statement with SQL_ID "a9bacd1uu35ga" for possible performance improvements. Related Object SQL statement with SQL_ID a9bacd1uu35ga and PLAN_HASH 2060173346. SELECT /*+NESTED_TABLE_GET_REFS+*/ "PM4H_AD"."SYS_INTERGRA

28、TION".* FROM "PM4H_AD"."SYS_INTERGRATION" Rationale SQL statement with SQL_ID "a9bacd1uu35ga" was executed 1 times and had an average elapsed time of 79 seconds. Recommendation 2: SQL Tuning Estimated benefit is 0 active sessions, 9.29% of total activity. - Action

29、Tune the PL/SQL block with SQL_ID "6gvch1xu9ca3g". Refer to the "Tuning PL/SQL Applications" chapter of Oracle's "PL/SQL User's Guide and Reference". Related Object SQL statement with SQL_ID 6gvch1xu9ca3g. DECLARE job BINARY_INTEGER := :job; next_date DATE := :m

30、ydate; broken BOOLEAN := FALSE; BEGIN EMD_MAINTENANCE.EXECUTE_EM_DBMS_JOB_PROCS(); :mydate := next_date; IF broken THEN :b := 1; ELSE :b := 0; END IF; END; Rationale SQL statement with SQL_ID "6gvch1xu9ca3g" was executed 179 times and had an average elapsed time of 0.3 seconds. Recommendat

31、ion 3: SQL Tuning Estimated benefit is 0 active sessions, 5.2% of total activity. - Action Run SQL Tuning Advisor on the SQL statement with SQL_ID "fqmpmkfr6pqyk". Related Object SQL statement with SQL_ID fqmpmkfr6pqyk and PLAN_HASH 2805031759. select s.synonym_name object_name, o.object_t

32、ype from sys.all_synonyms s, sys.all_objects o where s.owner in ('PUBLIC', user) and o.owner = s.table_owner and o.object_name = s.table_name and o.object_type in ('TABLE', 'VIEW', 'PACKAGE','TYPE', 'PROCEDURE', 'FUNCTION', 'SEQUENCE')

33、Action Investigate the SQL statement with SQL_ID "fqmpmkfr6pqyk" for possible performance improvements. Related Object SQL statement with SQL_ID fqmpmkfr6pqyk and PLAN_HASH 2805031759. select s.synonym_name object_name, o.object_type from sys.all_synonyms s, sys.all_objects o where s.owner

34、 in ('PUBLIC', user) and o.owner = s.table_owner and o.object_name = s.table_name and o.object_type in ('TABLE', 'VIEW', 'PACKAGE','TYPE', 'PROCEDURE', 'FUNCTION', 'SEQUENCE') Rationale SQL statement with SQL_ID "fqmpmkfr6pqyk"

35、; was executed 4 times and had an average elapsed time of 3.4 seconds. Recommendation 4: SQL Tuning Estimated benefit is 0 active sessions, 3.35% of total activity. - Action Run SQL Tuning Advisor on the SQL statement with SQL_ID "1rswbxwhbpmr7". Related Object SQL statement with SQL_ID 1r

36、swbxwhbpmr7 and PLAN_HASH 2506064221. select decode(bitand(a.flags, 16384), 0, a.next_run_date, a.last_enabled_time), a.obj#, decode(bitand(a.flags, 16384), 0, 0, 1), a.sch_job from (select p.obj# obj#, p.flags flags, p.next_run_date next_run_date, p.job_status job_status, p.class_oid class_oid, p.l

37、ast_enabled_time last_enabled_time, p.instance_id instance_id, 1 sch_job from sys.scheduler$_job p UNION ALL select q.obj#, q.flags, q.next_run_date, q.job_status, q.class_oid, q.last_enabled_time, q.instance_id, 1 from sys.scheduler$_lightweight_job q UNION ALL select j.job, 0, cast(j.next_date as

38、timestamp with time zone), 1, NULL, cast(j.next_date as timestamp with time zone), NULL, 0 from sys.job$ j where (:1 = 1) and (j.field1 is null or j.field1 = 0) and j.job not in (select v.id2 from v$lock v where v.type = 'JQ') a where bitand(a.job_status, 3) = 1 and (bitand(a.flags, 13421772

39、8 + 268435456) = 0) or (bitand(a.job_status, 1024) <> 0) and bitand(a.flags, 4096) = 0 and a.instance_id is NULL and (a.class_oid is null or (a.class_oid is not null and a.class_oid in (select b.obj# from sys.scheduler$_class b where b.affinity is null) and decode(bitand(a.flags, 16384), 0, a.

40、next_run_date, a.last_enabled_time) = (select min(decode(bitand(c.flags, 16384), 0, c.next_run_date, c.last_enabled_time) from (select r.flags flags, r.next_run_date next_run_date, r.job_status job_status, r.class_oid class_oid, r.last_enabled_time last_enabled_time, r.instance_id instance_id from s

41、ys.scheduler$_job r UNION ALL select s.flags, s.next_run_date, s.job_status, s.class_oid, s.last_enabled_time, s.instance_id from sys.scheduler$_lightweight_job s UNION ALL select 0, cast(k.next_date as timestamp with time zone), 1, NULL, cast(k.next_date as timestamp with time zone), NULL from sys.

42、job$ k where (:2 = 1) and (k.field1 is null or k.field1 = 0) and k.job not in (select w.id2 from v$lock w where w.type = 'JQ') c where bitand(c.job_status, 3) = 1 and (bitand(c.flags, 134217728 + 268435456) = 0) or (bitand(c.job_status, 1024) <> 0) and bitand(c.flags, 4096) = 0 and c.i

43、nstance_id is NULL and (c.class_oid is null or (c.class_oid is not null and c.class_oid in (select d.obj# from sys.scheduler$_class d where d.affinity is null) Action Investigate the SQL statement with SQL_ID "1rswbxwhbpmr7" for possible performance improvements. Related Object SQL stateme

44、nt with SQL_ID 1rswbxwhbpmr7 and PLAN_HASH 2506064221. select decode(bitand(a.flags, 16384), 0, a.next_run_date, a.last_enabled_time), a.obj#, decode(bitand(a.flags, 16384), 0, 0, 1), a.sch_job from (select p.obj# obj#, p.flags flags, p.next_run_date next_run_date, p.job_status job_status, p.class_o

45、id class_oid, p.last_enabled_time last_enabled_time, p.instance_id instance_id, 1 sch_job from sys.scheduler$_job p UNION ALL select q.obj#, q.flags, q.next_run_date, q.job_status, q.class_oid, q.last_enabled_time, q.instance_id, 1 from sys.scheduler$_lightweight_job q UNION ALL select j.job, 0, cas

46、t(j.next_date as timestamp with time zone), 1, NULL, cast(j.next_date as timestamp with time zone), NULL, 0 from sys.job$ j where (:1 = 1) and (j.field1 is null or j.field1 = 0) and j.job not in (select v.id2 from v$lock v where v.type = 'JQ') a where bitand(a.job_status, 3) = 1 and (bitand(

47、a.flags, 134217728 + 268435456) = 0) or (bitand(a.job_status, 1024) <> 0) and bitand(a.flags, 4096) = 0 and a.instance_id is NULL and (a.class_oid is null or (a.class_oid is not null and a.class_oid in (select b.obj# from sys.scheduler$_class b where b.affinity is null) and decode(bitand(a.fla

48、gs, 16384), 0, a.next_run_date, a.last_enabled_time) = (select min(decode(bitand(c.flags, 16384), 0, c.next_run_date, c.last_enabled_time) from (select r.flags flags, r.next_run_date next_run_date, r.job_status job_status, r.class_oid class_oid, r.last_enabled_time last_enabled_time, r.instance_id i

49、nstance_id from sys.scheduler$_job r UNION ALL select s.flags, s.next_run_date, s.job_status, s.class_oid, s.last_enabled_time, s.instance_id from sys.scheduler$_lightweight_job s UNION ALL select 0, cast(k.next_date as timestamp with time zone), 1, NULL, cast(k.next_date as timestamp with time zone

50、), NULL from sys.job$ k where (:2 = 1) and (k.field1 is null or k.field1 = 0) and k.job not in (select w.id2 from v$lock w where w.type = 'JQ') c where bitand(c.job_status, 3) = 1 and (bitand(c.flags, 134217728 + 268435456) = 0) or (bitand(c.job_status, 1024) <> 0) and bitand(c.flags,

51、4096) = 0 and c.instance_id is NULL and (c.class_oid is null or (c.class_oid is not null and c.class_oid in (select d.obj# from sys.scheduler$_class d where d.affinity is null) Rationale SQL statement with SQL_ID "1rswbxwhbpmr7" was executed 209 times and had an average elapsed time of 0.07 seconds. Recommendation 5: SQL Tuning Estimated benefit is 0 active sessions, 3.34% of total activity. - Action Investigate the SQL statement with SQL_ID "3am9cfkvx7gq1" for possible performance im