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

04-29

一、伺服器端日誌與客戶端日誌的區別

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

/** *@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 ", 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:mycodehack1230612306democlient12306.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:mycodehack1230612306democlient12306.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:mycodehack1230612306democlient12306.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:mycodehack1230612306democlient12306.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 ", 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，可能是用戶非法請求。日誌詳細了，請不用擔心伺服器的磁碟空間，因為相比較定位錯誤，這點磁碟空間還是值得的，實在不行可以定期清理日誌嘛。

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

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