MySQL慢查询日志分析
上一节中，有对MySQL的日志类型做过简单介绍。这节就它的慢查询日志文件怎么分析来做个笔记。
1、首先，慢查询是默认关闭的，先打开：
mysql> show variables like 'slow_query_log';
+----------------+-------+
| Variable_name | Value |
+----------------+-------+
| slow_query_log | OFF |
+----------------+-------+
1 row in set (0.00 sec)
mysql> set global slow_query_log = on;
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like 'slow_query_log';
+----------------+-------+
| Variable_name | Value |
+----------------+-------+
| slow_query_log | ON |
+----------------+-------+
1 row in set (0.00 sec)
2、然后，慢查询有个非常重要的参数，时间阈值long_query_time，表示SQL语句的运行时间超过该值将记录到慢查询日志中。
mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)
mysql>
mysql> set global long_query_time = 1;
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)
mysql> set long_query_time = 1;
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like 'long_query_time';
+-----------------+----------+
| Variable_name | Value |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
1 row in set (0.00 sec)
mysql>
从上可以看出，默认值10秒，设置时必须设置当前会话的，这里改为1秒，也可以精确到微秒。
3、从MySQL5.1开始，慢查询日志都放入一张表中，名为mysql.slow_log，格式默认为FILE，可以改为TABLE，便于查询。参数是log_output：
mysql> show variables like 'log_output';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output | FILE |
+---------------+-------+
1 row in set (0.00 sec)
mysql> set global log_output='TABLE';
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like 'log_output';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output | TABLE |
+---------------+-------+
1 row in set (0.01 sec)
mysql>
4、再人为的睡眠2.2秒，再查询就可以发现该SQL语句就记录在表格了：
mysql> select sleep(2.2);
+------------+
| sleep(2.2) |
+------------+
| 0 |
+------------+
1 row in set (2.22 sec)
mysql> select * from mysql.slow_log;
+---------------------+---------------------------+------------+-----------+-----------+---------------+----+----------------+-----------+-----------+-------------------+-----------+
| start_time | user_host | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text | thread_id |
+---------------------+---------------------------+------------+-----------+-----------+---------------+----+----------------+-----------+-----------+-------------------+-----------+
| 2020-03-02 14:00:17 | root[root] @ localhost [] | 00:00:02 | 00:00:00 | 1 | 0 | | 0 | 0 | 1 | select sleep(2.2) | 7 |
+---------------------+---------------------------+------------+-----------+-----------+---------------+----+----------------+-----------+-----------+-------------------+-----------+
1 row in set (0.00 sec)
mysql>
5、慢查询还有一个非常重要的参数log_queries_not_using_indexes，表示如果运行的SQL语句没有使用索引，也可以记录到慢查询日志文件中。
mysql> show variables like 'log_queries_not_using_indexes';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF |
+-------------------------------+-------+
1 row in set (0.00 sec)
mysql> set global log_queries_not_using_indexes=on;
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like 'log_queries_not_using_indexes';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | ON |
+-------------------------------+-------+
1 row in set (0.00 sec)
mysql>
以上设置可以看出，是全局变量。
6、我们再查看日志表格的记录。
mysql> select * from mysql.slow_log limit 5;
+---------------------+------------------------------------+------------+-----------+-----------+---------------+----------------+----------------+-----------+-----------+---------------------------------------------------------------------------------------------------------------------+-----------+
| start_time | user_host | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text | thread_id |
+---------------------+------------------------------------+------------+-----------+-----------+---------------+----------------+----------------+-----------+-----------+---------------------------------------------------------------------------------------------------------------------+-----------+
| 2020-03-02 14:00:17 | root[root] @ localhost [] | 00:00:02 | 00:00:00 | 1 | 0 | | 0 | 0 | 1 | select sleep(2.2) | 7 |
| 2020-03-02 14:22:47 | root[root] @ localhost [127.0.0.1] | 00:00:00 | 00:00:00 | 1 | 1 | NVRRecordFiles | 0 | 0 | 1 | SELECT COUNT(*) FROM information_schema.`TABLES` WHERE TABLE_SCHEMA = 'NVRRecordFiles' AND TABLE_NAME = 'FilesInfo' | 1 |
| 2020-03-02 14:22:47 | root[root] @ localhost [127.0.0.1] | 00:00:00 | 00:00:00 | 1 | 1 | NVRRecordFiles | 0 | 0 | 1 | SELECT FileId FROM FilesInfo LIMIT 1 | 1 |
| 2020-03-02 14:22:47 | root[root] @ localhost [127.0.0.1] | 00:00:00 | 00:00:00 | 1 | 1 | NVRRecordFiles | 0 | 0 | 1 | SELECT FileName FROM BadFiles LIMIT 1 | 1 |
| 2020-03-02 14:22:49 | root[root] @ localhost [127.0.0.1] | 00:00:00 | 00:00:00 | 1 | 1 | NVRRecordFiles | 0 | 0 | 1 | SELECT COUNT(*) FROM information_schema.`TABLES` WHERE TABLE_SCHEMA = 'NVRRecordFiles' AND TABLE_NAME = 'FilesInfo' | 1 |
+---------------------+------------------------------------+------------+-----------+-----------+---------------+----------------+----------------+-----------+-----------+---------------------------------------------------------------------------------------------------------------------+-----------+
5 rows in set (0.00 sec)
mysql>
7、MySQL 系统自带的工具mysqldumpslow
[root@localhost mysql]# mysqldumpslow -s -al localhost-slow.log
Reading mysql slow query log from localhost-slow.log
Count: 5 Time=0.03s (2s) Lock=0.20s (1s) Rows=4.4 (22), 0users@0hosts
SELECT FileId, FileStartTime FROM FilesInfo order by FileStartTime
Count：表示这个SQL总共执行了5次（慢查询日志中出现的次数）。
Time：表示执行时间，后面括号里面的2s 表示这个SQL语句累计的执行耗费时间为2秒。其实就是单次执行的时间和总共执行消耗的时间的区别。
Lock：表示锁定时间，后面括号里面表示这些SQL累计的锁定时间为1s。
Rows：表示返回的记录数，括号里面表示所有SQL语句累计返回记录数。
8、其他第三方工具，比较常见的是mysqlsla。需要自行下载和安装，显示的更加详细。
ps：今天再反复测试了，发现localhost-slow.log和mysql.slow_log两个日志文件，同一个时间点只会写入一个文件。即如果将 log_output改为'TABLE'，日志不会写入localhost-slow.log日志中，即只能从mysql.slow_log表格查询了。不过也建议用这个方式，因为可读性更佳！
