一個簡單而又不影響執行的日誌函式
阿新 • • 發佈：2019-02-16
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;
}