快速定位加锁 SQL

首先我们创建一个测试表：

mysql> create table t1(id decimal,v_name varchar(10));
mysql> insert into t1 values(1,'a'),(2,'b'),(3,'c');
mysql> select * from t1;
+------+--------+
| id   | v_name |
+------+--------+
|    1 | a      |
|    2 | b      |
|    3 | c      |
+------+--------+
3 rows in set (0.00 sec)

在会话 1 中开启事务，更新 id=1 的数据：

mysql> begin;
mysql> update t1 set v_name='aa' where id=1;

在会话 2 中开启另一个事务，删除 id=1 的数据：

mysql> begin;
mysql> delete from t1 where id=1;

此时会话 2 被锁定，出现锁等待。

我们再开一个会话 3，查查当前的 processlist，看看是否能发现什么？

mysql> show processlist;
+----+------+-----------+------+---------+------+----------+---------------------------+
| Id | User | Host      | db   | Command | Time | State    | Info                      |
+----+------+-----------+------+---------+------+----------+---------------------------+
| 38 | root | localhost | test | Sleep   |    5 |          | NULL                      |
| 41 | root | localhost | test | Query   |    2 | updating | delete from t1 where id=1 |
| 42 | root | localhost | NULL | Query   |    0 | starting | show processlist          |
+----+------+-----------+------+---------+------+----------+---------------------------+

可以看到 delete 这个 SQL 的进程在执行中，并没有发现其他有价值的内容，那锁在哪里了。接下来我们就一步步的定位出加锁的 SQL。

1）定位锁等待

mysql> select * from information_schema.innodb_lock_waits;
+-------------------+-------------------+-----------------+------------------+
| requesting_trx_id | requested_lock_id | blocking_trx_id | blocking_lock_id |
+-------------------+-------------------+-----------------+------------------+
| 2207              | 2207:28:3:7       | 2206            | 2206:28:3:7      |
+-------------------+-------------------+-----------------+------------------+
1 row in set, 1 warning (0.00 sec)

结果显示有一个锁等待。

2）定位锁

mysql> select * from information_schema.innodb_locks;
+-------------+-------------+-----------+-----------+-------------+-----------------+------------+-----------+----------+----------------+
| lock_id     | lock_trx_id | lock_mode | lock_type | lock_table  | lock_index      | lock_space | lock_page | lock_rec | lock_data      |
+-------------+-------------+-----------+-----------+-------------+-----------------+------------+-----------+----------+----------------+
| 2207:28:3:7 | 2207        | X         | RECORD    | `test`.`t1` | GEN_CLUST_INDEX |         28 |         3 |        7 | 0x000000000211 |
| 2206:28:3:7 | 2206        | X         | RECORD    | `test`.`t1` | GEN_CLUST_INDEX |         28 |         3 |        7 | 0x000000000211 |
+-------------+-------------+-----------+-----------+-------------+-----------------+------------+-----------+----------+----------------+
2 rows in set, 1 warning (0.00 sec)

结果显示有两个锁相关内容。

3）定位事务

mysql> select trx_id,trx_started,trx_requested_lock_id,trx_query,trx_mysql_thread_id from information_schema.innodb_trx;
+--------+---------------------+-----------------------+---------------------------+---------------------+
| trx_id | trx_started         | trx_requested_lock_id | trx_query                 | trx_mysql_thread_id |
+--------+---------------------+-----------------------+---------------------------+---------------------+
| 2207   | 2021-01-18 15:18:11 | 2207:28:3:7           | delete from t1 where id=1 |                  41 |
| 2206   | 2021-01-18 15:18:08 | NULL                  | NULL                      |                  38 |
+--------+---------------------+-----------------------+---------------------------+---------------------+
2 rows in set (0.01 sec)

结果有两个事务，MySQL 事务线程 id 为 38 和 41，很直观的看到 41 是我们的 delete 事务，被 38 锁定。

4）定位线程

mysql> select * from performance_schema.threads where processlist_id=38;
+-----------+---------------------------+------------+----------------+------------------+------------------+----------------+---------------------+------------------+-------------------+------------------+------------------+------+--------------+---------+-----------------+--------------+
| THREAD_ID | NAME                      | TYPE       | PROCESSLIST_ID | PROCESSLIST_USER | PROCESSLIST_HOST | PROCESSLIST_DB | PROCESSLIST_COMMAND | PROCESSLIST_TIME | PROCESSLIST_STATE | PROCESSLIST_INFO | PARENT_THREAD_ID | ROLE | INSTRUMENTED | HISTORY | CONNECTION_TYPE | THREAD_OS_ID |
+-----------+---------------------------+------------+----------------+------------------+------------------+----------------+---------------------+------------------+-------------------+------------------+------------------+------+--------------+---------+-----------------+--------------+
|        63 | thread/sql/one_connection | FOREGROUND |             38 | root             | localhost        | test           | Sleep               |               35 | NULL              | NULL             |             NULL | NULL | YES          | YES     | Socket          |        15070 |
+-----------+---------------------------+------------+----------------+------------------+------------------+----------------+---------------------+------------------+-------------------+------------------+------------------+------+--------------+---------+-----------------+--------------+
1 row in set (0.00 sec)

结果找到 MySQL 事务线程 38 对应的服务器线程 63。

5）定位加锁 SQL

mysql> select * from performance_schema.events_statements_current where thread_id=63;
+-----------+----------+--------------+----------------------+--------------------------+---------------------+---------------------+------------+-----------+--------------------------------------+----------------------------------+----------------------------------------------+----------------+-------------+---------------+-------------+-----------------------+-------------+-------------------+------------------------------------------+--------+----------+---------------+-----------+---------------+-------------------------+--------------------+------------------+------------------------+--------------+--------------------+-------------+-------------------+------------+-----------+-----------+---------------+--------------------+------------------+--------------------+---------------------+
| THREAD_ID | EVENT_ID | END_EVENT_ID | EVENT_NAME           | SOURCE                   | TIMER_START         | TIMER_END           | TIMER_WAIT | LOCK_TIME | SQL_TEXT                             | DIGEST                           | DIGEST_TEXT                                  | CURRENT_SCHEMA | OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | OBJECT_INSTANCE_BEGIN | MYSQL_ERRNO | RETURNED_SQLSTATE | MESSAGE_TEXT                             | ERRORS | WARNINGS | ROWS_AFFECTED | ROWS_SENT | ROWS_EXAMINED | CREATED_TMP_DISK_TABLES | CREATED_TMP_TABLES | SELECT_FULL_JOIN | SELECT_FULL_RANGE_JOIN | SELECT_RANGE | SELECT_RANGE_CHECK | SELECT_SCAN | SORT_MERGE_PASSES | SORT_RANGE | SORT_ROWS | SORT_SCAN | NO_INDEX_USED | NO_GOOD_INDEX_USED | NESTING_EVENT_ID | NESTING_EVENT_TYPE | NESTING_EVENT_LEVEL |
+-----------+----------+--------------+----------------------+--------------------------+---------------------+---------------------+------------+-----------+--------------------------------------+----------------------------------+----------------------------------------------+----------------+-------------+---------------+-------------+-----------------------+-------------+-------------------+------------------------------------------+--------+----------+---------------+-----------+---------------+-------------------------+--------------------+------------------+------------------------+--------------+--------------------+-------------+-------------------+------------+-----------+-----------+---------------+--------------------+------------------+--------------------+---------------------+
|        63 |       32 |           32 | statement/sql/update | socket_connection.cc:101 | 2757904906303653000 | 2757904906543381000 |  239728000 | 145000000 | update t1 set v_name='aa' where id=1 | 356a053ffb5eae2a35981b05090faa01 | UPDATE `t1` SET `v_name` = ? WHERE `id` = ?  | test           | NULL        | NULL          | NULL        |                  NULL |           0 | 00000             | Rows matched: 1  Changed: 0  Warnings: 0 |      0 |        0 |             0 |         0 |             3 |                       0 |                  0 |                0 |                      0 |            0 |                  0 |           0 |                 0 |          0 |         0 |         0 |             0 |                  0 |             NULL | NULL               |                   0 |
+-----------+----------+--------------+----------------------+--------------------------+---------------------+---------------------+------------+-----------+--------------------------------------+----------------------------------+----------------------------------------------+----------------+-------------+---------------+-------------+-----------------------+-------------+-------------------+------------------------------------------+--------+----------+---------------+-----------+---------------+-------------------------+--------------------+------------------+------------------------+--------------+--------------------+-------------+-------------------+------------+-----------+-----------+---------------+--------------------+------------------+--------------------+---------------------+
1 row in set (0.00 sec)

在结果中我们找到了加锁的 update 的 SQL 语句。

ALTER TALBE 进度监控

当我们对一张大表执行了一个 ALTER TABLE 操作，执行了很久也不知道是否执行完成。对于这种情况，我们可以通过 MySQL 提供的数据字典进行任务监控。MySQL 在 5.7 版本开始，对数据字典的使用有了很大的改进，使用上更加的方便，提供的能力也更高。performance_schema 可以查询事务信息、获取元数据锁、跟踪事件、统计内存使用情况等等。

想要使用这个能力，我们需要开启几个功能：

Enable the stage/innodb/alter% instruments

mysql> UPDATE performance_schema.setup_instruments
    ->        SET ENABLED = 'YES'
    ->        WHERE NAME LIKE 'stage/innodb/alter%';
Query OK, 0 rows affected (0.01 sec)
Rows matched: 7  Changed: 0  Warnings: 0

Enable the stage event consumer tables

mysql> UPDATE performance_schema.setup_consumers
    ->        SET ENABLED = 'YES'
    ->        WHERE NAME ='events_stages_current';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0
mysql> UPDATE performance_schema.setup_consumers
    ->        SET ENABLED = 'YES'
    ->        WHERE NAME ='events_stages_history';
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0
mysql> UPDATE performance_schema.setup_consumers
    ->        SET ENABLED = 'YES'
    ->        WHERE NAME ='events_stages_history_long';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

功能开启后，当我们对一张大表执行 ALTER TABLE 操作后，可以执行如下监控 SQL 语句：

mysql> select * from performance_schema.events_stages_current\G;
*************************** 1. row ***************************
         THREAD_ID: 28
          EVENT_ID: 14
      END_EVENT_ID: NULL
        EVENT_NAME: stage/innodb/alter table (read PK and internal sort)
            SOURCE: 
       TIMER_START: 159726265417733000
         TIMER_END: 159819571346680000
        TIMER_WAIT: 93305928947000
    WORK_COMPLETED: 118256
    WORK_ESTIMATED: 302958
  NESTING_EVENT_ID: 13
NESTING_EVENT_TYPE: STATEMENT
1 row in set (0.00 sec)
......
mysql> select * from performance_schema.events_stages_current\G;
*************************** 1. row ***************************
         THREAD_ID: 28
          EVENT_ID: 14
      END_EVENT_ID: NULL
        EVENT_NAME: stage/innodb/alter table (read PK and internal sort)
            SOURCE: 
       TIMER_START: 159726265417733000
         TIMER_END: 159910492100061000
        TIMER_WAIT: 184226682328000
    WORK_COMPLETED: 230688
    WORK_ESTIMATED: 302958
  NESTING_EVENT_ID: 13
NESTING_EVENT_TYPE: STATEMENT
1 row in set (0.01 sec)

多执行几次，可以发现数据是有变化的，这些内容代表了什么呢？

THREAD_ID：线程 ID
EVENT_ID：事件 ID
END_EVENT_ID：结束事件 ID
EVENT_NAME：事件名称，说明了当前执行的事件
SOURCE：源码位置
TIMER_START：事件开始时间（皮秒）
TIMER_END：事件结束时间（皮秒，如果没有执行完成，时间就是当前之间）
TIMER_WAIT：事件等待事件（皮秒）
WORK_COMPLETED：任务完成情况
WORK_ESTIMATED：任务估算情况
NESTING_EVENT_ID：事件对应的父事件 ID
NESTING_EVENT_TYPE：父事件类型（STATEMENT、STAGE、WAIT）

总结一下，如果我们想查看事件任务完成情况：

mysql> SELECT pt.INFO, ec.THREAD_ID, ec.EVENT_NAME, ec.WORK_COMPLETED, ec.WORK_ESTIMATED, pt.STATE FROM performance_schema.events_stages_current ec left join performance_schema.threads th on ec.thread_id = th.thread_id left join information_schema.PROCESSLIST pt on th.PROCESSLIST_ID = pt.ID where pt.INFO like 'ALTER%';
+-------------------------------------------+-----------+------------------------------------------------------+----------------+----------------+----------------+
| INFO                                      | THREAD_ID | EVENT_NAME                                           | WORK_COMPLETED | WORK_ESTIMATED | STATE          |
+-------------------------------------------+-----------+------------------------------------------------------+----------------+----------------+----------------+
| alter table sbtest.sbtest1 add d char(20) |        28 | stage/innodb/alter table (read PK and internal sort) |         201496 |         308223 | altering table |
+-------------------------------------------+-----------+------------------------------------------------------+----------------+----------------+----------------+
1 row in set (0.25 sec)

如果我们想查看任务完成事件：

mysql> select stmt.sql_text as sql_text, concat(work_completed, '/' , work_estimated) as progress, (stage.timer_end - stmt.timer_start) / 1e12 as current_seconds, (stage.timer_end - stmt.timer_start) / 1e12 * (work_estimated-work_completed) / work_completed as remaining_seconds from performance_schema.events_stages_current stage, performance_schema.events_statements_current stmt where stage.thread_id = stmt.thread_id and stage.nesting_event_id = stmt.event_id;
+-------------------------------------------+---------------+-----------------+--------------------+
| sql_text                                  | progress      | current_seconds | remaining_seconds  |
+-------------------------------------------+---------------+-----------------+--------------------+
| alter table sbtest.sbtest1 add d char(20) | 135192/308223 |   102.461512532 | 131.13954949201502 |
+-------------------------------------------+---------------+-----------------+--------------------+
1 row in set (0.00 sec)

这样我们通过 MySQL 的数据字典就可以很直观地看到 ALTER TABLE 的执行情况了。

大事务监控

在 MySQL 中提供了 PERFORMANCE_SCHEMA.events_statements_history 这个视图。这个视图里记录了最近运行的 SQL 语句，于是就有了下面的排查 SQL 语句：

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
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 |
+------------+------+-----------+----------+---------------------+------------------------------+-------------------------------------------+------+
|        530 | root | localhost |        7 | 2020-09-01 02:52:01 | statement/com/Init DB        | NULL                                      |  196 |
|        530 | root | localhost |        8 | 2020-09-01 02:52:01 | statement/sql/show_databases | show databases                            |  196 |
|        530 | root | localhost |        9 | 2020-09-01 02:52:01 | statement/sql/show_tables    | show tables                               |  196 |
|        530 | root | localhost |       10 | 2020-09-01 02:52:01 | statement/com/Field List     | NULL                                      |  196 |
|        530 | root | localhost |       11 | 2020-09-01 02:52:01 | statement/sql/show_tables    | show tables                               |  196 |
|        530 | root | localhost |       12 | 2020-09-01 02:52:01 | statement/sql/select         | select * from t_test                      |  196 |
|        530 | root | localhost |       13 | 2020-09-01 02:52:01 | statement/sql/begin          | begin                                     |  196 |
|        530 | root | localhost |       14 | 2020-09-01 02:52:01 | statement/sql/update         | update t_test set paymont=100 where id=99 |  196 |
|        530 | root | localhost |       15 | 2020-09-01 02:52:01 | statement/sql/select         | select * from t_test where id=98          |  196 |
|        530 | root | localhost |       16 | 2020-09-01 02:52:01 | statement/sql/update         | update t_test set paymont=101 where id=97 |  196 |
+------------+------+-----------+----------+---------------------+------------------------------+-------------------------------------------+------+
10 rows in set (0.34 sec)

慢查询监控

MySQL 的慢查询日志是 MySQL 提供的一种日志记录，它用来记录在 MySQL 中响应时间超过阈值的语句，具体指运行时间超过 long_query_time 值的 SQL，则会被记录到慢查询日志中。long_query_time 的默认值为 10，表示运行 10S 以上的语句。默认情况下，MySQL 数据库并不启动慢查询日志，需要我们手动来设置这个参数，当然，如果不是调优需要的话，一般不建议启动该参数，因为开启慢查询日志会或多或少带来一定的性能影响。慢查询日志支持将日志记录写入文件，也支持将日志记录写入数据库表。

慢查询相关参数：

slow_query_log：是否开启慢查询日志，值为 1 表示开启，0 表示关闭，默认是关闭的。

long_query_time：慢查询阈值，当查询时间大于设定的阈值时，记录慢查询日志，默认为 10 秒。精读可以配置到微秒级。

log_queries_not_using_indexes：是否将未使用索引的查询也被记录到慢查询日志中。

log_output：日志存储方式，值为 FILE 表示将日志存入文件（默认），值为 TABLE 表示将日志存入数据库，此时日志信息会被写入到 mysql.slow_log 表。MySQL 支持同时配置两种存储方式，配置时以逗号隔开。

在生产环境中，如果要手工分析慢查询日志，查找、分析 SQL，显然是个体力活，为此，MySQL 提供了慢查询日志分析工具 mysqldumpslow。查看 mysqldumpslow 的帮助信息：

[root@DB-Server ~]# mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]
Parse and summarize the MySQL slow query log. Options are
  --verbose    verbose
  --debug      debug
  --help       write this text to standard output
  -v           verbose
  -d           debug
  -s ORDER     what to sort by (al, at, ar, c, l, r, t), 'at' is default
                al: average lock time
                ar: average rows sent
                at: average query time
                 c: count
                 l: lock time
                 r: rows sent
                 t: query time  
  -r           reverse the sort order (largest last instead of first)
  -t NUM       just show the top n queries
  -a           don't abstract all numbers to N and strings to 'S'
  -n NUM       abstract numbers with at least n digits within names
  -g PATTERN   grep: only consider stmts that include this string
  -h HOSTNAME  hostname of db server for *-slow.log filename (can be wildcard),
               default is '*', i.e. match all
  -i NAME      name of server instance (if using mysql.server startup script)
  -l           don't subtract lock time from total time

其中的参数含义如下：

s：表示按照何种方式排序 c：访问计数 l：锁定时间 r：返回记录 t：查询时间 al：平均锁定时间 a：平均返回记录数 at：平均查询时间 t：是 top n 的意思，即为返回前面多少条的数据 g：后边可以写一个正则匹配模式，大小写不敏感的

比如，想要得到返回记录集最多的 10 个 SQL：

mysqldumpslow -s r -t 10 /usr/local/mysql/mysql06_slow.log

得到访问次数最多的 10 个 SQL：

mysqldumpslow -s c -t 10 /usr/local/mysql/mysql06_slow.log

中间件

MySQL 故障诊断

快速定位加锁 SQL

ALTER TALBE 进度监控

大事务监控

慢查询监控