高效可靠的日志记录模块的构建 | 艾瑞枫∑°

高效可靠的日志记录模块的构建

　　作为软件开发者，要记录软件日志是再平常不过的事儿了————就跟吃家常便饭一样，比如：日志是后台服务进程能唯一发出抱怨的地方(不信可以看看 ls /var/log)，可以用日志记录用户的行为及操作，还可以用日志记录软件自身的行为以便用于调试（见下一篇文章《基于日志的内存泄露的检测方法》就是利用这个哈）。既然这么多地方都用到了日志，那么作为一个崇尚自由的程序员，就不能重复造轮子———至少自己不能。所以必须要创建一个可移植的，简便高效的日志模块。

　　第一步要确定日志的格式，虽然各种风格的日志格式各异，但我比较喜欢linux风格的日志记录，命令vim /var/log/kern.log，可以看到日志内容被高亮显示了：

　　其中每行的开头是记录此条记录时的时间，这里是7月7日16时45分01秒，ulinux是主机名，CRON[25642]是记录进程的名字及PID(这里是内核)，最后是日志内容。Linux日志记录根据重要性还分为从DEBUG到EMERG的若干等级，标识该消息的重要性。在Linux下编程可以用syslog函数向系统日志(/var/log/syslog)中写入信息，syslog函数的用法如下：

View Code C

1234567891011121314

/* * ident字符串会被附加到每一条用syslog写入的条目前面（可为NULL）， * option指定一些可选项(如是否记录PID)，falicity用于指定该进程的类型（如FTP是LOG_FTP） */void openlog(const char *ident, int option, int facility);  /* * priority指定消息的等级，有LOG_EMERG/ALERT/CRIT/ERR/WARNING/NOTICE/INFO/DEBUG * 等8个等级，越往后的等级越不重要 */void syslog(int priority, const char*format, ...); void closelog(void);

　　Linux的日志设计从输出格式到函数用法都很有借鉴意义，但又考虑到此日志可能会作为软件调试日志来用，因此还需要附上写此条记录的代码所在的文件名、函数名、行号等信息，进程名和PID显然不需要了，在此用[]来存放等级信息，然后再用{}来存放代码位置信息。现在我们定义的日志格式就成了这个样子了： 06/Jul/2012 22:28:18 [Debug] {test.c main 18} 记录内容… … 。看上去蛮顺眼的，就这么定了吧。

　　现在已经设计完毕，该去实现它了。因为这些代码将来还不知道在什么环境下运行，所以在实现过程中要考虑到很多内容：

　　1、可移植性。使用C语言编写，因此各种平台下的各种C/C++项目都可以用。
　　2、便捷性。向开发人员提供便捷的操作接口，只需一行代码就可以写入日志。
　　3、可靠性。需要考虑到多线程的情况，必须设计成线程安全的。
　　4、灵活性。提供稍微复杂一点的接口以完成更“个性化”的操作。
　　5、支持多个日志。默认可以同时打开100个日志文件，此值可根据需要调整。
　　6、支持系统日志。开发人员除了那100个可以使用的日志外，还存在一个特殊的“系统日志”，用于跟踪内存分配/释放操作，主要由内存调试模块用来分析内存泄漏等（见下一篇文章《基于日志的内存泄露的检测方法》)，但是也允许开发人员使用。

　　根据这些准则，首先把数据结构和用户接口实现了：

View Code C

1234567891011121314151617181920212223242526272829

#define MAX_LOGS 100 /* 用户最多可打开日志数 */ #define LOG_INVALID -1 /* 无效的日志描述符(初始化定义) */#define LOG_SYSTEM 0 /* 系统日志(xmalloc, xabort.etc) */#define LOG_USER 1 /* 分配给用户的最小日志描述符 */ enum{ LOG_LEVEL_EMERG = 0, /* System is unusable */ LOG_LEVEL_ALERT, /* Action must be taken immediately */ LOG_LEVEL_CRIT, /* Critical conditions */ LOG_LEVEL_ERROR, /* Error conditions */ LOG_LEVEL_WARNING, /* Warning conditions */ LOG_LEVEL_NOTICE, /* Normal, but significant */ LOG_LEVEL_INFO, /* Information */ LOG_LEVEL_DEBUG, /* DEBUG message */}; int log_open(const char *path, const char* mode); /* 打开用户日志文件 */int log_open_sys(const char *path, const char* mode); /* 打开系统日志文件 */ void log_printf_raw(int log_id, const char *fmt, ...); /* 无日期、等级、位置信息 */void log_printf0(int log_id, int level, const char *fmt, ...); /* 无位置信息 */ void log_flush(int log_id); /* 将缓冲区数据写入日志 */void log_flush_sys(); void log_close(int log_id); /* 关闭日志文件 */void log_close_sys();void log_close_all();

　　用户使用log_open来打开日志(参数跟fopen一样)，然后就可以调用log_printf_raw和log_printf0来向日志中添加记录了。这两个函数的第一个参数都是log_open返回的描述符，两者不同的是前者仅写入用户指定的内容，而后者则会在每条记录的开头添加时间信息、重要等级信息。但是遗憾的是，两者都没有记录代码位置信息（文件名、函数名、行号等），这是因为以下两个原因：1、再加上行号会导致函数的参数太多，易用性不强。2、用户每调用这个函数都要键入文件名等信息，累不说，代码也会不美观。log_printf就是为了解决这个问题的，但是它的定义要颇费一番周折，现在要一步步分析它产生的过程。

　　接下来就要谈到宏的高级特性了。首先，有几个特殊的宏是专门用来记录该行代码的文件名、函数名和行号信息的，它们是__FILE__, __FUNCTION__, __LINE__，这好像方便了一些，因为调用函数的时候不用先看一下文件名、函数名再数一下行号了，但是这还是不理想，还是累啊！怎么办呢？其实我们可以换个思路，当用户要调用写入函数的时候，自动地给它加上这些信息多好！于是这需要用到宏的一般替换功能，比如这样定义:

#define log_printf(x) log_printf0(x, __FILE__, __FUNCTION__, __LINE__)

　　于是当用户调用log_printf的时候，行号等信息就被自动加上了！但是，别高兴地太早了，咱们这里的log_printf0有个可变参数”…”，要怎么替换它？没辙。而且这样的话还要修改log_printf0的定义，破坏了原来设计的接口。
　　是不是真没办法了？NO。您一定知道有可变参数函数，但您知道有可变参数红这种东西吗？如果不知道，那就真没辙了。算起来这也算宏的高级特性了，最新的GCC和VS才开始支持。可变参数宏就是为了解决这种情况而生的! 它用__VA_ARGS__来代表所有可变的参数部分。于是，我们的定义变成了这样：

#define log_printf(id, level, fmt, …) log_printf0(id, level, __FILE__, __FUNCTION__, __LINE__, fmt, __VA_ARGS__)

　　现在目标大体实现了，而且编译通过。但是这还是改变了log_printf0的接口啊，以后调用太复杂了！别急，宏的威力还不止如此。您是否知道宏的连接特性？用##可以连接起两个字符串来，就像”AB”##”CD”，在预处理之后就会变成”ABCD”了！而我们的fmt参数又是一个形如”%s %d”样式的字符串，我们再给它加上几个参数又如何！哈哈，感觉到希望了！

#define log_printf(id, level, fmt, …) log_printf0(id, level, “{%s %s %d} “##fmt, __FILE__, __FUNCTION__, __LINE__, __VA_ARGS)

　　现在，如果我们调用 log_printf(id, LOG_DEBUG, “%s”, “内容”)，它就会被展开为 log_printf0(id, LOG_DEBUG, “{%s %s %d} %s”, __FILE__, __FUNCTION__, __LINE__ , “内容”)

　　看似大功告成！但是其实还不够完善，
　　首先，因为__FILE__是全路径名，会导致日志臃肿；
　　其次，当用户没有传入可变参数的时候（比如fmt是一个纯字符串），在展开后__LINE__后面还有一个多余的逗号。当然可以告诉开发者一定要传个参数进来，但这太不友好了。其实编译器开发者们也考虑到了这个问题，解决方法是在__VA_ARGS__前加上##（这里不是字符串连接作用哦）；
　　最后，在给用户看的日志中，可能不希望透漏代码位置信息；可以的解决方案是在DEBUG模式下生成代码位置信息，而Release模式下不生成此信息，宏DBG_LOGTRACE控制此特性。

这是log_printf的最终版：

View Code C

123456789

#ifdef DBG_LOGTRACE #define log_printf(id, level, fmt, ...) log_printf0(id, level, "{%s %s %d} "##fmt, path_find_file_name(__FILE__), __FUNCTION__, __LINE__, ##__VA_ARGS__)#else #define log_printf(id, level, fmt, ...) log_printf0(id, level, fmt, ##__VA_ARGS__)#endif

一个完整的日志使用示例如下：

View Code C

123456789101112

int f1 = log_open(path, "w"); /* 软件启动时或使用前 */... log_printf(f1, LOG_DEBUG, "现在%s的值是%d", "a", 100);log_printf(f1, LOG_DEBUG, "%s测试", "bb"); int f2 = log_open(path2, "a"); /* 又要写另一个日志了 */log_printf (f2, LOG_INFO, "另一个日志");log_close(f2);...log_close(f1); /* 软件推出前或不再使用日志后 */

生成的第一个LOG内容如下：

06/Jul/2012 22:28:26 [Debug] {iri.c func1 144} 现在a的值是100
06/Jul/2012 22:28:26 [Debug] {iri.c func2 721} bb测试

日志格式完全满足调试要求了。接下来看看具体的实现。使用静态全部变量数据来存放文件指针，再声明一个同样大的数组来存放对应的自旋锁。
自旋锁用来实现线程间的互斥，如果不明白可以参见前一篇文件《线程同步与互斥——可移植的用户空间自旋锁》。

View Code C

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102

/* 日志记录 */struct log_level_desc{ enum LOG_LEVEL level; char* endesc; wchar_t* cndesc;}; static struct log_level_desc log_level_descs[] = { { LOG_LEVEL_EMERG, "Emergency", L"致命" }, { LOG_LEVEL_ALERT, "Alert", L"危急" }, { LOG_LEVEL_CRIT, "Critical", L"紧急" }, { LOG_LEVEL_ERROR, "Error", L"错误" }, { LOG_LEVEL_WARNING, "Warning", L"警告" }, { LOG_LEVEL_NOTICE, "Notice", L"注意" }, { LOG_LEVEL_INFO, "Info", L"消息" }, { LOG_LEVEL_DEBUG, "Debug", L"调试" },}; static FILE* log_files[MAX_LOGS+1];static spin_lock_t log_locks[MAX_LOGS+1]; /* 打开用户日志文件 */int log_open(const char *path, const char* mode){ int i;  for (i = LOG_USER; i < MAX_LOGS; i++) { if (log_files[i] == NULL) { log_files[i] = fopen(path, mode);  if (!log_files[i]) return LOG_INVALID;  spin_init(&log_locks[i], NULL); return i; } }  return LOG_INVALID;} /* 打开系统日志文件 */int log_open_sys(const char *path, const char* mode){ if (log_files[LOG_SYSTEM]) return LOG_SYSTEM;  log_files[LOG_SYSTEM] = fopen(path, mode); if (!log_files[LOG_SYSTEM]) return LOG_INVALID;  spin_init(&log_locks[LOG_SYSTEM], NULL); return LOG_SYSTEM;} /* 写入日志文件 */void log_printf0(int log_id, int log_level, const char *fmt, ...){ FILE *fp; time_t t; char tmbuf[30]; const char *p; va_list args; int level;  if (log_id < 0 || log_id >= MAX_LOGS) return; else if (!(fp = log_files[log_id])) return;  spin_lock(&log_locks[log_id]);  if (log_level > LOG_LEVEL_DEBUG) level = LOG_LEVEL_DEBUG; else if (log_level < LOG_LEVEL_EMERG) level = LOG_LEVEL_EMERG; else level = log_level;  //时间信息 t = time(NULL); memset(tmbuf, 0, sizeof(tmbuf)); strftime(tmbuf, sizeof(tmbuf), "%d/%b/%Y %H:%M:%S", localtime(&t)); fprintf (fp, "%s ", tmbuf);  //等级信息 fprintf(fp, "[%s] ", log_level_descs[level].endesc);  //正文信息 va_start(args, fmt); vfprintf(fp, fmt, args); va_end(args);  //换行符 p = fmt + strlen(fmt) - 1; if (*p != '\n') fputc('\n', fp);  spin_unlock(&log_locks[log_id]);}

最后贴上一个现实项目中的调试日志内容：

View Code PLAIN

123456789101112131415

06/Jul/2012 21:46:42 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 190} =======================================06/Jul/2012 21:46:42 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 191} Start download url http://www.leewei.org/wp-content/plugins/nextgen-gallery/js/jquery.cycle.all.min.js?ver=2.9995.06/Jul/2012 21:46:42 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 192} Saving to E:\Projects\SafeSite\Debug\www.leewei.org+80.5\wp-content\plugins\nextgen-gallery\js\jquery@ver=2.9995.cycle.all.min.js.06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 264} Mark this downloaded url as done.06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 348} Thread finished normally.06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 190} =======================================06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 191} Start download url http://www.leewei.org/wp-content/plugins/multi-level-navigation-plugin/scripts/superfish.js?ver=1.4.8.06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 192} Saving to E:\Projects\SafeSite\Debug\www.leewei.org+80.5\wp-content\plugins\multi-level-navigation-plugin\scripts\superfish@ver=1.4.8.js.06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 264} Mark this downloaded url as done.06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 348} Thread finished normally.06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 190} =======================================06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 191} Start download url http://www.leewei.org/xmlrpc.php?rsd.06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 192} Saving to E:\Projects\SafeSite\Debug\www.leewei.org+80.5\[e-mail].06/Jul/2012 21:46:44 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 264} Mark this downloaded url as done.06/Jul/2012 21:46:44 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 348} Thread finished normally.

呵呵，这才算是大功告成了！
短短几百行代码，以后就能一劳永逸了 ~\(≧▽≦)/~