一、將除錯資訊輸出到螢幕中
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)傳遞可變參數列,你可能很熟悉在函式中使用可變參數列,如:
在 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 目錄
-
編譯、執行