Windows程序调试时快速记录日志的方法
摘 要:生成日志信息是程序调试中常用的方法;将运行过程中的某些信息记录下来事后分析,有助于发现程序中的错误。目前记录日志的方法存在两大缺点:速度慢和程序崩溃时容易丢失信息。本文从这两点着手,使用内存映射文件API,设计出一套更快速、更稳定的日志生成方法。实验结果表明,该方法记录日志的最低耗时,仅是执行四字节变量赋值语句耗时的三倍左右,而传统方法是执行赋值语句耗时的上百倍;另外,该方法不会因程序崩溃而丢失信息。
关键字: Windows;调试;快速;日志
1 引言
在调试程序时,将运行过程中的某些信息记录下来,生成日志是常用的手段,事后可以分析日志信息找出问题所在。这是一种传统而又非常有效的调试手段。日志信息可以向控制台、也可以向文件输出,甚至可以向串口等设备输出。但无论哪种方式,在输出过程中,都需要CPU访问外设,因此,生成日志信息都会占用大量CPU时间,也因此,加入日志输出语句会影响程序的运行状态。程序运行时,是否生成日志信息可能表现出不一样的结果。在多任务并行程序中尤其如此,如下面程序所示:
//程序一 //测试平台:Win XP SP2、P4 3.2G CPU、512内存 int g_ Result = 0; DWORD CALLBACK ThreadProc(void *pArg) {return g_Result++;} void main(){ HANDLE hThread = CreateThread(NULL, 0, ThreadProc, 0, 0,NULL); /**** 下面这句产生日志信息 **** printf("Check the status of work thread: /nHandle = %d /n", hThread,); //*/ //下面是输出结果 printf("g_sum = %d /n", g_ Result); } |
该代码创建一个工作线程来处理数据,然后由主线程显示处理的结果。初衷希望结果为“1”;而实际上,大多数情况下结果为“0”。于是我们怀疑工作线程有时没有创建起来,因此在创建工作线程语句的后面加上日志信息,以检查工作线程是否正常启动。奇怪的是加上日志语句后,“1”出现的概率明显增加。这个现象很有意思:本想借助日志信息找出问题,结果却由于加上日志而问题出现次数减少了。在某些复杂环境下甚至会出现加上日志语句后BUG消失的情况。产生上述现象的原因是,由于工作线程在CreateThread函数返回后,未必已经执行完毕;而加上日志记录语句后,工作线程在printf打印结果前,有更多机会执行完毕。由此可知,想要日志生成语句对程序影响尽可能小,就要求日志生成语句尽可能快。
2影响日志生成速度的因素
影响日志输出速度的主要因素有两个方面:(1)输出信息的数量,(2)日志输出函数的快慢。
2.1输出信息的数量的影响
输出信息数量越多输出速度越慢,信息数量越少输出速度越快。输出不同数量的信息,所需时间是不一样的。下图是用printf函数对不同长度字符,对速度影响的测试结果;它显示了信息数量与速度呈正比关系。
图1 信息长度与耗时的关系
由图可知,信息中的字符数量多一倍,输出所花费的时间大致也多一倍。因此,减少输出信息中的冗余字符,可以提高日志输出的速度。
2.2日志输出函数的影响
日志输出函数的影响有三方面:第一是目标设备速度的影响,目标设备的不同输出速度也不同。第二是以数据块还是格式化方式输出,格式化输出往往要慢一点。第三是否以缓存的方式输出信息,有缓存会快些。
2.2.1目标设备速度的影响
目标设备的速度归根结底是由硬件速度决定的,其内部机制我们不必太关心,我们可以通过查询资料或进行测试得知它们的快慢。这里我们只讨论显示器和文件这两种情况。通过测试可知,向文件输出信息比向显示器输出要快。
2.2.2格式化的影响
同样是向文件输出信息,如果信息长度是相同的,则使用fwrite的速度比fprintf的速度要快,也就是说以数据块方式输出比格式化输出要快。产生这种速度差异的原因是,格式化输出首先要对数据进行分析和格式化,而这个过程是要耗费一定的时间,数据格式化后才输出。
2.2.3缓存的影响
一般外设为了提高速度都有缓存。就磁盘而言,它的存储是以簇为单位,一簇大约是1024Byte,所以向磁盘写入10Byte数据和写入1000Byte所消耗的时间是差不多的。以缓存方式向文件输出信息时(缓存大小一般为4096Byte),信息会先存放在缓存中,缓存存满时才会集中写入磁盘中。由于实际写盘次数减少,所以将大大提高整体速度。
使用缓存时如果程序运行中突然崩溃,最新的信息可能没能及时写入磁盘而丢失。为此有人为了保证把信息及时写入磁盘,会在fprintf等语句后面加上fflush函数。这种做法是值得注意,因为fprintf和fflush的组合所好耗费的时间,是单纯fprintf语句的很多倍,原因就是该方法舍弃了缓存的作用,使写盘次数大大增加。
下面是对几个常用函数速度测试的结果(测试平台:Win XP SP2、P4 3.2G CPU、512内存),它们输出字符长度都是十。
表1 常用函数耗时情况(单位:毫秒)
执行次数 函数名 | 20万次 | 30万次 | 40万次 |
fwrite | 31 | 62 | 94 |
fprintf | 125 | 157 | 219 |
fprint+fflush | 2094 | 3125 | 4125 |
printf | 28750 | 45859 | 61265 |
从表格中数据可以看出:向文件输出信息比向显示器输出快;有缓存比没有缓存快;数据块方式比格式化方式快。
3快速生成日志的主要思想
从上面的分析不难看出,只能从选择较快的函数着手。另外,使用时也应注意其它因素的影响,例如减小信息长度、尽量使用非格式化输出。
3.1 使用内存映射文件加快速度
内存映射文件函数操作文件,和普通的文件操作函数效果一样。但是前者的速度比后者快得多,因此该方法作为输出文件的方式效果更好。内存映射文件主要基于Win32 的虚拟内存管理机制,是虚拟内存管理系统的一个重要组成部分。
3.2 预防系统崩溃时信息丢失的方法
由于向文件输出信息会先存放在缓存中,只有当缓存满了或者用命令(如fflush函数)强制写入磁盘又或者关闭文件时,才会把缓存的信息写入磁盘。如果系统突然崩溃,信息就没有机会写入磁盘了,最新的信息也就丢失了。
为了防止这样的事情发生,最好的办法就是把缓存放在另一个进程空间里。这样即便产生日志的进程崩溃了,而它所产生的最信息依然保存在另一个进程的缓存中。这样既能有效的防止的信息丢失,又能避免fprintf+fflush那样降低速度。正好内存映射文件支持跨进程读写。具体做法如下:
(1)在服务进程中,创建命名的映射文件。然后进入可控的等待中,有结束命令时才退出等待。退出后关闭映射文件。
(2)在被调试进程中,也就是产生日志的进程中,打开命名的映射文件(之前要手动或通过程序启动服务进程),获取其首地址,然后像操作内存空间一样操作它。
(3)当被调试进程结束后(无论是正常结束还是异常结束),通过命令结束服务进程。当服务进程结束后,被调试进程所产生的日志将全部保存到磁盘中去。
该方法结构示意图如下:
图2 防信息丢失方法示意图
4快速日志系统的具体实现
该实现分为被调试端和服务端两个部分。这两个部分都要对映射文件进行操作。
4.1服务端的具体实现
下面是服务端的一个简单实现:
//程序二 void main() { HANDLE hfile = CreateFile("log.txt", GENERIC_READ | GENERIC_WRITE, FILE_SHARE_READ|FILE_SHARE_WRITE, NULL, CREATE_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL); HANDLE hfilemap = CreateFileMapping(hfile, NULL,PAGE_READWRITE, 0, 120000000, "FM_Service"); while(!_kbhit()) Sleep(1000);//等待结束 CloseHandle(hfilemap); CloseHandle(hfile); } |
上面程序的主要功能是产生一个映射文件,等待被调试进程来使用这个映射文件。当按下键盘上任何键时退出系统,日志信息随之写入磁盘。当然这个程序还可以加上进程通信、对被调试端进行监控等功能,使其功能更加强大。
4.2被调试端的具体实现
被调试端主要是打开命名的内存映射文件,然后记录信息。这里需要补充说明的是,打开内存映射文件后我们知道一个首地址。如何使用它,这对速度是有很大影响的。可以使用sprintf这样函数进行格式化输出,也可以使用memcpy这样的函数以数据块方式记录,当然后一种方法更快。但以数据块方式输出时还有一种更快的方法,那就是在32位系统下,以4个字节数据为一个单位,向能被4整除的地址写入数据,即保证写入时内存对齐。这种方法之所以快是因为它充分利用了系统的数据总线的带宽。这种情况下,再加上减少日志信息长度的方法,就能将记录日志信息的速度提到很高。
下面是被调试端的一个简单示例:
//程序三 //测试平台:Win XP SP2、P4 3.2G CPU、512内存 char *pText = "ABC/n"; #define LOOP_TIMES 30000000 void main() { DWORD i, start, end, temp, dwOffset = 0; start = GetTickCount();//测试赋值语句速度 for(i=0; i<LOOP_TIMES; i++)//第一个循环 temp = 0x12345678; end = GetTickCount(); printf("Write Mem Time2 = %d /n", end-start); HANDLE hfilemap = OpenFileMapping(FILE_MAP_WRITE, true, "FM_Service"); PBYTE pbFile = (PBYTE) MapViewOfFile(hfilemap, FILE_MAP_WRITE, 0, 0, 0); start = GetTickCount();//测试快速记录法速度 for(i=0; i<LOOP_TIMES; i++)//第二个循环 { *((int *)(pbFile+dwOffset)) = *((int *)(pText)); dwOffset += 4; } end = GetTickCount(); printf("Write MMF Time1 = %d /n", end-start); UnmapViewOfFile(pbFile); CloseHandle(hfilemap); } |
经测试该程序的第一个循环执行三千万次的赋值语句耗时为78ms。第二个循环同样执行三千万次,它会在250ms内记录114MB大小的日志信息。换句话说,记录日志的语句仅仅是四字节变量赋值语句耗时的三倍左右,当然这是一个极限速度。
这里对常用的日志记录函数和本文的快速记录法,相对于四字节变量赋值语句耗时倍数进行了测试,其结果如表2:
表2 各种方法相对于四字节赋值语句耗时的倍数
字符长度 记录方法 | 10个 | 20个 | 40个 |
快速记录法 | 7.95 | 12.85 | 30.00 |
fwrite | 126.15 | 192.31 | 366.66 |
fprintf | 372.56 | 514.74 | 823.21 |
从表格中数据可以看出:本文的方法比常用的方法快了10倍以上。
5 结束语
本文分析了影响产生日志文件速度的各种因素,并在此基础上设计出一套快速记录日志的方法。这对调试程序非常有帮助。该方法不足在于,事先要指定日志文件的大小,没有什么公式可以精确计算这个值,使用者只能根据经验来进行估算。
这里概括一下该方法的要点:首先,使用内存映射文件的方式来操作文件。其次,尽量减小日志信息的长度。然后,尽量使用数据块而不是格式化方式记录信息,并要充分利用数据总线带宽。最后,创建日志文件要在独立的进程中进行,以防止数据丢失。
参考文献
[1] Jeffrey Richter.Windows核心编程[M].清华大学出版社.2008
[2] 张正秋.Windows应用程序捆绑核心编程[M].清华大学出版社.2007