enq: TX - row lock contention，数据库差点又背锅

1、故障概述

1月征期刚开始，业务系统面临巨大压力，其中一个接口程序积压严重，并且有大量的业务超时。据业务方反馈：业务超时，将导致用户付费后，捐款成功，但无法获取确认信息，后续流程会出现失败。虽然过几天后，扣款会退还给用户，但这一故障给用户带来了极差的体验。

 

2、故障分析

2.1 虽然表面上是业务问题，但还是要先看看数据库是否异常。检查了数据库，发现enq: TX - row lock contention等待事件严重，看样子问题就出在这个上面。 继续检查enq: TX - row lock contention所涉及的SQL语句，发现是delete某张业务表。业务人员反馈，这个delete语句正是该接口程序所涉及的SQL语句。

 

2.2 继续分析enq: TX - row lock contention所涉及的行锁持有者和行锁等待者，发现了几个奇怪的现象：

(1). lock holder（行锁持有者）并不是一直持有锁，大概10秒左右，该lock holder就会消失。也即该lock holder提交了事务，锁资源已经释放。

(2). 在锁等待的过程中，发现持有锁资源的会话的SQL_ID会发生变化，有delete, insert , select语句。 这一现象说明：该事务的处理过程是先delete, 再进行insert 和 select，最后才执行commit操作。

2.3 将观察的现象分析给业务人员，enq: TX - row lock contention通常是业务逻辑出现问题，数据库层面基本毫无办法。同时建议业务人员修改业务逻辑，执行完DML后，立即commit,这样就基本不会出现enq: TX - row lock contention。

但是，业务人员平时只是简单的业务运维，担心业务代码修改后，造成业务不可用。 同时，业务人员表示，这段接口程序近期没有任何调整，怎么这个月的征期就出现异常，而以往都运行正常。并且再次将皮球踢到数据库端，认为是数据库处理缓慢才造成程序超时。

 

2.3 只能继续提供证据，证明数据库一切正常。

通常2.2的分析，基本上只以看出当前接口程序的一个事务中，涉及一个delete, 一个insert 和一个select语句， 整个事务的最后才执行commit操作。

查询dba_hist_sqlstat视图，可以看到其中的insert 和select SQL语句的历史执行时间几乎没有变化（毫秒级）， 而delete语句的执行时间明显变长（从以前的毫秒级变成秒级）。而delete语句变慢，这很容易理解，因为它大部分的时间都花费在enq: TX - row lock contention了。查询DBA_HIST_ACTIVE_SESS_HISTORY视图也可以看出，这个月的征期开始之前，该DELETE语句几乎没有enq: TX - row lock contention，但征期开始后，DELETE语句出现大量的enq: TX - row lock contention。

 

2.4 至此，基本上已经证明了数据库是无辜的，但故障仍然存在。询问业务人员，该接口程序有没有监控日志，如果有监控日志监控了该接口程序中每一步从几点开始的，几点结束的，每一步花费了多长时间，那么问题就变得简单了， 这样就可以知道程序为什么超时，哪一步花费的时间比较多。 但很遗憾，业务方没有相关的监控，只有程序运行过程中生成的祼日志。

 

2.5 开始分析接口程序生成的祼日志。从接口程序的祼日志可以分析出：insert语句花费的时间存在异常。该insert语句，从应用程序拼接出完整的SQL语句，到insert 语句执行完成，整个过程花费了好几秒钟，而数据库侧可知该insert语句在数据库内部的执行时间为毫秒级。这一现象说明了：时间都花费在在应用侧拼接出完整的insert语句上，也即应用程序自身无法及时生成SQL语句。

 

2.6 将这一铁证摆在业务人员面前， 业务人员也觉得有道理。他们开始排查业务系统。

 

2.7 结论：经过排查，发现是业务系统自身的问题。业务系统部署在6个server上，而发生接口程序超时的几乎都来自于其中的一个server，进一步发现，该server的某个cpu核一直处于100%。最终，业务运维人员处理了这个异常的server，接口程序恢复正常，数据库侧的enq: TX - row lock contention也消失。