一次Mutex死锁的原因探究

1、现象
   近期项目中调出一个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;
}

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的拥有者线程也显示出来了，而在即时调试的时候却没有该信息，须要绕一圈到内核中去查找。