【Mysql】是谁，把InnoDB表上的DML搞慢的之---一个参数救活被hang住的数据库！

  • 小亮520cl

    2017-02-09 14:14:47
  • MySQL
  • 原创

1 问题：好几条DML卡住，执行非常长的时间

  1. 如下：
  2. +-------+-----------+--------------------+------------------+---------+--------+-----------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
    | Id    | User      | Host               | db               | Command | Time   | State     | Info                                                                                                                                                                                                       |
    +-------+-----------+--------------------+------------------+---------+--------+-----------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
    |     2 | interface | 192.168.1.56:37642 | interface_hd_com | Sleep   |     68 |           | NULL                                                                                                                                                                                                       |
    | 61805 | interface | 192.168.1.56:60947 | interface_hd_com | Query   | 246201 | query end | UPDATE `admin` SET `last_time`=1486374664 WHERE ( `id` = 413 )                                                                                                                                             |
    | 61816 | interface | 192.168.1.56:33127 | interface_hd_com | Query   | 245816 | query end | INSERT INTO `admin_operation_log` (`op_desc`,`op_uid`,`op_time`,`ip`,`mod`,`act`) VALUES ('登录后台',413,1486375050,'124.192.156.166','Login','login')                                                     |
    | 61825 | interface | 192.168.1.56:33459 | interface_hd_com | Query   | 245598 | query end | UPDATE `admin` SET `last_time`=1486375268 WHERE ( `id` = 554 )                                                                                                                                             |
    | 61829 | interface | 192.168.1.56:33550 | interface_hd_com | Query   | 245477 | query end | INSERT INTO `admin_operation_log` (`op_desc`,`op_uid`,`op_time`,`ip`,`mod`,`act`) VALUES ('登录后台',554,1486375389,'124.192.156.166','Login','login')                                                     |
    | 61833 | interface | 192.168.1.56:33758 | interface_hd_com | Query   | 245416 | query end | UPDATE `admin` SET `last_time`=1486375450 WHERE ( `id` = 754 )                                                                                                                                             |
    | 61888 | interface | 192.168.1.56:36030 | interface_hd_com | Query   | 243552 | query end | UPDATE `b_users` SET `last_time`=1486377314,`last_did`=73232,`key`='NgSIC15RzXpSEJgW',`login_status`=1,`last_ip`='124.192.156.166' WHERE ( `tel` = '15718833655' )                                         |
    | 63547 | interface | 192.168.1.56:51671 | interface_hd_com | Query   | 182073 | query end | INSERT INTO `sms_log` (`tel`,`content`,`c_time`,`source`,`status`) VALUES ('14761542203','短信验证码：0653','2017-02-07 11:39:55',1,2)                                                                     |
    | 63550 | interface | 192.168.1.56:51726 | interface_hd_com | Query   | 182045 | query end | INSERT INTO `sms_log` (`tel`,`content`,`c_time`,`source`,`status`) VALUES ('14761542203','短信验证码：5195','2017-02-07 11:40:23',1,2)                                                                     |
    | 63551 | interface | 192.168.1.56:51763 | interface_hd_com | Query   | 182025 | query end | INSERT INTO `sms_log` (`tel`,`content`,`c_time`,`source`,`status`) VALUES ('14761542203','短信验证码：0145','2017-02-07 11:40:43',1,2)                                                                     |
    | 66695 | interface | 192.168.1.56:42570 | interface_hd_com | Query   |  69387 | query end | UPDATE `b_devices` SET `imei`='861322030576181',`key`='yjyH8MtSfSd6zx3c',`os_type`=1,`d_name`='',`c_ip`='124.192.156.166',`c_time`=1473663683,`u_time`=1486551484,`app_v`='34000' WHERE ( `did` = 343032 ) |
    | 68365 | interface | 192.168.1.56:53342 | interface_hd_com | Query   |  12279 | query end | UPDATE `b_devices` SET `imei`='869801024824741',`key`='8CXzJ2zUYEKzM1Zy',`os_type`=1,`d_name`='',`c_ip`='124.192.156.166',`c_time`=1477978901,`u_time`=1486608594,`app_v`='34000' WHERE ( `did` = 378254 ) |
    | 68636 | interface | 192.168.1.56:56140 | interface_hd_com | Query   |  10700 | query end | UPDATE `b_devices` SET `imei`='862265035973052',`key`='UlSphOuFL8M6MtzM',`os_type`=1,`d_name`='',`c_ip`='124.192.156.166',`c_time`=1481093099,`u_time`=1486610173,`app_v`='34000' WHERE ( `did` = 405110 ) |
    | 68917 | root      | 127.0.0.1:40543    | interface_hd_com | Query   |      0 | init      | show full processlist                                                                                                                                                                                      |
    | 68918 | root      | 127.0.0.1:40544    | interface_hd_com | Sleep   |     94 |           | NULL                                                                                                                                                                                                       |
    +-------+-----------+--------------------+------------------+---------+--------+-----------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
    观察可以发现 update语句执行了好长好长时间了！

2.explain查看执行计划

  1. 无异常，并且该表的数据量不大

3.查看show engine innodb status状况

  1. MySQL [interface_hd_com]> show engine innodb status\G;
  2. *************************** 1. row ***************************
  3.   Type: InnoDB
  4.   Name:
  5. Status:
  6. =====================================
  7. 2017-02-09 14:05:59 7f8b2824f700 INNODB MONITOR OUTPUT
  8. =====================================
  9. Per second averages calculated from the last 31 seconds
  10. -----------------
  11. BACKGROUND THREAD
  12. -----------------
  13. srv_master_thread loops: 978 srv_active, 0 srv_shutdown, 2076442 srv_idle
  14. srv_master_thread log flush and writes: 2077420
  15. ----------
  16. SEMAPHORES
  17. ----------
  18. OS WAIT ARRAY INFO: reservation count 20547
  19. OS WAIT ARRAY INFO: signal count 83719
  20. Mutex spin waits 98463, rounds 1057195, OS waits 12093
  21. RW-shared spins 31686, rounds 466826, OS waits 6145
  22. RW-excl spins 14116, rounds 245562, OS waits 1512
  23. Spin rounds per wait: 10.74 mutex, 14.73 RW-shared, 17.40 RW-excl
  24. ------------
  25. TRANSACTIONS
  26. ------------
  27. Trx id counter 1045619584
  28. Purge done for trx's n:o < 1045619565 undo n:o < 0 state: running but idle
  29. History list length 1067                  ----un-purge很小，非异常！
  30. LIST OF TRANSACTIONS FOR EACH SESSION:
  31. ---TRANSACTION 0, not started
  32. MySQL thread id 68947, OS thread handle 0x7f8b2824f700, query id 659898 127.0.0.1 root init
  33. show engine innodb status
  34. ---TRANSACTION 0, not started
  35. MySQL thread id 68917, OS thread handle 0x7f8b2820e700, query id 659648 127.0.0.1 root cleaning up
  36. ---TRANSACTION 1045619583, not started
  37. MySQL thread id 2, OS thread handle 0x7f8b2a6fe700, query id 659674 192.168.1.56 interface cleaning up
  38. ---TRANSACTION 1045619290, ACTIVE (PREPARED) 10873 sec    ---事务执行时间过长，和show full processlist里面的相对应的，并且undo也是很小的！凭着以往处理故障的经验，这是N多条未提交事务的SQL引起的。
  39. mysql tables in use 1, locked 1
  40. 2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
  41. MySQL thread id 68636, OS thread handle 0x7f8b2a3b1700, query id 657444 192.168.1.56 interface query end
  42. UPDATE `b_devices` SET `imei`='862265035973052',`key`='UlSphOuFL8M6MtzM',`os_type`=1,`d_name`='',`c_ip`='124.192.156.166',`c_time`=1481093099,`u_time`=1486610173,`app_v`='34000' WHERE ( `did` = 405110 )
  43. ---TRANSACTION 1045618887, ACTIVE (PREPARED) 12452 sec
  44. mysql tables in use 1, locked 1
  45. 2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
  46. MySQL thread id 68365, OS thread handle 0x7f8b2a578700, query id 655711 192.168.1.56 interface query end
  47. UPDATE `b_devices` SET `imei`='869801024824741',`key`='8CXzJ2zUYEKzM1Zy',`os_type`=1,`d_name`='',`c_ip`='124.192.156.166',`c_time`=1477978901,`u_time`=1486608594,`app_v`='34000' WHERE ( `did` = 378254 )
  48. ---TRANSACTION 1045617441, ACTIVE (PREPARED) 69560 sec
  49. mysql tables in use 1, locked 1
  50. 2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
  51. MySQL thread id 66695, OS thread handle 0x7f8b2a73f700, query id 648346 192.168.1.56 interface query end
  52. UPDATE `b_devices` SET `imei`='861322030576181',`key`='yjyH8MtSfSd6zx3c',`os_type`=1,`d_name`='',`c_ip`='124.192.156.166',`c_time`=1473663683,`u_time`=1486551484,`app_v`='34000' WHERE ( `did` = 343032 )
  53. ---TRANSACTION 1045614712, ACTIVE (PREPARED) 182198 sec
  54. mysql tables in use 1, locked 1
  55. 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
  56. MySQL thread id 63551, OS thread handle 0x7f8b2a433700, query id 634539 192.168.1.56 interface query end
  57. INSERT INTO `sms_log` (`tel`,`content`,`c_time`,`source`,`status`) VALUES ('14761542203','短信验证码：0145','2017-02-07 11:40:43',1,2)
  58. ---TRANSACTION 1045614711, ACTIVE (PREPARED) 182218 sec
  59. mysql tables in use 1, locked 1
  60. 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
  61. MySQL thread id 63550, OS thread handle 0x7f8b2a474700, query id 634534 192.168.1.56 interface query end
  62. INSERT INTO `sms_log` (`tel`,`content`,`c_time`,`source`,`status`) VALUES ('14761542203','短信验证码：5195','2017-02-07 11:40:23',1,2)
  63. ---TRANSACTION 1045614707, ACTIVE (PREPARED) 182246 sec
  64. mysql tables in use 1, locked 1
  65. 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
  66. MySQL thread id 63547, OS thread handle 0x7f8b2a4f6700, query id 634522 192.168.1.56 interface query end
  67. INSERT INTO `sms_log` (`tel`,`content`,`c_time`,`source`,`status`) VALUES ('14761542203','短信验证码：0653','2017-02-07 11:39:55',1,2)
  68. ---TRANSACTION 1045613296, ACTIVE (PREPARED) 243725 sec
  69. mysql tables in use 1, locked 1
  70. 3 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1
  71. MySQL thread id 61888, OS thread handle 0x7f8b2a4b5700, query id 627421 192.168.1.56 interface query end
  72. UPDATE `b_users` SET `last_time`=1486377314,`last_did`=73232,`key`='NgSIC15RzXpSEJgW',`login_status`=1,`last_ip`='124.192.156.166' WHERE ( `tel` = '15718833655' )
  73. ---TRANSACTION 1045613239, ACTIVE (PREPARED) 245589 sec
  74. mysql tables in use 1, locked 1
  75. 2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
  76. MySQL thread id 61833, OS thread handle 0x7f8b2a537700, query id 627162 192.168.1.56 interface query end
  77. UPDATE `admin` SET `last_time`=1486375450 WHERE ( `id` = 754 )
  78. ---TRANSACTION 1045613237, ACTIVE (PREPARED) 245650 sec
  79. mysql tables in use 1, locked 1
  80. 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
  81. MySQL thread id 61829, OS thread handle 0x7f8b2a5fa700, query id 627153 192.168.1.56 interface query end
  82. INSERT INTO `admin_operation_log` (`op_desc`,`op_uid`,`op_time`,`ip`,`mod`,`act`) VALUES ('登录后台',554,1486375389,'124.192.156.166','Login','login')
  83. ---TRANSACTION 1045613231, ACTIVE (PREPARED) 245771 sec
  84. mysql tables in use 1, locked 1
  85. 2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
  86. MySQL thread id 61825, OS thread handle 0x7f8b2a5b9700, query id 627005 192.168.1.56 interface query end
  87. UPDATE `admin` SET `last_time`=1486375268 WHERE ( `id` = 554 )
  88. ---TRANSACTION 1045613224, ACTIVE (PREPARED) 245989 sec
  89. mysql tables in use 1, locked 1
  90. 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
  91. MySQL thread id 61816, OS thread handle 0x7f8b2a6bd700, query id 626979 192.168.1.56 interface query end
  92. INSERT INTO `admin_operation_log` (`op_desc`,`op_uid`,`op_time`,`ip`,`mod`,`act`) VALUES ('登录后台',413,1486375050,'124.192.156.166','Login','login
。。。
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137363456; in additional pool allocated 0
Dictionary memory allocated 1488322
Buffer pool size   8191
Free buffers       1024
Database pages     6974
Old database pages 2554
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 130227, not young 12165739
0.00 youngs/s, 0.00 non-youngs/s
Pages read 363922, created 5124, written 41374
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6974, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]

4，查看锁状况

  1. SELECT 
      a.trx_id,
      trx_state,
      trx_started,
      b.id AS thread_id,
      b.info,
      b.user,
      b.host,
      b.db,
      b.command,
      b.state 
    FROM
      information_schema.`INNODB_TRX` a,
      information_schema.`PROCESSLIST` b 
    WHERE a.trx_mysql_thread_id = b.id 
    ORDER BY a.trx_started;
  2. +------------+-----------+---------------------+-----------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+--------------------+------------------+---------+-----------+
  3. | trx_id | trx_state | trx_started | thread_id | info | user | host | db | command | state |
  4. +------------+-----------+---------------------+-----------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+--------------------+------------------+---------+-----------+
  5. | 1045613212 | RUNNING | 2017-02-06 17:39:45 | 61805 | UPDATE `admin` SET `last_time`=1486374664 WHERE ( `id` = 413 ) | interface | 192.168.1.56:60947 | interface_hd_com | Query | query end |
  6. | 1045613224 | RUNNING | 2017-02-06 17:46:10 | 61816 | INSERT INTO `admin_operation_log` (`op_desc`,`op_uid`,`op_time`,`ip`,`mod`,`act`) VALUES ('登录后台',413,1486375050,'124.192.156.166','Login','login') | interface | 192.168.1.56:33127 | interface_hd_com | Query | query end |
  7. | 1045613231 | RUNNING | 2017-02-06 17:49:48 | 61825 | UPDATE `admin` SET `last_time`=1486375268 WHERE ( `id` = 554 ) | interface | 192.168.1.56:33459 | interface_hd_com | Query | query end |
  8. | 1045613237 | RUNNING | 2017-02-06 17:51:49 | 61829 | INSERT INTO `admin_operation_log` (`op_desc`,`op_uid`,`op_time`,`ip`,`mod`,`act`) VALUES ('登录后台',554,1486375389,'124.192.156.166','Login','login') | interface | 192.168.1.56:33550 | interface_hd_com | Query | query end |
  9. | 1045613239 | RUNNING | 2017-02-06 17:52:50 | 61833 | UPDATE `admin` SET `last_time`=1486375450 WHERE ( `id` = 754 ) | interface | 192.168.1.56:33758 | interface_hd_com | Query | query end |
  10. | 1045613296 | RUNNING | 2017-02-06 18:23:54 | 61888 | UPDATE `b_users` SET `last_time`=1486377314,`last_did`=73232,`key`='NgSIC15RzXpSEJgW',`login_status`=1,`last_ip`='124.192.156.166' WHERE ( `tel` = '15718833655' ) | interface | 192.168.1.56:36030 | interface_hd_com | Query | query end |
  11. | 1045614707 | RUNNING | 2017-02-07 11:28:33 | 63547 | INSERT INTO `sms_log` (`tel`,`content`,`c_time`,`source`,`status`) VALUES ('14761542203','短信验证码：0653','2017-02-07 11:39:55',1,2) | interface | 192.168.1.56:51671 | interface_hd_com | Query | query end |
  12. | 1045614711 | RUNNING | 2017-02-07 11:29:01 | 63550 | INSERT INTO `sms_log` (`tel`,`content`,`c_time`,`source`,`status`) VALUES ('14761542203','短信验证码：5195','2017-02-07 11:40:23',1,2) | interface | 192.168.1.56:51726 | interface_hd_com | Query | query end |
  13. | 1045614712 | RUNNING | 2017-02-07 11:29:21 | 63551 | INSERT INTO `sms_log` (`tel`,`content`,`c_time`,`source`,`status`) VALUES ('14761542203','短信验证码：0145','2017-02-07 11:40:43',1,2) | interface | 192.168.1.56:51763 | interface_hd_com | Query | query end |
  14. | 1045617441 | RUNNING | 2017-02-08 18:46:39 | 66695 | UPDATE `b_devices` SET `imei`='861322030576181',`key`='yjyH8MtSfSd6zx3c',`os_type`=1,`d_name`='',`c_ip`='124.192.156.166',`c_time`=1473663683,`u_time`=1486551484,`app_v`='34000' WHERE ( `did` = 343032 ) | interface | 192.168.1.56:42570 | interface_hd_com | Query | query end |
  15. | 1045618887 | RUNNING | 2017-02-09 10:38:27 | 68365 | UPDATE `b_devices` SET `imei`='869801024824741',`key`='8CXzJ2zUYEKzM1Zy',`os_type`=1,`d_name`='',`c_ip`='124.192.156.166',`c_time`=1477978901,`u_time`=1486608594,`app_v`='34000' WHERE ( `did` = 378254 ) | interface | 192.168.1.56:53342 | interface_hd_com | Query | query end |
  16. | 1045619290 | RUNNING | 2017-02-09 11:04:46 | 68636 | UPDATE `b_devices` SET `imei`='862265035973052',`key`='UlSphOuFL8M6MtzM',`os_type`=1,`d_name`='',`c_ip`='124.192.156.166',`c_time`=1481093099,`u_time`=1486610173,`app_v`='34000' WHERE ( `did` = 405110 ) | interface | 192.168.1.56:56140 | interface_hd_com | Query | query end |
  17. +------------+-----------+---------------------+-----------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+--------------------+------------------+---------+-----------+
  18. 12 rows in set (0.00 sec)
  19. trx_state事务状态是RUNNING，找不到堵塞的源头sql


思考：通过上面的观察发现以下几点：

1.undo是比较少的，buffer pool中的脏页不算多（Modified db pages  0，热数据交换都没有），排除innodb buffer内存不够的原因
2.好几条sql 事务处理时间过长，很明显是开启了事务但是未提交导致的！

解决方法：

  1. 让开发再排查代码，已经不太现实了，时间不等人，业务不等人，不能再增加用户的投诉量了，DBA首先要保证的是数据库别跑挂了，先恢复！

  3. 下面介绍给大家一个参数innodb_kill_idle_transaction，意思为当一个事务长时间未提交，那么这个连接就不能关闭，内存就不释放，并发一大，导致DB连接数增多，就会对性能产生影响。

  5. 默认是0秒，你可以根据自己的情况设定阈值。超过这个阈值，服务端自动杀死未提交的空闲事务。

  7. 下面的截图展示了这一过程：


      1. 从图中结果上可以看出，当未提交的事务超过空闲时间30秒时，被后台进程自动KILL掉，执行COMMIT提交后，连接被强行断开。



  10. 设置这个参数后只针对新的连接有效，正在执行的连接无效，固我们让运维又依次重启前端应用后，数据库终于复活成功！

  12. 注：官方MySQL5.5/5.6是没有这个参数的。


参考：
http://mp.weixin.qq.com/s/9v9Agf61vFdfB5JjDwJLfg   --一个参数救活被hang数据库
http://blog.itpub.net/29096438/viewspace-2129982   ---是谁吧DML搞慢的

请使用浏览器的分享功能分享到微信等