添加链接
link管理
链接快照平台
  • 输入网页链接,自动生成快照
  • 标签化管理网页链接

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

根据类型一般分为两类:

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

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

行锁等待的现象

如上图所示事务 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。

相关案例2

背景:
为了快速解决由于MDL元数据锁导致请求等待,造成大量线程积压的问题。
处理流程:
一、有正在执行的SQL导致
1、查找到正在做DDL的语句,获取对应表名
select * from information_schema.processlist
2、获取导致DDL操作阻塞的SQL
select * from information_schema.processlist
where command<>'Sleep' and db<>'null' and info like '%${table_name}%' order by time;
3、kill掉对应的SQL

二、未执行完的事务导致
1、获取未提交事务最后一条SQL的信息
SELECT *,t4.PROCESSLIST_ID FROM PERFORMANCE_SCHEMA.events_statements_current t3,
(SELECT t2.thread_id,t2.PROCESSLIST_ID FROM information_schema.INNODB_TRX t1,`performance_schema`.threads t2
WHERE t1.trx_mysql_thread_id = t2.PROCESSLIST_ID) t4
where t3.THREAD_ID = t4.thread_id

2、获取未提交事务的完整SQL信息
SELECT
locked_schema,
locked_table,
locked_type,
waiting_processlist_id,
waiting_age,
waiting_query,
waiting_state,
blocking_processlist_id,
blocking_age,
substring_index(sql_text,"transaction_begin;" ,-1) AS blocking_query,
sql_kill_blocking_connection
FROM
(
SELECT
b.OWNER_THREAD_ID AS granted_thread_id,
a.OBJECT_SCHEMA AS locked_schema,
a.OBJECT_NAME AS locked_table,
"Metadata Lock" AS locked_type,
c.PROCESSLIST_ID AS waiting_processlist_id,
c.PROCESSLIST_TIME AS waiting_age,
c.PROCESSLIST_INFO AS waiting_query,
c.PROCESSLIST_STATE AS waiting_state,
d.PROCESSLIST_ID AS blocking_processlist_id,
d.PROCESSLIST_TIME AS blocking_age,
d.PROCESSLIST_INFO AS blocking_query,
concat('KILL ', d.PROCESSLIST_ID) AS sql_kill_blocking_connection
FROM
performance_schema.metadata_locks a
JOIN performance_schema.metadata_locks b ON a.OBJECT_SCHEMA = b.OBJECT_SCHEMA
AND a.OBJECT_NAME = b.OBJECT_NAME
AND a.lock_status = 'PENDING'
AND b.lock_status = 'GRANTED'
AND a.OWNER_THREAD_ID <> b.OWNER_THREAD_ID
AND a.lock_type = 'EXCLUSIVE'
JOIN performance_schema.threads c ON a.OWNER_THREAD_ID = c.THREAD_ID
JOIN performance_schema.threads d ON b.OWNER_THREAD_ID = d.THREAD_ID
) t1,
(
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
) t2
WHERE
t1.granted_thread_id = t2.thread_id
3、根据2中字段sql_kill_blocking_connection,kill掉对应的进程。

三、异常导致表上持有的锁未释放
需要找到持有锁的线程,然后KILL,暂未遇到。可以通过performance_schema.events_statements_current、sys.schema_table_lock_waits查找。

相关案例3

最近几天持续收到客服数据库锁等待的告警信息,今天使用脚本收集到了相关信息,根据收集到的信息分析如下:

1 、告警时,系统会自动收集当前的锁等待信息

图中 1 、是被阻塞事务的执行时间; 2 、是被阻塞事务的线程 ID

2 、从锁等待信息中可以发现,最开始阻塞事务的线程 ID 1481272

3 、根据时间和线程 ID general 日志中查找记录( general 会记录数据库所有执行的 SQL ),

当前事务一直未有收到 commit/rollback 命令。

4 、从代理日志中可以发现 1481272 对应的事务一直执行了 5 分钟(从 36:02~~41:02 )后超时被代理 kill 掉了。

5 、当 1481272 对应的事务被 kill 后,阻塞的事务 commit 成功。

6 、当前数据库锁等待时间设置的是 120S ,当事务等待 120S 后会自动 rollback

7 、查看之前被阻塞的事务在 general 日中的信息,可以证实 2 分钟后被数据库自动回滚了

同时代理中也会有对应的锁等待超时记录

1、请业务侧排查一下,为什么没有 commit/rollback ?从最近收到锁等待告警信息来看都是更新 DSTAFFSTATUS 表中的记录,请检查与该表相关的业务逻辑是否存在异常;也可以咨询一下曹永斌,之前服开也有类似的问题。
2、调整数据库锁等待时间为默认的50S,尽早返回rollback,降低空跑带来的资源消耗。