記一次Mysql線上事故之metadata鎖詳解

時間 2020-02-09

原文原文鏈接

背景

在項目的一次需求中，須要對一個表增長字段，然而在執行增長字段的sql語句時，卡住了好久都沒提交到Mysql完成，而此時對外接口服務請求也卡住了，這時中斷卡住的alter table 語句，服務慢慢恢復正常，若是不搞清楚這個問題的根源，不敢增長字段，由於會直接影響到服務mysql

排查

經過show processlist 查看到在alter table語句執行卡住過程當中，累計了大量狀態爲 Waiting for table metadata lock 的記錄算法

而後查看當前的事務狀態執行 select * from information_schema.innodb_trxGsql

mysql> select * from information_schema.innodb_trx\G
*************************** 1. row ***************************
                    trx_id: 421408771164000
                 trx_state: RUNNING
               trx_started: 2019-07-02 14:27:09
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 0
       trx_mysql_thread_id: 11688
    ....複製代碼

發現了其中一條已經運行了好久的事務，我懷疑跟這個運行好久的並且沒有提交的事務有關。flask

測試還原

在本地mysql開多個終端測試session

session 1：開啓事務，執行select 語句，但不提交事務app

mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t1;
+------+
| c1   |
+------+
|    1 |
+------+
1 row in set (0.00 sec)複製代碼

session 2：執行增長字段sql測試

mysql> alter table t1 add c2 int;

複製代碼

執行被阻塞了ui

mysql> show processlist;
+----+------+-----------+------+---------+------+---------------------------------+---------------------------+
| Id | User | Host      | db   | Command | Time | State                           | Info                      |
+----+------+-----------+------+---------+------+---------------------------------+---------------------------+
| 27 | root | localhost | test | Query   |  141 | Waiting for table metadata lock | alter table t1 add c2 int |
| 29 | root | localhost | test | Query   |    0 | starting                        | show processlist          |
| 30 | root | localhost | test | Sleep   |  210 |                                 | NULL                |
+----+------+-----------+------+---------+------+---------------------------------+---------------------------+複製代碼

能夠看到alter table語句的狀態爲Waiting for table metadata lockthis

session 3 ：再次查詢t1表spa

mysql> select * from t1;複製代碼

也被阻塞了

mysql> show processlist;
+----+------+-----------+------+---------+------+---------------------------------+---------------------------+
| Id | User | Host      | db   | Command | Time | State                           | Info                      |
+----+------+-----------+------+---------+------+---------------------------------+---------------------------+
| 27 | root | localhost | test | Query   |  141 | Waiting for table metadata lock | alter table t1 add c2 int |
| 28 | root | localhost | test | Query   |    8 | Waiting for table metadata lock | select * from t1          |
| 29 | root | localhost | test | Query   |    0 | starting                        | show processlist          |
| 30 | root | localhost | test | Sleep   |  210 |                                 | NULL                      |
+----+------+-----------+------+---------+------+---------------------------------+-------------------複製代碼

select * from t1 再次查詢t1表也是 Waiting for table metadata lock狀態，說明因爲 metadata lock的存在，會致使後面正常的查詢都會由於等待鎖而阻塞

再查看當前事務運行狀態：

mysql> select * from information_schema.innodb_trx\G
*************************** 1. row ***************************
               trx_id: 421408771166760
               trx_state: RUNNING
               trx_started: 2019-08-02 15:34:41
               trx_mysql_thread_id: 30複製代碼

能夠看到，session1的事務因爲還沒提交，因此這裏能看到它的狀態仍是running

這時咱們commit session1的事務，看看效果

session 1：

mysql> select * from t1;
+------+
| c1   |
+------+
|    1 |
+------+
1 row in set (0.00 sec)

mysql> commit;
Query OK, 0 rows affected (0.00 sec)複製代碼

session 2：

mysql> alter table t1 add c2 int;
Query OK, 0 rows affected (30.51 sec)
Records: 0  Duplicates: 0  Warnings: 0複製代碼

session 3：

mysql> select * from t1;
+------+
| c1   |
+------+
|    1 |
+------+
1 row in set (7.56 sec)複製代碼

能夠看到session1的事務提交後，session2 和session3 都正常執行了，他們完成的時間分別是30秒和7秒

項目 autocommit 的設置

經過上面的還原測試，能夠知道是因爲事務沒有提交而給表加了鎖，致使後面alter語句由於等待鎖而阻塞，從而影響後面的正常請求。那說明咱們的項目是默認開啓了事務嗎？繼續排查，項目是使用flask-sqlchemy的插件來管理mysql接入，而後查了下文檔在實例化sqlchemy的時候，會建立一個用於跟Mysql交互的session對象，看看源碼

# db是這樣使用的
db = SQLAlchemy()
db.__init__(app)
.... 

# 看看SQLAlchemy裏面的session是怎麼建立的
class SQLAlchemy(object):
    def __init__(self, app=None, use_native_unicode=True, session_options=None,
                 metadata=None, query_class=BaseQuery, model_class=Model,
                 engine_options=None):
        ...
        self.session = self.create_session(session_options)
        ... 

def create_session(self, options):
    ...
    return orm.sessionmaker(class_=SignallingSession, db=self, **options)

# session 使用到是SignallingSession 這個類 
class SignallingSession(SessionBase):
    ...
    def __init__(self, db, autocommit=False, autoflush=True, **options):
     ...複製代碼

從 SignallingSession類的定義看來，autocommit=False，說明默認都給全部的sql執行開啓事務，也就是說，哪怕是純select語句，不須要加鎖的select，咱們的項目默認也須要開啓事務，這對於Mysql MVCC的版本控制來講，是不必的。

解決辦法：就是在實例化SQLAlchemy的時候，給一個參數，修改的session的autocommit=True：

db = SQLAlchemy(session_options={"autocommit": True})
db.__init__(app)複製代碼

關於 table metadata lock

來自官網的介紹：

To ensure transaction serializability, the server must not permit one session to perform a data definition language (DDL) statement on a table that is used in an uncompleted explicitly or implicitly started transaction in another session. The server achieves this by acquiring metadata locks on tables used within a transaction and deferring release of those locks until the transaction ends.

意思就是爲了保證事務的串行執行，而啓用的一個鎖，這個鎖只會在事務結束的時候釋放，所以在事務提交或回滾錢，任何對這個表作的DDL操做，都是會阻塞的

If the server acquires metadata locks for a statement that is syntactically valid but fails during execution, it does not release the locks early. Lock release is still deferred to the end of the transaction because the failed statement is written to the binary log and the locks protect log consistency.

這個 Metadata lock 是MySQL在5.5.3版本後引入了，爲的是防止5.5.3之前的一個bug的出現：

當一個會話在主庫執行DML操做還沒提交時，另外一個會話對同一個對象執行了DDL操做如drop table，而因爲MySQL的binlog是基於事務提交的前後順序進行記錄的，所以在從庫上應用時，就出現Q了先drop table，而後再向table中insert的狀況，致使從庫應用出錯。