问题描述
周五收到客户紧急求助，HIS系统挂号业务响应缓慢，每个挂号业务需要等待几分钟，挂号窗口操作人压力巨大。所有挂号业务卡顿的问题从周四下午已经出现，问题持续发生，包括门诊和急诊挂号都受影响，HIS系统的其他业务性能正常。
AWR分析
拉出一份AWR报告，两个节点的RAC，每个节点配置40 CPU核和252GB内存。每秒的DB Time 85，DB CPU 47. 数据库负载相当高。
主要的等待时间除了DB CPU，还有临时表空间操作的direct path write temp和少量的enq: SS - contention，随机读 db file sequential read，行锁enq: TX - row lockcontention 还有直接路径读 direct path read。
从等待事件来看，除了CPU负载高，改HIS系统应该明显有直接路径读和临时表空间的大量使用，经了解是因为该HIS系统分析报表类的业务。
Top SQL列表中经过和开发商确认，前五个topsql与报表类的业务，跟挂号业务没关系。第六个sql id 3tv39qk6qmtcb为update 语句，经过确认是挂号业务中的一条语句。这个sql执行过一次，执行时间是1400秒，在这1400秒钟，CPU%和IO%的比例只占0.02%和0.00%，也就是该SQL执行时，既不消耗CPU也不消耗IO，联系之前主要等待事件中有行锁，这又是一个update语句，这个sql很可能的等待是锁等待。
另外一个问题，挂号业务有多个窗口在办理，每个窗口都会出现卡顿的情况，为什么该SQL在一个小时里面只执行过一次呢？查看改sql文本可以发现因为没有使用绑定变量，每次传入的see_subject号码不一样，sql_id也不一样。
UPDATE fin_opr_seesequence --挂号看诊序号表
SET current_value=current_value+1 --当前序号
WHERE see_date=to_date('2019/5/10 0:00:00','yyyy-mm-dd HH24:mi:ss')
AND see_type='1'
AND see_subject='11234'
AND noon_code='1'
使用10046 SQL Trace进行跟踪调试
从AWR报告中我们了解到该数据库CPU和IO负载高，出现问题的挂号业务存在锁争用的问题。下一步，为了理解挂号业务每次提交需要等待超过2分钟的事务过程，我们考虑通过10046 trace。因为该医院的HIS系统为CS架构，挂号应用ClientHost.exe直连数据库。我们可以获取列出在数据库中列出客户端的主机名列表，让运维人员确认哪一台是挂号窗口所使用的。
select distinct machine from gv$session s where username = 'HIS_DAWN';
运维人员给出一台挂号客户主机名之后，在数据库中创建登录触发器，然后通知操作人员重启该电脑的挂号应用，让新处理的挂号操作打印10046跟踪，其中设置tracefile_identifier是为了让10046 日志文件名带上sql_trace关键字，方便查找。
create or replace trigger sys.set_trace
after logon on database
when (SYS_CONTEXT('USERENV', 'HOST') in ('WorkGroup\SKY-20160621XGI'))
declare
begin
execute immediate 'alter session set tracefile_identifier=''sql_trace''';
execute immediate 'alter session set statistics_level=all';
execute immediate 'alter session set max_dump_file_size=unlimited';
execute immediate 'alter session set events ''10046 trace name context forever, level 12''';
end set_trace;
/
业务人员在新的挂号操作卡顿之后，在后台可以寻找该跟踪文件。以下命令是在两个实例上运行，查询跟踪文件所在目录。
select value from v$diag_info where name='Default Trace File';
在2号节点上一个跟踪文件最大，超过4MB。拷贝该文件到本地电脑，通过orasrp工具对改文件yzeyhis2_ora_2615_sql_trace.trc进行分析。 orasrp是一位俄罗斯DBA出品的免费10046分析工具，http://www.oracledba.ru/orasrp/比oracle官方的tkprof更加强大：
What is OraSRP?
OraSRP is a profiler which processesExtended SQL Trace (a.k.a. 10046 event) files and creates session resourceprofile.
分析命令如下：
./orasrp Users/trace/yzeyhis2_ora_118436_sql_trace.trc sql_trace.html
SQL Trace分析
出现行锁的sql分析
开发sql_trace.html，该会话的确实出现了严重锁等待，时间是389秒。出现锁等待集中为两个sql 1656988603和1199150831。
从sql递归调用树（session call graph）直观显示了整个事务过程执行时间最长的sql以及他们的调用关系。
其中sql 1656988603为update语句，执行次数83，总执行时间为320秒，总锁等待时间为319秒，这个sql因为另一个sql 199811468 存储过程调用。平均逻辑读为71.
Sql 1199150831也是一个update语句，执行次数20，总执行时间为70秒，总锁等待时间为69秒，平均逻辑读为2019。也就是锁等待最长这两个sql，本身执行sql消耗的逻辑读和CPU时间很少，主要是因为行锁，被其他会话阻塞。
高消耗的sql分析
接下来分析sql 1223943092 和3226051042。
Sql 1223943092 总执行时间为33秒，执行次数为15，平均逻辑读88664。
逻辑读的消耗主要来源于对表FIN_OPR_SCHEMATIME的全表扫描。全表扫描返回总的记录数之后545行，平均每次执行更新的行数为545/15=36行。适合创建组合索引进行优化，避免全表扫描。
Sql 3226051042执行逻辑与1223943092类似，同样是对表FIN_OPR_SCHEMATIME进行更新，只是关联子查询中过滤字段不同。该sql执行4次，总执行时间6.2秒，平均逻辑读88663.
逻辑读和cpu时间的消耗同样来源于对表FIN_OPR_SCHEMATIME的全表扫描。全表扫描返回总的记录数之后146行。适合创建组合索引进行优化。
在挂号业务高并发时，因为业务存在这两个更新慢的语句，很可能导致行锁无法及时释放，导致整体业务卡顿。
解决方案
针对sql 1223943092 和3226051042，建议客户创建索引进行优化。
create index fin_opr_schematime_idx_yunqu on fin_opr_schematime(dept_code, doct_code, type, templet_flag, noon_code, to_char(b.see_date,'yyyy-MM-dd'),cardno, seq) online parallel 4 nologging;
alter index fin_opr_schematime_idx_yunqu parallel 1 logging;
优化结果
创建索引之后，挂号业务人员反馈卡顿几分钟的情况没有再出现，问题得到解决。
技术复盘
本案例从awr报告入手，了解到一个高并发高负载的HIS系统中，个别模块出现严重锁争用问题。为了定位挂号业务事务处理中造成锁争用的瓶颈，我们使用10046跟踪的技术，借助于orasrp工具，定位到事务处理中对表FIN_OPR_SCHEMATIME更新语句，存在全表扫描的操作，导致事务处理缓慢，事务无法及时提交，行锁无法及时释放，体现为高并发下行锁等待严重。解决全表扫描之后挂号业务卡顿的问题顺利得到解决。
关于云趣
宁波云趣网络科技有限公司是一家提供专业高科技服务的IT公司。我们专注于高端数据库及自动化运维服务领域， 我们拥有曾就职于ORACLE原厂资深专家及BAT互联网公司、运营商等领域的技术专家团队， 利用多年的实践及运维经验为客户提供一整套解决方案，致力于为传统行业、互联网企业提供专业的数据库系统及自动化运维相关的服务及产品。
