MySQL锁等待超时问题技术分享

背景

错误信息：Lock wait timeout exceeded; try restarting transaction，我们常称为锁等待超时。

根据类型一般分为两类：

1、行锁等待超时；最常见的场景，因为事务等待行锁超时。

2、元数据锁等待超时；常见在DDL操作期间（此次不涉及）。

行锁等待的现象

事务A	事务B
Begin;	Begin;
mysql> select * from t1; +----+------+ \| id \| name \| +----+------+ \| 1 \| paas \| \| 2 \| csd \| +----+------+
update t1 set name='paas_od' where id=1;
	delete from t1 where id=1;
	…………waiting…………
Commit;	mysql> select * from t1; +----+------+ \| id \| name \| +----+------+ \| 2 \| csd \| +----+------+
	Commit;

如上图所示事务A更新ID=1这行的name=’pass_od’，事务B删除ID=1这行；事务A先执行，所以优先获取了主键ID=1的行锁，事务B的DELETE执行下去的前提是获取ID=1的行锁，由于事务A已经获取了，那么事务B只能等待事务A释放这把锁（事务A commit后，事务B正常执行完成），这就是典型的锁等待的场景。

综上所述：当多个事务同时去操作（增删改）某一行数据的时候，MySQL 为了维护 ACID 特性，就会用锁的形式来防止多个事务同时操作某一行数据，避免数据不一致。只有获取到行锁的事务才可以操作该数据行，直到该事务结束释放行锁，而其他没有获取到行锁的事务就会产生锁等待。如果等待时间超过了配置值（也就是 innodb_lock_wait_timeout），则会抛出行锁等待超时错误。

锁等待产生的原因

1. 程序中非数据库交互操作导致事务挂起

将接口调用或者文件操作等这一类非数据库交互操作嵌入在 SQL 事务代码之中，那么整个事务很有可能因此挂起（接口不通等待超时或是上传下载大附件）。

2、事务中包含性能较差的查询 SQL

事务中存在慢查询，导致同一个事务中的其他 DML 无法及时释放占用的行锁，引起行锁等待。

3. 单个事务中包含大量 SQL

通常是由于在事务代码中加入 for 循环导致，虽然单个 SQL 运行很快，但是 SQL 数量一大，事务就会很慢。

4. 级联更新 SQL 执行时间较久

这类 SQL 容易让人产生错觉，例如：update A set ... where ...in (select B) 这类级联更新，不仅会占用 A 表上的行锁，也会占用 B 表上的行锁，当 SQL 执行较久时，很容易引起 B 表上的行锁等待。

综上可以看出，如果事务长时间未提交，且事务中包含了 DML 操作，那么就有可能产生行锁等待，引起报错。

处理方法

当出现锁等待时，往往都是事后业务反馈才发现，同时MySQL本身不会主动记录锁等待的相关信息，再加上锁等待存在偶然性，不容易复现，所以事后分析并不容易。

1、找开发了解详细情况，获取对应事务的SQL语句，手动复现，实际上很难，开发需要走读代码，耗时，还不一定准确。

2、增加监控，抓取锁等待时候的详细锁、SQL等信息。

模拟锁等待：

我们使用上面的事务A和事务B去模拟锁等待，并抓取信息来分析

mysql> select * from sys.innodb_lock_waits\G;

*************************** 1. row ***************************

wait_started: 2020-06-15 15:43:05

wait_age: 00:03:47

wait_age_secs: 227

locked_table: `test`.`t1`

locked_table_schema: test

locked_table_name: t1

locked_table_partition: NULL

locked_table_subpartition: NULL

locked_index: PRIMARY

locked_type: RECORD

waiting_trx_id: 27368

waiting_trx_started: 2020-06-15 15:42:52

waiting_trx_age: 00:04:00

waiting_trx_rows_locked: 1

waiting_trx_rows_modified: 0

waiting_pid: 18

waiting_query: delete from t1 where id=1

waiting_lock_id: 139860846826920:214:4:5:139860778262952

waiting_lock_mode: X,REC_NOT_GAP

blocking_trx_id: 27367

blocking_pid: 17

blocking_query: NULL

blocking_lock_id: 139860846826048:214:4:5:139860778257000

blocking_lock_mode: X,REC_NOT_GAP

blocking_trx_started: 2020-06-15 15:42:42

blocking_trx_age: 00:04:10

blocking_trx_rows_locked: 1

blocking_trx_rows_modified: 1

sql_kill_blocking_query: KILL QUERY 17

sql_kill_blocking_connection: KILL 17

通过sys.innodb_lock_waits可以获取到对应SQL的语句、等待时间、开始时间、锁的类型、事务ID、线程ID等，同时最后会给出建议的KILL `PID`；但是绝大多数时候无法查询到阻塞的SQL（blocking_query），而且就算能获取到也只能获取到阻塞事务中的某一条SQL语句，这时候我们有2种方式去获取整个事务的SQL语句：

一是开启general_log，根据blocking_pid查找对应事务的全部SQL，缺点是数据库繁忙时，日志信息巨多，影响性能。

根据阻塞的PID 17可以看到阻塞PID 18的SQL语句是UPDATE语句，我就方便我们后续分析具体原因。

二是开启P_S，根据events_statements_current、events_statements_histiory等获取SQL信息，缺点保存的信息有限，有可能被覆盖。

mysql> select t5.*,t4.PROCESSLIST_INFO as waiting_sql from PERFORMANCE_SCHEMA.threads t4 ,(SELECT t1.wait_started,t1.wait_age,t1.waiting_trx_id,t1.waiting_pid,t1.blocking_trx_id,t1.blocking_pid,t1.blocking_trx_age,t2.THREAD_ID AS block_thread_id,t4.SQL_TEXT as current_sql,t3.SQL_TEXT as history_sql from sys.innodb_lock_waits t1,`performance_schema`.threads t2, ( SELECT thread_id, group_concat( CASE WHEN EVENT_NAME = 'statement/sql/begin' THEN "transaction_begin" ELSE sql_text END ORDER BY event_id SEPARATOR ";" ) AS sql_text FROM performance_schema.events_statements_history GROUP BY thread_id ) t3,`performance_schema`.events_statements_current t4 where t1.blocking_pid = t2.PROCESSLIST_ID and t2.THREAD_ID= t3.THREAD_ID and t2.THREAD_ID =t4.THREAD_ID) t5 where t5.waiting_pid = t4.PROCESSLIST_ID\G;

*************************** 1. row ***************************

wait_started: 2020-06-15 15:43:05

wait_age: 00:01:15

waiting_trx_id: 27368

waiting_pid: 18

blocking_trx_id: 27367

blocking_pid: 17

blocking_trx_age: 00:01:38

block_thread_id: 71

current_sql: update t1 set name='paas_od' where id=1

history_sql: insert into t1 select (1,'paas');insert into t1 values(1,'paas');select * from t1;transaction_begin;update t1 set name='paas_od' where id=1;commit;transaction_begin;insert into t1 values(1,'paas');transaction_begin;update t1 set name='paas_od' where id=1

waiting_sql: delete from t1 where id=1

通过结合P_S库、I_S库中的表，可以获取到阻塞其他事务的SQL信息。

刚刚我们是模拟锁等待，所以肯定能获取被阻塞的SQL信息，但有的时候是事后我们才知道发生了锁等待，这时被阻塞的SQL语句因为超过innodb_lock_wait_timeout被回滚了，所以不知道执行哪一条SQL由于锁等待超时被回滚了；我们依旧可以用P_S库获取到报锁等待超时的SQL和相应的信息，然后分析一下对应时间点的慢SQL，看看是否有涉及该表的，然后做对应的优化，此方法存在可能找错SQL，也可能存在找不到的情况，如：阻塞者事务中涉及该表的SQL并不是慢SQL，而是其他SQL执行慢，或者其他原因导致事务慢。

总结：

锁等待分析起来并不难，难的是如何抓取阻塞事务执行的SQL语句，一般的情况都是写监控脚本定时监控采集等待锁等待复现。

相关案例1：

背景：

业务反馈INSERT INTO TF_O_ORDER出现大量锁等待报错。

处理过程：

1、抓取对应的MySQL信息，取如下表的内容

information_schema.innodb_trx：MySQL事务信息表

sys.innodb_lock_waits：MySQL锁等待信息表

show engine innodb status\G：MySQL 引擎日志

2、抓取完信息后，KILL innodb_trx中涉及到tf_o_order相关的事务连接；或者切换主备，然后KILL掉主库上的事务，防止出现两边不一致。

分析过程：

1、查innodb_trx中涉及tf_o_order相关的SQL

总共48个SQL，只有DELETE与INSERT两类SQL。

2、查sys.innodb_lock_waits中阻塞insert into tf_o_oder相关的SQL

锁等待表中最多的就是15746（执行了43S）、15099（执行了37S）阻塞了对应的INSERT SQL。

合计阻塞了50个对应的SQL。

3、完整SQL信息与执行计划

delete from tf_i_activeinfo where phone_no='18599655483' and 0=(select count(1) from tf_o_order,tf_o_trade where tf_o_order.phone_no='18599655483' and tf_o_order.trade_id = tf_o_trade.trade_id and tf_o_trade.status = 'H0')

执行计划如下：

DELETE条件中的子查询中tf_o_order为全表扫描

4、解析慢SQL

该慢SQL从2月18日至今，总计执行了238W多次，95%是在69S执行完成，属于高频SQL的慢SQL。

结论：

Lock wait timeout锁等待超时，是指一个SQL语句执行下去需要获取对应表中某些记录的锁，而这些锁被另外的SQL或者事务占有，当等待时间超过innodb_lock_wait_timeout设置的值后，就会报锁等待超时的错误。这类错误一般是由SQL效率低下或者业务逻辑冲突导致的。

而本次是因为DELETE语句中涉及TF_O_ORDER表的操作为全表扫描且执行时间过长，执行DELETE时会长时间持有锁，导致所有对该表进行的增删改都将阻塞等待。

建议：

1、调整数据库与代理的隔离级别，默认是RR，调整为RC，减少GAP锁的持有和减少某些特定类型SQL获取的锁。（PAAS组操作）
2、业务对此DELETE慢SQL进行优化，可以优先尝试给tf_o_order.phone_no添加一个索引；如果不行，则需要改写SQL逻辑。（业务侧执行，PAAS组核实）
3、定期优化慢SQL。

Harda

MySQL锁等待超时问题技术分享

公告