一次Mutex死鎖的原因探究
近期項目中調出一個bug,某些時候程序會卡死不動,用windbg進行載入後用 ~*kb 命令列出全部的線程棧調用,發現有多個線程調用 WaitForMultipleObjects 在等待同一個內核對象:
輸入 !handle cc f 命令列出該內核對象的具體信息:
發現是是一個Mutex對象。對象名是 Mutex_DebugMsg2 ,查找代碼知道這個Mutex是用寫log時鎖定文件寫入用的。代碼例如以下:
BOOL CDebugMsg::WriteLogA(LPSTR pszLog) { #ifdef _WRITEDEBUGMSGLOG BOOL bRet = FALSE; if (WaitForSingleObject(m_hMutex, INFINITE) != WAIT_OBJECT_0) { return bRet; } FILE* fp = _tfopen(m_ptszLogPath, _T("a+")); if (fp) { TCHAR ptszTime[16] = {0}; char pszWriteMsg[MAXDEBUGMSGCHARNUM] = {0}; GetTimeString(ptszTime); USES_CONVERSION; _snprintf(pszWriteMsg, MAXDEBUGMSGCHARNUM, "%s %s\n", T2A(ptszTime), pszLog); fputs(pszWriteMsg, fp); fclose(fp); bRet = TRUE; } ReleaseMutex(m_hMutex); return bRet; #endif return FALSE; }
為了知道那個線程占用了Mutex沒有釋放,參考此篇文章說明(http://blog.csdn.net/gufeng99/article/details/46714711)
同一時候,為了簡化問題原因查找,寫了小Demo起3個線程調用log記錄代碼,觸發上述bug,後開啟windbg進入內核調試模式。
2.1 查看測試Demo進程
2.2 查看進程的全部線程及等待狀態信息
發現有3個線程都在等待同一個Mutex,線程全部者是0xfffffa8004d1b590
2.3 查看Mutex全部者線程信息。看是那個線程在占用
找到該線程所在進程的PID = 0xC30,也就是本進程。線程ID = 0xD74
2.4 停止內核附加,切換Windbg改用用戶態調試附加Demo進程。列出全部線程信息及調用棧
發現線程擁有者就是主線程,難道是主線程調用後未釋放成功麽?為了驗證這個情況。於是在ReleaseMutex(m_hMutex)加上返回跟蹤輸出。結果每次釋放都是成功的。再看看代碼,可能的解釋不多了,想得到的可能就是WaitForSingleObject返回了。但返回值不是WAIT_OBJECT_0,導致沒有調用ReleaseMutex進行釋放。於是再跟蹤了下WaitForSingleObject的返回值,發現第一次調用時返回值是128。
去翻了下《windows核心編程》一書,原來Mutex和其它內核對象不一樣,當擁有Mutex的線程未進行釋放時被終止。這時Mutex處於被廢棄狀態。其它線程WaitForSingleObject可馬上獲得Mutex的全部權。但返回值會是WAIT_ABANDONED(128)。而並非WAIT_OBJECT_0。這是Mutex很特殊的一點。
到了這裏,原因就很明了了。因為log輸出在項目中使用很頻繁。而寫log時又須要反復調用fopen()和fclose打開關閉文件,這對IO的操作是比較費時間的。導致某些線程在此處因為等待超時被終止(因為其它Mutex是可跨進程的。所以其它進程中的線程意外終止或進程未正常退出都會有此問題)。進而導致Mutex未被釋放處於廢棄狀態。而程序收到WAIT_ABANDONED後未是Mutex進行釋放,導致Mutex死鎖。這裏再次深刻的警示。線程是不能任意終止的,同一時候頻繁打開關閉文件操作也是不合理的,正確的做法應該是打開一次後保存文件句柄,再程序退出時再關閉。
另因為這個bug不是必現(因為線程不是每次都會因為等待超時被終止),在調試過程中我保存了下dump,後來調試下dump的時候顯示handle信息是發現一個很有意思的事情:
dump中在調用 !handle cc f 命令後,同一時候也將Mutex的擁有者線程也顯示出來了,而在即時調試的時候卻沒有該信息,須要繞一圈到內核中去查找。
一次Mutex死鎖的原因探究