首页
学习
活动
专区
工具
TVP
发布
社区首页 >专栏 >“大”事务引起的锁等待分析案例

“大”事务引起的锁等待分析案例

作者头像
wubx
发布2019-04-24 18:48:21
6770
发布2019-04-24 18:48:21
举报
文章被收录于专栏:MySQLBeginnerMySQLBeginner

导读

作者:周晓,知数堂第8期学员 曾在TP-LINK任Oracle DBA和系统运维工作,目前在六度人和科技做MySQL DBA,主导多次与数据库相关的项目重构与设计、数据无停服迁移,帮助开发优化了大量SQL并组织培训,网络常用id: seanlook。

一、现象

生产环境数据库在某一刻突然发现大量活跃连接,而且大部分状态是updating。问题出现在周六上午,持续了大概三、四分钟,得益于我们自己的快照程序,拿到了当时现场的processlist, 锁等待关系,及innodb status 信息:(经过脱敏处理)

innodb_status.txt gist片段: var_mydb_snapshot.html,详见https://gist.coding.net/u/seanlook/d6ad649f81c64e23a25f3a980c44a1fe (也可以通过 pt-stalk 收集)

首先在 Lock Waits Info 一节,看到每行的trx_id(事务)的role分为 Blocker(引起阻塞的线程) 与 Blockee(被阻塞者);最后一列 blocking_trx_id 在role是Blockee时才有值,代表谁阻塞了当前事务。 根据上面的关系,可以得出以下结论:

1、事务 19705811640 运行了231s,阻塞了19706118937、19706124453、19706124752,而这些事务都在做同一个UPDATE语句;

2、被锁定的记录是 mydb.mytable1表的主键索引值为5317885行;

3、事务19706124752既被阻塞,也阻塞了别人19706125253;

4、不难发现19705811640应该最先运行的事务,且对其它事务产生了链式阻塞,它的thread_id(9898630) 和来源IP信息(xx.76)。

但是,当你兴冲冲地找到引起阻塞的事务19705811640 在做什么事情时,发现它没有任何sql的信息,lock info以及processlist里面都是None。那么有哪些情况会导致在会话是活跃的,但sql的内容为空:

1、执行show processlist的时候,刚好在事务里面两个sql的中间;

2、sql已经执行完成,但长时间没有提交。

二、初步分析

其实这个现象已经遇到过很多次了,第1个原因常发生在 大量单条记录更新 的情况,一个sql在一个事务里循环执行10000次,即使每条都很快,但大部分时间都在网络传输上,(可以改成批量的形式)。在本案例基本上能确定的是第2个原因:事务开启之后,sql也执行了,但中间又做别的事情去了。那么怎样才能知道这个事务是什么内容呢?两个方向去找:

1、从来源ip上的应用程序的日志里分析

2、binlog里面分析

应用程序日志里可以看 10:21:00 ~ 10:26:00 之间,mydb.mytable1 表上主键id=5317885 在做什么事情。因为我们上了听云,在听云APM里面也可以清楚的看到这个时间点的哪个方法慢:

响应时间230多秒,从“相关SQL”里面看到操作的记录内容,确定就是它了(根据innodb status快照时间 - ACTIVE 230.874 sec,倒推得到的时间与这里刚好吻合)。

从接口名称也清楚的知道是在进行禁用用户的操作,猜想: 禁用用户的逻辑上有先挪到回收站,再删资料、删权限、删关系,清理缓存等等一系列操作,放在事务里保证他们的原子性,似乎是合理的。但为什么执行了将近4分钟还没有提交呢,分析相关的sql效率都很高。

有三种情况:

1、这个事务执行到一半,它需要操作的数据被别人锁住,等待了这么久

2、类似事务要操作5000条数据,但是一条一条的操作,然后一起提交(已出现过类似的例子)

3、事务务执行完成很快,但调用其它接口迟迟没有返回,导致事务没提交。

不会是1和2,因为从一开始的分析看到事务 19705811640 都是在阻塞别人,而不是受害者。那么结合上图中有个有两个操作redis的接口执行时间占比96%,可以下定论了: 在禁用用户时,开启了一个事务,四五个增删改很快完成,但是操作redis缓存过程比较慢,也包含在了事务代码之间,长时间没有提交。前端用户操作的时候因为迟迟没有响应,进行了多次重复点击操作,因为影响的还是同一行记录,所以只能等待前面的锁释放。

Bingo,跟最初的设想一样。但是,开发检查代码之后告诉我,没有用事务!那前面的猜想和结论都不成立了。

三、 论证

于是走另外一个思路,分析binlog。如果binlog里面记录那条记录修改(设置禁用标志)和删除(真正删除)的时间是 10:21:58,说明数据库操作那时候就完成;如果是10:25:xx,说明最后才提交。为了弄明白这个问题,也为了搞情况事务的内容到底是什么,解析当时的binlog。(阿里云rds的数据追踪功能本来挺好用,但这一次用着报内部错误)

还记得前面那个thread_id吗,可以用在这里过滤(也可以用记录值):

$ mysqlbinlog --base64-output=decode-rows -vv --start-datetime="2017-09-16 10:21:00"  --stop-datetime="2017-09-16 10:27:00" mysql-bin.010743 > mysql-bin.010743.sql
$ grep -B5 -A200 "thread_id=9898630" mysql-bin.010743.sql > mysql-bin.010743.sql.txt
$ ./summarize_binlogs.sh > mysql-bin.010743.sql.xid  # 会比较慢
$ cat mysql-bin.010743.sql.xid|grep Transaction|awk '{if($19>0)print}'
[Transaction total : 10 Insert(s) : 1 Update(s) : 0 Delete(s) : 9 Xid : 99370218911 period : 190 ]
[Transaction total : 10 Insert(s) : 1 Update(s) : 0 Delete(s) : 9 Xid : 99370268888 period : 236 ]

上面的 summarize_binlogs.sh 脚本来源于《MySQL运维内参》,可以汇总分析binlog里面事务的执行时间。

mysql-bin.010743.sql.txt:

# at 112037144
#170916 10:25:54 server id 1508836346  end_log_pos 112037192 CRC32 0x25216430    GTID [commit=yes]
SET @@SESSION.GTID_NEXT= '56506509-b971-11e6-8c19-6c92bf2c8aaf:10306353216'/*!*/;
# at 112037192
#170916 10:21:58 server id 1508836346  end_log_pos 112037268 CRC32 0x9cddeec2    Query    thread_id=9898630    exec_time=0    error_code=0
SET TIMESTAMP=1505528518/*!*/;
SET @@session.sql_mode=2097152/*!*/;
BEGIN
/*!*/;
# at 112037268
#170916 10:21:58 server id 1508836346  end_log_pos 112037342 CRC32 0x373641db    Table_map: `mydb`.`mytable01_del` mapped to number 950163
# at 112037342
#170916 10:21:58 server id 1508836346  end_log_pos 112037460 CRC32 0x4bba2efb    Write_rows: table id 950163 flags: STMT_END_FBINLOG '
xoq8WRP6A+9ZSgAAAN6NrQYAAJN/DgAAAAEACWRfZWNfdXNlcgAKdF91c2VyX2RlbAAMCAgICBEB
CAgRCA8IBAAAyAAAAdtBNjc=
xoq8WRf6A+9ZdgAAAFSOrQYAAJN/DgAAAAEADP//APEL/VAAAAAAAP0kUQAAAAAACKpYGQQAAAAK
/VAAAAAAAFm8isYAAAAAAAAAAAAAAAAAAAAAADojUQAAAAAADOW+kOaxn+e6oue7hOE3BAAAAAAA
+y66Sw==
'/*!*/;
### INSERT INTO `mydb`.`mytable01_del`
# at 112037460
#170916 10:21:58 server id 1508836346  end_log_pos 112037542 CRC32 0x7b55174a    Table_map: `mydb`.`mytable1` mapped to number 950159
# at 112037542
#170916 10:21:58 server id 1508836346  end_log_pos 112037636 CRC32 0x3bdcebf7    Delete_rows: table id 950159 flags: STMT_END_FBINLOG '
xoq8WRP6A+9ZUgAAAKaOrQYAAI9/DgAAAAEACWRfZWNfdXNlcgAOdF91c2VyX2FjY291bnQADAgC
Dw8BARISAQMBDwiAABAAAADwADgBShdVew==
xoq8WRn6A+9ZXgAAAASPrQYAAI9/DgAAAAEADP//APD9JFEAAAAAAAAACzE3NjA1MTEwMjgwEDc9
OokVkE7wcJ6AvWQXyZMEAJmc6TjAmZzs458AAAAAAAAA9+vcOw==
'/*!*/;
### DELETE FROM `mydb`.`mytable1`
......
# at 112038300
#170916 10:25:54 server id 1508836346  end_log_pos 112038331 CRC32 0x01b508cf    Xid = 99370268888
COMMIT/*!*/;

binlog格式当中,一个事务最先记录的是GTID事件,而这个GTID的值只有在提交的时候才会生成,binlog里面的GTID时间的时间10:25:54就是事务提交的时间。 Xid在最末尾,时间也是10:25:54。但中间该事务的其它binlog事件,像UpdateRows/DeleteRows/InsertRows,前面的时间10:21:58是事务开始的时间。中间有4分钟的空档,与前面redis操作4分钟不谋而合。

这下就更加明朗了:有显式的开启事务。但开发说没有用事务,又该怎么解释呢?

不同的语言,不同的框架,使用事务的方式不一样。数据库里面开启显式事务有两种方式,一是设置 set autocommit=0,二是运行start transaction。两者都要显式调用commit命令提交事务。 为了证实程序的确用了事务,在测试环境应用服务器模拟用户的操作,然后抓包:

$ sudo tcpdump -s 0 -l -w - dst your_db_ipaddr and port 3306 -i eth0 > mysql_3306.tcp
$ strings mysql_3306.tcp|grep -n commit
28:SET autocommit=0
123:commit
124:SET autocommit=1
222:SET autocommit=0
257:commit
258:SET autocommit=1
268:SET autocommit=0
333:SET autocommit=1
399:commit
400:SET autocommit=1

有发送 set autocommit=0,这下更放心了。开发再次回去检查,发现在Spring框架的时,在类上面用 @Transactional 的方式做了事务,而常规的做法是把注解加在类的方法上,导致忽略了这个因素。

四、解决

解决办法是把需要做事务控制的地方放到Services接口级别,让redis清理缓存的操作在事务之外,或者异步清理。(但也要考虑这样做会有什么负面影响) 另外,Redis操作慢,是否是设计上的问题。(听云监控里面显示该事务里面调用了1300次)

五、总结

首先根据但是的现场快照,分析锁等待关系;根据以前的经验,怀疑是“大”事务中有无关的调用;根据程序日志和听云分析出对应的接口;但开发说没有事务,于是进一步通过分析binlog,经过tcp抓包,拿出证据;最后解决。

我们经常说,尽量少用大事务,但由于现在开发都是基于各种框架,使用事务的方式被封装,要理解它们的用法。其次,我们上面的事务并不大,每个sql更新都很快,但是却把其它调用也写在事务里面,就容易阻塞而长时间不提交,也许这样做的初衷是操作db与清理redis缓存放在一个事务里,要么都成功,要么都失败,但是这种分布式设计就不合理(当然有办法是可以做到,这里不展开)。

本文即是一个大事务锁的分析案例,也展示了引用各种工具,去分析论证的过程。

本文参与 腾讯云自媒体分享计划,分享自微信公众号。
原始发表:2017-11-07,如有侵权请联系 cloudcommunity@tencent.com 删除

本文分享自 MySQLBeginner 微信公众号,前往查看

如有侵权,请联系 cloudcommunity@tencent.com 删除。

本文参与 腾讯云自媒体分享计划  ,欢迎热爱写作的你一起参与!

评论
登录后参与评论
0 条评论
热度
最新
推荐阅读
目录
  • 二、初步分析
  • 三、 论证
  • 四、解决
  • 五、总结
相关产品与服务
云数据库 SQL Server
腾讯云数据库 SQL Server (TencentDB for SQL Server)是业界最常用的商用数据库之一,对基于 Windows 架构的应用程序具有完美的支持。TencentDB for SQL Server 拥有微软正版授权,可持续为用户提供最新的功能,避免未授权使用软件的风险。具有即开即用、稳定可靠、安全运行、弹性扩缩等特点。
领券
问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档