MySQL中查询日志与慢查询日志的基本学习教程

一、查询日志

  查询日志记录mysql中所有的query，通过"--log[=file_name]"来打开该功能。由于记录了所有的query，包括所有的select，体积比较大，开启后对性能也有比较大的影响，所以请大家慎用该功能。一般只用于跟踪某些特殊的sql性能问题才会短暂打开该功能。默认的查询日志文件名为：hostname.log. 
----默认情况下查看是否启用查询日志：

[root@node4 mysql5.5]# service mysql start

starting mysql....                     [ ok ]

[root@node4 mysql5.5]# 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 '%log';

+--------------------------------+-------+
| variable_name         | value |
+--------------------------------+-------+
| back_log            | 50  |
| general_log          | off  |
| innodb_locks_unsafe_for_binlog | off  |
| log              | off  |
| relay_log           |    |
| slow_query_log         | off  |
| sync_binlog          | 0   |
| sync_relay_log         | 0   |
+--------------------------------+-------+
8 rows in set (0.00 sec)

----备注：log和general_log这两个参数是兼容的。而默认的情况下查询日志是不开启的
----使用下面的命令是开启查询日志
mysql> set global log=1;

 

query ok, 0 rows affected, 1 warning (0.03 sec)

mysql> show variables like '%log';

+--------------------------------+-------+
| variable_name         | value |
+--------------------------------+-------+
| back_log            | 50  |
| general_log          | on  |
| innodb_locks_unsafe_for_binlog | off  |
| log              | on  |
| relay_log           |    |
| slow_query_log         | off  |
| sync_binlog          | 0   |
| sync_relay_log         | 0   |
+--------------------------------+-------+
8 rows in set (0.00 sec) 
----其中log参数是过时的，在启动选项中使用log参数的话，会在err日志中显示出来。
----修改my.cnf文件，添加log的参数设置

[root@node4 mysql5.5]# vi my.cnf
[root@node4 mysql5.5]# cat ./my.cnf |grep '^log='
log=/tmp/mysqlgen.log
----清空err日志
[root@node4 mysql5.5]# cat /dev/null > /tmp/mysql3306.err 
[root@node4 mysql5.5]# ll /tmp/mysql3306.err 
-rw-rw---- 1 mysql root 0 jul 31 07:50 /tmp/mysql3306.err
[root@node4 mysql5.5]# service mysql start

starting mysql...                     [ ok ]
----启动数据库后查看err日志的内容

[root@node4 mysql5.5]# cat /tmp/mysql3306.err 

130731 07:51:32 mysqld_safe starting mysqld daemon with databases from /opt/mysql5.5/data
130731 7:51:32 [warning] the syntax '--log' is deprecated and will be removed in a future release. please use '--general-log'/'--general-log-file' instead.
130731 7:51:33 innodb: the innodb memory heap is disabled
130731 7:51:33 innodb: mutexes and rw_locks use innodb's own implementation
130731 7:51:33 innodb: compressed tables use zlib 1.2.3
130731 7:51:33 innodb: initializing buffer pool, size = 128.0m
130731 7:51:33 innodb: completed initialization of buffer pool
130731 7:51:33 innodb: highest supported file format is barracuda.
130731 7:51:33 innodb: waiting for the background threads to start
130731 7:51:34 innodb: 1.1.8 started; log sequence number 1625855
130731 7:51:34 [note] event scheduler: loaded 0 events
130731 7:51:34 [note] /opt/mysql5.5/bin/mysqld: ready for connections.
version: '5.5.22-log' socket: '/tmp/mysql.sock' port: 3306 source distribution
----使用最新的参数
----general_log和general_log_file。

[root@node4 mysql5.5]# service mysql stop

shutting down mysql.                    [ ok ]

[root@node4 mysql5.5]# vi my.cnf
[root@node4 mysql5.5]# cat ./my.cnf |grep '^general'

general_log = 1 
general_log_file = /tmp/mysqlgen.log

[root@node4 mysql5.5]# service mysql start

starting mysql...                     [ ok ]

[root@node4 mysql5.5]# 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 '%log';

+--------------------------------+-------+
| variable_name         | value |
+--------------------------------+-------+
| back_log            | 50  |
| general_log          | on  |
| innodb_locks_unsafe_for_binlog | off  |
| log              | on  |
| relay_log           |    |
| slow_query_log         | off  |
| sync_binlog          | 0   |
| sync_relay_log         | 0   |
+--------------------------------+-------+
8 rows in set (0.04 sec)

mysql> show variables like '%file';

+---------------------+-----------------------------------+
| variable_name    | value               |
+---------------------+-----------------------------------+
| ft_stopword_file  | (built-in)            |
| general_log_file  | /tmp/mysqlgen.log         |
| init_file      |                  |
| local_infile    | on                |
| pid_file      | /tmp/mysql3306.pid        |
| relay_log_info_file | relay-log.info          |
| slow_query_log_file | /opt/mysql5.5/data/node4-slow.log |
+---------------------+-----------------------------------+
7 rows in set (0.00 sec)
----在上面的操作中可以看到已经启用查询日志，并且文件目录是/tmp/mysqlgen.log。
----查询日志记录了哪些东西？

进行下面的查询

mysql> show databases;

+--------------------+
| database      |
+--------------------+
| information_schema |
| mysql       |
| performance_schema |
| test        |
| test2       |
+--------------------+
5 rows in set (0.08 sec)

mysql> use test;

database changed

mysql> show tables;

empty set (0.00 sec)

mysql> use test2;

database changed

mysql> show tables;

+-----------------+
| tables_in_test2 |
+-----------------+
| course     |
| jack      |
| sc       |
| student     |
| t        |
| teacher     |
+-----------------+
6 rows in set (0.07 sec)

mysql> drop table t;

query ok, 0 rows affected (0.13 sec)

mysql> select * from sc;

empty set (0.04 sec)

----可以看到上面的操作都记录在了mysqlgen.log里面。

[root@node4 ~]# tail -f /tmp/mysqlgen.log

/opt/mysql5.5/bin/mysqld, version: 5.5.22-log (source distribution). started with:
tcp port: 3306 unix socket: /tmp/mysql.sock
time         id command  argument
130731 7:55:41    1 query  show databases
130731 7:55:56    1 query  select database()
      1 init db  test
130731 7:55:59    1 query  show tables
130731 7:56:19    1 query  select database()
      1 init db  test2
130731 7:56:23    1 query  show tables
130731 7:56:27    1 query  drop table t
130731 7:56:39    1 query  select * from sc

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

----使用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 

02:26:28 mysqld_safe starting mysqld daemon with databases from /opt/mysql5.5/data
 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.
 2:26:28 [warning] you need to use --log-bin to make --binlog-format work.
 2:26:28 innodb: the innodb memory heap is disabled
 2:26:28 innodb: mutexes and rw_locks use innodb's own implementation
 2:26:28 innodb: compressed tables use zlib 1.2.3
 2:26:28 innodb: initializing buffer pool, size = 128.0m
 2:26:28 innodb: completed initialization of buffer pool
 2:26:28 innodb: highest supported file format is barracuda.
 2:26:28 innodb: waiting for the background threads to start
 2:26:30 innodb: 1.1.8 started; log sequence number 3069452
 2:26:30 [note] event scheduler: loaded 0 events
 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 |
+---------------------+---------------------+
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 |
+-----------------+----------+
row in set (0.00 sec)

----进行一下相关操作，查看/tmp/mysqlslow.log1的内容

mysql> select database();

+------------+
| database() |
+------------+
| null    |
+------------+
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  |
+-------------------------------+-------+
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  |
+-------------------------------+-------+
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  |   |     |    |
+-----------------+---------------------+------+-----+---------+-------+
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';

ps：slow query log相关变量

命令行参数：

    --log-slow-queries

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

系统变量

    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，可以根据情况决定是否开启

三、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