Mysql 启动慢查询日志 (不用重启) and 理解mysql的slow log

梦里梦外; 2022-05-25 14:19 271阅读 0赞

1. 查看mysql系统参数  
  
mysql> show variables like "%slow%";  
\+---------------------------+-------------------------------+  
| Variable\_name             | Value                         |  
\+---------------------------+-------------------------------+  
| log\_slow\_admin\_statements | OFF                           |  
| log\_slow\_slave\_statements | OFF                           |  
| slow\_launch\_time          | 2                             |  
| slow\_query\_log            | OFF                           |  
| slow\_query\_log\_file       | /mysql/data/nagiosdb-slow.log |  
\+---------------------------+-------------------------------+  
5 rows in set (0.00 sec)  
  
  
slow\_query\_log： off关闭状态  on开启状态  
slow\_launch\_time   默认超过2s为慢查询  
slow\_query\_log\_file  慢查询日志存放地点  
  
  
这三个参数，在不同的mysql版本中，不太一样，不过都可以通过 show variables like "%slow%" 查看出来  
  
  
2. 运行如下命令即可运行慢查询日志  
  
mysql> set global slow\_query\_log=ON;  
Query OK, 0 rows affected (0.03 sec)  
  
mysql> set global slow\_launch\_time=5;  
Query OK, 0 rows affected (0.00 sec)  
  
mysql> show variables like "%slow%";  
\+---------------------------+-------------------------------+  
| Variable\_name             | Value                         |  
\+---------------------------+-------------------------------+  
| log\_slow\_admin\_statements | OFF                           |  
| log\_slow\_slave\_statements | OFF                           |  
| slow\_launch\_time          | 5                             |  
| slow\_query\_log            | ON                            |  
| slow\_query\_log\_file       | /mysql/data/nagiosdb-slow.log |  
\+---------------------------+-------------------------------+  
5 rows in set (0.00 sec)  
  
  
mysql 5.1.6版本起，slow\_query\_log 和 slow\_launch\_time 支持写文件或写数据库表两种方式，并且日志的开启，输出方式的修改，都可以在global级别动态修改。  
只需简单通过set global slow\_query\_log=ON;即可开启慢查询，而不需要重启数据库！  
  
  
3. 可以直接写到配置文件中  my.cnf  
  
slow\_query\_log\_file=/mysql/log/nagiosdb-slow.log  
slow\_launch\_time=5

可以完成配置！！

\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*

PS：所有的前提，慢查询时间设置为3s

### 1 log\_output参数为TABLE时，慢查询记录到mysql.slow\_log表里，但这时这个系统表没有任何索引，我们一般可以在start\_time列自行加上索引方便检索，类似这样 ###

mysql> show create table mysql.slow\_log\\G  
\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\* 1. row \*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*  
       Table: slow\_log  
Create Table: CREATE TABLE \`slow\_log\` (  
  \`start\_time\` timestamp NOT NULL DEFAULT CURRENT\_TIMESTAMP ON UPDATE CURRENT\_TIMESTAMP,  
  \`user\_host\` mediumtext NOT NULL,  
  \`query\_time\` time NOT NULL,  
  \`lock\_time\` time NOT NULL,  
  \`rows\_sent\` int(11) NOT NULL,  
  \`rows\_examined\` int(11) NOT NULL,  
  \`db\` varchar(512) NOT NULL,  
  \`last\_insert\_id\` int(11) NOT NULL,  
  \`insert\_id\` int(11) NOT NULL,  
  \`server\_id\` int(10) unsigned NOT NULL,  
  \`sql\_text\` mediumtext NOT NULL,  
  KEY \`start\_time\` (\`start\_time\`)  
) ENGINE=MyISAM DEFAULT CHARSET=utf8 COMMENT='Slow log'  
1 row in set (0.00 sec)

### 2 start\_time指的是SQL结束时间，而不是开始执行时间。 ###

mysql> select now();  
\+---------------------+  
| now()               |  
\+---------------------+  
| 2016-06-13 11:34:12 |  
\+---------------------+  
1 row in set (0.00 sec)  
  
mysql> select sleep(20);  
\+-----------+  
| sleep(20) |  
\+-----------+  
|         0 |  
\+-----------+  
1 row in set (19.99 sec)  
  
mysql> select now();  
\+---------------------+  
| now()               |  
\+---------------------+  
| 2016-06-13 11:34:47 |  
\+---------------------+  
1 row in set (0.00 sec)

start\_time: 2016-06-13 11:34:46  
     user\_host: ucloudbackup\[ucloudbackup\] @  \[10.10.249.91\]  
    query\_time: 00:00:20  
     lock\_time: 00:00:00  
     rows\_sent: 1  
 rows\_examined: 0  
            db: test  
last\_insert\_id: 0  
     insert\_id: 0  
     server\_id: 168491355  
      sql\_text: select sleep(20)  
10 rows in set (0.00 sec)

### 3 log\_queries\_not\_using\_indexes为1时，会记录任何不使用索引的sql，从而无视long\_query\_time参数 ###

mysql> set global log\_queries\_not\_using\_indexes=1;  
Query OK, 0 rows affected (0.00 sec)

虽然是global变量，但不用重开session

mysql> select \* from xx limit 1;

\+------+------+  
| id   | dd   |  
\+------+------+  
|  123 | NULL |  
\+------+------+  
1 row in set (0.00 sec)

start\_time: 2016-06-13 11:38:04  
     user\_host: ucloudbackup\[ucloudbackup\] @  \[10.10.249.91\]  
    query\_time: 00:00:00  
     lock\_time: 00:00:00  
     rows\_sent: 1  
 rows\_examined: 1  
            db: test  
last\_insert\_id: 0  
     insert\_id: 0  
     server\_id: 168491355  
      sql\_text: select \* from xx limit 1  
12 rows in set (0.00 sec)

### 4 默认情况下不会记录DDL操作，不管执行时间多长，除非将log\_slow\_admin\_statements参数设置为1，而这个参数只在5.6.11后支持 ###

mysql> alter table xx add column dd varchar(100);  
Query OK, 8388608 rows affected (1 min 4.47 sec)  
Records: 8388608  Duplicates: 0  Warnings: 0

mysql> select \* from mysql.slow\_log where sql\_text like '%alter%';  
Empty set (0.00 sec)

### 5 在log\_queries\_not\_using\_indexes为1的情况下，默认没走索引的sql有多少就记录多少，而设置了log\_throttle\_queries\_not\_using\_indexes为N后，表示1分钟内该SQL最多记录N条，这个参数在5.6.5后支持 ###

set global log\_queries\_not\_using\_indexes=1;

mysql> select \* from xx;  
Empty set (0.00 sec)  
  
mysql> select \* from xx;  
Empty set (0.00 sec)  
  
mysql> select \* from xx;  
Empty set (0.00 sec)

mysql> select \* from mysql.slow\_log where sql\_text like '%xx%';  
\+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+------------------+-----------+  
| start\_time          | user\_host                                    | query\_time | lock\_time | rows\_sent | rows\_examined | db   | last\_insert\_id | insert\_id | server\_id | sql\_text         | thread\_id |  
\+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+------------------+-----------+  
| 2016-06-13 11:45:50 | ucloudbackup\[ucloudbackup\] @  \[10.10.218.80\] | 00:00:00   | 00:00:00  |         0 |             0 | test |              0 |         0 | 168483408 | select \* from xx |        29 |  
\+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+------------------+-----------+  
1 row in set (0.00 sec)

###    6 默认情况下有记录就记录，而设置了min\_examined\_row\_limit为N后，表示只有返回条数大于N才记录到慢查询 ###

mysql> set min\_examined\_row\_limit=1;  
Query OK, 0 rows affected (0.00 sec)

mysql> select sleep(4.5);  
\+------------+  
| sleep(4.5) |  
\+------------+  
|          0 |  
\+------------+  
1 row in set (4.50 sec)  
  
mysql> select \* from mysql.slow\_log where sql\_text like '%sleep(4.5)%';  
Empty set (0.00 sec)  
  
mysql> show variables like '%long%';  
\+---------------------------------------------------+----------+  
| Variable\_name                                     | Value    |  
\+---------------------------------------------------+----------+  
| long\_query\_time                                   | 3.000000 |  
| max\_long\_data\_size                                | 16777216 |  
| performance\_schema\_events\_waits\_history\_long\_size | 10000    |  
\+---------------------------------------------------+----------+  
3 rows in set (0.00 sec)  
  
mysql> set min\_examined\_row\_limit=0;  
Query OK, 0 rows affected (0.00 sec)  
  
mysql> select sleep(4.5);  
\+------------+  
| sleep(4.5) |  
\+------------+  
|          0 |  
\+------------+  
1 row in set (4.50 sec)  
  
mysql> select \* from mysql.slow\_log where sql\_text like '%sleep(4.5)%';  
\+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+-------------------+  
| start\_time          | user\_host                                    | query\_time | lock\_time | rows\_sent | rows\_examined | db   | last\_insert\_id | insert\_id | server\_id | sql\_text          |  
\+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+-------------------+  
| 2016-06-13 11:27:07 | ucloudbackup\[ucloudbackup\] @  \[10.10.249.91\] | 00:00:04   | 00:00:00  |         1 |             0 | test |              0 |         0 | 168491355 | select sleep(4.5) |  
\+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+-------------------+  
1 row in set (0.00 sec)

### 7 只有sql的实际执行时间超过long\_query\_time，才会记录到慢查询（这里的实际执行时间排除了lock的时间），而当记录到slow\_log后，query\_time列记录的时间是实际执行时间+lock\_time的时间。 ###

case 1 实际执行时间为5s，lock时间为40s，记录到慢查询

session 1 执行

mysql> flush tables with read lock;

Query OK, 0 rows affected (0.00 sec)

session 2执行以下sql，这时sql被锁住

mysql> insert into xx values (sleep(5));

session1断开连接释放全局读锁

session2 经过5s后执行完成

mysql> insert into xx values (sleep(5));  
Query OK, 1 row affected (45.27 sec)

这时查看mysql.slow\_log

start\_time: 2016-06-13 11:54:15  
     user\_host: ucloudbackup\[ucloudbackup\] @  \[10.10.218.80\]  
    query\_time: 00:00:45  
     lock\_time: 00:00:40  
     rows\_sent: 0  
 rows\_examined: 0  
            db: test  
last\_insert\_id: 0  
     insert\_id: 0  
     server\_id: 168483408  
      sql\_text: insert into xx values (sleep(5))  
     thread\_id: 34  
14 rows in set (0.00 sec)

可以看到query\_time为45s，locktime为40s，query\_time是40+5，包括了lock时间和实际执行时间

case 2 实际执行时间为1s，locktime为5s，不记录慢查询

session 1执行flush tables with read lock;

session 2 执行mysql> insert into xx values (sleep(1));

断开session1释放全局读锁

session2过1s后执行完成，总耗时为6s

mysql> insert into xx values (sleep(1));  
Query OK, 1 row affected (6.02 sec)

查看慢查询，无session2的记录

mysql> select \* from mysql.slow\_log where sql\_text like '%sleep(1)%';  
Empty set (0.00 sec)

### 8 默认slave不会记录主库传过来的慢查询，除非开启log\_slow\_slave\_statements为1（官方文档是这么说的），但是我在主从上都打开了这个参数，发现从库还是没有记录，这tmd是bug吧（5.6.11支持这个参数，我用的是5.6.20） ###