读书频道 > 网站 > 网页设计 > MySQL技术内幕:InnoDB存储引擎(第2版)
3.2.2 慢查询日志
13-05-24    奋斗的小年轻
收藏    我要投稿   
本书由国内资深MySQL专家亲自执笔,国内外多位数据库专家联袂推荐。作为国内唯一一本关于InnoDB的专著,本书的第1版广受好评,第2版不仅针对最新的MySQL 5.6对相关内容进行了全面的补充,还根据广大读者的反馈意...立即去当当网订购

3.2.1小节提到可以通过错误日志得到一些关于数据库优化的信息,而慢查询日志(slow log)可帮助DBA定位可能存在问题的SQL语句,从而进行SQL语句层面的优化。例如,可以在MySQL启动时设一个阈值,将运行时间超过该值的所有SQL语句都记录到慢查询日志文件中。DBA每天或每过一段时间对其进行检查,确认是否有SQL语句需要进行优化。该阈值可以通过参数long_query_time来设置,默认值为10,代表10秒。

在默认情况下,MySQL数据库并不启动慢查询日志,用户需要手工将这个参数设为ON:

mysql> SHOW VARIABLES LIKE 'long_query_time'\G;

*************************** 1. row ***************************

Variable_name: long_query_time

       Value: 10.000000

1 row in set (0.00 sec)

 

mysql> SHOW VARIABLES LIKE 'log_slow_queries'\G;

*************************** 1. row ***************************

Variable_name: log_slow_queries

       Value: ON

1 row in set (0.00 sec)

这里有两点需要注意。首先,设置long_query_time这个阈值后,MySQL数据库会记录运行时间超过该值的所有SQL语句,但运行时间正好等于long_query_time的情况并不会被记录下。也就是说,在源代码中判断的是大于long_query_time,而非大于等于。其次,从MySQL 5.1开始,long_query_time开始以微秒记录SQL语句运行的时间,之前仅用秒为单位记录。而这样可以更精确地记录SQL的运行时间,供DBA分析。对DBA来说,一条SQL语句运行0.5秒和0.05秒是非常不同的,前者可能已经进行了表扫,后面可能是进行了索引。

另一个和慢查询日志有关的参数是log_queries_not_using_indexes,如果运行的SQL语句没有使用索引,则MySQL数据库同样会将这条SQL语句记录到慢查询日志文件。首先确认打开了log_queries_not_using_indexes:

mysql> SHOW VARIABLES LIKE 'log_queries_not_using_indexes'\G;

*************************** 1. row ***************************

Variable_name: log_queries_not_using_indexes

       Value: ON

1 row in set (0.00 sec)

MySQL 5.6.5版本开始新增了一个参数log_throttle_queries_not_using_indexes,用来表示每分钟允许记录到slow log的且未使用索引的SQL语句次数。该值默认为0,表示没有限制。在生产环境下,若没有使用索引,此类SQL语句会频繁地被记录到slow log,从而导致slow log文件的大小不断增加,故DBA可通过此参数进行配置。

DBA可以通过慢查询日志来找出有问题的SQL语句,对其进行优化。然而随着MySQL数据库服务器运行时间的增加,可能会有越来越多的SQL查询被记录到了慢查询日志文件中,此时要分析该文件就显得不是那么简单和直观的了。而这时MySQL数据库提供的mysqldumpslow命令,可以很好地帮助DBA解决该问题:

[root@nh122-190 data]# mysqldumpslow nh122-190-slow.log

Reading mysql slow query log from nh122-190-slow.log

Count: 11  Time=10.00s (110s)  Lock=0.00s (0s)  Rows=0.0 (0), dbother[dbother]@localhost

  insert into test.DbStatus select now(),(N-com_select)/(N-uptime),(N-com_insert)/(N-uptime),(N-com_update)/(N-uptime),(N-com_delete)/(N-uptime),N-(N/N),N-(N/N),N.N/N,N-N/(N*N),GetCPULoadInfo(N) from test.CheckDbStatus order by check_id desc limit N

Count: 653  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 9YOUgs_SC[9YOUgs_SC]@[192.168.43.7]

  select custom_name_one from 'low_game_schema'.'role_details' where role_id='S'

rse 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

如果用户希望得到执行时间最长的10条SQL语句,可以运行如下命令:

[root@nh119-141 data]# mysqldumpslow -s al -n 10 david.log

Reading mysql slow query log from david.log

Count: 5  Time=0.00s (0s)  Lock=0.20s (1s)  Rows=4.4 (22), Audition[Audition]@[192.168.30.108]

  SELECT OtherSN, State FROM wait_friend_info WHERE UserSN = N

 

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), audition-kr[audition-kr]@[192.168.30.105]

  SELECT COUNT(N) FROM famverifycode WHERE UserSN=N AND verifycode='S'

……

MySQL 5.1开始可以将慢查询的日志记录放入一张表中,这使得用户的查询更加方便和直观。慢查询表在mysql架构下,名为slow_log,其表结构定义如下:

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(11) NOT NULL,

  'sql_text' mediumtext NOT NULL

) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log'

1 row in set (0.00 sec)

参数log_output指定了慢查询输出的格式,默认为FILE,可以将它设为TABLE,然后就可以查询mysql架构下的slow_log表了,如:

mysql>SHOW VARIABLES LIKE 'log_output'\G;

+---------------+---------+

| Variable_name | Value |

+---------------+---------+

| log_output    | FILE |

+---------------+---------+

1 row in set (0.00 sec)

 

mysql>SET GLOBAL log_output='TABLE';

Query OK, 0 rows affected (0.00 sec)

 

mysql>SHOW VARIABLES LIKE 'log_output'\G;

+---------------+---------+

| Variable_name | Value |

+---------------+---------+

| log_output  | TABLE |

+---------------+---------+

1 row in set (0.00 sec)

 

mysql> select sleep(10)\G;

+-----------+

| sleep(10)|

+-----------+

|       0 |

+-----------+

1 row in set (10.01 sec)

 

mysql> SELECT * FROM mysql.slow_log\G;

*************************** 1. row ***************************

    start_time: 2009-09-25 13:44:29

     user_host: david[david] @ localhost []

    query_time: 00:00:09

     lock_time: 00:00:00

     rows_sent: 1

 rows_examined: 0

            db: mysql

last_insert_id: 0

     insert_id: 0

     server_id: 0

      sql_text: select sleep(10)

1 row in set (0.00 sec)

参数log_output是动态的,并且是全局的,因此用户可以在线进行修改。在上表中人为设置了睡眠(sleep)10秒,那么这句SQL语句就会被记录到slow_log表了。

查看slow_log表的定义会发现该表使用的是CSV引擎,对大数据量下的查询效率可能不高。用户可以把slow_log表的引擎转换到MyISAM,并在start_time列上添加索引以进一步提高查询的效率。但是,如果已经启动了慢查询,将会提示错误:

mysql>ALTER TABLE mysql.slow_log ENGINE=MyISM;

ERROR 1580 (HY000): You cannot 'ALTER' a log table if logging is enabled

 

mysql>SET GLOBAL slow_query_log=off;

Query OK, 0 rows affected (0.00 sec)

 

mysql>ALTER TABLE mysql.slow_log ENGINE=MyISAM;

Query OK, 1 row affected (0.00 sec)

Records: 1  Duplicates: 0  Warnings: 0

不能忽视的是,将slow_log表的存储引擎更改为MyISAM后,还是会对数据库造成额外的开销。不过好在很多关于慢查询的参数都是动态的,用户可以方便地在线进行设置或修改。

MySQL的slow log通过运行时间来对SQL语句进行捕获,这是一个非常有用的优化技巧。但是当数据库的容量较小时,可能因为数据库刚建立,此时非常大的可能是数据全部被缓存在缓冲池中,SQL语句运行的时间可能都是非常短的,一般都是0.5秒。

InnoSQL版本加强了对于SQL语句的捕获方式。在原版MySQL的基础上在slow log中增加了对于逻辑读取(logical reads)和物理读取(physical reads)的统计。这里的物理读取是指从磁盘进行IO读取的次数,逻辑读取包含所有的读取,不管是磁盘还是缓冲池。例如:

# Time: 111227 23:49:16

# User@Host: root[root] @ localhost [127.0.0.1]

# Query_time: 6.081214 Lock_time: 0.046800 Rows_sent: 42 Rows_examined: 727558 Logical_reads: 91584 Physical_reads: 19

use tpcc;

SET timestamp=1325000956;

SELECT orderid,customerid,employeeid,orderdate

FROM orders

WHERE orderdate IN

( SELECT MAX(orderdate)

FROM orders

GROUP BY (DATE_FORMAT(orderdate,'%Y%M'))

);

从上面的例子可以看到该子查询的逻辑读取次数是91584次,物理读取为19次。从逻辑读与物理读的比例上看,该SQL语句可进行优化。

用户可以通过额外的参数long_query_io将超过指定逻辑IO次数的SQL语句记录到slow log中。该值默认为100,即表示对于逻辑读取次数大于100的SQL语句,记录到slow log中。而为了兼容原MySQL数据库的运行方式,还添加了参数slow_query_type,用来表示启用slow log的方式,可选值为:

0表示不将SQL语句记录到slow log

1表示根据运行时间将SQL语句记录到slow log

2表示根据逻辑IO次数将SQL语句记录到slow log

3表示根据运行时间及逻辑IO次数将SQL语句记录到slow log

 

点击复制链接 与好友分享!回本站首页
分享到: 更多
您对本文章有什么意见或着疑问吗?请到论坛讨论您的关注和建议是我们前行的参考和动力  
上一篇:1.3 功能
下一篇:1.5 小结
相关文章
图文推荐
JavaScript网页动画设
1.9 响应式
1.8 登陆页式
1.7 主题式
排行
热门
文章
下载
读书

关于我们 | 联系我们 | 广告服务 | 投资合作 | 版权申明 | 在线帮助 | 网站地图 | 作品发布 | Vip技术培训
版权所有: 红黑联盟--致力于做最好的IT技术学习网站