情況描述：

最近在分析服務(wù)器的slow-log和bin-log的時候，發(fā)現(xiàn)這兩個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
而出現(xiàn)這種極長執(zhí)行時間的語句卻不固定，最終通過以下的分析過程，找到了這個問題出現(xiàn)的原因

updated at 2012-05-14: chinaunix 上也有網(wǎng)友表示遇到過這樣的情況:?鏈接

第一步：確認(rèn)相關(guān)語句沒有問題

使用以下語句，過濾出執(zhí)行時間極大SQL語句（maatkit的digest工具，按照執(zhí)行時間排序）
mysqlbinlog binlog.xxxxxxx |mk-query-digest –type binlog –nofor-explain
在測試機(jī)上執(zhí)行篩選的語句，并沒有發(fā)現(xiàn)有任何的性能異常

?

第二步：確實(shí)是否是死鎖導(dǎo)致的語句長時間hang

分析：如果出現(xiàn)能hang這么長時間的語句，必定會對服務(wù)器的性能產(chǎn)生巨大影響。而日常運(yùn)行過程中，mysql并沒有任何異常，更沒有死鎖的發(fā)生。況且死鎖的語句的等待超過timeout時，會被自動kill；而timeout不可能有如此大的值。
至此排除這語句本身存在的問題。

第三步： 再一次回到原點(diǎn)，尋找問題規(guī)律

通過對所有具有極大execute time的log記錄的分析，有了重大發(fā)現(xiàn)！ 所有execute time的值都為 4294967295 或者4294967296 。 這不就是 2³²?-1 的值嗎？！ 4個字節(jié)變量的最大值。

第四步：大膽猜想

execute time的計(jì)算應(yīng)該等于 stop_timestamp – start_timestamp ，如果stop小于start 則為負(fù)數(shù)，而execute time應(yīng)該是一個unsigned long 的變量，因此把 -1變成了 4294967295 。

過程解析：

t100 : 語句開始運(yùn)行
t101 : 時間開始同步，并把系統(tǒng)時間設(shè)置為 99
t102：語句運(yùn)行結(jié)束， 計(jì)算語句執(zhí)行時間， 99 - 100 = -1 ，又由于?query-time 是unsigned int?因此 -1 = 4294967295

?

第五步：找到合理的解釋

原來服務(wù)器每隔一段時間會運(yùn)行腳本去某個時間服務(wù)器同步時間。如果同步之前某個時刻（T）語句正巧觸發(fā)，而在執(zhí)行過程中，腳本把服務(wù)器時間設(shè)置為了 T-1 ，那么在語句執(zhí)行完進(jìn)行時間結(jié)算時，就會得到語句執(zhí)行了-1秒的結(jié)論。通過unsigned的轉(zhuǎn)后就變成了 4294967295這個恐怖的值了。

總結(jié)

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

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。