0
将代码中的调试信息输出到日志文件中 - MElephant
source link: https://www.cnblogs.com/hyacinthLJP/p/17291132.html
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
一、将调试信息输出到屏幕中
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 纳秒
- 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
#endif3.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", "\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
__EOF__
Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK