Windows程序调试时快速记录日志的方法

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