Oracle故障和性能诊断流程V0.1_20120116

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