MySQL 慢日志 :你想要的这里都有

导语

关于MySQL慢日志的信息,源码分析,良心制作。

# Time: 170524 18:21:04 
# User@Host: user[user] @ [192.168.0.7] Id: 2058705
# Query_time: 6.977880 Lock_time: 0.000056 Rows_sent: 2 Rows_examined: 3961943 
SET timestamp=1495621264; 
SELECT colume1,colume2,COUNT(1) 
FROM db.table 
WHERE colume1 ='20170524' AND colume2 = 'xxx' 
GROUP BY  colume1,colume2;

什么是慢日志?

MySQL的慢查询日志是MySQL提供的一种日志记录,它用来记录在MySQL中响应时间超过阀值的语句,具体指运行时间超过long_query_time值的SQL,则会被记录到慢查询日志中。long_query_time的默认值为10,意思是运行10S以上的语句。默认情况下,MySQL数据库并不启动慢查询日志,需要我们手动来设置这个参数,当然,如果不是调优需要的话,一般不建议启动该参数,因为开启慢查询日志会或多或少带来一定的性能影响。慢查询日志支持将日志记录写入文件,也支持将日志记录写入数据库表。

参考文档:

什么情况下产生慢日志?

看图说话,有很多开关影响着慢日志的生成,相关的参数后面会挨个说明。从上图可以看出慢日志输出的内容有两个,第一执行时间过长(大于设置的long_query_time阈值);第二未使用索引,或者未使用最优的索引。这两种日志默认情况下都没有打开,特别是未使用索引的日志,因为这一类的日志可能会有很多,所以还有个特别的开关log_throttle_queries_not_using_indexes用于限制每分钟输出未使用索引的日志数量。

关键代码如下:

    //(5.6.34)代码路径 /sql/sql_parse.cc : 1812
    bool log_slow_applicable(THD *thd)
    {
      if (thd->enable_slow_log)
      {
        bool warn_no_index= ((thd->server_status &
                              (SERVER_QUERY_NO_INDEX_USED |
                               SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
                             opt_log_queries_not_using_indexes &&
                             !(sql_command_flags[thd->lex->sql_command] &
                               CF_STATUS_COMMAND));
        bool log_this_query=  ((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
                               warn_no_index) &&
                              (thd->get_examined_row_count() >=
                               thd->variables.min_examined_row_limit);
        bool suppress_logging= log_throttle_qni.log(thd, warn_no_index);
        if (!suppress_logging && log_this_query)
          DBUG_RETURN(true);
      }
      DBUG_RETURN(false);
    }

Slow log调用栈(MySQL 5.6.34 ):

sql_cache.cc:  1003:    3: | | >Query_cache::end_of_result
sql_cache.cc:  1007:    3: | | <Query_cache::end_of_result 1007
sql_parse.cc:  1937:    3: | | >log_slow_statement
sql_parse.cc:  1862:    4: | | | >log_slow_applicable
sql_parse.cc:  1891:    4: | | | <log_slow_applicable 1891
sql_parse.cc:  1906:    4: | | | >log_slow_do
sql_parse.cc:   611:    4: | | | | THD::enter_stage:
sql_profile.cc: 348:    5: | | | | >PROFILING::status_change
sql_profile.cc: 354:    5: | | | | <PROFILING::status_change 354
      log.cc:  1999:    5: | | | | >MYSQL_QUERY_LOG::write
mf_iocache.c:  1740:    6: | | | | | >my_b_flush_io_cache
mf_iocache.c:  1741:    6: | | | | | | enter: cache: 0x2ca7f50
  my_write.c:    45:    7: | | | | | | >my_write
  my_write.c:    47:    7: | | | | | | | my: fd: 31  Buffer: ...
  my_write.c:   115:    7: | | | | | | <my_write 115
mf_iocache.c:  1809:    6: | | | | | <my_b_flush_io_cache 1809
      log.cc:  2117:    5: | | | | <MYSQL_QUERY_LOG::write 2117
sql_parse.cc:  1918:    4: | | | <log_slow_do 1918
sql_parse.cc:  1942:    3: | | <log_slow_statement 1942

慢日志相关参数

以上应该是最完整的和慢日志相关的所有参数,大多数参数都有前置条件,所以在使用的时候可以参照上面的流程图。5.6官方文档:

https://dev.mysql.com/doc/refman/5.6/en/server-system-variables.html

https://dev.mysql.com/doc/refman/5.6/en/server-options.html

慢日志输出内容

第一行:标记日志产生的时间,准确说是SQL执行完成的时间点,改行记录每一秒只打印一条;

第二行:客户端的账户信息,两个用户名(第一个是授权账户,第二个为登录账户),客户端IP地址,还有mysqld的线程ID;

第三行:查询执行的信息,包括查询时长,锁持有时长,返回客户端的行数,扫描行数。通常我需要优化的就是最后一个内容,尽量减少SQL语句扫描的数据行数。

第四行:通过代码看,貌似和第一行的时间没有区别。

第五话:最后就是产生慢查询的SQL语句;

--log-short-format=true:

如果mysqld启动时指定了--log-short-format参数,则不会输出第一、第二行。

log-queries-not-using-indexes=on   

log_throttle_queries_not_using_indexes > 0 :

如果启用了以上两个参数,每分钟超过log_throttle_queries_not_using_indexes配置的未使用索引的慢日志将会被抑制,被抑制的信息会被汇总,每分钟输出一次。格式如下:


# Time: 170526 11:26:10
# User@Host: [] @  []  Id:    38
# Query_time: 0.021872  Lock_time: 0.008620 Rows_sent: 0  Rows_examined: 0
SET timestamp=1495769170;
throttle:         14 'index not used' warning(s) suppressed.;

慢日志分析工具

  1. 官方自带工具: mysqldumpslow
  2. 开源工具:mysqlsla
  3. percona-toolkit:工具包中的pt-query-digest工具可以分析汇总慢查询信息,具体逻辑可以看SlowLogParser这个函数;

总的来mysql的日志内容本身不复杂,上面3个工具都是用perl脚本实现,代码行数不超过200行,有兴趣的同学也可以自己尝试着解析下。详情可以参阅下这篇文章:

《MySQL 慢查询设置和分析工具 》

以上的工具可以支撑慢日志的常用统计,但是当我们需要做到SQL级别的统计时,我们还需要取解析SQL把参数提取出来。

慢日志的清理与备份

删除:直接删除慢日志文件,执行flush logs(必须的);

备份:先用mv重命名文件(不要跨分区),然后执行flush logs(必须的);

另外修改系统变量slow_query_log_file也可以立即生效;

执行flush logs,系统会先close当前的句柄,然后重新open;mv , rm日志文件系统并不会报错,具体的原因可以Google下linux i_count i_nlink

原创声明,本文系作者授权云+社区发表,未经许可,不得转载。

如有侵权,请联系 yunjia_community@tencent.com 删除。

编辑于

邹鹏的专栏

1 篇文章1 人订阅

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏乐沙弥的世界

MySQL 慢查询日志(Slow Query Log)

    同大多数关系型数据库一样,日志文件是MySQL数据库的重要组成部分。MySQL有几种不同的日志文件,通常包括错误日志文件,二进制日志,通用日志,慢查询日...

462
来自专栏散尽浮华

Mysql读写分离方案-MySQL Proxy环境部署记录

Mysql的读写分离可以使用MySQL Proxy和Amoeba实现,其实也可以使用MySQL-MMM实现读写分离的自动切换。MySQL Proxy有一项强大功...

2878
来自专栏杨建荣的学习笔记

关于权限设置的一个小把戏(r2第27天)

现在有一个需求,需要开放一些"特殊“的权限给开发组。 具体的背景是这样的: 有三个数据库用户,tabowner, tabconn, tab_temp三个用户 t...

2609
来自专栏Jackson0714

30分钟全面解析-SQL事务+隔离级别+阻塞+死锁

2746
来自专栏jouypub

MySQL事务锁问题-Lock wait timeout exceeded

  接口响应时间超长,耗时几十秒才返回错误提示,后台日志中出现Lock wait timeout exceeded; try restarting transa...

1807
来自专栏黑白安全

MSSQL手工注入总结

之前搞mssql数据库的注入都是直接跑工具,但是总是有些注入点工具一扫就崩,关键时候还是要手工注入,因此总结学习mssql手工注入,写此文留作笔记。本次主要总结...

1332
来自专栏杨建荣的学习笔记

使用12c PDB整合环境的总结 (r10笔记第66天)

从开始使用12c PDB整合环境以来,发现确实不错,原来11g中整合的难题在这里得到了解决。 目前存在多套的测试环境,之前整合了一批,基本是采用整合schema...

34916
来自专栏晓晨的专栏

Sql Server利用游标批量清空数据表

703
来自专栏Java编程技术

Mysql中INSERT ... ON DUPLICATE KEY UPDATE的实践

在日常业务开发中经常有这样一个场景,首先创建一条记录,然后插入到数据库;如果数据库已经存在同一主键的记录,则执行update操作,如果不存在,则执行insert...

893
来自专栏散尽浮华

Mysql慢查询操作梳理

Mysql慢查询解释 MySQL的慢查询日志是MySQL提供的一种日志记录,它用来记录在MySQL中响应时间超过阀值的语句,具体指运行时间超过long_quer...

1946

扫码关注云+社区