情況描述：

最近在分析服務(wù)器的slow-log和bin-log的時(shí)候，發(fā)現(xiàn)這兩個(gè)log中有某些語(yǔ)句的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ǎng)執(zhí)行時(shí)間的語(yǔ)句卻不固定，最終通過(guò)以下的分析過(guò)程，找到了這個(gè)問(wèn)題出現(xiàn)的原因

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

第一步：確認(rèn)相關(guān)語(yǔ)句沒(méi)有問(wèn)題

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

?

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

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

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

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

第四步：大膽猜想

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

過(guò)程解析：

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

?

第五步：找到合理的解釋

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

總結(jié)

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

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