情况描述：

最近在分析服务器的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. server日志的路径分析    (阅读：10079)
2. AWStats简介：Apache/Windows IIS的日志分析工具的下载，安装，配置样例和使用（含6.9中文定义补丁）    (阅读：8833)
3. 利用脚本分析日志并利用snmp自定义OID，再通过cacti画图    (阅读：8670)
4. tomcat catalina.out日志切割每天生成一个文件    (阅读：8065)
5. 分布式日志系统scribe使用手记    (阅读：8021)
6. AWStats是一个基于Perl的WEB日志分析工具。    (阅读：6089)
7. 使用nginx记日志    (阅读：5047)
8. 大于2GB的Listener.log和运行超过198天的主机上的Oracle实例    (阅读：4840)
9. 在 shell 脚本里打日志    (阅读：4767)
10. Sentry: 错误日志集中管理    (阅读：4334)