Mysql slow query log

时间:2020-12-31 11:26:59

一、概念部分: 

顾名思义,慢查询日志中记录的是执行时间较长的query,也就是我们常说的slow query,通过设--log-slow-queries[=file_name]来打开该功能并设置记录位置和文件名,默认文件名为hostname-slow.log,默认目录也是数据目录。
    慢查询日志采用的是简单的文本格式,可以通过各种文本编辑器查看其中的内容。其中记录了语句执行的时刻,执行所消耗的时间,执行用户,连接主机等相关信息。MySQL还提供了专门用来分析满查询日志的工具程序mysqlslowdump,用来帮助数据库管理人员解决可能存在的性能问题。

二、slow query log相关变量

2.1、命令行参数:

--log-slow-queries

指定日志文件存放位置,可以为空,系统会给一个缺省的文件host_name-slow.log

2.2、系统变量

log_slow_queries

指定日志文件存放位置,可以为空,系统会给一个缺省的文件host_name-slow.log

slow_query_log

slow quere log的开关,当值为1的时候说明开启慢查询。

slow_query_log_file

指定日志文件存放位置,可以为空,系统会给一个缺省的文件host_name-slow.log

long_query_time

记录超过的时间,默认为10s

log_queries_not_using_indexes

log下来没有使用索引的query,可以根据情况决定是否开启

三、实验部分:

----使用log_slow_queries参数打开慢查询,由于该参数已经过时,因此在err日志中将出现提示信息
----修改my.cnf文件,添加log_slow_queries参数
[root@node4 ~]# vi /opt/mysql5.5/my.cnf
[root@node4 ~]# cat /opt/mysql5.5/my.cnf |grep '^log_slow'
log_slow_queries = /tmp/mysqlslow.log
----清空err日志内容:
[root@node4 ~]# cat /dev/null > /tmp/mysql3306.err
[root@node4 ~]# service mysql start
Starting MySQL.... [ OK ]
----查看err日志的信息
[root@node4 data]# tail -f /tmp/mysql3306.err
130801 02:26:28 mysqld_safe Starting mysqld daemon with databases from /opt/mysql5.5/data
130801 2:26:28 [Warning] The syntax '--log-slow-queries' is deprecated and will be removed in a future release. Please use '--slow-query-log'/'--slow-query-log-file' instead.
130801 2:26:28 [Warning] You need to use --log-bin to make --binlog-format work.
130801 2:26:28 InnoDB: The InnoDB memory heap is disabled
130801 2:26:28 InnoDB: Mutexes and rw_locks use InnoDB's own implementation
130801 2:26:28 InnoDB: Compressed tables use zlib 1.2.3
130801 2:26:28 InnoDB: Initializing buffer pool, size = 128.0M
130801 2:26:28 InnoDB: Completed initialization of buffer pool
130801 2:26:28 InnoDB: highest supported file format is Barracuda.
130801 2:26:28 InnoDB: Waiting for the background threads to start
130801 2:26:30 InnoDB: 1.1.8 started; log sequence number 3069452
130801 2:26:30 [Note] Event Scheduler: Loaded 0 events
130801 2:26:30 [Note] /opt/mysql5.5/bin/mysqld: ready for connections.
Version: '5.5.22-log' socket: '/tmp/mysql.sock' port: 3306 Source distribution ----使用slow_query_log和slow_query_log_file
[root@node4 ~]# vi /opt/mysql5.5/my.cnf
[root@node4 ~]# cat /opt/mysql5.5/my.cnf |grep '^slow_query'
slow_query_log = 1
slow_query_log_file = /tmp/mysqlslow.log1 [root@node4 ~]# service mysql start
Starting MySQL... [ OK ]
[root@node4 ~]# mysql
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.22-log Source distribution Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> show variables like '%slow%';
+---------------------+---------------------+
| Variable_name | Value |
+---------------------+---------------------+
| log_slow_queries | ON |
| slow_launch_time | 10 |
| slow_query_log | ON |
| slow_query_log_file | /tmp/mysqlslow.log1 |
+---------------------+---------------------+
4 rows in set (0.00 sec) ----关于slow_launch_time参数,首先修改一下参数值
mysql> set global long_query_time=1;
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like '%long_query%';
+-----------------+----------+
| Variable_name | Value |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
1 row in set (0.00 sec) ----进行一下相关操作,查看/tmp/mysqlslow.log1的内容
mysql> select database();
+------------+
| database() |
+------------+
| NULL |
+------------+
1 row in set (0.00 sec) mysql> use test;
Database changed
mysql> show tables;
Empty set (0.00 sec) mysql> create table t as select * from information_schema.tables;
Query OK, 85 rows affected (0.38 sec)
Records: 85 Duplicates: 0 Warnings: 0 mysql> insert into t select * from t;
Query OK, 85 rows affected (0.05 sec)
Records: 85 Duplicates: 0 Warnings: 0 mysql> insert into t select * from t;
Query OK, 170 rows affected (0.03 sec)
Records: 170 Duplicates: 0 Warnings: 0 mysql> insert into t select * from t;
Query OK, 340 rows affected (0.05 sec)
Records: 340 Duplicates: 0 Warnings: 0 mysql> insert into t select * from t;
Query OK, 680 rows affected (0.08 sec)
Records: 680 Duplicates: 0 Warnings: 0 mysql> insert into t select * from t;
Query OK, 1360 rows affected (0.29 sec)
Records: 1360 Duplicates: 0 Warnings: 0 mysql> insert into t select * from t;
Query OK, 2720 rows affected (1.49 sec)
Records: 2720 Duplicates: 0 Warnings: 0 ----在这里已经超过1s了,查看/tmp/mysqlslow.log1
[root@node4 data]# tail -f /tmp/mysqlslow.log1
# Time: 130801 2:36:25
# User@Host: root[root] @ localhost []
# Query_time: 2.274219 Lock_time: 0.000322 Rows_sent: 0 Rows_examined: 5440
use test;
SET timestamp=1375295785;
insert into t select * from t; ----log_queries_not_using_indexes参数实验
mysql> show variables like '%indexes%';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF |
+-------------------------------+-------+
1 row in set (0.00 sec) mysql> set log_queries_not_using_indexes = 1;
ERROR 1229 (HY000): Variable 'log_queries_not_using_indexes' is a GLOBAL variable and should be set with SET GLOBAL
mysql> set global log_queries_not_using_indexes = 1;
Query OK, 0 rows affected (0.01 sec) mysql> show variables like '%indexes%';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | ON |
+-------------------------------+-------+
1 row in set (0.00 sec) mysql> desc t;
+-----------------+---------------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+-----------------+---------------------+------+-----+---------+-------+
| TABLE_CATALOG | varchar(512) | NO | | | |
| TABLE_SCHEMA | varchar(64) | NO | | | |
| TABLE_NAME | varchar(64) | NO | | | |
| TABLE_TYPE | varchar(64) | NO | | | |
| ENGINE | varchar(64) | YES | | NULL | |
| VERSION | bigint(21) unsigned | YES | | NULL | |
| ROW_FORMAT | varchar(10) | YES | | NULL | |
| TABLE_ROWS | bigint(21) unsigned | YES | | NULL | |
| AVG_ROW_LENGTH | bigint(21) unsigned | YES | | NULL | |
| DATA_LENGTH | bigint(21) unsigned | YES | | NULL | |
| MAX_DATA_LENGTH | bigint(21) unsigned | YES | | NULL | |
| INDEX_LENGTH | bigint(21) unsigned | YES | | NULL | |
| DATA_FREE | bigint(21) unsigned | YES | | NULL | |
| AUTO_INCREMENT | bigint(21) unsigned | YES | | NULL | |
| CREATE_TIME | datetime | YES | | NULL | |
| UPDATE_TIME | datetime | YES | | NULL | |
| CHECK_TIME | datetime | YES | | NULL | |
| TABLE_COLLATION | varchar(32) | YES | | NULL | |
| CHECKSUM | bigint(21) unsigned | YES | | NULL | |
| CREATE_OPTIONS | varchar(255) | YES | | NULL | |
| TABLE_COMMENT | varchar(2048) | NO | | | |
+-----------------+---------------------+------+-----+---------+-------+
21 rows in set (0.05 sec)
----下面的命令是查看索引的
mysql> show index from t;
Empty set (0.01 sec) mysql> select * from t where engine='xxx';
Empty set (0.18 sec) # Time: 130801 2:43:43
# User@Host: root[root] @ localhost []
# Query_time: 0.185773 Lock_time: 0.148868 Rows_sent: 0 Rows_examined: 5440
SET timestamp=1375296223;
select * from t where engine='xxx';

四、Mysqldumpslow

如果日志内容很多,用眼睛一条一条看会累死,mysql自带了分析的工具,使用方法如下:

[root@node4 data]# 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