一个简单而又不影响运行的日志函数

I/O操作比较耗时，在硬盘频繁读写时尤其耗时，比如杀毒软件扫描，磁盘碎片整理，索引服务之类的。如果在运行效率有要求的环境下有大量I/O的话就不得不考虑如何让I/O不影响运行。

I/O操作比如说日志，可以输出到DbgView，也可以输出到文件。当有bug时，可以告诉我们问题出在哪儿。输出到DbgView与输出到文件各有利弊。输出到DbgView，好处是不影响程序运行，坏处是需要开DbgView(有时客户不方便开)，要考虑DbgView内存开销(这样的话，无法看到时间靠前的日志)，不能动DbgView(否则会堵塞程序，拖动进度条，保存文件，清除log之类的操作)。输出到文件，好处是要求少，坏处是有大量I/O操作，必须合理的设计保证不影响程序运行。

最先想到也是最容易想到的解决方案是，将Log丢到缓冲，创建一个子线程专门将这些Log输出到文件。我问自己能不能在现有的文件日志基础上做最少的改动以实现目的。

现有的日志函数

static unsigned short  EnableLog = 1;	//允许写日志
static unsigned short  EnableDbgView = 0;	//允许写到debug view
TCHAR g_szFilePath[MAX_PATH];
int MyIO(LPCSTR fmt, ...)
{
	va_list ap;
	char MsgBuf[512] = {0};	

	static char	szDate[50] = {0};
	static char	szTime[50] = {0};

	clock_t tStart = clock();
	va_start( ap,fmt );
	vsprintf( MsgBuf,fmt,ap );
	va_end( ap );
	if(MsgBuf[strlen(MsgBuf)-1] == '\n')  
		MsgBuf[strlen(MsgBuf)-1] = '\0';

	if(EnableLog)
	{
		SYSTEMTIME st;  
		char szLog[1024] = {0}
		GetLocalTime(&st);              // 取当前系统时间
		sprintf_s(szTime, sizeof(szTime), "%02d:%02d:%02d.%03d", \
			st.wHour, st.wMinute, st.wSecond, st.wMilliseconds);
		
		sprintf_s(szDate, sizeof(szDate), "%04d%02d%02d", st.wYear, st.wMonth, st.wDay);
		
		sprintf_s();
		int nBufLen = strlen(szBufferPerSec);
		sprintf(szLog, "%s -> %s\r\n", szTime, MsgBuf);	

		TCHAR szFileName[MAX_PATH];
		sprintf_s(szFileName, sizeof(szFileName), "%sMyIODemo_%s.txt", \
			g_szFilePath, szDate);
		HANDLE hLogFile = CreateFile(szFileName, 
				GENERIC_WRITE,
				FILE_SHARE_READ,//|FILE_SHARE_DELETE,
				NULL,
				OPEN_ALWAYS,//if not exist,creat new //CREATE_ALWAYS,
				FILE_ATTRIBUTE_NORMAL,
				0);

		if(hLogFile  == INVALID_HANDLE_VALUE)
		{
			TRACE("Error!!!can't open %s to write", szFileName);
			return -1;
		}
		SetFilePointer(hLogFile , NULL, NULL, FILE_END);		

		BOOL bRet = WriteFile(hLogFile , szLog, strlen(szLog), 
			NULL, NULL);

		if(!bRet)
		{
			TRACE( "Error!Could not write to file (error %d)\n", GetLastError());
		}

		if(clock()-tStart>2)
		{				
			OutputDebugString("Error!log time-consumingly to file");
		}
		if(hLogFile )
		{
			CloseHandle(hLogFile );
			hLogFile  = NULL;
		}
	}

	if(EnableDbgView)
		OutputDebugString(MsgBuf);

	return 0;
}

我想到了采用异步I/O的方式，或许能解决这个问题。按照Windows核心编程的说法

Consider a thread that issues an asynchronous I/O request to a device. This I/O request is passed to a device driver,which assumes the responsibility of actually performing the I/O.While the device driver waits for the device to respond, the application's thread is not suspended as it waits for the I/O request to complete. Instead, this thread continues executing and performs other usefull tasks.

但是采用了异步I/O之后，实际测试过程中，CreateFile有时候需要16ms，而WriteFile经常超过2ms，甚至超过100ms。因此我考虑文件句柄放到全局，一开始的时候创建，退出程序前销毁，同时将日志先丢到缓冲，每隔1s再一次性写到文件中。

改进后的日志函数

static unsigned short  EnableLog = 1;		//允许写日志
static unsigned short  EnableDbgView = 0;	//允许写到debug view
static HANDLE g_hLogFile = NULL;
static OVERLAPPED g_laped = {0};
TCHAR g_szFilePath[MAX_PATH];

int MyIO(LPCSTR fmt, ...)
{
	va_list ap;
	SYSTEMTIME _SysTime;


	char MsgBuf[512] = {0};	


	bool bFlush = false;
	static clock_t tLastLog = clock()-1;
	static clock_t tLast = clock()-1;
	clock_t tStart = clock();


	char szToday[50] = {0};
	static char	szDate[50] = {0};
	static char	szTime[50] = {0};
	static char szBufferPerSec[1024*1024] = {0};
	static int nCurFileSize = 1024*1024;


	va_start( ap,fmt );
	vsprintf( MsgBuf,fmt,ap );
	va_end( ap );
	if(MsgBuf[strlen(MsgBuf)-1] == '\n')  
		MsgBuf[strlen(MsgBuf)-1] = '\0';


	if(EnableLog)
	{
		SYSTEMTIME st;  
		if(tStart>tLast)
		{
			GetLocalTime(&st);              // 取当前系统时间
			sprintf_s(szTime, sizeof(szTime), "%02d:%02d:%02d.%03d", \
					st.wHour, st.wMinute, st.wSecond, st.wMilliseconds);


			if(tStart-tLastLog>1000)
			{
				bFlush = true;	
				tLastLog = tStart;
			}		
			tLast = tStart;
		}
		
		sprintf_s(szToday, sizeof(szToday), "%04d%02d%02d", st.wYear, st.wMonth, st.wDay);
		if(strcmp(szToday, szDate))
		{
			if(g_hLogFile!=NULL)
			{
				CloseHandle(g_hLogFile);
				g_hLogFile = NULL;
			}
			strcpy(szDate, szToday);
		}


		int nBufLen = strlen(szBufferPerSec);
		sprintf(szBufferPerSec+strlen(szBufferPerSec)/*, sizeof(szBufferPerSec)*/, "%s -> %s\r\n", szTime, MsgBuf);	


		if(bFlush)
		{
			if(g_hLogFile == NULL)
			{
				TCHAR szFileName[MAX_PATH];
				sprintf_s(szFileName, sizeof(szFileName), "%sMyIODemo_%s.txt", \
					g_szFilePath, szDate);
				g_hLogFile = CreateFile(szFileName, 
						GENERIC_WRITE,
						FILE_SHARE_READ,//|FILE_SHARE_DELETE,
						NULL,
						OPEN_ALWAYS,//if not exist,creat new //CREATE_ALWAYS,
						FILE_FLAG_OVERLAPPED/*FILE_ATTRIBUTE_NORMAL*/,
						0);


				if(g_hLogFile == INVALID_HANDLE_VALUE)
				{
					TRACE("Error!!!can't open %s to write", szFileName);
					return -1;
				}
				SetFilePointer(g_hLogFile, nCurFileSize, NULL, FILE_BEGIN);
				SetEndOfFile(g_hLogFile);
			}		
                        //!sld! 2011.9.13 快满的时候，文件尺寸翻倍。如果不加这个的话，一旦写入超过文件尺寸，最后文件Log将没有内容，全是NULL。
			if((int)(nCurFileSize - g_laped.Offset - strlen(szBufferPerSec))<=0)
			{
				nCurFileSize = nCurFileSize*2;
				SetFilePointer(g_hLogFile, nCurFileSize, NULL, FILE_BEGIN);
				SetEndOfFile(g_hLogFile);
			}
			BOOL bRet = WriteFile(g_hLogFile, szBufferPerSec, strlen(szBufferPerSec), 
				NULL, &g_laped);


			if(!bRet)
			{
				DWORD dwErrNo = GetLastError();
				if(dwErrNo!=ERROR_IO_PENDING)
				{
					char szErr[1024];
					sprintf_s(szErr, sizeof(szErr), "Error!Could not write to file (error %d)\n", dwErrNo);      
					OutputDebugString(szErr);
				}
			}


			if(clock()-tStart>2)
			{				
				OutputDebugString("Error!log time-consumingly to file");
			}
			g_laped.Offset+=strlen(szBufferPerSec);
			memset(szBufferPerSec, 0, sizeof(szBufferPerSec));
			
		}
	}


	if(EnableDbgView)
		OutputDebugString(MsgBuf);


	return 0;
}

现在经过测试WriteFile开销还是像之前一样，但是已经可以容忍了。没有在多线程环境下测试，但是料想应该能正常工作。