MySQL运维中长事务和锁等待排查

原文引用 大专栏  https://www.dazhuanlan.com/2019/08/16/5d5610059ebd1/

作为一个DBA, 常常实际工作中遇到各种稀奇八怪的问题。这里重点说一说长事务和锁等待。

  • 长事务
    简单来说就是长时间未递交的事务。它又可分为读长事务和写常事务。

    • 读长事务
      比如研发同事连接查询机(从库)查询,没有启用autocommit, 执行了一个查询SQL,没有commit(一般执行查询都不会再执行commit),连接就这样长时间挂起。这就造成了一个读长事务。这个事务持有一个share_read DML锁,它会影响对该表的DDL操作。如果这时DBA在主库对这个表执行了DDL操作,这个DDL操作复制到从库的时候,会因等待MDL锁而无法执行。这会造成从库复制大量延迟!

      还有一种读长事务的情况就是研发人员执行了一个复杂的统计类SQL,这个SQL执行完本身就耗时很长,这也会造成长时间占用DML锁,即使启用了autocommit也没用。而且还有可能大量数据文档排序造成磁盘空间耗尽。

      更有甚者,进程的连接执行了查询,没有commit,而进程用的是连接池,连接又不关闭。这个问题就很严重了。

    • 写长事务
      写长事务比较好理解,就是批量更新、插入,造成事务长时间执行。还有就是事务本身逻辑比较复杂,存在锁竞争、锁等待。锁等待都会有超时,超时后应用端应该回滚或者重试。

      面对复杂的应用场景,DBA要以不变应万变,这个法宝就是监控。监控的目的是即时发现,发现了就能即时处理。对于读长事务,一旦超过一定阈值(比如10m)可立马kill,对于写操作则不能这么任性,需要结合业务来分析。

      INFORMATION_SCHEMA.INNODB_TRX表中包含了当前innodb内部正在运行的事务信息,包括只读事务。这个表中给出了事务的开始时间,我们可以稍加运算即可得到事务的运行时间。

      1
      2
      3
      4
      5
      6
      7
      8
      9
      10
      11
      12
      13
      14
      15
      16
      17
      18
      19
      20
      21
      22
      23
      24
      25
      26
      27
      28
      mysql> select t.*,to_seconds(now())-to_seconds(t.trx_started) idle_time from INFORMATION_SCHEMA.INNODB_TRX t G
      *************************** 1. row ***************************
      trx_id: 421860487065200
      trx_state: RUNNING
      trx_started: 2018-06-28 08:42:50
      trx_requested_lock_id: NULL
      trx_wait_started: NULL
      trx_weight: 0
      trx_mysql_thread_id: 207
      trx_query: NULL
      trx_operation_state: NULL
      trx_tables_in_use: 0
      trx_tables_locked: 0
      trx_lock_structs: 0
      trx_lock_memory_bytes: 1136
      trx_rows_locked: 0
      trx_rows_modified: 0
      trx_concurrency_tickets: 0
      trx_isolation_level: READ COMMITTED
      trx_unique_checks: 1
      trx_foreign_key_checks: 1
      trx_last_foreign_key_error: NULL
      trx_adaptive_hash_latched: 0
      trx_adaptive_hash_timeout: 0
      trx_is_read_only: 0
      trx_autocommit_non_locking: 0
      idle_time: 1164
      1 row in set (0.00 sec)

      在结果中idle_time是计算产生的,也是事务的持续时间。但事务的trx_query是NUL,这并不是说事务什么也没执行,一个事务可能包含多个SQL,如果SQL执行完毕就不再显示了。当前事务正在执行,innodb也不知道这个事务后续还有没有sql,啥时候会commit。 因此trx_query不能提供有意义的信息。

      再看trx_is_read_only字段,它为1说明这个事务时只读事务,虽然我只是执行了一个select, 但它还是为0。 这是因为它不能确定后续有没有写操作的SQL。只有在开启事务时,使用start transaction read only,它才会是1. 如果执行一个只读事务,使用start transaction read only是很有好处的,这明确告诉innodb 可以采用只读事务的流程来处理这个事务,这会节省不少数据结构,对提升性能帮助很大。如果开启了autocommit, 一个statement就是一个事务,如果是select操作,innodb也会采用只读事务流程处理(这类事务统称为AC-NL-RO)。对于满足AC-NL-RO的事务也不会出现在show engine innodb status中。

      另外一个有用的字段是trx_mysql_thread_id, 这个id就是show processlist中的会话ID。 如果需要终止事务,可kill 这个ID终止会话。

      我们甚至可以通过查询产生这个KILL SQL

      1
      select t.*,to_seconds(now())-to_seconds(t.trx_started) idle_time ,concat('kill ',trx_mysql_thread_id,';') kill_sql from INFORMATION_SCHEMA.INNODB_TRX t G

      如果需要知道这个事务来自于哪个用户,就要和processlist关联查询了

      1
      select * from information_schema.INNODB_TRX i, information_schema.processlist p where i.trx_mysql_thread_id=p.id and p.time > 60;

      关联查询可以看到更多的信息,包括用户,包括客户端IP等,但依然看不到SQL。如果我们想看到这个事务所有SQL,怎么办呢?勉强也是可以做的到,需要开启events_statements_history consumer,mysql5.7默认开启。我们需要information_schema.processlist 、performance_schema.threads 、information_schema.innodb_trx 和performance_schema.events_statements_history关联查询。

      1
      mysql> SELECT ps.id 'PROCESS ID',ps.user,ps.host, esh.EVENT_ID, trx.trx_started,esh.event_name 'EVENT NAME',esh.sql_text 'SQL' ,ps.time from performance_schema.events_statements_history esh   join performance_schema.threads th on esh.thread_id = th.thread_id       join information_schema.processlist ps on ps.id = th.processlist_id left join information_schema.innodb_trx trx on trx.trx_mysql_thread_id = ps.id      where ps.time > 60 AND trx.trx_id is not null and ps.USER != 'SYSTEM_USER'  order by   esh.EVENT_ID;
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
+------------+------+-----------+----------+---------------------+----------------------+-----------------------------+------+
| PROCESS ID | user | host | EVENT_ID | trx_started | EVENT NAME | SQL | time |
+------------+------+-----------+----------+---------------------+----------------------+-----------------------------+------+
| 207 | root | localhost | 836 | 2018-06-28 08:42:50 | statement/sql/error | start transaction read_only | 608 |
| 207 | root | localhost | 837 | 2018-06-28 08:42:50 | statement/sql/begin | start transaction read only | 608 |
| 207 | root | localhost | 838 | 2018-06-28 08:42:50 | statement/sql/select | select * from t1 limit 5 | 608 |
| 207 | root | localhost | 839 | 2018-06-28 08:42:50 | statement/sql/commit | commit | 608 |
| 207 | root | localhost | 840 | 2018-06-28 08:42:50 | statement/sql/begin | start transaction read only | 608 |
| 207 | root | localhost | 841 | 2018-06-28 08:42:50 | statement/sql/select | select * from t1 limit 5 | 608 |
| 207 | root | localhost | 842 | 2018-06-28 08:42:50 | statement/sql/commit | commit | 608 |
| 207 | root | localhost | 843 | 2018-06-28 08:42:50 | statement/sql/begin | begin | 608 |
| 207 | root | localhost | 844 | 2018-06-28 08:42:50 | statement/sql/select | select * from t1 limit 5 | 608 |
| 207 | root | localhost | 845 | 2018-06-28 08:42:50 | statement/sql/select | select * from t2 limit 5 | 608 |
+------------+------+-----------+----------+---------------------+----------------------+-----------------------------+------+
10 rows in set (0.00 sec)

遗憾的是events_statements_history这个表没有trx_id的信息,无法按事务来分组。但按照event_id排序的结果也勉强可以帮助分析问题。(注意随后一个time字段,它指的是最后一个SQL执行后的idle时长,而不是事务执行的精确时长)

  • 锁等待
    锁等待与长事务由密切关系,不管哪种长事务都会造成MDL锁等待。对于MDL锁排查MySQL5.7提供了单独的方案(详见这里),这里不过多分析这个锁。对于行级锁,mysql5.7中也提供了比较优雅的方案,即使用 sys.innodb_lock_waits视图
    1
    2
    3
    4
    5
    6
    7
    mysql> SELECT waiting_trx_id, waiting_pid, waiting_query, blocking_trx_id,blocking_pid,blocking_query FROM sys.innodb_lock_waits;
    +----------------+-------------+---------------------------------------+-----------------+--------------+----------------+
    | waiting_trx_id | waiting_pid | waiting_query | blocking_trx_id | blocking_pid | blocking_query |
    +----------------+-------------+---------------------------------------+-----------------+--------------+----------------+
    | 870773675 | 206 | update t2 set name='x' where name='a' | 870773295 | 207 | NULL |
    +----------------+-------------+---------------------------------------+-----------------+--------------+----------------+
    1 row in set, 3 warnings (0.00 sec)

对于mysql5.6没有sys database的情况下,可以使用:

1
2
3
4
5
6
7
8
9
10
11
mysql> SELECT r.trx_state wating_trx_state, r.trx_id waiting_trx_id, r.trx_mysql_thread_Id waiting_thread,r.trx_query waiting_query,b.trx_state blocking_trx_state,b.trx_id blocking_trx_id,b.trx_mysql_thread_id blocking_thread,b.trx_query blocking_query FROM information_schema.innodb_lock_waits w INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id G
*************************** 1. row ***************************
wating_trx_state: LOCK WAIT
waiting_trx_id: 870773675
waiting_thread: 206
waiting_query: update t2 set name='x' where name='a'
blocking_trx_state: RUNNING
blocking_trx_id: 870773295
blocking_thread: 207
blocking_query: NULL
1 row in set, 1 warning (0.00 sec)

这两个查询都有一个问题,就是如果blocking_query已经执行完毕,但还没有commit,这种情况下显示为NULL. 那么这样才能看到blocking_query呢?这与我们刚才分析长事务的方法类似,结合performance_schema相关表,构成如下SQL:

1
2
3
4
5
6
7
8
9
10
11
12
13
select tmp.*,c.SQL_Text blocking_sql_text,p.Host blocking_host from (SELECT r.trx_state wating_trx_state, r.trx_id waiting_trx_id, r.trx_mysql_thread_Id waiting_thread,r.trx_query waiting_query,b.trx_state blocking_trx_state,b.trx_id blocking_trx_id,b.trx_mysql_thread_id blocking_thread,b.trx_query blocking_query FROM information_schema.innodb_lock_waits w INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id ) tmp ,information_schema.processlist p, performance_schema.events_statements_current c,performance_schema.threads t where tmp.blocking_thread=p.id and  t.thread_id= c.THREAD_ID and t.PROCESSLIST_ID=p.id G
*************************** 1. row ***************************
wating_trx_state: LOCK WAIT
waiting_trx_id: 870773675
waiting_thread: 206
waiting_query: update t2 set name='x' where name='a'
blocking_trx_state: RUNNING
blocking_trx_id: 870773979
blocking_thread: 207
blocking_query: NULL
blocking_sql_text: update t2 set name='x' where name='a'
blocking_host: localhost
1 row in set, 1 warning (0.00 sec)

看到了吧?blocking_sql_text: update t2 set name=’x’ where name=’a’,但这里显示的SQL只是这个事务最后一条SQL,并不是所有的SQL,一个事务可以包含多条SQL,因为我们关联的表是performance_schema.events_statements_current。能不能显示事务内所有的SQL呢?有兴趣的可以去研究下。

上一篇:Nagios 里面监控MySQL事务一直RUNNING没有结束的报警Shell脚本


下一篇:Mysql删除数据时出现执行很慢并且删除失败的情况--线程堵塞