慢查询日志中出现超大时间的案例分析_MySQL

内容导读

互联网集市收集整理的这篇技术教程文章主要介绍了慢查询日志中出现超大时间的案例分析_MySQL，小编现在分享给大家，供广大互联网技能从业者学习和参考。文章包含1820字，纯文字阅读大概需要3分钟。

内容图文

bitsCN.com

情况描述：

最近在分析服务器的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 。 这不就是 2³² -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这个恐怖的值了。

bitsCN.com

内容总结

以上是互联网集市为您收集整理的慢查询日志中出现超大时间的案例分析_MySQL全部内容，希望文章能够帮你解决慢查询日志中出现超大时间的案例分析_MySQL所遇到的程序开发问题。 如果觉得互联网集市技术教程内容还不错，欢迎将互联网集市网站推荐给程序员好友。

内容备注

版权声明：本文内容由互联网用户自发贡献，该文观点与技术仅代表作者本人。本站仅提供信息存储空间服务，不拥有所有权，不承担相关法律责任。如发现本站有涉嫌侵权/违法违规的内容， 请发送邮件至 gblab@vip.qq.com 举报，一经查实，本站将立刻删除。

内容手机端

---