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

時間  2019-12-08
標籤 服務器 編程 心得 如何 編寫 高性能 日誌 简体版
原文   原文鏈接

1、服務器端日誌與客戶端日誌的區別編程

在正式講解以前，咱們先來看一個日誌類的實現方法，這個日誌類也是表明着大多數客戶端日誌的主流寫法:json

/** *@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，固然你也能夠擴展本身的日誌級別。多線程

2、日誌裏面應該寫些什麼？併發

我開始在試着去寫日誌的時候，也走了很多彎路，不管是客戶端仍是服務器端，日誌寫的內容卻是很多，但都是些廢話，雖然也報出故障，但對解決實際問題時毫無做用。尤爲是在服務器上生產環境之後，出現不少問題，問題也暴露出來了，可是因爲日誌含有的當時現場的環境信息太少，只能看到錯誤，卻無法追蹤問題，更別說解決問題了。咱們來看兩個具體的例子：函數

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，多是用戶非法請求。日誌詳細了，請不用擔憂服務器的磁盤空間，由於相比較定位錯誤，這點磁盤空間仍是值得的，實在不行能夠按期清理日誌嘛。post

另一點是，能夠將錯誤日誌、運行狀態日誌等分開，甚至能夠將程序記錄日誌與業務自己日誌分開，這樣排查故障時優先查看是否有錯誤日誌文件產生，再去錯誤日誌裏面去找，而不用在一堆日誌中篩選錯誤日誌。個人不少項目在生產環境也是這麼作的。

以上是關於日誌的一些我的心得吧，若有一些說的不對的地方，歡迎指正。

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程