暂无图片
暂无图片
暂无图片
暂无图片
暂无图片

SQL性能问题案例一则

1697

SQL性能问题案例一则

问题现象

3月13日早晨8点左右,客户一套系统测算任务跑了5个小时还没有结束,正常情况下一个小时执行完毕。初步怀疑数据库存在阻塞,登录到数据库查看当前等待事件主要为buffer busy waits、cache buffer chains、enq: TX - row lock contention等待。为了快速恢复应用在得到甲方许可的情况下对session进行批量kill,并重启应用,测算任务恢复正常。

分析过程

1. 使用ash脚本对阻塞会话进行分析,发现阻塞者和被阻塞者具有相同的SQL_ID,那么很有可能是SQL执行效率太差引起的TX行锁。

select  h.sample_time,

       h.INST_ID,

       h.session_id,

       h.sql_id,

       h.event,

       session_state,

       h.p1text || '=' || to_char(h.p1, 'XXXXXXXX') p1,

       h.p2,

       blocking_inst_id || '-' || blocking_session block_sess,

       time_waited 1000000 wait

  from gv$active_session_history h

 where h.sample_time >= to_date('&begin_time', 'yyyy-mm-dd-hh24:mi:ss')

   and h.sample_time <= to_date('&end_time', 'yyyy-mm-dd-hh24:mi:ss')

   and h.event like 'enq%'

 order by h.sample_time, 9, 10

/

2. 对问题SQL运行sqltrpt.sql

sqltrpt.sql是Oracle提供的SQL优化指导工具,通过结果分析,plan_hash为657982381的执行时间远大于其他两条,是不是执行计划发生改变了呢?

再次用到Oracle提供的工具SQLHC,可以观察sql的历史执行情况

结合snapshot、plan_hash、Execs、buffer gets、分析

2022-03-11 22:00:54 这个时间点plan_hash为4140669520 执行了5038次,这个是业务程序第一次发布,根据语句持续时间看,当时测算程序是正常的。

12日测算程序正常,plan_hash为4140669520执行了4775次,657982381在8点执行了73次,这个时候测算任务基本完成没有影响。

13日凌晨4点出现了两个plan_hash值,但是657982381是实际执行的,因为存在逻辑读和执行时间,而plan_hash 4140669520各项数据均为0。10点钟恢复正常后执行计划plan_hash为4140669520 。由此可以判断为执行计划改变引起SQL执行效率缓慢导致TX锁。

解决办法

定位到问题原因后,采用coe_load_sql_profile.sql将好的执行计划进行绑定。

事后分析

我们可以使用10053工具分析SQL执行计划发生改变的原因是什么。具体用法为

oradebug unlimit;

oradebug event 10053 trace name context,forever level 1;

--执行SQL

oradebug event 10053 trace name context off;

oradebug tracefile_name;

在得到的信息截取了以下部分:

通过索引R_MROBJ_DATA_FK_UNION访问的执行计划cost为3,而通过其他索引访问的cost为5,所以Oracle选择通过索引R_MROBJ_DATA_FK_UNION来访问数据。

Oracle中index range scan计算cost的公式为

index_cost=blevel+ceiling(leaf_blocks* effective index selectivity)+ceiling(clustering_factor * effective table selectivity)

根据10053结果R_MROBJ_DATA_FK_UNION执行计划的

ix_sel(effective index selectivity) =0,

ix_sel_with_filters(effective table selectivity)=0 

索引的blevel为3所以cost为3,成本最低,

走了R_MROBJ_DATA_FK_UNION索引,

根据相关信息在mos找到一篇文章,Doc ID 16747257.8其中有以下描述,如果在10053 trace文件中发现ix_sel和ix_sel_with_filters为0那么很有可能就是命中了bug 16747257 。

- END -


文章转载自Oracle一体机用户组,如果涉嫌侵权,请发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论