ITPub博客

首页 > 数据库 > MySQL > 一个慢查询日志中执行时间超大SQL问题分析

一个慢查询日志中执行时间超大SQL问题分析

原创 MySQL 作者:bestpaydata 时间:2016-04-30 23:24:17 0 删除 编辑

情况描述:

曾经遇到过这样一个案例,查看slow-log的时候,发现log中有某些语句的execute time 极大例如:4294967295。
log信息:#150708 21:40:04 server id 1  end_log_pos 3440531       Query   thread_id=63169 exec_time=4294967295    error_code=0
而出现这种极长执行时间的语句却不固定,最终通过以下的分析过程,找到了这个问题出现的原因。

第一步:查看语句执行情况。

将这些执行非常长的SQL提取出来。查看执行计划,走了索引,执行计划优良。在测试环境执行这些SQL语句,速度也是非常快的。

第二步:查看服务器状况。

如 果出现能hang这么长时间的语句,必定会对服务器的性能产生巨大影响。而日常运行监控中,mysql并没有任何异常,更没有死锁的发生。况且死锁的语句 的等待超过timeout时,会被自动kill;而timeout不可能有如此大的值。至此排除这语句本身存在的问题。

第三步:查看execute time定义。

百思不得其解,后仔细观察发现,这些执行语句非常长的语句的执行时间不是4294967295就是4294967296,执行时间这么相近,刚好是232 -1,难道是值超过值类型表示范围而导致?execute time的计算应该等于 stop_timestamp – start_timestamp ,如果stop小于start 则为负数,而execute time应该是一个unsigned long 的变量,因此会把 -1变成了 4294967295 。也就是说问题可能出在stop_timestamp小于start_timestamp上。出现这种情况一般是人为调整了系统时间。

根据这个思路去查找,果不其然发现:

原来服务器每隔一段时间会运行脚本去某个时间服务器同步时间。如果同步之 前某个时刻(T)语句正巧触发,而在执行过程中,脚本把服务器时间设置为了 T-1 ,那么在语句执行完进行时间结算时,就会得到语句执行了-1秒的结论。通过unsigned的转后就变成了 4294967295这个恐怖的值了。


来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/30109892/viewspace-2091364/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论

注册时间:2015-01-19

  • 博文量
    126
  • 访问量
    985774