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开销还是像之前一样,但是已经可以容忍了。没有在多线程环境下测试,但是料想应该能正常工作。