将代码中的调试信息输出到日志文件中

一、将调试信息输出到屏幕中

1.1 一般写法

我们平常在写代码时，肯定会有一些调试信息的输出：

#include <stdio.h> #include <stdlib.h>  int main() {     char szFileName[] = "test.txt";     FILE *fp = fopen(szFileName, "r");     if (fp == NULL)     {         // 文件打开失败，提示错误并退出         printf("open file(%s) error.n", szFileName);         exit(0);     }     else     {         // 文件打开成功，进行相应的文件读/写操作     }      return 0; } 

假设当前目录下没有 test.txt 文件。当程序执行到第 7 行时，必然返回 NULL，这时候通过第 11 行的调试信息，我们可以帮助我们精确排查到程序退出的原因：原来是文件打开失败了。

那如果当前目录下存在 test.txt 文件，只是不可读呢？

• 同样输出了 open file(test.txt) error

在这种情况下如何快速定位文件打开失败的原因呢？我们可以考虑使用 errno。

1.2 使用 errno

errno 是记录系统的最后一次错误代码。错误代码是一个 int 型的值，在 errno.h 中定义。

#include <errno.h>	// errno 头文件 #include <string.h>	// strerror 头文件  // 文件打开失败，提示错误并退出 printf("open file(%s) error, errno[%d](%s).n", szFileName, errno, strerror(errno)); 

修改后再次运行 main.exe：

如果代码中包含很多的调试信息呢？我们并不能一下子知道这条信息到底是在哪里打印出来的，于是，我们又想，能不能把当前调试信息所在的文件名和源码行位置也打印出来呢，这样不就一目了然了吗。基于此，便有了 1.3 的内容。

1.3 编译器内置宏

ANSI C 标准中有几个标准预定义宏：

• __LINE__：在源代码中插入当前源代码行号
• __FILE__：在源文件中插入当前源文件名
• __FUNCTION_：在源文件中插入当前函数名
• __DATE__：在源文件中插入当前的编译日期
• __TIME__：在源文件中插入当前编译时间
• __STDC__：当要求程序严格遵循ANSI C标准时该标识被赋值为 1
• __cplusplus：当编写C++程序时该标识符被定义

于是我们这么修改输出语句：

// 文件打开失败，提示错误并退出 printf("[%s][%s:%d] open file(%s) error, errno[%d](%s).n",                                                      __FILE__,                                                     __FUNCTION__,                                                     __LINE__,                                                     szFileName,                                                      errno, strerror(errno)); 

• 从日志信息中，我们可以精确的获取到：main.c 文件中的 main 函数的第 16 行报错了，错误原因是 Permission denied

相比于之前，确实是能帮助我们精准的定位问题，但是，总不能每次都要写这么长的 printf 吧，有没有偷懒的办法呢？

1.4 使用可变宏输出调试信息

1.4.1 可变宏介绍

用可变参数宏（variadic macros）传递可变参数表，你可能很熟悉在函数中使用可变参数表，如：

void printf(const char* format, ...);

在 1999 年版本的 ISO C 标准中，宏可以像函数一样，定义时可以带有可变参数。宏的语法和函数的语法类似，如下所示：

#define DEBUG(...) printf(__VA_ARGS__)  int main() {     int x = 10;     DEBUG("x = %dn", x); // 等价于 printf("x = %dn", x);          return 0; } 

• 缺省号（...）指可变参数
• __VA_ARGS__宏用来接收不定数量的参数

这类宏在被调用时，它（这里指缺省号...）被表示成零个或多个符号（包括里面的逗号），一直到右括弧结束为止。当被调用时，在宏体（ macro body ）中，这些符号序列集合将代替里面的 _VA_ARGS_ 标识符。当宏的调用展开时，实际的参数就传递给 printf 了。

相比于 ISO C 标准，GCC 始终支持复杂的宏，它使用一种不同的语法从而可以使你可以给可变参数一个名字，如同其它参数一样。例如下面的例子：

#define DEBUG(format, args...) printf(format, args)  int main() {     int x = 10;     DEBUG("x = %dn", x); // 等价于 printf("x = %dn", x);          return 0; } 

• 这和上面举的「ISO C」定义的宏例子是完全一样的，但是这么写可读性更强并且更容易进行描述

在标准 C 里，你不能省略可变参数，但是你却可以给它传递一个空的参数。例如，下面的宏调用在「ISO C」里是非法的，因为字符串后面没有逗号：

#define DEBUG(...) printf(__VA_ARGS__)  int main() {     DEBUG("hello world.n"); // 非法调用 } 

GCC 在这种情况下可以让你完全的忽略可变参数。在上面的例子中，编译是仍然会有问题，因为宏展开后，里面的字符串后面会有个多余的逗号。为了解决这个问题， GCC 使用了一个特殊的##操作。书写格式为：

#define DEBUG(format, args...) printf(format, ##args) 

• 这里，如果可变参数被忽略或为空，##操作将使预处理器去除掉它前面的那个逗号

• 如果你在宏调用时，确实提供了一些可变参数，该宏定义也会工作正常，它会把这些可变参数放到逗号的后面

1.4.2 使用可变宏输出调试信息

有了 1.4.1 的基础知识，我们可以这么修改代码：

#define DEBUG(format, args...)              printf("[%s][%s:%d] "format"n",                          		__FILE__,                          		__FUNCTION__,                          		__LINE__,                          		##args)  // 文件打开失败，提示错误并退出 DEBUG("open file(%s) error, errno[%d](%s).", szFileName, errno, strerror(errno)); 

• 通过可变宏，完美解决了调试信息书写过长的问题

书写过长的问题解决后，又来新问题了，如果我想知道某一调试信息是何时被打印的呢？

下面让我们学习一下 Linux 中与时间相关的内容。

二、Linux 中与时间相关的函数

2.1 表示时间的结构体

通过查看头文件「/usr/include/time.h」和「/usr/include/bits/time.h」，我们可以找到下列四种表示「时间」的结构体：

/* Returned by `time'. */ typedef __time_t time_t; 

/* A time value that is accurate to the nearest    microsecond but also has a range of years. */ struct timeval {     __time_t tv_sec;       /* Seconds. */     __suseconds_t tv_usec; /* Microseconds. */ }; 

struct timespec {     __time_t tv_sec;  /* Seconds. */     long int tv_nsec; /* Nanoseconds. */ }; 

struct tm {     int tm_sec;   /* Seconds.		[0-59] (1 leap second) */     int tm_min;   /* Minutes.		[0-59] */     int tm_hour;  /* Hours.    		[0-23] */     int tm_mday;  /* Day.			[1-31] */     int tm_mon;   /* Month.			[0-11] */     int tm_year;  /* Year.			自 1900 起的年数 */     int tm_wday;  /* Day of week.	[0-6] */     int tm_yday;  /* Days in year.	[0-365] */     int tm_isdst; /* DST.			夏令时 */  #ifdef __USE_BSD     long int tm_gmtoff;    /* Seconds east of UTC. */     __const char *tm_zone; /* Timezone abbreviation. */ #else     long int __tm_gmtoff;    /* Seconds east of UTC. */     __const char *__tm_zone; /* Timezone abbreviation. */ #endif }; 

1. time_t 是一个长整型，用来表示「秒数」
2. struct timeval 结构体用「秒和微秒」来表示时间
3. struct timespec 结构体用「秒和纳秒」来表示时间
4. struct tm 直接用「秒、分、小时、天、月、年」等来表示时间

2.2 获取当前时间

// 可以获取精确到秒的当前距离1970-01-01 00:00:00 +0000 (UTC)的秒数 time_t time(time_t *t);  

// 可以获取精确到微秒的当前距离1970-01-01 00:00:00 +0000 (UTC)的微秒数 int gettimeofday(struct timeval *tv, struct timezone *tz); 

// 可以获取精确到纳秒的当前距离1970-01-01 00:00:00 +0000 (UTC)的纳秒数 int clock_gettime(clockid_t clk_id, struct timespec *tp) 

使用方式如下所示：

#include <stdio.h> #include <time.h> #include <sys/time.h>  int main() {     time_t lTime;     time(&lTime);     printf("lTime       : %ldn", lTime);      struct timeval stTimeVal;     gettimeofday(&stTimeVal, NULL);     printf("stTimeVal   : %ldn", stTimeVal.tv_sec);      struct timespec stTimeSpec;     clock_gettime(CLOCK_REALTIME, &stTimeSpec);     printf("stTimeSpec  : %ldn", stTimeSpec.tv_sec);      return 0; } 

• 我们可以通过上面三个函数获得三种不同精度的当前时间

Notes：

1. POSIX.1-2008 marks gettimeofday() as obsolete, recommending the use of clock_gettime(2) instead.
2. 并且，有人曾经做过测试，连续两次使用 gettimeofday 时，会以一种小概率出现「时光倒流」的现象，第二次函数调用得到的时间要小于或说早于第一次调用得到的时间。
3. gettimeofday 函数并不是那么稳定，没有 times 或 clock 计时准确，但它们用法相似。
4. clock有计时限制，据说是 596.5+小时，一般情况足以应付。
5. ntpd 之类的进程可能会修改系统时间，导致计时出现误差。
6. 据网上的讨论来看，TSC 和 HPET 中断之类的东西，可能导致系统的 wall time 回退。这个应该和具体的系统实现有关了，总之 gettimeofday 函数并没有保证提供怎样的精度，也不保证得到系统的准确时间，它返回的结果是「the system's best guess at wall time」。
7. 有可能的话，尽量使用 clock_gettime(CLOCK_MONOTONIC)，不过不是所有系统都实现了 posix realtime，例如 mac os x。
8. 所以现在应该用：int clock_gettime(CLOCK_MONOTONIC, struct timespec *tp);
   CLOCK_MONOTONIC：Clock that cannot be set and represents monotonic time since some unspecified starting point.

2.3 秒、毫秒、微秒、纳秒之间的转换

• 1 秒 = 1000 毫秒
• 1 毫秒 = 1000 微秒
• 1 微秒 = 1000 纳秒

so:

• 1 秒 = 1000,000 微秒（一百万微秒）
• 1 秒 = 1000,000,000 纳秒（十亿纳秒）

从秒到毫秒，毫秒到微秒，微秒到纳秒都是 1000 的倍关系，也就是多 3 个 0 的关系。

另：个人电脑的微处理器执行一道指令（如将两数相加）约需 2~4 纳秒，所以程序只要精确到纳秒就够了。

2.4 对时间进行格式化输出

1. 首先将 struct timeval 或 struct timespec 转换成 time_t 表示的秒数：

   struct timeval stTimeVal; gettimeofday(&stTimeVal, NULL);  time_t lTime = stTimeVal.tv_sec; 

2. 利用系统函数将 time_t 转换为 struct tm：

   struct tm stTime; localtime_r(&lTime, &stTime); // 注意，localtime_r 的第二个参数是入参 

3. 格式化输出：

   char buf[128]; // 自定义输出格式：YYYY-MM-DD hh:mm:ss snprintf(buf, 128, "%.4d-%.2d-%.2d %.2d:%.2d:%.2d",                          stTime.tm_year + 1900,                         stTime.tm_mon + 1,                         stTime.tm_mday,                         stTime.tm_hour,                         stTime.tm_min,                         stTime.tm_sec); puts(buf); 

将 time_t 转换成 struct tm 的函数一共有 4 个，分别为：

1. struct tm *gmtime(const time_t *timep);
2. struct tm *gmtime_r(const time_t *timep, struct tm *result);
3. struct tm *localtime(const time_t *timep);
4. struct tm *localtime_r(const time_t *timep, struct tm *result);

形如 localtime 和形如 localtime_r 函数的区别是：localtime 获得的返回值存在于一个 static 的 struct tm 型的变量中，可能被后面的 localtime 调用覆盖掉。如果要防止覆盖，我们可以自己提供一个 struct tm 型的变量，利用 localtime_r 函数，将我们自己定义的变量的地址传进去，将结果保存在其中，这样就可以避免覆盖。

因此可知，函数 gmtime 和 localtime 是线程不安全的，多线程编程中要慎用！

2.5 获取毫秒时间

#include <stdio.h> #include <time.h> #include <sys/time.h> #include <stdlib.h> #include <string.h>  char *GetMsecTime() {     static char buf[128];     time_t lTime = 0;     struct timeval stTimeVal = {0};     struct tm stTime = {0};      gettimeofday(&stTimeVal, NULL);     lTime = stTimeVal.tv_sec;     localtime_r(&lTime, &stTime);      snprintf(buf, 128, "%.4d-%.2d-%.2d %.2d:%.2d:%.2d.%.3d",              stTime.tm_year + 1900,              stTime.tm_mon + 1,              stTime.tm_mday,              stTime.tm_hour,              stTime.tm_min,              stTime.tm_sec,              stTimeVal.tv_usec / 1000); // 微秒 -> 毫秒     return buf; } int main() {     puts(GetMsecTime());      return 0; } 

• 注意，该函数所返回的 buf 是通过 static 修饰的，是线程不安全的

2.6 调试信息中新增时间信息

#define DEBUG(format, args...)              printf("%s [%s][%s:%d] "format"n",                          		GetMsecTime(),                          		__FILE__,                          		__FUNCTION__,                          		__LINE__,                          		##args) 

至此，我们已经将调试信息的输出格式完善了，接下来就要考虑怎么将调试信息输出到日志文件中了。

三、将调试信息输出到日志文件中

3.1 日志等级

Log4J 定义了 8 个级别的 Log（除去 OFF 和 ALL，可以说分为 6 个级别），优先级从高到低依次为：OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE、 ALL。

• OFF：最高等级的，用于关闭所有日志记录

• FATAL：指出每个严重的错误事件将会导致应用程序的退出。这个级别比较高了，重大错误，这种级别你可以直接停止程序了

• ERROR：指出虽然发生错误事件，但仍然不影响系统的继续运行。打印错误和异常信息，如果不想输出太多的日志，可以使用这个级别

• WARN：表明会出现潜在错误的情形，有些信息不是错误信息，但是也要给程序员的一些提示

• INFO：打印一些你感兴趣的或者重要的信息，这个可以用于生产环境中输出程序运行的一些重要信息，但是不能滥用，避免打印过多的日志

• DEBUG：主要用于开发过程中打印一些运行信息

• TRACE： 很低的日志级别，一般不会使用

• ALL： 最低等级的，用于打开所有日志记录

Log4J 建议只使用四个级别，优先级从高到低分别是 ERROR、WARN、INFO、DEBUG。我们下面的程序也将围绕这四个日志等级来进行编码。

先贴上源码，后续有时间在详细解释~

3.2 源码

3.2.1 log.h

#ifndef __LOG_H__ #define __LOG_H__  #ifdef __cplusplus extern "C" { #endif  // 日志路径 #define LOG_PATH       "./Log/" #define LOG_ERROR             "log.error" #define LOG_WARN              "log.warn" #define LOG_INFO              "log.info" #define LOG_DEBUG             "log.debug" #define LOG_OVERFLOW_SUFFIX             "00"    // 日志溢出后的文件后缀，如 log.error00  #define LOG_FILE_SIZE  (5*1024*1024)            // 单个日志文件的大小，5M  // 日志级别 typedef enum tagLogLevel {     LOG_LEVEL_ERROR    = 1,                             /* error级别 */     LOG_LEVEL_WARN     = 2,                             /* warn级别  */     LOG_LEVEL_INFO     = 3,                             /* info级别  */     LOG_LEVEL_DEBUG    = 4,                             /* debug级别 */ } LOG_LEVEL_E;  typedef struct tagLogFile {     char szCurLog[64];     char szPreLog[64]; } LOG_FILE_S;  #define PARSE_LOG_ERROR(format, args...)       WriteLog(LOG_LEVEL_ERROR, __FILE__, __FUNCTION__, __LINE__, format, ##args)  #define PARSE_LOG_WARN(format, args...)       WriteLog(LOG_LEVEL_WARN, __FILE__, __FUNCTION__, __LINE__, format, ##args)  #define PARSE_LOG_INFO(format, args...)       WriteLog(LOG_LEVEL_INFO, __FILE__, __FUNCTION__, __LINE__, format, ##args)  #define PARSE_LOG_DEBUG(format, args...)       WriteLog(LOG_LEVEL_DEBUG, __FILE__, __FUNCTION__, __LINE__, format, ##args)  extern void WriteLog (     LOG_LEVEL_E enLogLevel,     const char *pcFileName,     const char *pcFuncName,     int iFileLine,     const char *format,      ... );  #ifdef __cplusplus } #endif  #endif 

3.2.2 log.c

#include <stdio.h> #include <string.h> #include <stdlib.h> #include <stdarg.h>     // va_stat 头文件 #include <errno.h>      // errno 头文件 #include <time.h>       // 时间结构体头文件 #include <sys/time.h>   // 时间函数头文件 #include <sys/stat.h>   // stat 头文件 #include "log.h"  static LOG_FILE_S gstLogFile[5] =  {     {"", ""},     {         /* error级别 */         LOG_PATH LOG_ERROR,                     // ./Log/log.error         LOG_PATH LOG_ERROR LOG_OVERFLOW_SUFFIX  // ./Log/log.error00     },     {         /* warn级别 */         LOG_PATH LOG_WARN,                      // ./Log/log.warn         LOG_PATH LOG_WARN LOG_OVERFLOW_SUFFIX   // ./Log/log.warn00     },      {         /* info级别 */         LOG_PATH LOG_INFO,                      // ./Log/log.info         LOG_PATH LOG_INFO LOG_OVERFLOW_SUFFIX   // ./Log/log/info00     },      {         /* debug级别 */         LOG_PATH LOG_DEBUG,                     // ./Log/log.debug         LOG_PATH LOG_DEBUG LOG_OVERFLOW_SUFFIX  // ./Log/log.debug00     },  };  static void __Run_Log (     LOG_LEVEL_E enLogLevel,     const char *pcFileName,     const char *pcFuncName,     int iFileLine,     const char *format,     va_list vargs ) {     FILE *logfile = NULL;     logfile = fopen(gstLogFile[enLogLevel].szCurLog, "a");     if (logfile == NULL)     {         printf("open %s error[%d](%s).n", gstLogFile[enLogLevel].szCurLog, errno, strerror(errno));         return;     }      /* 获取时间信息 */     struct timeval stTimeVal = {0};     struct tm stTime = {0};     gettimeofday(&stTimeVal, NULL);     localtime_r(&stTimeVal.tv_sec, &stTime);      char buf[768];     snprintf(buf, 768, "%.2d-%.2d %.2d:%.2d:%.2d.%.3lu [%s][%s:%d] ",                                             stTime.tm_mon + 1,                                             stTime.tm_mday,                                             stTime.tm_hour,                                             stTime.tm_min,                                             stTime.tm_sec,                                             (unsigned long)(stTimeVal.tv_usec / 1000),                                             pcFileName,                                             pcFuncName,                                             iFileLine);      fprintf(logfile, "%s", buf);     vfprintf(logfile, format, vargs);     fprintf(logfile, "%s", "rn");     fflush(logfile);      fclose(logfile);      return; } static void __LogCoverStrategy(char *pcPreLog) // 日志满后的覆盖策略 {     int iLen = strlen(pcPreLog);     int iNum = (pcPreLog[iLen - 2] - '0') * 10 + (pcPreLog[iLen - 1] - '0');     iNum = (iNum + 1) % 10;      pcPreLog[iLen - 2] = iNum / 10 + '0';     pcPreLog[iLen - 1] = iNum % 10 + '0'; }  void WriteLog (     LOG_LEVEL_E enLogLevel,     const char *pcFileName,     const char *pcFuncName,     int iFileLine,     const char *format,      ... ) {     char szCommand[64]; // system函数中的指令     struct stat statbuff;     if (stat(gstLogFile[enLogLevel].szCurLog, &statbuff) >= 0) // 如果存在     {         if (statbuff.st_size > LOG_FILE_SIZE) // 如果日志文件超出限制         {             printf("LOGFILE(%s) > 5M, del it.n", gstLogFile[enLogLevel].szCurLog);             snprintf(szCommand, 64, "cp -f %s %s", gstLogFile[enLogLevel].szCurLog, gstLogFile[enLogLevel].szPreLog);              puts(szCommand);             system(szCommand);      // 将当前超出限制的日志保存到 log.error00 中              snprintf(szCommand, 64, "rm -f %s", gstLogFile[enLogLevel].szCurLog);             system(szCommand);      // 删掉 log.error             printf("%snn", szCommand);                          // 如果 log.error 超出 5M 后，将依次保存在 log.error00、log.error01、... 中             __LogCoverStrategy(gstLogFile[enLogLevel].szPreLog);          }     }     else // 如果不存在，则创建     {         printf("LOGFILE(%s) is not found, create it.nn", gstLogFile[enLogLevel].szCurLog);         snprintf(szCommand, 64, "touch %s", gstLogFile[enLogLevel].szCurLog);         system(szCommand);     }      va_list argument_list;     va_start(argument_list, format);      if (format)     {         __Run_Log(enLogLevel, pcFileName, pcFuncName, iFileLine, format, argument_list);     }      va_end(argument_list);      return; } 

3.3.3 main.c

#include <stdio.h> #include <unistd.h> // sleep 头文件 #include "log.h"  int main() {     for (int i = 0; i < 5; i++)     {         PARSE_LOG_ERROR("我是第 %d 条日志", i+1);     }      return 0; } 

3.3.4 Tutorial

1. 将 log.h、log.c、main.c 置于同一个目录中

2. 并新建一个 Log 目录
   

3. 编译、运行
   

参考资料

• 怎样写参数个数可变的宏_多个参数的宏_aobai219的博客-CSDN博客

• 转：Ｃ＋＋ 调试中日志打印printf技巧 ，宏的方法_c++2010里面怎么打印printf_nedwons的博客-CSDN博客

• Linux中表示“时间”的结构体和相关函数-digdeep126-ChinaUnix博客

• Linux 获取毫秒级时间戳_linux获取毫秒时间戳_MCNS_37的博客-CSDN博客

• localtime线程不安全 以及 localtime_s、localtime_r、mktime的使用_localtime函数不安全怎么办

• C语言time()函数的用法_c语言time函数怎么用_埋头干饭ing的博客-CSDN博客

• 8个日志级别（OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE、 ALL）_warn日志_Upaaui的博客-CSDN博客

• C语言可变参数va_list - 立超的专栏 - 博客园 (cnblogs.com)

• C语言之va_list_c语言va_list_蓝天巨人的博客-CSDN博客

• C语言fscanf和fprintf函数的用法详解（格式化读写文件） (biancheng.net)

• vfprintf用法解析 - 百度文库 (baidu.com)

• c语言中fflush作用,详解C语言fflush()函数的使用_weixin_39891158的博客-CSDN博客

• struct stat结构体简介_zwzwzwh的博客-CSDN博客

• struct stat结构体简介_sunshineywz的博客-CSDN博客

• 对于linux下system()函数的深度理解(整理) - WHISHT - 博客园 (cnblogs.com)

• 【C/C++】Linux下使用system()函数一定要谨慎 - 恋恋美食的个人空间 - OSCHINA - 中文开源技术交流社区

• linux判断目录是否存在命令（linux判断目录是否存在命令窗口）-智享网 (tangjichun.com)

• 如何在Linux中使用test命令丨在Linux中使用test命令解决方法 _ 电脑系统城 (dnxtc.net)

• 学习笔记——Linux下system()函数详解_linux system_石子君的博客-CSDN博客