poYBAGNGjaOAMXLOAAFPNBX4uHU023.png

最近业务系统生产环境的IDB在执行事务的过程中出现了ERROR 1205 (HY000): Lock waitimeout exceeded; try restarting transaction 异常。通过相关资料的查询和了解,发现出现这个问题的原因是产生了悬挂事务。整个排查的过程也比较困难,因此和大家分享下排查问题的经过。如果文中有错漏的地方,欢迎大家指正。

原理篇

▐ 什么是事务

首先介绍下事务的相关知识。什么是事务?事务就是用户定义的一系列数据库操作,这些操作可以视为一个完成的逻辑处理工作单元,要么全部执行,要么全部不执行,是不可分割的工作单元。

事务的的四大特性:原子性(Atomicity)、一致性(Consistency)、隔离性(Isolation)、持久性(Durability)。

mysql innodb引擎是如何实现上面四个特性的?

事务的隔离性由锁机制+MVCC实现。

事务的原子性、一致性和持久性由事务的 redo 日志和undo 日志来保证。

mysql的锁主要分为 共享锁(S Lock)、排它锁(X Lock)

共享锁(S Lock):共享锁又称为读锁,简称S锁,共享锁就是多个事务对于同一数据可以共享一把锁,都能访问到最新数据。但是不能执行Update、Delete操作。

排它锁(X Lock):排它锁又称为写锁,简称X锁,排它锁不能与其它锁并存,而且只有一个事务能拿到某一数据行的排它锁,其余事务不能再获取该数据行的所有锁。一旦有一个事务获取了该数据的排它锁之后,其余事务对于该数据的操作将会被阻塞,直至锁释放。常见的排他锁:行锁、间隙锁等等。

mysql的重要日志:redo log、undo log和binlog

redo log:重做日志,记录的是事务提交时数据页的物理修改,是用来实现事务的持久性。该日志文件由两部分组成:重做日志缓冲(redo log buffer)以及重做日志文件(redo log file),前者是在内存中,后者在磁盘中。

当事务提交之后会把所有修改信息都存到该日志文件中, 用于在刷新脏页到磁盘,发生错误时, 进行数据恢复使用。mysql在进行修改操作的时候并不是直接进行磁盘IO,因为那样效率太低。而是将修改操作写到缓存区(redo log buffer)中,再在适合的时机进行刷页。为了防止缓存区中的数据因为意外错误丢失,所以会将缓冲区的数据写入到redo 日志。

undo log:主要记录的是数据的逻辑变化,为了在发生错误时回滚之前的操作,需要将之前的操作都记录下来,然后在发生错误时才可以回滚。undo log和redo log记录物理日志不一样,它是逻辑日志。可以认为当delete一条记录时,undo log中会记录一条对应的insert记录,反之亦然,当update一条记录时,它记录一条对应相反的update记录。当执行rollback时,就可以从undo log中的逻辑记录读取到相应的内容并进行回滚。

binlog: 归档日志,属于逻辑日志,是以二进制的形式记录的,用于记录数据库执行的写入性操作(不包括查询)信息。binlog不仅会记录insert操作,还会记录对应的反向操作delete,binlog提供基于时间点的数据恢复能力。

binlog的主要使用场景:主从复制和数据恢复。对于数据恢复场景,我们可以通过使用mysqlbinlog工具来恢复数据。集团内的IDB的数据追踪功能也是利用binlog实现的,可用于找回被误操作的数据。

一次事务的执行过程大致如下:

poYBAGNGjaOAMXLOAAFPNBX4uHU023.png

如上图所示,事务执行流程步骤(更新操作):

查询数据若Buffer Pool存在,则输出,不存在则读取磁盘中的数据并放入Buffer Pool;

更新操作,会先将数据的旧值写入undo log,以便回滚。(保证原子性);

更新Buffer Pool(内存)数据;

将更新数据写入到Redo Log Buffer(内存中);

准备提交事务,会调用fsync将Redo Log Buffer的值刷入到redo log日志文件中,状态为prepare;

准备提交事务,binlog 日志写入磁盘;

binlog写入成功后,将redo log的状态变更为commit;

在合适的时间,将Buffer Pool的数据刷盘;

▐ 什么是悬挂事务

正常的事务流程 (人为控制事务提交):begin, rollback, commit。正常情况下的流程如下:

poYBAGNGjbSAO6E9AAA5T8JvlxI133.png

试想一下,如果我们开启一个事务,但不rollback也不commit这个事务,会发生什么现象。答案是:事务将一直挂起,事务中获得的锁也不会被释放,其他事务也无法操作被锁定的数据,此时就产生了悬挂事务。伴随着悬挂事务的产生,通常会出现ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction 这个错误。下面举个简单的例子:

pYYBAGNGjceAHoKPAABf9F6L-yQ126.png

事务1会获得id=2的行锁,然后一直不释放,事务1的会话将一直存在。事务2也要获得id=2的行锁,这时,事务2开始等待id=2的行锁释放,到了默认的超时时间50s(mysql的默认超时时间参数:

innodb_lock_wait_timeout=50),事务2抛出异常:ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction 。事务1除了人为commit或者杀死该进程,否则事务1的进程永远处于挂起状态(即sleep状态)。

▐ 悬挂事务产生的问题

如果一个数据库连接中开启事务且未显式提交或回滚,在不考虑其他因素的前提下,只有在连接断开的时候才会回滚或者将该事务的进程杀死,该事务才会被回滚。这样一来,悬挂事务将会带来两个非常严重的问题。

悬挂事务不回滚,随着用户操作越来越多,悬挂事务也会不断堆积,整张表被锁的数据行也会越来越多。最终会导致这个表被完全锁住。所有的后续事务都无法获取锁而导致获取锁超时,整个系统彻底崩溃。

悬挂事务回滚,当前这段时间内,用户提交的数据是无法找回的。参考上面的事务执行过程,这个事务其实是被认为失败了,被rollback掉了,也无法通过binlog找回丢失的数据。

实践篇

在前半部分,我分享了有关悬挂事物的相关知识。下面我将分享一例生产环境中的关于悬挂事务的案例。

▐起因

某日中午,钉钉报警群里面开始零星出现 Lock wait timeout exceeded; try restarting transaction异常(如下图所示)。立即开始排查问题,到了下午的时候,钉钉报警群开始大量出现无法获得数据库链接和获取锁超时异常,系统开始出现用户无法提交数据的情况。我立即和团队内的小伙伴的开始紧急处理这个问题。

poYBAGNGjdmAPU-xAAE_AvQWOJM268.png

一开始的时候,通过查阅相关资料,已经定位到产生问题的原因是产生了悬挂事务。那么悬挂事务怎么产生的呢?Spring提供了两种实现事务的方式,@Transactional 注解 和 调用事务管理器的getTransaction方法。值得注意的是getTransaction需要自己控制commit和rollback逻辑。

而@Transactional注解则不需要。我们立即排查了最近上线的几个需求是否使用了getTransaction这种人工控制事务的方式,因为手动控制事务的方式,极有可能会出现事务不commit的情况。通过排查,最近上线的需求没有使用getTransaction这种人工控制事务,初步排除是最近上线的需求导致的。

我们再次开始排查系统中使用了getTransaction这种人工控制事务的方式的代码,系统中大概有7-8处使用了这种方式,这些代码最后一次提交日期大概是2020年,大致走查下来,也没发现什么问题。其实很难通过这种方式排查出原因。

随着时间的流逝,由于悬挂事务的存在导致其他正常的事务也无法执行,数据库中的活跃会话越来越多,越来越多的用户无法提交数据。我们可以从活跃会话得到当前正在执行的sql,导致这些sql无法提交的原因是前面的悬挂事务导致的,无法从当前众多的活跃会话中提取到更多的有效信息。

我们立即联系DBA,协助解决问题。DBA确认了悬挂事务的存在(部分事务执行了3个多小时一直未提交),由于这些进程处于sleep状态,DBA也无法找出关联的sql。事后,查阅了相关资料,发现下面的方法可以找出“可能”的悬挂事务。我们请求DBA将这些悬挂事务的进程全部杀掉(即使不杀掉,这些事务也无法被 commit)。

pYYBAGNGjfmAZ2S2AAC37KLWy8I742.pngpYYBAGNGjf6AZbHXAACxp_khDBc377.png

随着悬挂事务的进程被清理掉之后,数据库活跃会话开始逐渐减少,系统开始正常工作。然而,好景不长,因为一直没找到产生悬挂事务的根源,大约10分钟后又开始出现了Lock wait timeout exceeded; try restarting transaction异常。

我尝试从SLS日志(我们系统的所有日志均会被采集到SLS日志系统中)出发,看看能否找到错误日志从而定位到问题。我重点查看了系统恢复到再次发生问题的这段时间的所有日志,终于发现下图这个异常。其实这段时间内系统的乱七八糟异常信息很多。

能重点注意到这个异常的主要的原因主要是在第2步的时候,我对这段代码(AddServiceToCart)有点印象,记得这段代码好像使用的是手动事务控制事务的。

poYBAGNGjhOANBE_AAB43r-ZGAw962.png

重点查看AddServiceToCart这段代码,立即发现问题。这段代码大致下面这样的方式实现的。

pYYBAGNGji2ACL_vAACOVA69L44710.png

在jsonObject.getLong(“quota”)时,quota不是Long型,jsonObject.getLong抛出RuntimeException,由于异常没有被捕获,事务的rollback和commit都没被执行,这样这个事务就会一直存在。除了应用重启和人工杀掉该事务的进程,让这个事务回滚,没有其他办法。

而这样做带来的后果是这段时间内用户提交的数据都会丢失。如果想要找回,可能只能自己通过应用日志,自己将丢失的数据找回,然后人工将数据重新录入。通过mysql的binlog是无法直接找回的。

▐复盘

从前面的实践篇章节中,我们很容易知道两个事务要操作相同行的数据会产生锁等待的情况。那么是不是意味着上面的代码只会影响到自己事务里面的表呢?现在假设上面的代码只会用到A表,那么是不是同一数据库中的其他的B、C、D表是不是不受影响呢。先揭晓答案:会受到影响,B、C、D表的数据行也会被锁。这是为啥?

首先介绍一下Spring的事务的实现机制。

pYYBAGNGjj2AC3L3AAC5UMPdqAg715.png

Spring事务是如何保证iBatis执行sql时,这些sql用的是相同的Connection?答案是:ThreadLocal。在执行完doBegin方法后,其实是通过bindResouce方法将从DruidDataSource连接池中获得的链接放入当前线程的TheadLocal,这里的TheadLocal中存放的是一个Map, key是dataSouce,value是connectionHolder(connectionHolder中持有Connection的引用。近似认为connectionHolder和Connection是一回事)。

pYYBAGNGjkyAdK91AADfh_Nl8Tw218.png

IBatis在执行sql时,通过DataSourceUtils.getConnection获取数据库链接。这里会优先从当前线程的ThreadLocal中获取,如果获取不到,从数据源中获取。

poYBAGNGjlyAJeCUAAEPTiJ9SS0349.png

ThreadLocal中的变量什么时候会被清除呢?当commit和rollback的时候,ThreadLocal中的变量会被清理掉。

poYBAGNGjmyAQGftAADyYExgn-k156.png

从上面的分析过程中,可以看出,当事务没有被commit和rollback的时候,当前线程可能会有上次残留的ThreadLocal的。因为当前线程是从线程池中获取的,线程是会被复用的。如果当前线程之前执行的事务没有被正确commit或者rollback的话,现在继续要获取链接并执行sql,由于上次是开启了事务且未提交,这次的sql也会被认为进入事务,这些sql也会锁住相应的数据行,这样就造成数据库中大面积的表被锁。

总结

尽量不使用getTransaction这种人工控制事务(这种方式比较容易埋坑,推荐使用@Transactional ),如果要使用,请务必要try catch。一定注意提前return的问题(由于提前return导致rollback和commit都没被执行,这种case也很常见)。否则万一出问题,可能真的很头大;

参数校验一定要严谨,任何类型转化的地方不做类型检查可能都会产生异常;

Loading

发表回复