一、前言
本文讲述了一个ZLHIS删除操作案例,该操作的SQL语句执行计划中使用到索引,但是执行性能却不高,最终导致带来了严重的性能问题。通过跟踪日志分析,发现导致删除操作性能差的原因是在删除时候出现db file sequential read等待事件,进而分析阐述了产生该等待事件的原因和解决方法,最后把问题解决。本案例通过问题的排查,分析对于以后同事处理类似SQL语句性能问题有一定的参考价值。
二、渠道求助
5月10号早上正在专心的做着优化手段测试的实验,手机电话突然响起,一看来电是NM渠道的技术人员,肯定又是那个医院出了紧急问题,需要马上处理。接听电话,对方首先是一整寒暄,然后直奔主题,原来是渠道的一家医院,周末刚刚升级,升级后其他业务都正常,但是在门诊医生站病人取消接诊操作却异常的慢,一个病人取消接诊要3分钟,已经严重影响医院的正常业务。渠道的技术人员已经按照升级后的常规处理方式,对ZLHIS用户的统计信息进行了收集,但是问题依旧,渠道已经无计可施,因此申请技术支持。其实这个通过描述比较好定位,通过SQL跟踪工具就可以轻松定位问题SQL,这点技术人员也能够掌握,通过SQL跟踪工具,可以轻松定位到问题原来是Zl_病人接诊_Cancel执行性能比较差,光是这个过程执行就需要半分钟左右才能完成,渠道技术人员只能定位到这里,至于为什么这个过程执行慢,其就没有办法判断了,所以申请技术支持。
三、问题分析
其实要诊断过程为什么执行慢,我们可以通过过程调试,带入过程参数通过过程的单步调试功能,就可以跟踪出诊断出其具体执行情况,通过这种方式,我定位到了这个过程执行慢的原因,是如下的SQL语句:
Update 门诊费用记录
Set 执行人 = v_执行人, 执行状态 = 0, 执行时间 = Null, 发药窗口 = Decode(v_分诊方式, 0, Null, 发药窗口), 结论 = Null
Where NO = No_In And 记录性质 = 4 And 记录状态 In (1, 3);
单就该SQL的执行就占了Zl_病人接诊_Cancel过程的大部分时间,但是在其他正常环境中该SQL的执行只需要1秒左右,可以看到性能差距相当的明显,这时我单独把该语句提出出来,加上条件在PLSQL中执行确很快,不存在性能问题,看来该SQL语句必须在过程中性能问题才会突显,这就需要我们分析在过程执行中的该SQL语句的执行情况,我们平时查看单独的SQL语句的执行计划非常简单,但是如何查看存储过程中的SQL语句的执行计划,这里我们就必须要用到一个熟悉的方法----SQL TRACE,以前的文档中也对其进行了详细的介绍,我们这里就不做过多的说明,启用SQL TRACE的方法有很多种,为了得到更多的信息,我们这里采用dbms_session包来对Zl_病人接诊_Cancel存储过程的执行进行跟踪,新打开一个会话窗口,然后执行如下操作:
exec dbms_session.session_trace_enable(waits => True); --跟踪包括等待事件
exec Zl_病人接诊_Cancel('213685','M0064711'); ---传入参数根据实际情况调整
通过执行完上面的语句,对应的TRACE文件就在USER_DUMP_DEST下生成,但是这个原生trace文件格式比较复杂,可读性较差,我们需要通过tkprof命令行工具进行格式化才能够好的解读,格式化的语法如下:
Tkprof tracefile outputfile [explain= ] [table= ] [print= ] [insert= ] [sys= ] [sort= ]
参数说明:
o tracefile: 你要分析的trace文件
o outputfile: 格式化后的文件
o explain=user/password@connectstring
o table=schema.tablename
这两个参数是一起使用的,通过连接数据库对在trace文件中出现的每条sql语句查看执行计划,并将之输出到outputfile中。注意,该table必须是数据库中不存在的,如果存在会报错。为了保证信息准确,这两个参数一般不使用。
o print=n: 只列出最初N个sql执行语句
o insert=filename: 会产生一个sql文件,运行此文件可将收集到的数据insert到数据库表中
o sys=no: 过滤掉由sys执行的语句
o record=filename: 可将非嵌套执行的sql语句过滤到指定的文件中去
o waits=yes|no: 是否统计任何等待事件
o aggregate=yes|no: 是否将相同sql语句的执行信息合计起来,默认为yes
o sort=option: 设置排序选项,主要常用的有exeela(执行时间),execpu(cpu资源),execnt扫行次数等
由于我们需要查看SQL语句的执行计划,因此要使用到explain参数,这里的用户名和密码是你执行存储过程时候的用户名和密码,例如我们这里生成的原文件名为orcl1_ora_14128.trc,格式化操作如下:
tkprof D:\oracle\product\10.2.0\admin\orcl\udump\orcl1_ora_14128.trc D:\oracle\product\10.2.0\admin\orcl\udump\orcl1_ora_14128.txt explain=zlhis/his@orcl
通过上面的格式化操作,我们就得到了一个新的文件orcl1_ora_14128.txt,里面的内容就是已经格式化了的内容,接着我们就需要认真分析该文件。
首先看下整个存储过程的执行时间,如下,
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 18 0.00 0.00 0 0 16 0
Execute 20 4.02 21.42 26015 80437 32 7
Fetch 10 0.00 0.00 0 30 0 8
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 48 4.02 21.43 26015 80467 48 15
大概需要21.43秒,效率确实不高,我们再一步查看先前已经重点关注的SQL语句执行计划如下:
UPDATE 门诊费用记录 SET 执行人 = :B3 , 执行状态 = 0, 执行时间 = NULL,
发药窗口 = DECODE(:B2 , 0, NULL, 发药窗口), 结论 = NULL
WHERE
NO = :B1 AND 记录性质 = 4 AND 记录状态 IN (1, 3)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 3.98 21.39 26015 80366 28 4
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 3.98 21.39 26015 80366 28 4
需要21.39秒,占整个过程执行时间的99%,因此也可以判断这就是该过程执行慢的根本原因,另外我们还可以看出,物理读非常大,难道是没有或者走错了索引导致?我们再来看下这个SQL语句的执行计划,如下:
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 65 (ZLHIS) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT MODE: ALL_ROWS
0 UPDATE OF '门诊费用记录'
0 INDEX MODE: ANALYZED (RANGE SCAN) OF '门诊费用记录_UQ_NO'
(INDEX (UNIQUE))
从执行计划看,没有什么问题,用到了门诊费用记录_UQ_NO索引,而且走的是索引范围扫描,同单独提取该SQL在PLSQL执行的执行计划是一样的,这就奇怪了,但是我们再观察其他信息,发现该语句执行过程中,出现了如下的等待事件:
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 7168 0.09 4.66
db file scattered read 5252 0.10 3.92
这就很奇怪了,特别是db file scattered read等待事件,在使用索引范围扫面的情况下,是不应该出现的,为什么这里会出现呢?带着这个疑问,在metalink中进行了查询,还真让我找到了一篇文章《Delete or Update running slow -- db file scattered read waits on index range scan [ID 296727.1]》,这篇文章给出了详细的解释,在使用了索引范围扫面出现db file scattered read和db file sequential reads等待事件原因:
1.由于每次进行索引范围扫描操作时,都需要对索引叶块进行预取(prefetching)操作,而在删除和修改操作时候,oracle要对预取指数进行维护,因此出现了db file sequential read和db file scattered read等待事件。
2.oracle有个隐含参数“_db_file_noncontig_mblock_read_count”定义了索引每次预期的数据块数,默认是11。
一般情况下,预取指数很少会影响查询的性能,在考虑到用户那里也没做任何修改的情况下,决定不动隐含参数,毕竟隐含参数的修改存在一定的风险,文档中提供了两种处理方式:1.重建索引;2.在WHERE条件中加入更多的索引字段,这里我们采用重建索引的方式,如下:
alter index 门诊费用记录_UQ_NO rebuild online;
四、问题解决
通过重建完索引后,我们再次操作取消接诊,只需要1秒多钟,就完成操作,看来问题已经得到解决,我们再次对Zl_病人接诊_Cancel过程进行一个SQL TRACE操作,生成个TRACE文件,格式化后,结果如下:
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 16 0.00 0.00 0 0 0 0
Execute 18 1.26 1.23 0 45072 34 7
Fetch 8 0.00 0.00 0 28 0 8
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 42 1.27 1.24 0 45100 34 15
可以看到,整个过程的执行时间已经骤减到1.24秒,然后我们再看看刚才那个SQL语句的执行计划,如下:
UPDATE 门诊费用记录 SET 执行人 = :B3 , 执行状态 = 0, 执行时间 = NULL,
发药窗口 = DECODE(:B2 , 0, NULL, 发药窗口), 结论 = NULL
WHERE
NO = :B1 AND 记录性质 = 4 AND 记录状态 IN (1, 3)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 1.24 1.21 0 45001 30 4
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 1.24 1.21 0 45001 30 4
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 65 (ZLHIS) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT MODE: ALL_ROWS
0 UPDATE OF '门诊费用记录'
0 INLIST ITERATOR
0 INDEX MODE: ANALYZED (RANGE SCAN) OF '门诊费用记录_UQ_NO'
(INDEX (UNIQUE))
*******************************************************************************
物理读已经没有了,执行时间同样骤减到1.21秒,而且先前的db file sequential read和db file scattered read等待事件也不在了,这个问题已经得到了处理,随后的几天观察也未再次出现性能问题,至此问题得到圆满解决。
五、小结
通过本案例,我们简单的分析下为什么会出现该性能问题,我想ORACLE内部维护有一套复杂的机制,再一些特定的环境下,这些机制可能出现问题,从而导致出现性能问题,如本例中就是索引的叶块的预期值在进行维护的时候,出现了性能问题,通过重建该索引,相当于重新构建了维护机制,从而解决了问题,另外我们从该问题的解决过程可以得到一些启示:
1.处理性能问题,SQL TRACE是一个非常有用的手段,我们每个技术人员都应该掌握。
2.对于隐含参数,再没有特殊必要的情况下,尽量少用。
3.多利用ORACLE在线帮助,这是一个宝库里面包含了许多我们想要的知识。
希望本文对各位技术人员以后在处理类似问题时,有一个清晰的处理思路,不必再不知所措。
来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/182736/viewspace-730791/,如需转载,请注明出处,否则将追究法律责任。
转载于:http://blog.itpub.net/182736/viewspace-730791/