记录一次线上 Oracle 数据库 ORA-00060: deadlock detected 故障案例

布满荆棘的人生 2022-10-28 10:10 139阅读 0赞

客户报告在做 job 导入的时候偶尔会碰到 ORA-00060 错误，客户端日志如下：

<table> 
 <tbody> 
  <tr> 
   <td align="left"> 2020-11-23 12:22:15 (GMT+0100) [ERROR] : java.sql.SQLException: ORA-00060: deadlock detected while waiting for resource </td> 
  </tr> 
 </tbody> 
</table>

因为碰不到客户的生产环境，所以要了一下他们的服务端日志。一般来讲，ORA-00060 总是结对出现，然后我们根据这个错误抛出的程序调用栈，可以分别找到对应的两个线程，根据上下文及各自的 sql 语句不难得出数据库死锁的原因所在。  
但本文案例有些特殊，属于二般情况。拿到服务端日志以后直奔 ORA-00060 的抛错调用栈而去，却发现只有一种线程栈，对应的 sql 语句也只有一种：

update jobother set jobother.allocatestatus='C'  where job_unid in (142000000000397637,140000000000397301,140000000000397302,140000000000397303,140000000000397304,140000000000397543,140000000000397548,140000000000397638,140000000000397639,140000000000397640,140000000000397641,140000000000397642,140000000000397643)

走到这里，先头脑风暴一下。

*  上述 sql 在同一时间段内有五处日志打印，难道是重复执行？
 *  对端死锁 sql 是什么，服务端日志里没有发现 00060 下的其他 sql，难道上述 sql 的 session 抛 00060 后对端线程就能得以成功执行？
 *  抑或是上述 sql 由五个线程同时执行，它们同时执行了同样的逻辑，但为何会有五个相同的业务逻辑在同时执行，是客户端重复请求还是接口没有做好幂等性设计？

带着这些疑问去问客户要了 trc 文件，直奔 Deadlock graph：  
![Deadlock graph.png][]

可见这是一个 Transaction Deadlock 型死锁。查找 session 425 的当前 sql：

update jobother set jobother.allocatestatus=:1   where job_unid in (142000000000405269,140000000000405066,140000000000405237,140000000000405264,140000000000405272,140000000000405275,140000000000405277,140000000000405279,140000000000405281,140000000000405283,140000000000405285,140000000000405287,140000000000405289,140000000000405291)

然后再找到 session 627 的当前执行 sql：

对比之下，它们其实是一样的，头脑风暴 3 命中。这个线索很关键，这个分布式环境中 db 这一块的情况已经清晰明了。目前要做的事情则是找到接口介入的源头情况。带着它回过头去继续去分析服务端日志。两路并进，按图索骥：

*  找到 00060 抛出的线程栈，找到该处代码往前捋；
 *  在服务端日志 00060 处抛出，结合相关代码往前捋。

两路互相结合参考分析，接着就发现确实有 5 个线程在执行同样的逻辑。重复请求？抑或是多线程误启了 5 个线程执行同样逻辑？带着这些疑问继续往前捋，最终发现是确实有 5 个不同的文件需要导入，以致导入服务器响应了五个不同的任务线程分别同时执行导入，在执行到上述 sql 时造成死锁：

<table> 
 <tbody> 
  <tr> 
   <td align="left"> cargoMateFinishedQueue/ID:Defonds-Prod-App.hhh-37181-1606128682104-1:1:2189:1:1<br> cargoMateFinishedQueue/ID:Defonds-Prod-App.hhh-37181-1606128682104-1:1:2197:1:1<br> cargoMateFinishedQueue/ID:Defonds-Prod-App.hhh-37181-1606128682104-1:1:2200:1:1<br> cargoMateFinishedQueue/ID:Defonds-Prod-App.hhh-37181-1606128682104-1:1:2207:1:1<br> cargoMateFinishedQueue/ID:Defonds-Prod-App.hhh-37181-1606128682104-1:1:2213:1:1 </td> 
  </tr> 
 </tbody> 
</table>

经分析，这 5 个文件是同样的内容，导致问题的根本完全是上游服务器误生成了同样不同名的五个导入文件，并非是下游 job 导入服务器的接口幂等性问题。

[Deadlock graph.png]: /images/20221024/70737597f3754ba18edbe79696c91288.png