將程式碼中的除錯資訊輸出到日誌檔案中

MElephant發表於2023-04-05

一、將除錯資訊輸出到螢幕中

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 行的除錯資訊,我們可以幫助我們精確排查到程式退出的原因:原來是檔案開啟失敗了。

image-20230402170006527

那如果當前目錄下存在 test.txt 檔案,只是不可讀呢?

image-20230402175503739

  • 同樣輸出了 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:

image-20230402180115008

如果程式碼中包含很多的除錯資訊呢?我們並不能一下子知道這條資訊到底是在哪裡列印出來的,於是,我們又想,能不能把當前除錯資訊所在的檔名和原始碼行位置也列印出來呢,這樣不就一目瞭然了嗎。基於此,便有了 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));

image-20230402181519935

  • 從日誌資訊中,我們可以精確的獲取到: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
};
  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       : %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:

  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 timevalstruct 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", "\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

  1. 將 log.h、log.c、main.c 置於同一個目錄中

  2. 並新建一個 Log 目錄
    image-20230405221056915

  3. 編譯、執行
    image-20230405221126201

參考資料

相關文章