情況描述：

最近在分析服務器的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這個恐怖的值了。

總結

以上是生活随笔為你收集整理的慢查询日志中出现超大时间的案例分析的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。