慢查询日志中出现超大时间的案例分析
来源:互联网 发布:葵千惠喷水 知乎 编辑:程序博客网 时间:2024/05/21 21:36
情况描述:
最近在分析服务器的slow-log和bin-log的时候,发现这两个log中有某些语句的execute time 极大例如:4294967295。
log信息:#091008 21:40:04 server id 1 end_log_pos 3440531 Query thread_id=63169 exec_time=4294967295 error_code=0
而出现这种极长执行时间的语句却不固定,最终通过以下的分析过程,找到了这个问题出现的原因updated at 2012-05-14: chinaunix 上也有网友表示遇到过这样的情况: 链接
第一步:确认相关语句没有问题
使用以下语句,过滤出执行时间极大SQL语句(maatkit的digest工具,按照执行时间排序)
mysqlbinlog binlog.xxxxxxx |mk-query-digest –type binlog –nofor-explain
在测试机上执行筛选的语句,并没有发现有任何的性能异常
第二步:确实是否是死锁导致的语句长时间hang
分析:如果出现能hang这么长时间的语句,必定会对服务器的性能产生巨大影响。而日常运行过程中,mysql并没有任何异常,更没有死锁的发生。况且死锁的语句的等待超过timeout时,会被自动kill;而timeout不可能有如此大的值。
至此排除这语句本身存在的问题。
第三步: 再一次回到原点,寻找问题规律
通过对所有具有极大execute time的log记录的分析,有了重大发现! 所有execute time的值都为 4294967295 或者4294967296 。 这不就是 232 -1 的值吗?! 4个字节变量的最大值。
第四步:大胆猜想
execute time的计算应该等于 stop_timestamp – start_timestamp ,如果stop小于start 则为负数,而execute time应该是一个unsigned long 的变量,因此把 -1变成了 4294967295 。
过程解析:
t100 : 语句开始运行
t101 : 时间开始同步,并把系统时间设置为 99
t102:语句运行结束, 计算语句执行时间, 99 - 100 = -1 ,又由于 query-time 是unsigned int 因此 -1 = 4294967295
第五步:找到合理的解释
原来服务器每隔一段时间会运行脚本去某个时间服务器同步时间。如果同步之前某个时刻(T)语句正巧触发,而在执行过程中,脚本把服务器时间设置为了 T-1 ,那么在语句执行完进行时间结算时,就会得到语句执行了-1秒的结论。通过unsigned的转后就变成了 4294967295这个恐怖的值了。
- 慢查询日志中出现超大时间的案例分析
- 分析慢查询日志
- 慢查询日志分析
- 慢查询日志分析
- 慢查询日志分析
- mysql慢查询日志分析
- mysql慢查询日志分析
- mysql慢查询日志分析
- mysql 慢查询日志分析
- MySQL慢查询日志分析
- mysql 慢查询日志导致时间无效的假象
- 分析mysql慢查询日志的好工具--mysqlsla
- 分析mysql慢查询日志的好工具--mysqlsla
- 分析mysql慢查询日志的好工具--mysqlsla
- 分析mysql慢查询日志的好工具--mysqlsla
- 详解MySql的慢查询分析及开启慢查询日志
- 详解MySql的慢查询分析及开启慢查询日志
- 详解MySql的慢查询分析及开启慢查询日志
- 彻底学会使用epoll(一)——ET模式实现分析
- 人脸识别-人脸切图
- phpstorm直接在控制台中调试不用每次都打开浏览器
- es,redis,nginx启动
- mysql事务的默认隔离级别
- 慢查询日志中出现超大时间的案例分析
- 视频封装格式之mkv--2
- 【touch】改变文件或者目录时间的时间戳
- Session的生命周期
- Java读取配置(.properties)文件的方法
- linux 特殊的文件描述符
- 第一标
- 图像缩小到指定分辨率
- 好好做程序猿