实时多线程系统中程序日志的实现

为了分析软件系统在测试和运行期产生的故障，目前大多数软件系统所广泛使用的一种方法就是日志记录。但系统在保存日志时需要大量的磁盘I/O操作，同时由于多线程并发互斥访问文件系统可能造成的阻塞，会引起实时软件系统的性能下降，严重时造成整个系统停止响应。

本文给出了利用循环缓冲区和单独的日志读写线程实现实时系统的日志功能。

“如果有两种方式可以编写出没有错误的程序，那么只有第三种方式是有效的。” —ALGOL语言之父Alan J. Perlis。

任何软件系统，都不可避免的存在设计上的BUG，发现BUG和解决BUG贯穿于软件系统的整个生命期。当软件系统产生非预期的结果时，分析故障原因成为首要任务。对于非实时的单线程程序，可采取设置断点、单步跟踪等手段，能比较容易地确定故障点。然而对于实时的多线程软件系统来说，这些方法不能满足实时性要求，从而在调试过程中往往使系统变得不可用。因此日志记录成为关键的计算机应用系统的生存期中一件非常重要的活动。通过分析在系统出现故障时的日志，即可确定故障原因。在运行过程中，系统将不断地产生跟踪数据，并将其写入到磁盘上的文本文件中。通常的做法是在程序运行的关键点把系统的状态信息写入磁盘，然而这种做法的副作用就是，由于磁盘I/O操作所耗费的时间往往远大于系统中实际工作线程的执行时间，甚至一次磁盘操作消耗的时间比一个线程的整个生命期还要长，这就影响了线程的执行速度，再考虑到线程间的同步运行，其他线程可能会等待该线程的执行结果，这样就会造成整个系统性能的下降，不能满足实时系统的要求。同时由于可能不只一个线程在记录运行日志，因此会有多个线程并发的访问磁盘，造成线程间的长时间阻塞和等待，更大大影响了系统运行时的响应速度，严重时可能造成系统停止响应。这种情况在实时性要求高的系统中是不允许的。

笔者在最近为IPSWITCH系统开发的网关中，利用日志线程和循环缓冲区解决了上述问题。本文把所有用来实现系统自身功能的线程统称为“工作线程”，用于读写磁盘记录日志的线程称为“日志线程”，一个可循环使用、被所有线程共享的固定大小的内存区域称为“循环缓冲区”。

在工作线程中，在需要记录日志的地方把程序运行的状态信息写入循环缓冲区，再由单独的日志线程读出并写入磁盘保存。在工作线程把日志写入缓冲区时占用的时间很少，基本不影响工作线程运行。在日志线程进行磁盘I/O操作时，不占用工作线程的运行时间，同时由于只有一个单独的日志线程对单个进行读写，因此完全避免了由于并发操作同一文件而造成的线程间的阻塞。

以下是实现上述功能的伪代码（根据面向对象思想设计成日志类）：

日志类说明 
Class ClassLogThread 
private: 
var 
Head//循环缓冲区写入指针 
Tail//循环缓冲区读取指针 
LogCount//缓冲区中待处理日志记数器 
Buffer[1024]//循环缓冲区（大小可根据实际情况在这里是一个字符串数组，数组中每个元素代表一行日志） 
Lock//同步变量，用于多线程同时读写循环缓冲区 
F//日志文件句柄 
procedureExecute//线程函数体，实现日志线程功能 
public: 
procedureADD(状态信息)//工作线程调用，把状态信息写入缓冲区 
日志类实现 
构造函数 
create 
begin 
getmem（Buffer）//申请缓冲区 
Head <- 0 //初始化指针 
Tail <- 0 
LogCount <- 0//初始化待处理日志记数器 
F <- Open(Filename)//创建或打开日志文件 
Createthread(logthread,execute)//创建日志线程并指定线程函数 
end 
析构函数 
destroy 
begin 
close(F)//关闭日志文件 
free(Buffer)//释放缓冲区 
terminate(logthread)//中止释放日志线程 
free(logthread) 
end 
线程函数体 
Execute 
Begin 
While not terminate do//循环直到线程被中止 
begin 
If LogCount > 0 then //缓冲区中有待处理日志 
Writeln(f,Buffer[tail])//写日志到文件 
Tail <- Tail + 1 mod sizeof(buffer)//循环移动指针 
Lock.Acquire//互斥访问 
LogCount <- LogCount-1 
Lock.Release//释放互斥资源 
Endif 
end 
end 
公有成员函数:ADD 
ADD(状态信息)//工作线程（或住线程）调用，把状态信息写入缓冲区 
Begin 
Lock.Acquire 
If LogCountBuffer[Head] <- 状态信息 
Head <- head + 1 mod sizeof(buffer) 
LogCount <- LogCount + 1 
Endif 
Lock.Release 
End 
在程序的初始化部分创建一个日志类的实例 
Log<-ClassLogThread.create 
在工作线程中把状态信息写入缓冲区 
…… 
i <- func(j) 
Log.ADD(timetostr(now) + inttostring(threadID) + “current i is ” + inttostring(i)) 
……

在以上的代码可以看到，在工作线程中用读写内存代替磁盘I/O操作，保证了工作线程以及系统的响应速度。同时我们也注意到，工作线程把日志写入缓冲区时同样需要线程间的互斥访问，否则就会产生意想不到的后果。通常，每个工作线程在写入缓冲区之前都要锁定共享变量LogCount和Head，在完成操作时释放该资源。但由于锁定的只是变量而非磁盘资源，因此用在同步上的时间开销同样很少。为了减少锁定资源给程序带来的负面影响，在设计时应注意最小化锁定对象，尽量把无需锁定的代码放在锁定范围之外，例如线程函数Execute中判断是否有待处理日志时，并没有锁定LogCount，同时由于Tail变量和磁盘操作都是日志线程单独操作，也被放在锁定范围之外，因此不会影响其他工作线程的运行。

一些需要注意的事项和提示：

◆在系统开始运行时就应分配好缓冲区，并且在线程中读写缓冲区时应注意缓冲区的边界，否则可能造成内存溢出。
◆在代码中可以看到，当缓冲区满时，可能会丢弃一些日志，因此为了保存所有日志，应该把缓冲区设置得尽可能大，同时精心设计需要日志记录的关键点，减少不必要的日志记录。
◆在日志中记录工作线程的ID，以便在日后分析时方便的提取同一线程的日志。
◆在日志中加时间戳，这样可方便分析不同线程之间的同步关系。
◆对于有大量线程同时进行日志记录的系统来说，这些线程将在获得和释放锁上花费大部分的时间，会影响整体系统的性能。这时可以创建多个日志线程类的实例，各自独立操作不同的缓冲区和文件，减少共享冲突的发生。在工作线程中，把日志分类，根据不同的日志类型，写入到不同的缓冲区，再由相应的日志线程写入不同文件。