MySQL数据库故障分析-锁等待(一)

IT小Chen 2022-06-13

779

环境说明：

MySQL:5.7.34 双主
OS:Redhat 7.5

问题现象：

XXX应用登录，提示数据库连接失败。

问题原因：

有一张权限表，同时执行了delete和truncate操作，并且长时间没有提交，导致metadata lock无法释放，应用登录时无法正常读取权限表，导致应用无法登录。
初步怀疑应用在执行delete操作时开启了事务，并且没有及时提交，导致锁无法释放。

解决方案：

和应用相关同事沟通，终止相关会话后，恢复正常。

问题重现：

1.开启锁监控。

MySQL [cjc]> select * from performance_schema.setup_instruments where name like '%lock%' limit 20;
+---------------------------------------------------------+---------+-------+
| NAME                                                    | ENABLED | TIMED |
+---------------------------------------------------------+---------+-------+
| wait/synch/mutex/sql/TC_LOG_MMAP::LOCK_tc               | NO      | NO    |
| wait/synch/mutex/sql/LOCK_des_key_file                  | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_commit         | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_commit_queue   | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_done           | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_flush_queue    | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_index          | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_log            | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_binlog_end_pos | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_sync           | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_sync_queue     | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_xids           | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_commit       | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_commit_queue | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_done         | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_flush_queue  | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_index        | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_log          | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_sync         | NO      | NO    |
| wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_sync_queue   | NO      | NO    |
+---------------------------------------------------------+---------+-------+
20 rows in set (0.00 sec)

开启监控

MySQL [cjc]> update performance_schema.setup_instruments set enabled = 'YES' where  name like '%lock%';
Query OK, 173 rows affected (0.00 sec)
Rows matched: 180  Changed: 173  Warnings: 0

2.关闭自动提交

注意：关闭自动提交的用户权限需要小于启动mysql的用户权限，否则关闭自动提交不生效，而且没有任何提示。

MySQL [cjc]> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)


MySQL [cjc]> show variables like 'autocommit';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| autocommit    | OFF   |
+---------------+-------+
1 row in set (0.00 sec)

3.会话1，删除表，不提交。

delete from t2;

4.会话2，可以正常查询表数据。

MySQL [cjc]> select * from t2;
+------+------+
| id   | age  |
+------+------+
|    1 |  100 |
|    2 |   30 |
|    3 |   80 |
+------+------+
3 rows in set (0.01 sec)

5.会话3，执行truncate操作，被阻塞

truncate table t2;

卡住

6.会话2，仍然可以查询表数据。

MySQL [cjc]> select * from t2;
+------+------+
| id   | age  |
+------+------+
|    1 |  100 |
|    2 |   30 |
|    3 |   80 |
+------+------+
3 rows in set (0.01 sec)

7.打开另一个新的会话4，无法查询数据，被阻塞

MySQL [cjc]> select * from t2;

卡住

8.打开会话5，执行数据库备份，被阻塞。

执行备份

[mysql@mysql01 backup]$ mysqldump -uroot -p cjc  > /home/mysql/backup/cjc.sql

卡住

9.打开会话6，查询会话信息id 16,31,33都被阻塞

MySQL [(none)]> select id,host,user,command,time,state,info from information_schema.processlist where command !='sleep';
+----+-----------+------+---------+------+---------------------------------+---------------------------------------------------------------------------------------------------------+
| id | host      | user | command | time | state                           | info                                                                                                    |
+----+-----------+------+---------+------+---------------------------------+---------------------------------------------------------------------------------------------------------+
| 34 | localhost | root | Query   |    0 | executing                       | select id,host,user,command,time,state,info from information_schema.processlist where command !='sleep' |
| 31 | localhost | cjc  | Query   |  253 | Waiting for table metadata lock | select * from t2                                                                                        |
| 16 | localhost | cjc  | Query   |  269 | Waiting for table metadata lock | truncate table t2                                                                                       |
| 33 | localhost | root | Query   |  171 | Waiting for table metadata lock | LOCK TABLES `t1` READ *!32311 LOCAL */,`t2` READ *!32311 LOCAL */                                     |
+----+-----------+------+---------+------+---------------------------------+---------------------------------------------------------------------------------------------------------+
4 rows in set (0.00 sec)

10.查看锁阻塞源头

MySQL [(none)]> select * from performance_schema.metadata_locks where OWNER_THREAD_ID !=sys.ps_thread_id(connection_id())\G;
*************************** 1. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: cjc
          OBJECT_NAME: t2
OBJECT_INSTANCE_BEGIN: 139671541629072
            LOCK_TYPE: SHARED_WRITE
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: GRANTED
               SOURCE: 
      OWNER_THREAD_ID: 37
       OWNER_EVENT_ID: 36
*************************** 2. row ***************************
          OBJECT_TYPE: GLOBAL
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 139671933907680
            LOCK_TYPE: INTENTION_EXCLUSIVE
        LOCK_DURATION: STATEMENT
          LOCK_STATUS: GRANTED
               SOURCE: 
      OWNER_THREAD_ID: 41
       OWNER_EVENT_ID: 26
*************************** 3. row ***************************
          OBJECT_TYPE: SCHEMA
        OBJECT_SCHEMA: cjc
          OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 139671933882208
            LOCK_TYPE: INTENTION_EXCLUSIVE
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: GRANTED
               SOURCE: 
      OWNER_THREAD_ID: 41
       OWNER_EVENT_ID: 26
*************************** 4. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: cjc
          OBJECT_NAME: t2
OBJECT_INSTANCE_BEGIN: 139671933942976
            LOCK_TYPE: EXCLUSIVE
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: PENDING
               SOURCE: 
      OWNER_THREAD_ID: 41
       OWNER_EVENT_ID: 26
*************************** 5. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: cjc
          OBJECT_NAME: t2
OBJECT_INSTANCE_BEGIN: 139671799800656
            LOCK_TYPE: SHARED_READ
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: PENDING
               SOURCE: 
      OWNER_THREAD_ID: 56
       OWNER_EVENT_ID: 9
*************************** 6. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: cjc
          OBJECT_NAME: t1
OBJECT_INSTANCE_BEGIN: 139672135191008
            LOCK_TYPE: SHARED_READ
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: GRANTED
               SOURCE: 
      OWNER_THREAD_ID: 58
       OWNER_EVENT_ID: 10
*************************** 7. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: cjc
          OBJECT_NAME: t2
OBJECT_INSTANCE_BEGIN: 139672135191104
            LOCK_TYPE: SHARED_READ
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: PENDING
               SOURCE: 
      OWNER_THREAD_ID: 58
       OWNER_EVENT_ID: 10
7 rows in set (0.10 sec)


ERROR: No query specified

MySQL [(none)]> select THREAD_ID,PROCESSLIST_ID,name,type from  performance_schema.threads where PROCESSLIST_ID is not NULL;
+-----------+----------------+--------------------------------+------------+
| THREAD_ID | PROCESSLIST_ID | name                           | type       |
+-----------+----------------+--------------------------------+------------+
|        28 |              3 | thread/sql/compress_gtid_table | FOREGROUND |
|        37 |             12 | thread/sql/one_connection      | FOREGROUND |
|        41 |             16 | thread/sql/one_connection      | FOREGROUND |
|        56 |             31 | thread/sql/one_connection      | FOREGROUND |
|        57 |             32 | thread/sql/one_connection      | FOREGROUND |
|        58 |             33 | thread/sql/one_connection      | FOREGROUND |
|        59 |             34 | thread/sql/one_connection      | FOREGROUND |
+-----------+----------------+--------------------------------+------------+
7 rows in set (0.00 sec

可以看到阻塞源头是THREAD_ID=37 PROCESSLIST_ID=12

|        37 |             12 | thread/sql/one_connection      | FOREGROUND |


select * from performance_schema.events_statements_current where thread_id=37\G;

查看最后一次执行的命令

MySQL [(none)]> select * from performance_schema.events_statements_current where thread_id=37\G;
*************************** 1. row ***************************
              THREAD_ID: 37
               EVENT_ID: 35
           END_EVENT_ID: 35
             EVENT_NAME: statement/sql/delete
                 SOURCE: 
            TIMER_START: 6409813713486000
              TIMER_END: 6409813929865000
             TIMER_WAIT: 216379000
              LOCK_TIME: 64000000
               SQL_TEXT: delete from t2
                 DIGEST: 3ba93c5fbd4c5721001bc1856c74459a
            DIGEST_TEXT: DELETE FROM `t2` 
         CURRENT_SCHEMA: cjc
            OBJECT_TYPE: NULL
          OBJECT_SCHEMA: NULL
            OBJECT_NAME: NULL
  OBJECT_INSTANCE_BEGIN: NULL
            MYSQL_ERRNO: 0
      RETURNED_SQLSTATE: 00000
           MESSAGE_TEXT: NULL
                 ERRORS: 0
               WARNINGS: 0
          ROWS_AFFECTED: 3
              ROWS_SENT: 0
          ROWS_EXAMINED: 3
CREATED_TMP_DISK_TABLES: 0
     CREATED_TMP_TABLES: 0
       SELECT_FULL_JOIN: 0
 SELECT_FULL_RANGE_JOIN: 0
           SELECT_RANGE: 0
     SELECT_RANGE_CHECK: 0
            SELECT_SCAN: 0
      SORT_MERGE_PASSES: 0
             SORT_RANGE: 0
              SORT_ROWS: 0
              SORT_SCAN: 0
          NO_INDEX_USED: 0
     NO_GOOD_INDEX_USED: 0
       NESTING_EVENT_ID: NULL
     NESTING_EVENT_TYPE: NULL
    NESTING_EVENT_LEVEL: 0
1 row in set (0.00 sec)


ERROR: No query specified

在刚刚执行delete操作的窗口查询，确实是12。

MySQL [cjc]> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
|              12 |
+-----------------+
1 row in set (0.00 sec)

11.终止12会话

MySQL [(none)]> kill 12;
Query OK, 0 rows affected (0.00 sec)

12.验证

查询t2数据已经被清空

MySQL [(none)]> select * from cjc.t2;
Empty set (0.00 sec)

锁已释放

MySQL [(none)]> select id,host,user,command,time,state,info from information_schema.processlist where command !='sleep' and  user !='root';

###chenjuchao 20220612###

文章转载自IT小Chen，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

MySQL数据库故障分析-锁等待(一)

评论