1.版本

1)作業系統

 cat /etc/issue cat /etc/issue CentOS release 6.6 (Final) Kernel \r on an \m

 cat /proc/version cat /proc/version Linux version 2.6.32-504.el6.x86_64 ([email protected]) (gcc version 4.4.7 20120313 (Red Hat 4.4.7-11) (GCC) ) #1 SMP Wed Oct 15 04:27:16 UTC 2014

2)mysql資料庫版本

MySQL --version

MySQL

2.問題描述

   一個朋友讓我幫忙分析一個問題，他先執行了一個online ddl，如 alter table test engine=innodb(mysql 5.6引入online ddl)。然後在另一個session中開啟了一個事物，在事物中對test表執行了dml操作，但是不提交也不回滾。最後他發現先執行的ddl操作，被後面執行的dml操作阻塞。

1)先在我的測試環境還原一下這個問題

按時間順序，執行如下操作：

1. session1

2. alter table tb_battle_member_bak1 engine=innodb;

3. session2

4. mysql> begin;

5. Query OK, 0 rows affected (0.00 sec)

6. mysql> delete from tb_battle_member_bak1 where BattleID='CX201605240076';

7. Query OK, 1 row affected (0.01 sec)

2)在session3 觀察session1和session2操作情況

1. mysql> show processlist;

2. +-----+------+----------------------+-------+-------------+---------+-----------------------------------------------------------------------+-------------------------------------------------+

3. | Id | User | Host | db | Command | Time | State | Info |

4. +-----+------+----------------------+-------+-------------+---------+-----------------------------------------------------------------------+-------------------------------------------------+

5. | 2 | repl | 172.172.178.76:45429 | NULL | Binlog Dump | 2518274 | Master has sent all binlog to slave; waiting for binlog to be updated | NULL |

6. | 202 | repl | 172.172.178.77:46833 | NULL | Binlog Dump | 1552398 | Master has sent all binlog to slave; waiting for binlog to be updated | NULL |

7. | 271 | root | 127.0.0.1:22201 | test5 | Query | 177 | altering table | alter table tb_battle_member_bak1 engine=innodb |

8. | 272 | root | 127.0.0.1:22202 | test5 | Sleep | 161 | | NULL |

9. | 273 | root | 127.0.0.1:22204 | NULL | Query | 0 | init | show processlist |

10. +-----+------+----------------------+-------+-------------+---------+-----------------------------------------------------------------------+-------------------------------------------------+

11. 5 rows in set (0.00 sec)

12. mysql> show processlist;

13. +-----+------+----------------------+-------+-------------+---------+-----------------------------------------------------------------------+-------------------------------------------------+

14. | Id | User | Host | db | Command | Time | State | Info |

15. +-----+------+----------------------+-------+-------------+---------+-----------------------------------------------------------------------+-------------------------------------------------+

16. | 2 | repl | 172.172.178.76:45429 | NULL | Binlog Dump | 2518275 | Master has sent all binlog to slave; waiting for binlog to be updated | NULL |

17. | 202 | repl | 172.172.178.77:46833 | NULL | Binlog Dump | 1552399 | Master has sent all binlog to slave; waiting for binlog to be updated | NULL |

18. | 271 | root | 127.0.0.1:22201 | test5 | Query | 178 | Waiting for table metadata lock | alter table tb_battle_member_bak1 engine=innodb |

19. | 272 | root | 127.0.0.1:22202 | test5 | Sleep | 162 | | NULL |

20. | 273 | root | 127.0.0.1:22204 | NULL | Query | 0 | init | show processlist |

21. +-----+------+----------------------+-------+-------------+---------+-----------------------------------------------------------------------+-------------------------------------------------+

22. 5 rows in set (0.00 sec)

NOTE:我們發現session1的online ddl在altering table這一步花了大概177秒，然後在轉入下一步(committing alter table to stor)的時候，發生等待，我們看到的等待資訊是Waiting for table metadata lock。

1. session1 profile:

2. mysql> show profiles;

3. +----------+--------------+----------------------------------------------------------------------+

4. | Query_ID | Duration | Query |

5. +----------+--------------+----------------------------------------------------------------------+

6. | 1 | 0.00120700 | select @@version_comment limit 1 |

7. | 2 | 0.00086900 | show slave hosts |

8. | 3 | 0.00203125 | show databases |

9. | 4 | 0.00065800 | SELECT DATABASE() |

10. | 5 | 0.00088225 | show tables |

11. | 6 | 0.00026350 | SELECT DATABASE() |

12. | 7 | 0.00087025 | show tables |

13. | 8 | 4.55985575 | select count(1) from tb_battle_member_bak1 |

14. | 9 | 0.42077325 | truncate table tb_battle_member_bak1 |

15. | 10 | 260.97370150 | insert into tb_battle_member_bak1 select * from tb_battle_member_bak |

16. | 11 | 205.00446375 | alter table tb_battle_member_bak1 engine=innodb |

17. +----------+--------------+----------------------------------------------------------------------+

18. 11 rows in set, 1 warning (0.00 sec)

19. mysql> show profile for query 11;

20. +--------------------------------+------------+

21. | Status | Duration |

22. +--------------------------------+------------+

23. | starting | 0.000383 |

24. | checking permissions | 0.000011 |

25. | checking permissions | 0.000036 |

26. | init | 0.000007 |

27. | Opening tables | 0.000133 |

28. | setup | 0.000242 |

29. | creating table | 0.054524 |

30. | After create | 0.000493 |

31. | System lock | 0.000019 |

32. | preparing for alter table | 0.073421 |

33. | altering table | 177.612401 |

34. | Waiting for table metadata loc | 1.000169 | >>因為session2 中關於該表的事物未提交，所以產生metadata等待

35. | altering table | 0.000018 | >>因鎖等待無法執行committing alter...，再次轉到altering table(因為執行已經執行完，此時執行時間很短)

36. | Waiting for table metadata loc | 1.000157 |

37. | altering table | 0.000023 |

38. | Waiting for table metadata loc | 1.000120 |

39. | altering table | 0.000019 |

40. ...........................

41. ...........................

42. ...........................

43. | Waiting for table metadata loc | 0.042325 |

44. | altering table | 0.000098 |

45. | committing alter table to stor | 1.205005 | >>此時session2中事物已提交，altering table後順利轉到下一步

46. | end | 0.000029 |

47. | query end | 0.010155 |

48. | closing tables | 0.000050 |

49. | freeing items | 0.000182 |

50. | logging slow query | 0.000142 |

51. | cleaning up | 0.000028 |

52. +--------------------------------+------------+

53. 72 rows in set, 1 warning (0.00 sec)

3. 問題分析，解決

  從上面的分析我們可以看出來，online ddl執行到committing alter table to stor這一步的時候需要獲取表的metadata lock(online ddl中最耗時的altering table這一步不需要獲取metadata鎖，不會阻塞dml)。而這時session2 對該表的dml並未提交(佔用該表的metadata 鎖)，所以session1中的online ddl被session2 中的dml阻塞。

   居然知道了原因，那麼修改應用，解決問題就簡單了。