Windows程序调试时快速记录日志的方法
邓俊
（江苏科技大学 计算机科学与工程学院，江苏省镇江市，212003）
摘 要:生成日志信息是程序调试中常用的方法；将运行过程中的某些信息记录下来事后分析，有助于发现程序中的错误。目前记录日志的方法存在两大缺点：速度慢和程序崩溃时容易丢失信息。本文从这两点着手，使用内存映射文件API，设计出一套更快速、更稳定的日志生成方法。实验结果表明，该方法记录日志的最低耗时，仅是执行四字节变量赋值语句耗时的三倍左右，而传统方法是执行赋值语句耗时的上百倍；另外，该方法不会因程序崩溃而丢失信息。
关键字: Windows；调试；快速；日志 中图法分类号: TP319 文献标识码: A
A Method of Fast Recording Log File for Debugging Windows program
Deng Jun
(School of Computer Science and Technology, Jiangsu University of Science and Technology, Zhenjiang, 212003)
Abstract: Logging information is a usual method for debugging Windows program. We log some information and
then analyses them to help finding errors. At present, there are two shortages of logging information which are low speed and losing information easily when program crash. This paper designed a faster and more stable method of logging information using API of memory mapping file. The results of tests show that the lowest consumed time of this method is just about three times of executing assignment statement. However, the consumed time of traditional method is hundreds times of executing assignment statement assignment. In addition, the method does not lose any information when debugging program crash suddenly. Key words: Windows; Debugging; Fast; Log File
/**** 下面这句产生日志信息 ****
printf("Check the status of work thread: \nHandle = %d \n", hThread,); //*/ //下面是输出结果
printf("g_sum = %d \n", g_ Result); }
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(){
ThreadProc, 0, 0,NULL);
该代码创建一个工作线程来处理数据，然后由主线程显示处理的结果。初衷希望结果为“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 常用函数耗时情况（单位：毫秒）
从表格中数据可以看出：向文件输出信息比向显示器输出快；有缓存比没有缓存快；数据块方式比格式化方式快。
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
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
*((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倍以上。
5 结束语
本文分析了影响产生日志文件速度的各种因素，并在此基础上设计出一套快速记录日志的方法。这对调试程序非常有帮助。该方法不足在于，事先要指定日志文件的大
小，没有什么公式可以精确计算这个值，使用者只能根据经验来进行估算。
这里概括一下该方法的要点：首先，使用内存映射文件的方式来操作文件。其次，尽量减小日志信息的长度。然后，尽量使用数据块而不是格式化方式记录信息，并要充分利用数据总线带宽。最后，创建日志文件要在独立的进程中进行，以防止数据丢失。
参考文献
[1] Jeffrey Richter.Windows核心编程[M].清华大学出版社.2008
[2] 张正秋.Windows应用程序捆绑核心编程[M].清华大学出版社.2007
Windows程序调试时快速记录日志的方法
邓俊
（江苏科技大学 计算机科学与工程学院，江苏省镇江市，212003）
摘 要:生成日志信息是程序调试中常用的方法；将运行过程中的某些信息记录下来事后分析，有助于发现程序中的错误。目前记录日志的方法存在两大缺点：速度慢和程序崩溃时容易丢失信息。本文从这两点着手，使用内存映射文件API，设计出一套更快速、更稳定的日志生成方法。实验结果表明，该方法记录日志的最低耗时，仅是执行四字节变量赋值语句耗时的三倍左右，而传统方法是执行赋值语句耗时的上百倍；另外，该方法不会因程序崩溃而丢失信息。
关键字: Windows；调试；快速；日志 中图法分类号: TP319 文献标识码: A
A Method of Fast Recording Log File for Debugging Windows program
Deng Jun
(School of Computer Science and Technology, Jiangsu University of Science and Technology, Zhenjiang, 212003)
Abstract: Logging information is a usual method for debugging Windows program. We log some information and
then analyses them to help finding errors. At present, there are two shortages of logging information which are low speed and losing information easily when program crash. This paper designed a faster and more stable method of logging information using API of memory mapping file. The results of tests show that the lowest consumed time of this method is just about three times of executing assignment statement. However, the consumed time of traditional method is hundreds times of executing assignment statement assignment. In addition, the method does not lose any information when debugging program crash suddenly. Key words: Windows; Debugging; Fast; Log File
/**** 下面这句产生日志信息 ****
printf("Check the status of work thread: \nHandle = %d \n", hThread,); //*/ //下面是输出结果
printf("g_sum = %d \n", g_ Result); }
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(){
ThreadProc, 0, 0,NULL);
该代码创建一个工作线程来处理数据，然后由主线程显示处理的结果。初衷希望结果为“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 常用函数耗时情况（单位：毫秒）
从表格中数据可以看出：向文件输出信息比向显示器输出快；有缓存比没有缓存快；数据块方式比格式化方式快。
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
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
*((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倍以上。
5 结束语
本文分析了影响产生日志文件速度的各种因素，并在此基础上设计出一套快速记录日志的方法。这对调试程序非常有帮助。该方法不足在于，事先要指定日志文件的大
小，没有什么公式可以精确计算这个值，使用者只能根据经验来进行估算。
这里概括一下该方法的要点：首先，使用内存映射文件的方式来操作文件。其次，尽量减小日志信息的长度。然后，尽量使用数据块而不是格式化方式记录信息，并要充分利用数据总线带宽。最后，创建日志文件要在独立的进程中进行，以防止数据丢失。
参考文献
[1] Jeffrey Richter.Windows核心编程[M].清华大学出版社.2008
[2] 张正秋.Windows应用程序捆绑核心编程[M].清华大学出版社.2007