服務器編程心得（五）—— 如何編寫高性能日志

一、服務器端日志與客戶端日志的區別

在正式講解之前，我們先來看一個日志類的實現方法，這個日志類也是代表著大多數客戶端日志的主流寫法:

/**
 *@desc:    程序運行log類,log.h
 *@author:  zhangyl
 *@date:    2017.01.17
 **/
#ifndef __LOG_H__
#define __LOG_H__

#ifdef _ZYL_LOG_
#define LogInfo(...)     Log::GetInstance().AddLog("INFO", __FILE__, __LINE__, __FUNCSIG__, __VA_ARGS__)
#define LogWarning(...)  Log::GetInstance().AddLog("WARNING", __FILE__, __LINE__, __FUNCSIG__, __VA_ARGS__)
#define LogError(...)    Log::GetInstance().AddLog("ERROR", __FILE__, __LINE__, __FUNCSIG__, __VA_ARGS__)
#else
#define LogInfo(...) (void(0))
#define LogError(...) (void(0))
#endif

class Log
{
public:
    static Log& GetInstance();

    bool AddLog(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSig, char* pszFmt, ...);

private:
    Log();
    ~Log();
    Log(const Log&);
    Log& operator=(const Log&);

private:
    FILE*   m_file;

};

#endif //!__LOG_H__

/**
 *@desc:    程序運行log類,log.cpp
 *@author:  zhangyl
 *@date:    2017.01.17
 **/

#include <time.h>
#include <stdio.h>
#include <stdarg.h>
#include "Log.h"

Log& Log::GetInstance()
{
    static Log log;
    return log;
}

bool Log::AddLog(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSig, char* pszFmt, ...)
{
    if (m_file == NULL)
        return false;

    char tmp[8192*10] = { 0 };
    va_list va;                 //定義一個va_list型的變量,這個變量是指向參數的指針.
    va_start(va, pszFmt);           //用va_start宏初始化變量,這個宏的第二個參數是第一個可變參數的前一個參數,是一個固定的參數
    _vsnprintf(tmp, ARRAYSIZE(tmp), pszFmt, va);//注意,不要漏掉前面的_
    va_end(va);

    time_t now = time(NULL);
    struct tm* tmstr = localtime(&now);
    char content[8192 * 10 + 256] = {0};
    sprintf_s(content, ARRAYSIZE(content), "[%04d-%02d-%02d %02d:%02d:%02d][%s][0x%04x][%s:%d %s]%s\r\n",
                tmstr->tm_year + 1900,
                tmstr->tm_mon + 1,
                tmstr->tm_mday,
                tmstr->tm_hour,
                tmstr->tm_min,
                tmstr->tm_sec,
                pszLevel,
                GetCurrentThreadId(),
                pszFile,
                lineNo,
                pszFuncSig,
                tmp);

    if (fwrite(content, strlen(content), 1, m_file) != 1)
        return false;

    fflush(m_file);

    return true;
}

Log::Log()
{
    time_t now = time(NULL);
    struct tm* tmstr = localtime(&now);
    char filename[256];
    sprintf_s(filename, ARRAYSIZE(filename), "%04d%02d%02d%02d%02d%02d.runlog", 
                tmstr->tm_year + 1900, 
                tmstr->tm_mon + 1, 
                tmstr->tm_mday, 
                tmstr->tm_hour, 
                tmstr->tm_min, 
                tmstr->tm_sec);

    m_file = fopen(filename, "at+");
}

Log::~Log()
{
    if (m_file != NULL)
        fclose(m_file);
}

這個Log類的定義和實現代碼節選自我的一款12306刷票軟件，如果需要使用這個類的話包含Log.h頭文件，然后使用宏：LogInfo/LogWarning/LogError這三個宏就可以了。示例如下：

    string strResponse;
    string strCookie = "Cookie: ";
    strCookie += m_strCookies;
    if (!HttpRequest(osURL.str().c_str(), strResponse, true, strCookie.c_str(), NULL, false, 10))
    {
        LogError("QueryTickets2 failed");
        return false;
    }

這個日志類，每次輸出一行，一行中輸出時間、日志級別、線程id、文件名、行號、函數簽名和自定義的錯誤信息，演示如下：

[2017-02-16 17:30:08][INFO][0x0e7c][f:\mycode\hack12306\12306demo\client12306.cpp:1401 bool __thiscall Client12306::HttpRequest(const char *,class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &,bool,const char *,const char *,bool,int)]http response: {"validateMessagesShowId":"_validatorMessage","status":true,"httpstatus":200,"data":{"loginAddress":"10.1.232.219","otherMsg":"","loginCheck":"Y"},"messages":[],"validateMessages":{}}

[2017-02-16 17:30:08][INFO][0x0e7c][f:\mycode\hack12306\12306demo\client12306.cpp:1379 bool __thiscall Client12306::HttpRequest(const char *,class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &,bool,const char *,const char *,bool,int)]http post: url=https://kyfw.12306.cn:443/otn/login/userLogin, headers=Cookie: JSESSIONID=0A01D965C45FE88A1FB289F288BD96C255E3547783; BIGipServerotn=1708720394.50210.0000; , postdata=_json_att=

[2017-02-16 17:30:08][INFO][0x0e7c][f:\mycode\hack12306\12306demo\client12306.cpp:1401 bool __thiscall Client12306::HttpRequest(const char *,class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &,bool,const char *,const char *,bool,int)]http response: 

[2017-02-16 17:30:08][INFO][0x0e7c][f:\mycode\hack12306\12306demo\client12306.cpp:1379 bool __thiscall Client12306::HttpRequest(const char *,class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &,bool,const char *,const char *,bool,int)]http post: url=https://kyfw.12306.cn:443/otn/index/initMy12306, headers=Cookie: JSESSIONID=0A01D965C45FE88A1FB289F288BD96C255E3547783; BIGipServerotn=1708720394.50210.0000; , postdata=

上文中也說了，以上示例是我曾經寫的一款客戶端程序的日志，注意“客戶端”這個重要的關鍵字。因為上述日志的實現雖然通用，但其局限性也只能用于客戶端這樣對性能和效率要求不高的程序（這里的性能和效率是相對于高并發高性能的服務器程序來說的，也就是說上述日志實現可用于大多數客戶端程序，但不能用于高性能高并發的服務器程序）。那么上述程序存在什么問題？問題是效率低！
不知道讀者有沒有注意上，上述日志類實現，是在調用者線程中直接進行IO操作，相比較于高速的CPU，IO磁盤操作是很慢的，直接在某些工作線程（包括UI線程）寫文件，程序執行速度太慢，尤其是當日志數據比較多的時候。
這也就是服務器端日志和客戶端日志的區別之一，客戶端程序日志一般可以在直接在所在的工作線程寫日志，因為這點性能和時間損失對大多數客戶端程序來說，是可以忽略的，但對于要求高并發（例如并發量達百萬級乃至千萬級的系統）的服務器程序來說，單位時間內耗在磁盤寫操作上的時間就相當可觀了。我目前的做法是參考陳碩的muduo庫的做法，使用一個隊列，需要寫日志時，將日志加入隊列中，另外一個專門的日志線程來寫日志，我給出下我的具體實現代碼，如果需要查看muduo庫的做法，請參考陳碩的書《Linux多線程服務端編程：使用muduo C++網絡庫》關于日志章節。注意：以下是純C++11代碼：

/** 
 * 日志類頭文件, Logger.h
 * zhangyl 2017.02.28
 **/

#ifndef __LOGGER_H__
#define __LOGGER_H__

#include <string>
#include <memory>
#include <thread>
#include <mutex>
#include <condition_variable>
#include <list>

//struct FILE;

#define LogInfo(...)        Logger::GetInstance().AddToQueue("INFO", __FILE__, __LINE__, __PRETTY_FUNCTION__, __VA_ARGS__)
#define LogWarning(...)     Logger::GetInstance().AddToQueue("WARNING", __FILE__, __LINE__, __PRETTY_FUNCTION__, __VA_ARGS__)
#define LogError(...)       Logger::GetInstance().AddToQueue("ERROR", __FILE__, __LINE__, __PRETTY_FUNCTION__, __VA_ARGS__)

class Logger
{
public:
    static Logger& GetInstance();

    void SetFileName(const char* filename);
    bool Start();
    void Stop();

    void AddToQueue(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSig, char* pszFmt, ...);

private:
    Logger() = default;
    Logger(const Logger& rhs) = delete;
    Logger& operator =(Logger& rhs) = delete;

    void threadfunc();

private:
    std::string                     filename_;
    FILE*                           fp_{};
    std::shared_ptr<std::thread>    spthread_;
    std::mutex                      mutex_;
    std::condition_variable         cv_;            //有新的日志到來的標識
    bool                            exit_{false};
    std::list<std::string>          queue_;
};

#endif //!__LOGGER_H__

/**
 * 日志類實現文件, Logger.cpp
 * zhangyl 2017.02.28
 **/

#include "Logger.h"
#include <time.h>
#include <stdio.h>
#include <memory>
#include <stdarg.h>

Logger& Logger::GetInstance()
{
    static Logger logger;
    return logger;
}

void Logger::SetFileName(const char* filename)
{
    filename_ = filename;
}

bool Logger::Start()
{
    if (filename_.empty())
    {
        time_t now = time(NULL);
        struct tm* t = localtime(&now);
        char timestr[64] = { 0 };
        sprintf(timestr, "%04d%02d%02d%02d%02d%02d.imserver.log", t->tm_year + 1900, t->tm_mon + 1, t->tm_mday, t->tm_hour, t->tm_min, t->tm_sec);
        filename_ = timestr;
    }

    fp_ = fopen(filename_.c_str(), "wt+");
    if (fp_ == NULL)
        return false;

    spthread_.reset(new std::thread(std::bind(&Logger::threadfunc, this)));

    return true;
}

void Logger::Stop()
{
    exit_ = true;
    cv_.notify_one();

    //等待時間線程結束
    spthread_->join();
}

void Logger::AddToQueue(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSig, char* pszFmt, ...)
{
    char msg[256] = { 0 };

    va_list vArgList;                            
    va_start(vArgList, pszFmt);
    vsnprintf(msg, 256, pszFmt, vArgList);
    va_end(vArgList);

    time_t now = time(NULL);
    struct tm* tmstr = localtime(&now);
    char content[512] = { 0 };
    sprintf(content, "[%04d-%02d-%02d %02d:%02d:%02d][%s][0x%04x][%s:%d %s]%s\n",
                tmstr->tm_year + 1900,
                tmstr->tm_mon + 1,
                tmstr->tm_mday,
                tmstr->tm_hour,
                tmstr->tm_min,
                tmstr->tm_sec,
                pszLevel,
                std::this_thread::get_id(),
                pszFile,
                lineNo,
                pszFuncSig,
                msg);

    {
        std::lock_guard<std::mutex> guard(mutex_);
        queue_.emplace_back(content);
    }

    cv_.notify_one();
}

void Logger::threadfunc()
{
    if (fp_ == NULL)
        return;

    while (!exit_)
    {
        //寫日志
        std::unique_lock<std::mutex> guard(mutex_);
        while (queue_.empty())
        {
            if (exit_)
                return;

            cv_.wait(guard);
        }

        //寫日志
        const std::string& str = queue_.front();

        fwrite((void*)str.c_str(), str.length(), 1, fp_);
        fflush(fp_);
        queue_.pop_front();
    }
}

以上代碼只是個簡化版的實現，使用std::list來作為隊列，使用條件變量來作為新日志到來的觸發條件。當然，由于使用了兩個固定長度的數組，大小是256和512，如果日志數據太長，會導致數組溢出，這個可以根據實際需求增大緩沖區或者改用動態長度的string類型。使用這兩個文件只要包含Logger.h，然后使用如下一行代碼啟動日志線程就可以了：

Logger::GetInstance().Start();

生成日志，使用頭文件里面定義的三個宏LogInfo、LogWarning、LogError，當然你也可以擴展自己的日志級別。

二、日志里面應該寫些什么？

我開始在試著去寫日志的時候，也走了不少彎路，無論是客戶端還是服務器端，日志寫的內容倒是不少，但都是些廢話，雖然也報出故障，但對解決實際問題時毫無作用。尤其是在服務器上生產環境以后，出現很多問題，問題也暴露出來了，但是由于日志含有的當時現場的環境信息太少，只能看到錯誤，卻沒法追蹤問題，更別說解決問題了。我們來看兩個具體的例子：

CIULog::Log(LOG_WARNING, __FUNCSIG__, _T("Be cautious! Unhandled net data! req_ans_command=%d."), header.cmd);

這條日志記錄，只打印出一條警告信息和命令號（cmd），對具體產生這個警告的輸入參數和當時的環境也沒進行任何記錄，即使產生問題，事后也無法追蹤。再看一條

    if (!HttpRequest(osURL.str().c_str(), strResponse, true, strCookie.c_str(), NULL, false, 10))
    {
        LogError("QueryTickets1 failed");
        return false;
    }

這條日志，因為http請求報了個簡單的錯誤，至于產生錯誤的參數和原因一概沒有交待，這種日志如果在生產環境上出現如何去排查呢？出錯原因可能是設置的參數非法，這是外部原因，可以解決的，甚至是交互雙方的一端傳過來的，需要對方去糾正；也可能是當時的網絡故障，這個也可以解決，也不算是程序的bug，不需要解決；也可能是的bug引起的，這個需要程序作者去解決。另外，如果是服務器程序，甚至應該在錯誤中交待下產生日志的用戶id、操作類型等信息，這樣事后才能便于定位位置，進行重現等。
總結起來，日志記錄應該盡量詳細，能反映出當時出錯的現場情節、產生的環境等。比如一個注冊請求失敗，至少要描述出當時注冊的用戶名、密碼、用戶狀態（比如是否已經注冊）、請求的注冊地址等等。因為日志報錯不一定是程序bug，可能是用戶非法請求。日志詳細了，請不用擔心服務器的磁盤空間，因為相比較定位錯誤，這點磁盤空間還是值得的，實在不行可以定期清理日志嘛。

另外一點是，可以將錯誤日志、運行狀態日志等分開，甚至可以將程序記錄日志與業務本身日志分開，這樣排查故障時優先查看是否有錯誤日志文件產生，再去錯誤日志里面去找，而不用在一堆日志中篩選錯誤日志。我的很多項目在生產環境也是這么做的。

以上是關于日志的一些個人心得吧，如有一些說的不對的地方，歡迎指正。