一、将调试信息输出到屏幕中
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 = %d\n", x); // 等价于 printf("x = %d\n", 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 = %d\n", x); // 等价于 printf("x = %d\n", 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
- };
复制代码
- time_t 是一个长整型,用来表示「秒数」
- struct timeval 结构体用「秒和微秒」来表示时间
- struct timespec 结构体用「秒和纳秒」来表示时间
- 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 : %ld\n", lTime);
- struct timeval stTimeVal;
- gettimeofday(&stTimeVal, NULL);
- printf("stTimeVal : %ld\n", stTimeVal.tv_sec);
- struct timespec stTimeSpec;
- clock_gettime(CLOCK_REALTIME, &stTimeSpec);
- printf("stTimeSpec : %ld\n", stTimeSpec.tv_sec);
- return 0;
- }
复制代码
- 我们可以通过上面三个函数获得三种不同精度的当前时间
Notes:
- POSIX.1-2008 marks gettimeofday() as obsolete, recommending the use of clock_gettime(2) instead.
- 并且,有人曾经做过测试,连续两次使用 gettimeofday 时,会以一种小概率出现「时光倒流」的现象,第二次函数调用得到的时间要小于或说早于第一次调用得到的时间。
- gettimeofday 函数并不是那么稳定,没有 times 或 clock 计时准确,但它们用法相似。
- clock有计时限制,据说是 596.5+小时,一般情况足以应付。
- ntpd 之类的进程可能会修改系统时间,导致计时出现误差。
- 据网上的讨论来看,TSC 和 HPET 中断之类的东西,可能导致系统的 wall time 回退。这个应该和具体的系统实现有关了,总之 gettimeofday 函数并没有保证提供怎样的精度,也不保证得到系统的准确时间,它返回的结果是「the system's best guess at wall time」。
- 有可能的话,尽量使用 clock_gettime(CLOCK_MONOTONIC),不过不是所有系统都实现了 posix realtime,例如 mac os x。
- 所以现在应该用: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 对时间进行格式化输出
- 首先将 struct timeval 或 struct timespec 转换成 time_t 表示的秒数:
- struct timeval stTimeVal;
- gettimeofday(&stTimeVal, NULL);
- time_t lTime = stTimeVal.tv_sec;
复制代码 - 利用系统函数将 time_t 转换为 struct tm:
- struct tm stTime;
- localtime_r(&lTime, &stTime); // 注意,localtime_r 的第二个参数是入参
复制代码 - 格式化输出:
- 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 个,分别为:
- struct tm *gmtime(const time_t *timep);
- struct tm *gmtime_r(const time_t *timep, struct tm *result);
- struct tm *localtime(const time_t *timep);
- 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,
- 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", "\r\n");
- 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("%s\n\n", szCommand);
-
- // 如果 log.error 超出 5M 后,将依次保存在 log.error00、log.error01、... 中
- __LogCoverStrategy(gstLogFile[enLogLevel].szPreLog);
- }
- }
- else // 如果不存在,则创建
- {
- printf("LOGFILE(%s) is not found, create it.\n\n", 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
- 将 log.h、log.c、main.c 置于同一个目录中
- 并新建一个 Log 目录

- 编译、运行

参考资料
免责声明:如果侵犯了您的权益,请联系站长,我们会及时删除侵权内容,谢谢合作! |