欢迎您访问程序员文章站本站旨在为大家提供分享程序员计算机编程知识!
您现在的位置是: 首页  >  IT编程

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

程序员文章站 2024-02-25 11:02:40
一、查询日志   查询日志记录mysql中所有的query,通过"--log[=file_name]"来打开该功能。由于记录了所有的query,包括所有的se...

一、查询日志

  查询日志记录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