云南信托数据库性能问题排查 【处理时间】 2015年05月25日 ~ 2015年06月10日 【客户名称】 云南信托 【主机信息】 IBM X3850 x5;Redhat 5.7 x86_64，oracle10.2.0.5 RAC ;RAM 64GB;ASM; 2 pyhsical 12 logical CPU Intel(R) Xeon(R) CPU E7- 4807 @ 1.87GHz 【处理人员】 周光晖 【问题说明】 现象： 接到云南信托客户反映数据库性能一直很慢。和同行业的其他客户相比数据库的处理能力很低。 要求恒生电子DBA介入查找原因，并给出相关建议。 事 件 分 析 1. 2015年05月25日下午16:40分登陆云南信托数据库服务器fapdb。发现当前RAC环境只有一个节点在运行。cpu使用率波动非常大。从10%到99%不等。当前CPU型号为 E7-4807 6 核心 2 socket 12 个逻辑CPU。 2. 通过和客户交流及查看相关日志。在2015年4月3日，由于客户认为存在比较大的gc争用而关闭了节点2。同时客户表示关闭一个节点并没有对性能上有明显的提升。由于时间过久，目前已无法考证当时的情况。 通过现场的情况来看，cpu的使用率非常高。随即对数据库做了266级别的systemdump 。 并使用$ORACLE_HOME/rdbms/admin/awrextr.sql脚本导出了近期的awr报告继续分析。 3. 使用awk分析systemdump的trace发现当前数据库没有阻塞及明显长时间的等待事件。
4. 查看下午2:00~3:00及3:00~4:00的awr。 从load pfrofile中发现硬解析的比率略高一般建议每秒钟少于20次。过高的硬解析容易导致Cursor pin s on X， library cache: mutex X ， latch: row cache objects /shared pool等问题。 通过对比 Parse CPU to Parse Elapsd %和% Non-Parse CPU的值发现解析对cpu的消耗比较严重，如果cpu都在忙于解析而非真正执行语句，无异于是好钢没有用在刀刃上。 Soft Parse %的值表明软解析率过低，一般建议在90%以上。 从时间模型可以看出解析在整个SQL的执行过程中占用了近一般的时间。 过多的的解析可能是一个性能隐患。后面对于具体SQL分析中会提到相关的解析及SQL重用的问题。 其中每秒的逻辑读高达1,628,745次，逻辑读的大小为次数*db_block_size。这里每秒逻辑读高达12724MB。逻辑读高则往往DB CPU高。 Load Profile Redo size: Logical reads: Per Second 1,008,354.81 1,628,745.79 Per Transaction 162,341.16 62,221.67 Block changes: Physica reads: Physical writes: 17,138.41 ** 2,759.22 ** ** ** User calls: ** ** Parses: ** ** Hard parses: ** ** Sorts: ** ** Logons: ** ** Executes: 1,006.66 ** Transactions: ** Instance Efficiency Percentages (Target 100%) Buffer Nowait %: ** Redo NoWait %: ** Buffer Hit %: ** In-memory Sort %: **
Library Hit %: ** Soft Parse %: ** Execute to Parse %: ** Latch Hit %: ** Parse CPU to Parse Elapsd %: ** % Non-Parse CPU: ** Time Model Statistics Statistic Name DB CPU Time (s) % of DB Time 44,064.71 ** sql execute elapsed time 30,910.79 ** parse time elapsed 16,377.37 ** hard parse elapsed time 16,352.31 ** failed parse elapsed time 15,652.79 ** PL/SQL execution elapsed time 1,942.75 ** PL/**pilation elapsed time ** ** hard parse (sharing criteria) elapsed time ** ** hard parse (bind mismatch) elapsed time ** ** connection management call elapsed time ** ** sequence load elapsed time ** ** repeated bind elapsed time ** ** DB time background elapsed time 47,241.93 ** background cpu time **
5. 分析awr中top 5 event部分发现主要的等待为cpu time。这表明大部分时间是耗费在CPU上了。一般来说对于稳健的数据库系统来说。主要的等待在CPU和IO上并不是坏事，至少表明CPU一直在不停的工作。 如果cpu time出现在top的列表中，并同时伴随着性能低下的现象就需要分析关注cpu的使用了。这种情况下，往往是性能不佳的SQL引起的。或者这种SQL具有很高的逻辑读导致了物理读上升。 在列表中我们同样发现了db fiel sequential read等待，这个i/o的等待一般和单块读有关。如索引扫描。其平均等待时间为5ms 一般对于平均等待小于20ms的i/o等待我们都是可以接受的。 Event CPU time Waits Time(s) 2 ,187 db file sequential read 241,063 1,280 5 A g Wait(ms) % Total Call Time Wait Class ** ** User I/O log file parallel write log file sync latch: cache buffers chains 26,479 21,872 18,818 38 35 20 1 2 1 .1 System I/O .1 Commit .1 Concurrency 6. 基于第五项中的等待事件类型，我们下面来分析SQL Statistics中的SQL ordered by CPU Time的情况。 top列表中列出来的SQL使用cpu非常高。每次执行都将CPU资源全部耗尽。 同时存在大量的SQL没有使用绑定变量。下面我们来看下这些SQL。 CPU Time (s) 13,094.16 Executions 4,243 CPU per Exec (s) ** %Total ** Elapsed Time (s) 12,994.17 %CPU %IO ** SQL Id SQL Module SQL Text ** 8qa2p5ac7ghudJDBC Thin BEGIN p_generate_msg(:1 , :2 ,... 8,491.36 4,068 ** ** 8,432.10 ** ** 6d8wqaywfjkxtClient JDBC Thin insert into TSYS_MSG_TMP Client ** fb5wkqavtpxyq** 1,292.62 915 ** ** 1,799.14 ** ** (sele... BEGIN HSFA.SP_RPT_GZB( :1, :2,... ** 52 ** ** ** ** ** Client ** 8dgbuxddu865v** ** bd6qnx1b9vdnhJDBC Thin select t.id_ as taskId, t.prio... ** 2,751 ** ** ** ** ** UPDATE TTMPGZB A SET (A.EN_CB,... ** 45 ** 29 ** ** ** ** Client ** 5crba657x3st9** 6cd1hvykqm3j2JDBC Thin select t.id_ as taskId, t.prio... ** 22 ** ** ** ** JDBC Thin select t.id_ as taskId, t.prio... Client ** ** 4xwh0gp9bthh9JDBC Thin select t.id_ as taskId, t.prio... Client
** 21 ** ** ** ** ** 9rmyr52624xmuJDBC Thin select t.id_ as taskId, t.prio... ** 21 ** ** ** ** ** 5k3cr8aatbukkClient JDBC Thin select t.id_ as taskId, t.prio... Client ** bptmuhzvv4pa2JDBC Thin select t.id_ as taskId, t.prio... ** 20 ** ** ** ** ** ** 20 ** ** ** ** ** Client ** 7xnbn20rfnk7mJDBC Thin select t.id_ as taskId, t.prio... ** 5 ** ** ** ** Client ** 9t9qm1yxypsd7JDBC Thin BEGIN INTF_TA_F(:1 ); END; ** 20 ** ** ** ** ** 6h6t0g7rf5mvvClient JDBC Thin select t.id_ as taskId, t.prio... Client ** 3cxjbn5dr2mc0JDBC Thin select t.id_ as taskId, t.prio... ** 20 ** 20 ** ** ** ** ** 20 ** ** ** ** Client ** aadzzu36mqt58JDBC Thin select t.id_ as taskId, t.prio... ** ** ** ** Client ** 919cnwua14wnsJDBC Thin select t.id_ as taskId, t.prio... ** 20 ** ** ** ** ** g8cfjg2ku95qhClient JDBC Thin select t.id_ as taskId, t.prio... Client ** 75qjc3x4rakts ** 18 ** 53 ** ** ** ** JDBC Thin select t.id_ as taskId, t.prio... Client ** 49 ** ** ** ** ** ghkuu8tkudq3qJDBC Thin select count(*) as col_0_0_ fr... ** ** ** 6f5dv1n5csx47Client JDBC Thin select * from ( select jbpm4ex... Client 7. 如SQL_ID为6cd1hvykqm3j2 和SQL_ID为：6h6t0g7rf5mvv明显只是查询的谓词条件变量不一致，符合绑定变量的要求。确没有使用绑定变量。Oracle在执行完全相同的SQL语句的时候不需要再次硬解析SQL语句，因为硬解析是很耗费资源的一种操作。对于具有同样子游标的SQL可以直接执行而不需要再次解析。对于下面的两条SQL可以考虑在谓词条件中使用绑定变量减少硬解析。从而降低CPU资源的利用率。 下面的SQL的详细情况: sql_id=6cd1hvykqm3j2 sql_text: select t.id_ as taskId, t.priority_ as priority, t.name_ as taskName, t.proc_name_ as proName, t.activity_name_ as activityName, t.taskstatus as taskStatus, (select aa.display_
云南信托_TCMP_TA_数据库性能优化方案(760)
