签到成功

知道了

CNDBA社区CNDBA社区

MariaDB 慢查询日志

2018-02-08 00:34 3175 0 原创 MySQL
作者： dave
本文链接：http://www.cndba.cn/dave/article/2637

在前面的2篇文章中，我们看了MariaDB的2种日志：
MariaDB 的错误日志
http://www.cndba.cn/dave/article/2635http://www.cndba.cn/dave/article/2637

MariaDB 查询日志
http://www.cndba.cn/dave/article/2636http://www.cndba.cn/dave/article/2637http://www.cndba.cn/dave/article/2637

这里我们看第三种日志：慢查询日志。

1 慢查询日志概念

MariaDB的慢查询日志用来记录数据库中响应时间超过阀值的语句，具体指运行时间超过long_query_time值的SQL，会被记录到慢查询日志中。long_query_time的默认值为10，单位是秒。默认情况下，MariaDB数据库并不启动慢查询日志，开启慢查询日志会带来一定的性能影响。慢查询日志支持将日志记录写入文件，也支持将日志记录写入数据库表。

2 慢查询日志相关参数

slow_query_log ：是否开启慢查询日志，1表示开启，0表示关闭。
log-slow-queries ：旧版（5.6以下版本）MySQL数据库慢查询日志存储路径。可以不设置该参数，系统则会默认给一个缺省的文件host_name-slow.log
slow-query-log-file：当使用文件存储慢查询日志时(log_output设置为”FILE”或者”FILE,TABLE”时)，指定慢查询日志存储于哪个日志文件中，默认的慢查询日志文件名为”主机名-slow.log”，慢查询日志的位置为datadir参数所对应的目录位置。
long_query_time ：表示”多长时间的查询”被认定为”慢查询”，此值得默认值为10秒，表示超过10秒的查询被认定为慢查询。
log_queries_not_using_indexes：表示如果运行的sql语句没有使用到索引，是否也被当做慢查询语句记录到慢查询日志中，OFF表示不记录，ON表示记录。
log_output：日志存储方式。

  1. ‘FILE’表示将日志存入文件，默认值是’FILE’。
  2. ‘TABLE’表示将日志存入数据库，这样日志信息就会被写入到mysql.slow_log表中。
  3. ‘FILE,TABLE’，同时记录两种日志存储方式。日志记录到系统的专用日志表中，要比记录到文件耗费更多的系统资源，因此对于需要启用慢查询日志，又需要能够获得更高的系统性能，那么建议优先记录到文件。

log_throttle_queries_not_using_indexes ：5.6.5版本新引入的参数，当log_queries_not_using_inde设置为ON时，没有使用索引的查询语句也会被当做慢查询语句记录到慢查询日志中，使用log_throttle_queries_not_using_indexes可以限制这种语句每分钟记录到慢查询日志中的次数，因为在生产环境中，有可能有很多没有使用索引的语句，此类语句频繁的被记录到慢查询日志中，可能会导致慢查询日志快速不断的增长，管理员可以通过此参数进行控制。

mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

mysql> show variables like '%slow%';
mysql> show variables like 'log_output';
+---------------+------------+
| Variable_name | Value      |
+---------------+------------+
| log_output    | FILE,TABLE |
+---------------+------------+
1 row in set (0.00 sec)

3 启用慢查询日志

3.1 使用命令行启动

慢查询的参数是动态的，可以动态的进行修改。

--设置long_query_time：
mysql>  show variables like "%long_query%";
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

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 | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

这里貌似没有生效，实际上加上global后,需要在下次进mysq时才会生效。http://www.cndba.cn/dave/article/2637http://www.cndba.cn/dave/article/2637http://www.cndba.cn/dave/article/2637

--设置：slow_query_log
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 | OFF   |
+----------------+-------+
1 row in set (0.01 sec)

--设置：log_slow_admin_statements
mysql> show variables like 'log_slow_admin%';
+---------------------------+-------+
| Variable_name             | Value |
+---------------------------+-------+
| log_slow_admin_statements | ON    |
+---------------------------+-------+
1 row in set (0.00 sec)1 row in set (0.00 sec)


--设置log_queries_not_using_indexes
mysql> show variables like 'log_queries_not%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF   |
+-------------------------------+-------+
1 row in set (0.00 sec)

mysql> set global log_queries_not_using_indexes=1;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'log_queries_not%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | ON    |
+-------------------------------+-------+
1 row in set (0.00 sec)
3.2 修改参数启动

在my.cnf 中的[mysqld]部分添加如下内容：

slow_query_log=on  
long_query_time=1  
log_queries_not_using_indexes=1
--记录下来没有使用索引的查询
log_slow_admin_statements=1
--执行速度较慢的管理命令也会被记录

然后重启一下mysql即可启动慢查询日志。

4 慢查询日志输出位置

默认情况下是输出到File的，我们这里已经修改过：

mysql>  show variables like 'log_output';
+---------------+------------+
| Variable_name | Value      |
+---------------+------------+
| log_output    | FILE,TABLE |
+---------------+------------+
1 row in set (0.00 sec)

[root@www.cndba.cn/dave ~]# cd /mysql/data
[root@www.cndba.cn/dave data]# ll
total 123000
drwx------ 2 mysql mysql     4096 Jan 31 07:57 cndba
-rw-rw---- 1 mysql mysql      832 Jan 31 03:34 Dave.err
-rw-rw---- 1 mysql mysql     1780 Jan 31 08:50 Dave.log
-rw-rw---- 1 mysql mysql        5 Jan 31 03:34 Dave.pid
-rw-rw---- 1 mysql mysql      179 Jan 31 08:48 Dave-slow.log
[root@www.cndba.cn/dave data]#


--查看慢查询表定义：
mysql> show create table mysql.slow_log;
+----------+--------------------------------------------------------------------------------
| Table    | Create Table                                                                   
+----------+--------------------------------------------------------------------------------
| slow_log | 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,
  `thread_id` bigint(21) unsigned NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log' |
+----------+--------------------------------------------------------------------------------
1 row in set (0.00 sec)


mysql> select sleep(10);
+-----------+
| sleep(10) |
+-----------+
|         0 |
+-----------+
1 row in set (10.00 sec)

查询slow_log 表：http://www.cndba.cn/dave/article/2637

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 | rows_affected |
+----------------------------+---------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+------------------------------+-----------+---------------+
| 2018-01-31 08:53:01.982057 | root[root] @ localhost [] | 00:00:00.000189 | 00:00:00.000117 |         0 |             0 |    |              0 |         0 |         1 | select * from mysql.slow_log |        12 |             0 |
| 2018-01-31 08:54:01.397154 | root[root] @ localhost [] | 00:00:10.001338 | 00:00:00.000000 |         1 |             0 |    |              0 |         0 |         1 | select sleep(10)             |        12 |             0 |
+----------------------------+---------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+------------------------------+-----------+---------------+
2 rows in set (0.00 sec)

mysql>

查看慢查询文件：http://www.cndba.cn/dave/article/2637

[root@www.cndba.cn/dave data]# pwd
/mysql/data
[root@www.cndba.cn/dave data]# cat Dave-slow.log 
/usr/local/mysql/bin/mysqld, Version: 10.2.12-MariaDB-log (MariaDB Server). started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 180131  8:53:01
# User@Host: root[root] @ localhost []
# Thread_id: 12  Schema:   QC_hit: No
# Query_time: 0.000189  Lock_time: 0.000117  Rows_sent: 0  Rows_examined: 0
# Rows_affected: 0
SET timestamp=1517359981;
select * from mysql.slow_log;
# Time: 180131  8:54:01
# User@Host: root[root] @ localhost []
# Thread_id: 12  Schema:   QC_hit: No
# Query_time: 10.001338  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
# Rows_affected: 0
SET timestamp=1517360041;
select sleep(10);
# Time: 180131  8:54:38
# User@Host: root[root] @ localhost []
# Thread_id: 12  Schema:   QC_hit: No
# Query_time: 0.000241  Lock_time: 0.000148  Rows_sent: 2  Rows_examined: 2
# Rows_affected: 0
SET timestamp=1517360078;
select * from mysql.slow_log;
[root@www.cndba.cn/dave data]#

5 使用mysqldumpslow 工具分析慢查询日志

慢查询日志可以使用mysql 自带的工具：mysqldumpslow 来进行分析。这种分析就是把慢查询日志中的重要信息依照便于阅读以及依照特定的排序方式来提取SQL。有点相似于Oracle中有个tkprof来格式化oracle的trace文件。

[root@www.cndba.cn/dave 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, ae, c, l, r, e, t), 'at' is default
                al: average lock time
                ar: average rows sent
                at: average query time
                aa: average rows affected
                 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

[root@www.cndba.cn/dave data]#

主要介绍两个参数-s和-t

  1. -s 这个是排序参数，可选的有：
  2. al: 平均锁定时间
  3. ar: 平均返回记录数
  4. at: 平均查询时间
  5. c: 计数
  6. l: 锁定时间
  7. r: 返回记录
  8. t: 查询时间
  9. -t n 显示头n条记录。

示例：http://www.cndba.cn/dave/article/2637http://www.cndba.cn/dave/article/2637

mysqldumpslow -s c -t 20 host-slow.log
mysqldumpslow -s r -t 20 host-slow.log
上述命令可以看出访问次数最多的20个sql语句和返回记录集最多的20个sql。

mysqldumpslow -t 10 -s t -g “left join” host-slow.log
这个是按照时间返回前10条里面含有左连接的sql语句。

我们这里的结果：

[root@www.cndba.cn/dave data]# mysqldumpslow Dave-slow.log 

Reading mysql slow query log from Dave-slow.log
Count: 1  Time=10.00s (10s)  Lock=0.00s (0s)  Rows_sent=1.0 (1), Rows_examined=0.0 (0), Rows_affected=0.0 (0), root[root]@localhost
  select sleep(N)

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1.0 (2), Rows_examined=1.0 (2), Rows_affected=0.0 (0), root[root]@localhost
  select * from mysql.slow_log

[root@www.cndba.cn/dave data]#

用了这个工具就可以查询出来那些sql语句是性能的瓶颈，进行优化。

版权声明：本文为博主原创文章，未经博主允许不得转载。

用户评论
* 以下用户言论只代表其个人观点，不代表CNDBA社区的观点或立场
dave

dave

关注

人的一生应该是这样度过的：当他回首往事的时候，他不会因为虚度年华而悔恨，也不会因为碌碌无为而羞耻；这样，在临死的时候，他就能够说：“我的整个生命和全部精力，都已经献给世界上最壮丽的事业....."

  • 2262
    原创
  • 3
    翻译
  • 579
    转载
  • 192
    评论
  • 访问：8089962次
  • 积分：4350
  • 等级：核心会员
  • 排名：第1名
精华文章

    达梦数据库运维实战

    Oracle 18c 必须掌握的新特性：管理与实战

    Oracle数据库问题解决方案和故障排除手册
    最新问题
    查看更多+
    热门文章
      热门用户
      推荐用户
        友情链接： CNDBA社区 | openGauss | openEuler | openAnolis | 广告联系: database@ustc.edu
        Copyright © 2016 All Rights Reserved. Powered by CNDBA · 皖ICP备2022006297号-1·

        QQ交流群

        注册联系QQ