一次生产环境死锁问题的排查笔记

背景

订单处理系统,线上单据转换到系统单据,需要数据库Sequence表生成自增序列号作为订单号码。
用户反馈单据保存延迟严重,页面单据修改速度很慢,会提示失败。

排查过程

首先查看了服务日志:

Caused by: com.ibatis.common.jdbc.exception.NestedSQLException:
--- The error occurred in com/xxx/xxx/dal/sqlmap/mapping/sequence/sequence-number-mapping.xml.
--- The error occurred while applying a parameter map.
--- Check the UPDATE-NEXT_SEQUENCE_NUMBER-BY-TYPE-InlineParameterMap.
--- Check the statement (update failed).
--- Cause: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
    ... 33 more

发现更新Sequence等锁超时,先猜测是数据库性能问题,但是发现性能消耗和IO都正常,也没有明显相关的慢SQL。
继续排查,看了下数据库正在处理的进程:

mysql> show processlist;
+-------+-------+------------------+-----------+---------+------+----------+-------------------------------------------------------------------------------------------+
| Id    | User  | Host             | db        | Command | Time | State    | Info                                                                                      |
+-------+-------+------------------+-----------+---------+------+----------+-------------------------------------------------------------------------------------------+
| 32690 | xxx | 192.168.xx.xx:35738 | wheeljack | Sleep   |    16 |          | NULL                                                                                      |
| 32869 | xxx | 192.168.xx.xx:36030 | wheeljack | Query   |    16 | updating | update sequence_number set next_sequence = 36948685 where  sequence_type = 'REFUND_ORDER' |
+-------+-------+------------------+-----------+---------+------+----------+-------------------------------------------------------------------------------------------+

发现这两条相关的进程,其中32869是要更新Sequence的进程,还有一条sleep状态可疑的进程32690。经过多次show processlist发现一个规律,每次有更新Sequence等锁的时候都会有一条执行时长相同的Sleep进程,猜想应该是发生死锁了。

通过数据库命令SHOW ENGINE INNODB STATUS,查看死锁情况:

| InnoDB |      | 
=====================================
2022-02-25 18:00:30 7f4c62e30700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 21 seconds
------------
TRANSACTIONS
------------
---TRANSACTION 214086751, ACTIVE 5.833 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
LOCK BLOCKING MySQL thread id: 32690 block 32869
MySQL thread id 32869, OS thread handle 0x7f4c65462700, query id 13251348 192.168.32.234 xxx updating
update sequence_number set next_sequence = 36948685 where  sequence_type = 'REFUND_ORDER'
------- TRX HAS BEEN WAITING 6 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 190 page no 3 n bits 80 index `PRIMARY` of table `xxx`.`sequence_number` trx id 214086751 lock_mode X locks rec but not gap waiting
Record lock, heap no 9 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
------------------
---TRANSACTION 214086750, ACTIVE 5.840 sec
4 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 13
MySQL thread id 32690, OS thread handle 0x7f4bbc9b8700, query id 13251347 192.168.32.234 gaozi cleaning up
--------
----------------------------
END OF INNODB MONITOR OUTPUT
============================

显示 进程32690阻塞了要更新Sequence的进程32869,阻塞进程却在sleep。。疑惑了半天,猜想可能是数据库锁和代码锁竞争了,为了验证猜想,去排查线上服务的运行情况。

服务器通过Arthas(阿里开源工具,5星推荐!线上问题排查利器)命令thread -b发现果然有被阻塞的进程:

"org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-4" Id=19 cpuUsage=0.0% deltaTime=0ms time=16271ms 
BLOCKED on com.xxx.wheeljack.biz.manager.SequenceNumberManager@723ad78e 
owned by "org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-9" Id=24
    at 
com.xxx.wheeljack.biz.manager.SequenceNumberManager.getSequenceByType(SequenceNumberManager.java:50)
    -  blocked on com.xxx.wheeljack.biz.manager.SequenceNumberManager@723ad78e
... 33 more

显示进程19被进程24阻塞,位置在SequenceNumberManager的第50行,接着来看看进程24的情况,命令:thread 24

"org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-9" Id=24 cpuUsage=0.0% deltaTime=0ms time=16112ms RUNNABLE (in native)
com.xxx.wheeljack.dal.daoImpl.SequenceNumberDao.updateNextSequenceByType(SequenceNumberDao.java:28)

显示进程24在执行数据库更新,并且和进程19等待时间相近,基本可以断定分别对应到数据库的两个进程,一个持有代码锁在等待数据库锁来更新Sequence表,一个持有数据库锁却在等待代码锁。

再来看看代码验证猜测,SequenceNumberManager的50行:

    public synchronized Long getSequenceByType(SequenceTypeEnum type) {
        //省略
    }

果然,是一个synchronized修饰的方法。

再来看看业务场景为什么会发生锁竞争,找到调用获取Sequence的代码:

for (int i = 0; i < list.size(); i++) {
  AfterOrderDo afterOrderDo = list.get(i);
  String asOrderId = sequenceNumberManager.getSequenceByType(SequenceTypeEnum.REFUND_ORDER);
  afterOrderDo.setAsOrderId(asOrderId);
  afterOrderDao.insert(afterOrderDo);
}

以上代码在事务内,第3行调用获取Sequence的方法。多线程调用,每个线程内又循环处理单据列表,获取Sequence,由此断定发生死锁的步骤:

1.线程a进入事务处理单据a1;
2.线程a得到Sequence表的锁并成功获取Sequence;
3.线程b进入事务处理单据b1;
4.线程b成功获取代码块synchronized锁,申请获取Sequence表时被迫等待;
5.线程a开始处理单据a2,等待代码块synchronized锁。

由此两个线程相互等待对方持有的锁,直至一方等待超时。

找到问题以后解决方式也就简单了,将获取Sequence的方法放在事务外部,单独处理,避免锁竞争。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,684评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 87,143评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,214评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,788评论 1 277
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,796评论 5 368
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,665评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,027评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,679评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 41,346评论 1 299
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,664评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,766评论 1 331
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,412评论 4 321
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,015评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,974评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,203评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,073评论 2 350
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,501评论 2 343

推荐阅读更多精彩内容