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

作为一个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内部正在运行的事务信息,包括只读事务。这个表中给出了事务的开始时间,我们可以稍加运算即可得到事务的运行时间。

    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

    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关联查询了

    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关联查询。

    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;
    
+------------+------+-----------+----------+---------------------+----------------------+-----------------------------+------+
| 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视图
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的情况下,可以使用:

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:

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呢?有兴趣的可以去研究下。

相关阅读

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 196,099评论 5 462
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 82,473评论 2 373
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 143,229评论 0 325
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 52,570评论 1 267
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 61,427评论 5 358
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 46,335评论 1 273
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 36,737评论 3 386
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 35,392评论 0 254
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 39,693评论 1 294
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 34,730评论 2 312
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 36,512评论 1 326
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 32,349评论 3 314
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 37,750评论 3 299
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,017评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 30,290评论 1 251
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 41,706评论 2 342
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 40,904评论 2 335

推荐阅读更多精彩内容