IT技术博客大学习 共学习 共进步
全部 移动开发 后端 数据库 AI 算法 安全 DevOps 前端 设计 开发者

slow-log中出现极大的执行时间的问题解决

SQL部落 2009-11-29 22:00:37 累计浏览 3,160 次
本机暂存

    情况描述:

最近在分析服务器的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

    而出现这种极长执行时间的语句却不固定,最终通过以下的分析过程,找到了这个问题出现的原因

    第一步:确认相关语句没有问题

使用以下语句,过滤出执行时间极大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 。

    第五步:找到合理的解释

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

    总结:

虽然这个问题属于及其特殊的一个特例,实际运用中遇到的可能性不大,把这个问题拿出来分享的真正目的,是在于分享一个问题的分析、解决过程。以便今后触类旁通应用到其他问题的分析过程中去。如果对过程有更好的建议或意见,欢迎留言拍砖~~~

同分类推荐文章

  1. 使用deepseek进行Oracle恢复,引起重大故障 (2026-06-22 10:56:00)
  2. 接手一个只差临门一脚的数据库恢复 (2026-06-18 00:13:09)
  3. 我做了一个 AI 版的 StarRocks 升级风险扫描工具,直接帮我定位到一个风险 (2026-06-15 01:00:00)

查看更多 数据库 文章 →

建议继续学习

  1. 用Hyer来进行网站的抓取 (累计阅读 158,250)
  2. 如何成为Python高手 (累计阅读 54,992)
  3. MySQL数据库在实际应用一些方面的介绍 (累计阅读 36,397)
  4. WordPress插件开发 -- 在插件使用数据库存储数据 (累计阅读 29,163)
  5. Mysql监控指南 (累计阅读 21,350)
  6. 由浅入深探究mysql索引结构原理、性能分析与优化 (累计阅读 16,519)
  7. 在Apache2.2.XX下安装Mod-myvhost模块 (累计阅读 13,056)
  8. Linux 性能监控、测试、优化工具 (累计阅读 13,010)
  9. include(“./file.php”)和include(“file.php”)区别 (累计阅读 12,788)
  10. 15个最好的免费开源电子商务平台 (累计阅读 12,540)