列異步日志系統(tǒng)：高并發(fā)場(chǎng)景下徹底解決同步日志阻塞問(wèn)題)
1. 先別急著一股腦寫(xiě)文件同步日志為什么扛不住生產(chǎn)環(huán)境先說(shuō)結(jié)論再聊細(xì)節(jié)日志系統(tǒng)最容易被低估也最容易被埋雷。很多項(xiàng)目剛開(kāi)始的時(shí)候日志就是到處printf或者更“規(guī)范”一點(diǎn)接個(gè)log4j、spdlog級(jí)別的庫(kù)線上跑一跑也沒(méi)覺(jué)得有什么問(wèn)題。但等流量上來(lái)高并發(fā)場(chǎng)景一壓第一塊倒下的往往不是業(yè)務(wù)代碼而是看似人畜無(wú)害的日志鏈路。我們做雙緩沖隊(duì)列異步日志系統(tǒng)要解決的核心痛點(diǎn)很簡(jiǎn)單日志寫(xiě)入不再阻塞業(yè)務(wù)線程。同步日志為什么會(huì)阻塞因?yàn)閣rite()到磁盤(pán)并不便宜。一個(gè)日志條目看起來(lái)只是一行字符串但這條字符串從用戶(hù)態(tài)的日志緩沖區(qū)到內(nèi)核的文件系統(tǒng)緩存再到真正的磁盤(pán)設(shè)備中間隔著至少兩道拷貝還伴隨一次系統(tǒng)調(diào)用。生產(chǎn)環(huán)境里無(wú)論是機(jī)械硬盤(pán)還是 SSD單次寫(xiě)入的小 IO 都遠(yuǎn)沒(méi)有想象中的快。日志一多、高頻一寫(xiě)業(yè)務(wù)線程就被迫排隊(duì)等磁盤(pán)。我舉個(gè)真實(shí)場(chǎng)景某線上服務(wù)需要記錄每次請(qǐng)求的完整參數(shù)和響應(yīng)體單個(gè)請(qǐng)求撐死幾十行日志但 QPS 上了幾千之后同步日志的磁盤(pán)寫(xiě)壓力瞬間拉滿(mǎn)接口平均耗時(shí)從 2ms 漲到了 40ms最夸張的時(shí)候業(yè)務(wù)線程被日志卡的連心跳包都發(fā)不出去。后來(lái)把策略改成“攢一批再寫(xiě)”問(wèn)題才算緩解。這就是異步日志的核心思路把日志寫(xiě)入從業(yè)務(wù)線程上搬走交給專(zhuān)門(mén)的線程去處理。業(yè)務(wù)線程只負(fù)責(zé)把日志內(nèi)容往內(nèi)存里一放就返回磁盤(pán)寫(xiě)入由后臺(tái)線程異步完成。聽(tīng)起來(lái)簡(jiǎn)單但實(shí)現(xiàn)上有很多講究尤其是“怎么把日志內(nèi)容安全高效地交到后臺(tái)線程”這一步選型不同效果天差地別。雙緩沖隊(duì)列就是這條鏈路里比較經(jīng)典、也比較容易理解的一種實(shí)現(xiàn)方案。如果你現(xiàn)在正被“日志寫(xiě)入拖慢接口”“日志一多系統(tǒng)就卡頓”“日志模塊與業(yè)務(wù)模塊共用鎖導(dǎo)致死等”這些問(wèn)題困擾這篇文章適合你。我會(huì)從設(shè)計(jì)思路講到接口封裝再到部署使用把雙緩沖日志系統(tǒng)的“上半場(chǎng)”講透。2. 雙緩沖隊(duì)列的工作機(jī)制把“寫(xiě)日志”和“寫(xiě)磁盤(pán)”拆開(kāi)2.1 兩段式緩沖一個(gè)正寫(xiě)一個(gè)在刷雙緩沖隊(duì)列這個(gè)名字關(guān)鍵在于“雙”和“隊(duì)列”。“緩沖”比較好理解就是一塊預(yù)先分配好的內(nèi)存。日志內(nèi)容先落在這塊內(nèi)存里攢多了再一次性寫(xiě)入磁盤(pán)。為什么要攢因?yàn)橐淮蝫rite()寫(xiě)入 1MB 數(shù)據(jù)和分 1 萬(wàn)次每次寫(xiě) 100 字節(jié)兩者的 IO 效率完全是兩個(gè)量級(jí)。批量寫(xiě)不僅能大大減少系統(tǒng)調(diào)用的次數(shù)還能讓磁盤(pán)的寫(xiě)模式更規(guī)整性能提升非常明顯?！半p緩沖”指的是這塊預(yù)分配內(nèi)存有兩份。一份被業(yè)務(wù)線程用來(lái)寫(xiě)入日志稱(chēng)為“待寫(xiě)緩沖區(qū)”或“當(dāng)前緩沖區(qū)”另一份被后臺(tái)線程用來(lái)讀取并刷入磁盤(pán)稱(chēng)為“待刷緩沖區(qū)”。當(dāng)“當(dāng)前緩沖區(qū)”寫(xiě)滿(mǎn)了或者到了固定時(shí)間系統(tǒng)會(huì)執(zhí)行一次緩沖區(qū)交換swap把業(yè)務(wù)線程寫(xiě)滿(mǎn)的這塊換成后臺(tái)線程手里的那塊。交換之后業(yè)務(wù)線程繼續(xù)往新?lián)Q來(lái)的空緩沖區(qū)里寫(xiě)后臺(tái)線程則拿著裝滿(mǎn)日志的緩沖區(qū)去刷磁盤(pán)。圖景大概是這樣業(yè)務(wù)線程 后臺(tái)線程 | | | 寫(xiě)入Buffer A | |-------------| | Buffer A滿(mǎn) | | 交換 | |-------------| | 寫(xiě)入Buffer B | | | 刷Buffer A到磁盤(pán) | |------------- Disk簡(jiǎn)化成文字描述就是業(yè)務(wù)線程永遠(yuǎn)只面對(duì)一塊“可以寫(xiě)”的內(nèi)存寫(xiě)完一塊就換一塊完全不碰磁盤(pán) IO。后臺(tái)線程永遠(yuǎn)只面對(duì)一塊“已經(jīng)寫(xiě)滿(mǎn)”的內(nèi)存刷完一塊就換一塊完全不阻塞業(yè)務(wù)線程。兩者之間只有一次極短的交換操作需要同步。2.2 為什么是“雙”緩沖而不是單緩沖或多緩沖單緩沖的方案看起來(lái)也能用一塊緩沖區(qū)寫(xiě)滿(mǎn)了就刷盤(pán)刷盤(pán)期間業(yè)務(wù)線程等著。但問(wèn)題在于“寫(xiě)滿(mǎn)后刷盤(pán)”這個(gè)動(dòng)作是阻塞的而且刷盤(pán)耗時(shí)不定。一旦磁盤(pán)繁忙業(yè)務(wù)線程就卡住了和同步日志沒(méi)有本質(zhì)區(qū)別只是把fprintf換成了memcpy仍然治標(biāo)不治本。多緩沖方案呢理論上可以準(zhǔn)備 N 塊緩沖區(qū)寫(xiě)滿(mǎn)一塊就換下一塊后臺(tái)線程依次刷。這能進(jìn)一步降低交換頻率內(nèi)存占用也更高。但在大部分場(chǎng)景下兩塊緩沖區(qū)已經(jīng)足夠只要后臺(tái)線程刷盤(pán)的平均速度大于業(yè)務(wù)線程寫(xiě)入的平均速度兩塊就能循環(huán)起來(lái)。如果后臺(tái)線程的消費(fèi)速度跟不上說(shuō)明系統(tǒng)已經(jīng)到了日志量過(guò)載的狀態(tài)即使準(zhǔn)備更多緩沖區(qū)也只是延緩問(wèn)題并不能消除問(wèn)題。這里有個(gè)很多人會(huì)忽略的點(diǎn)雙緩沖系統(tǒng)里的交換是“一次性”完成的。生產(chǎn)線程與消費(fèi)線程之間只共享一個(gè)狀態(tài)指針一次 swap 操作只需要幾納秒到幾十納秒的臨界區(qū)保護(hù)。對(duì)比直接用std::queue存日志的逐條入隊(duì)方案雙緩沖避免了高頻的鎖競(jìng)爭(zhēng)把鎖的粒度從“每條日志”降到了“每批日志”這是它能扛高吞吐的根本原因。另外雙緩沖天然支持延遲刷新。很多時(shí)候日志峰值只出現(xiàn)在一秒內(nèi)的某幾百毫秒中其他時(shí)間業(yè)務(wù)線程并不忙。如果每寫(xiě)一條就通知后臺(tái)線程來(lái)取線程喚醒、上下文切換的成本反而會(huì)拖垮性能。雙緩沖方案可以設(shè)定“緩沖區(qū)未滿(mǎn)就定時(shí)刷”比如每 1 秒強(qiáng)制交換一次保證日志延遲可控且不會(huì)出現(xiàn)長(zhǎng)時(shí)間無(wú)輸出。2.3 雙緩沖的兩個(gè)隱藏風(fēng)險(xiǎn)設(shè)計(jì)時(shí)繞不開(kāi)第一個(gè)風(fēng)險(xiǎn)是日志丟失。異步意味著業(yè)務(wù)線程返回時(shí)日志還沒(méi)落盤(pán)如果此時(shí)進(jìn)程崩潰或者被kill -9最后一段還在內(nèi)存里的日志就沒(méi)了。這個(gè)問(wèn)題沒(méi)法完全規(guī)避只能降低損失。常見(jiàn)做法是后臺(tái)線程定期刷盤(pán)并且支持外部顯式調(diào)用Flush()在需要保命的關(guān)鍵節(jié)點(diǎn)比如服務(wù)收到終止信號(hào)后強(qiáng)制把所有緩沖數(shù)據(jù)落盤(pán)。第二個(gè)風(fēng)險(xiǎn)是背壓?jiǎn)栴}。如果日志生產(chǎn)速度長(zhǎng)期超過(guò)消費(fèi)速度緩沖區(qū)很快會(huì)處于“寫(xiě)滿(mǎn)-交換-刷盤(pán)-再寫(xiě)滿(mǎn)”的循環(huán)表現(xiàn)為磁盤(pán)持續(xù)高負(fù)載系統(tǒng)整體性能下降。此時(shí)不能無(wú)限等下去常見(jiàn)策略是當(dāng)兩緩沖都占滿(mǎn)且后臺(tái)線程來(lái)不及刷時(shí)要么直接丟棄未來(lái)日志并按計(jì)數(shù)報(bào)錯(cuò)要么將當(dāng)前緩沖區(qū)擴(kuò)容一擋臨時(shí)救急。我一般推薦前者因?yàn)槿罩玖窟^(guò)載時(shí)保留完整性的優(yōu)先級(jí)低于保證業(yè)務(wù)可用性而且丟失提示本身也是重要日志。3. 核心接口設(shè)計(jì)Buffer、隊(duì)列交換與 AsyncLogger設(shè)計(jì)雙緩沖日志系統(tǒng)時(shí)最重要的是把三個(gè)角色拆清楚Buffer負(fù)責(zé)存儲(chǔ)字節(jié)流BufferQueue負(fù)責(zé)管理兩個(gè) Buffer 的交換與調(diào)度AsyncLogger負(fù)責(zé)向上層業(yè)務(wù)提供日志寫(xiě)入 API同時(shí)管理后臺(tái)線程的生命周期。3.1 Buffer 的核心字段與內(nèi)存使用Buffer本質(zhì)是一塊預(yù)分配內(nèi)存加上讀寫(xiě)游標(biāo)。我常用的定義大概是class Buffer { public: explicit Buffer(size_t capacity) { data_.reserve(capacity); } void Append(const char* log, size_t len) { if (len WritableBytes()) { return; // 或觸發(fā)擴(kuò)容 / 丟棄策略 } data_.insert(data_.end(), log, log len); } void Reset() { data_.clear(); } bool Empty() { return data_.empty(); } size_t WritableBytes() { return data_.capacity() - data_.size(); } const char* Data() { return data_.data(); } size_t Size() { return data_.size(); } private: std::vectorchar data_; };注意這里我用的是std::vector而不是裸指針加char[]。生產(chǎn)級(jí)日志系統(tǒng)對(duì)性能苛刻通常會(huì)直接用預(yù)分配的char[]配合size_t游標(biāo)甚至用mmap映射文件。但std::vector足夠滿(mǎn)足絕大多數(shù)業(yè)務(wù)系統(tǒng)的日志壓力而且內(nèi)存管理更安全。真正要緊的是讓 Buffer 的容量在初始化時(shí)一次定好盡量避免運(yùn)行期擴(kuò)容——擴(kuò)容可能觸發(fā)內(nèi)存搬移而且擴(kuò)容期間的操作會(huì)引入額外的不確定性。Buffer 容量取多大這個(gè)沒(méi)有標(biāo)準(zhǔn)答案。我個(gè)人的經(jīng)驗(yàn)值是單條日志平均長(zhǎng)度按 256 字節(jié)估如果 QPS 峰值為 1 萬(wàn)每秒日志量約為 2.5MB那么每塊 Buffer 設(shè)為 8MB 左右比較合適兩塊就是 16MB。日志量小的服務(wù)4MB 也已經(jīng)足夠了。內(nèi)存是便宜的資源不必太摳但也不要拍腦袋選個(gè) 1GB —— 那會(huì)讓緩存的優(yōu)勢(shì)變成內(nèi)存的壓力。3.2 BufferQueue 的交換邏輯BufferQueue是雙緩沖結(jié)構(gòu)的中樞。它內(nèi)部維護(hù)兩個(gè) Buffer 指針并在合適的時(shí)機(jī)執(zhí)行交換。class BufferQueue { public: explicit BufferQueue(size_t buffer_capacity) : buffer_capacity_(buffer_capacity), current_(new Buffer(buffer_capacity)), next_(new Buffer(buffer_capacity)) {} void Append(const char* data, size_t len) { std::lock_guardstd::mutex lock(mutex_); if (current_-WritableBytes() len) { Swap(); } current_-Append(data, len); } std::shared_ptrBuffer TakeForFlush() { std::lock_guardstd::mutex lock(mutex_); if (current_-Empty() next_-Empty()) { return nullptr; } Swap(); return std::shared_ptrBuffer swap_result_; } private: void Swap() { std::swap(current_, next_); // 這里同時(shí)喚醒消費(fèi)線程 } size_t buffer_capacity_; std::unique_ptrBuffer current_; std::unique_ptrBuffer next_; std::mutex mutex_; std::condition_variable cond_; };這段邏輯里有幾個(gè)微妙的地方第一Append時(shí)發(fā)現(xiàn)當(dāng)前緩沖區(qū)寫(xiě)不下一條日志立刻交換然后把日志寫(xiě)到新緩沖區(qū)上。這意味著next_可能已經(jīng)在積累數(shù)據(jù)了交換前它會(huì)被重置。這里有一個(gè)取舍如果next_里還有沒(méi)來(lái)得及被后臺(tái)線程刷盤(pán)的數(shù)據(jù)交換會(huì)造成日志順序錯(cuò)亂或數(shù)據(jù)覆蓋。所以更嚴(yán)謹(jǐn)?shù)膶?xiě)法是當(dāng)Append時(shí)current_寫(xiě)不下且next_非空即后臺(tái)線程還沒(méi)取走過(guò)要介入“等待消費(fèi)線程完成一次 flush”的流程。我在實(shí)現(xiàn)時(shí)通過(guò)條件變量控制保證交換發(fā)生時(shí)next_一定是已經(jīng)刷完的空 Buffer。第二條件變量的喚醒時(shí)機(jī)。最直接的邏輯是Swap()之后立刻喚醒后臺(tái)線程。但如果每次Append都喚醒日志量一高線程頻繁被喚醒上下文切換成本就上去了。我的做法是只有滿(mǎn)足“當(dāng)前緩沖區(qū)由空變?yōu)榉强铡被颉敖粨Q發(fā)生時(shí)next_中有數(shù)據(jù)”這兩個(gè)條件才喚醒。這能把線程喚醒次數(shù)與日志寫(xiě)入頻率解耦后臺(tái)線程還可以配合定時(shí)策略每 100ms 檢查一次。3.3 AsyncLogger 的對(duì)外接口設(shè)計(jì)對(duì)外接口是我的原則是極簡(jiǎn)。業(yè)務(wù)方不需要理解雙緩沖內(nèi)部機(jī)制他們只需要“初始化、寫(xiě)日志、關(guān)閉”這三個(gè)動(dòng)作。class AsyncLogger { public: static AsyncLogger* Instance(); bool Init(const LogConfig config); void Write(LogLevel level, const char* fmt, ...); void Flush(); void Shutdown(); private: AsyncLogger(); ~AsyncLogger(); void WriteToBuffer(const char* line, size_t len); void FlushThread(); std::unique_ptrBufferQueue queue_; std::thread background_thread_; std::atomicbool running_{false}; LogLevel level_{LOG_INFO}; };Init()初始化配置啟動(dòng)后臺(tái)線程Write()格式化日志寫(xiě)入 BufferQueue返回即代表日志“已受理”Flush()強(qiáng)制刷新緩沖區(qū)用于關(guān)鍵節(jié)點(diǎn)Shutdown()停止后臺(tái)線程刷完所有遺留數(shù)據(jù)安全退出Write()為什么設(shè)計(jì)成可變參數(shù)因?yàn)槲蚁Ｍ罩菊{(diào)用點(diǎn)在形式上盡可能接近原生的printf。業(yè)務(wù)側(cè)配合宏定義使用體驗(yàn)上就像寫(xiě)printf一樣自然#define LOG_DEBUG(...) AsyncLogger::Instance()-Write(LOG_DEBUG, __VA_ARGS__) #define LOG_INFO(...) AsyncLogger::Instance()-Write(LOG_INFO, __VA_ARGS__) #define LOG_ERROR(...) AsyncLogger::Instance()-Write(LOG_ERROR, __VA_ARGS__)在Write()內(nèi)部格式化日志用vsnprintf完成這是一個(gè)常見(jiàn)的性能熱區(qū)。vsnprintf本身不慢但如果每條日志都調(diào)用在超高并發(fā)場(chǎng)景下仍會(huì)占用大量 CPU。優(yōu)化的思路是把格式化拆成兩步先在生產(chǎn)線程上完成字符串拼接雙緩沖只負(fù)責(zé)搬運(yùn)已經(jīng)成型的字節(jié)流。后臺(tái)線程不能再做格式化否則格式化開(kāi)銷(xiāo)就從業(yè)務(wù)線轉(zhuǎn)移到了后臺(tái)很快會(huì)成為新的瓶頸。4. 部署與使用指南從配置到線上切換的完整流程4.1 配置項(xiàng)的選擇與建議初始化日志系統(tǒng)時(shí)我給LogConfig設(shè)計(jì)了四個(gè)最關(guān)鍵的配置項(xiàng)日志文件路徑前綴、單塊緩沖區(qū)大小、日志級(jí)別、刷新間隔。配置項(xiàng)推薦值說(shuō)明base_filename日志目錄 文件名前綴例如/var/log/app/server_buffer_capacity4MB ~ 16MB根據(jù) QPS 估算內(nèi)存緊張可降到 1MBlog_levelLOG_INFO或LOG_WARN生產(chǎn)環(huán)境不建議開(kāi) DEBUGflush_interval100ms ~ 1000ms越小日志越實(shí)時(shí)但刷盤(pán)越頻繁這里的核心原則是緩沖容量不是越大越好刷新間隔也不是越小越好。容量太大內(nèi)存里堆積的日志變多一旦崩潰丟的就多刷新間隔太小疊加的批量寫(xiě)效果被削弱。線上我常用的組合是8MB 緩沖區(qū)、200ms 刷新間隔、LOG_INFO級(jí)別。這個(gè)組合在各種服務(wù)上表現(xiàn)都比較均衡。文件切分也建議在設(shè)計(jì)時(shí)就考慮進(jìn)去。日志系統(tǒng)跑久了單個(gè)日志文件無(wú)限增長(zhǎng)是災(zāi)難。我通常會(huì)再提供兩個(gè)參數(shù)max_file_size和max_file_count。當(dāng)單文件超過(guò)max_file_size寫(xiě)入切換到下一個(gè)文件當(dāng)文件數(shù)量超過(guò)max_file_count刪除最老的文件。這樣磁盤(pán)占用能被嚴(yán)格限制在可控范圍內(nèi)。4.2 初始化到寫(xiě)日志的代碼示例以一個(gè)典型服務(wù)的主程序?yàn)槔齣nt main() { LogConfig cfg; cfg.base_filename /var/log/app/order_; cfg.buffer_capacity 8 * 1024 * 1024; // 8MB cfg.log_level LogLevel::LOG_INFO; cfg.flush_interval_ms 200; cfg.max_file_size 512 * 1024 * 1024; // 512MB滾動(dòng) cfg.max_file_count 10; if (!AsyncLogger::Instance()-Init(cfg)) { std::cerr init logger failed std::endl; return 1; } LOG_INFO(server started, enabled modules: %s, core,order,pay); // 業(yè)務(wù)邏輯... LOG_DEBUG(request%s, response%s, req_str, resp_str); // 程序退出前 AsyncLogger::Instance()-Shutdown(); return 0; }注意Shutdown()之間的業(yè)務(wù)邏輯如果存在長(zhǎng)期運(yùn)行的線程日志系統(tǒng)必須是線程安全的。我在Write()內(nèi)部用了BufferQueue::Append()上的鎖所以多線程寫(xiě)日志不會(huì)互相干擾。對(duì)于日志順序要求很高的場(chǎng)景順序僅由鎖獲取的順序決定——大多數(shù)業(yè)務(wù)場(chǎng)景不需要關(guān)心這一點(diǎn)。有個(gè)體驗(yàn)上的細(xì)節(jié)日志文件里的時(shí)間戳格式。建議輸出格式帶上精確到毫秒的時(shí)間戳、線程 ID 和日志級(jí)別。后臺(tái)服務(wù)排查問(wèn)題特別是偶發(fā)問(wèn)題缺少線程 ID 會(huì)讓上下文追蹤變得非常痛苦。格式類(lèi)似2025-01-18 14:23:45.678 [12345] INFO request accepted, traceabc1234.3 進(jìn)程優(yōu)雅退出時(shí)的日志處理進(jìn)程退出時(shí)的日志處理是最容易被忽略的坑。如果直接調(diào)用exit()后臺(tái)線程可能才格式化完一半日志進(jìn)程就沒(méi)了。正確順序是通知所有業(yè)務(wù)線程不再寫(xiě)日志或至少保證寫(xiě)日志操作已經(jīng)返回調(diào)用Shutdown()在Shutdown()內(nèi)部停止后臺(tái)刷新線程并把隊(duì)列里剩余的所有 Buffer 全部刷盤(pán)最后進(jìn)程退出為什么必須在Shutdown()里“清空所有 Buffer”因?yàn)槊r(shí)可能有兩個(gè)非空 Buffer一個(gè)是正在寫(xiě)入還沒(méi)滿(mǎn)的一個(gè)是交換后還沒(méi)被后臺(tái)線程取走的。如果只刷了當(dāng)前移交的那個(gè) Buffer另一個(gè)殘留的數(shù)據(jù)就丟了。測(cè)試中就很容易出現(xiàn)一種情況平時(shí)日志正常但進(jìn)程退出瞬間最后幾十條日志神秘失蹤根源就在這里。4.4 信號(hào)處理與崩潰保底線上服務(wù)被kill是常事。比如SIGTERM時(shí)一般會(huì)希望優(yōu)雅退出。我的做法是注冊(cè)了信號(hào)處理器在捕捉到SIGTERM和SIGINT后調(diào)用Shutdown()再退出。但對(duì)于SIGKILL和段錯(cuò)誤SIGSEGV進(jìn)程瞬間死亡任何代碼都來(lái)不及執(zhí)行此時(shí)只能依賴(lài)“日志文件最近一次 flush 之后的內(nèi)容未丟失”這一保證。有個(gè)小技巧可以降低崩潰恢復(fù)的代價(jià)日志系統(tǒng)的后臺(tái)線程每次寫(xiě)完一個(gè) Buffer就執(zhí)行一次fdatasync()或者至少是flush()而不是等到文件關(guān)閉時(shí)再刷。這樣崩潰后最多丟失的就是上一次 flush 之后的數(shù)據(jù)。代價(jià)是磁盤(pán) IO 頻率上升但換來(lái)的是日志可靠性。5. 高頻日志場(chǎng)景下最容易踩的坑和調(diào)優(yōu)路徑5.1 問(wèn)題一日志大量丟失而且丟得沒(méi)有規(guī)律很多第一次用異步日志的團(tuán)隊(duì)上線后發(fā)現(xiàn)日志有缺口第一個(gè)懷疑是磁盤(pán) IO 不夠但實(shí)際上經(jīng)常是Buffer 容量太小 生產(chǎn)速度大于消費(fèi)速度的組合。排查思路在Append()里加一個(gè)丟棄計(jì)數(shù)當(dāng)出現(xiàn)“當(dāng)前緩沖區(qū)寫(xiě)不下且next_也沒(méi)法交換”的情況時(shí)直接丟棄該條日志并累計(jì)計(jì)數(shù)。日志系統(tǒng)可以每秒打印一次這個(gè)計(jì)數(shù)到標(biāo)準(zhǔn)輸出或單獨(dú)的文件。如果丟包率持續(xù)增長(zhǎng)說(shuō)明日志量與 Buffer 容量不匹配。調(diào)優(yōu)手段有兩個(gè)方向增大單塊 Buffer 容量讓攢批的窗口更長(zhǎng)增加后臺(tái)刷新線程數(shù)量或提高刷新頻率注意方向 2 有一個(gè)副作用線程數(shù)量增加意味著刷新更頻繁可能削弱批量寫(xiě)效果。我個(gè)人的經(jīng)驗(yàn)是先嘗試把刷新間隔從 200ms 調(diào)整到 100ms如果還不夠再考慮擴(kuò)容 Buffer一般不推薦加第二個(gè)后臺(tái)線程除非數(shù)據(jù)量真的到了單線程刷盤(pán)上限。5.2 問(wèn)題二雙緩沖交換時(shí)鎖競(jìng)爭(zhēng)激烈日志線程本身成為瓶頸業(yè)務(wù)線程在調(diào)用Write()時(shí)最終都會(huì)進(jìn)入BufferQueue::Append()。當(dāng)日志量大時(shí)這把鎖就成了高頻熱點(diǎn)。雖然我的設(shè)計(jì)里鎖只保護(hù)了一次 append 加一次可能的 swap但 QPS 極高的服務(wù)依然能把這把鎖的競(jìng)爭(zhēng)壓力拉滿(mǎn)。應(yīng)對(duì)辦法有幾個(gè)按性?xún)r(jià)比排序用更精細(xì)的鎖替代std::mutex比如std::shared_mutex在日志量極高時(shí)寫(xiě)鎖其實(shí)不多只在交換的時(shí)候大部分是讀鎖。每個(gè)業(yè)務(wù)線程獨(dú)立的小 Buffer先寫(xiě)入線程本地緩沖積攢到一定閾值再合并到主雙緩沖隊(duì)列。這個(gè)方案稍微復(fù)雜但能大幅降低鎖競(jìng)爭(zhēng)。接受現(xiàn)狀只把日志級(jí)別開(kāi)關(guān)在生產(chǎn)環(huán)境關(guān)掉80% 的日志量來(lái)自 DEBUG生產(chǎn)環(huán)境把級(jí)別調(diào)到 INFO 以上絕大部分性能問(wèn)題自然消失我推薦從第 3 步開(kāi)始。很多團(tuán)隊(duì)上線時(shí)忘了關(guān) DEBUG日志量爆炸式增長(zhǎng)最后怪異步日志系統(tǒng)不行。實(shí)際上把 DEBUG 一關(guān)系統(tǒng)壓力立減 80%。5.3 問(wèn)題三日志內(nèi)容里包含二進(jìn)制、亂碼或超長(zhǎng)行日志系統(tǒng)最常見(jiàn)的使用誤區(qū)是把任意二進(jìn)制數(shù)據(jù)塞進(jìn)日志文本。比如記錄網(wǎng)絡(luò)上報(bào)文的原始字節(jié)或者記錄一個(gè)包含\n的字符串。這些數(shù)據(jù)會(huì)導(dǎo)致日志文件結(jié)構(gòu)被破壞后續(xù)按行解析時(shí)自然錯(cuò)亂。我的做法是在Write()時(shí)對(duì)非打印字符做轉(zhuǎn)義處理。尤其注意\n、\r、\0這幾個(gè)字符轉(zhuǎn)成\\n、\\r之類(lèi)的可見(jiàn)文本。如果業(yè)務(wù)確實(shí)需要記錄完整的二進(jìn)制 dump建議單獨(dú)設(shè)計(jì)一個(gè)WriteBinary()接口走十六進(jìn)制編碼再寫(xiě)文本日志而不是硬塞。另外設(shè)置單條日志的最大長(zhǎng)度。通常一條日志超過(guò) 4KB 就已經(jīng)很夸張了遇到超長(zhǎng)內(nèi)容寧可截?cái)嘁膊荒苋嗡鼡伪?Buffer。vsnprintf本身就支持傳入長(zhǎng)度上限超出部分返回的長(zhǎng)度大于實(shí)際寫(xiě)入長(zhǎng)度你可以據(jù)此判斷是否發(fā)生截?cái)嗖⒀a(bǔ)一個(gè)“日志超長(zhǎng)截?cái)唷钡臉?biāo)記。5.4 問(wèn)題四日志線程退出時(shí)隊(duì)列里還有數(shù)據(jù)沒(méi)來(lái)得及寫(xiě)這個(gè)問(wèn)題在“4.3 進(jìn)程優(yōu)雅退出”里提過(guò)。但還有一種特殊情況后臺(tái)線程在刷最后一個(gè) Buffer 時(shí)業(yè)務(wù)線程仍然在搶鎖寫(xiě)日志兩者互相等待甚至死鎖。我處理的辦法是Shutdown()先把running_原子變量置為false這樣業(yè)務(wù)線程再調(diào)用Write()時(shí)直接放棄寫(xiě)入并返回。接著后臺(tái)線程拿到隊(duì)列鎖把剩下的 Buffer 全部刷盤(pán)。這樣保證了退出路徑上沒(méi)有新的數(shù)據(jù)生成也不會(huì)卡住主程序。5.5 性能數(shù)據(jù)參考與容量估算在常見(jiàn)的高配服務(wù)器上普通 SSD 磁盤(pán)雙緩沖異步日志能實(shí)現(xiàn)百萬(wàn)級(jí)日志行每秒的寫(xiě)入能力。更保守地講和同步日志相比任何一條fprintf直接落盤(pán)的方案切換到雙緩沖異步方案后日志側(cè)性能都能提升一到兩個(gè)數(shù)量級(jí)。給一個(gè)我實(shí)際線上服務(wù)的配置參考業(yè)務(wù)HTTP 網(wǎng)關(guān)高峰期 QPS 1.2 萬(wàn)每請(qǐng)求約產(chǎn)生 8 條日志日志寫(xiě)入峰值約 10 萬(wàn)條/秒文本量約 30~40 MB/s配置雙緩沖各 16MB刷新間隔 100ms日志等級(jí) INFO實(shí)測(cè)結(jié)果業(yè)務(wù)接口 P99 耗時(shí)波動(dòng)小于 1ms日志線程 CPU 占用約 12%這組數(shù)據(jù)可以當(dāng)作一個(gè)估算基線如果你們的日志量是這個(gè)規(guī)模的 5 到 10 倍就該考慮引入多級(jí)緩沖或者直接上專(zhuān)業(yè)的日志采集框架了。5.6 快速故障排查表現(xiàn)象可能原因排查手段日志文件出現(xiàn)缺口Buffer 容量不足 / 刷新線程未跟上檢查丟棄計(jì)數(shù)擴(kuò)容 Buffer 或調(diào)短刷新間隔日志線程 CPU 過(guò)高格式化在后臺(tái)線程執(zhí)行 / 鎖競(jìng)爭(zhēng)嚴(yán)重確保格式化在生產(chǎn)線程完成關(guān) DEBUG 日志日志亂碼或錯(cuò)行二進(jìn)制數(shù)據(jù)未轉(zhuǎn)義在 Write() 中加入轉(zhuǎn)義邏輯限制單條長(zhǎng)度退出時(shí)最后日志丟失Shutdown 未清空剩余 Buffer檢查 Shutdown 實(shí)現(xiàn)確保刷完所有 Buffer日志按小時(shí)延遲刷新間隔過(guò)大 / 文件緩存未刷調(diào)小 flush_interval 或加入定時(shí) flush6. 用了一段時(shí)間之后的幾點(diǎn)體會(huì)雙緩沖日志系統(tǒng)已經(jīng)在我們這邊服務(wù)里平穩(wěn)跑了挺長(zhǎng)時(shí)間最大的感受是“日志”和“業(yè)務(wù)”終于不再互相牽扯。以前同步日志時(shí)代每次線上問(wèn)題排查都要祈禱日志別把系統(tǒng)拖慢切到異步之后日志只是安靜地把該記的記下來(lái)業(yè)務(wù)線程完全不用關(guān)心磁盤(pán)的脾氣。如果只看設(shè)計(jì)雙緩沖方案的代碼量并不大核心邏輯可能兩三百行就能寫(xiě)完。但真正值錢(qián)的不是代碼而是對(duì)邊角情況的處理。比如交換時(shí) Buffer 的狀態(tài)判斷、Shutdown 時(shí)清理隊(duì)列的邏輯、超長(zhǎng)日志的截?cái)嗯c轉(zhuǎn)義這些細(xì)節(jié)決定了系統(tǒng)在線上是否可靠。文檔里不會(huì)告訴你這些坑只有實(shí)際踩過(guò)才知道。還有一點(diǎn)個(gè)人建議日志系統(tǒng)的代碼最好保持簡(jiǎn)單、可讀、少依賴(lài)。它不像業(yè)務(wù)模塊那樣圍繞架構(gòu)演進(jìn)穩(wěn)定和可靠永遠(yuǎn)排在第一位。就算將來(lái)要升級(jí)也盡量在現(xiàn)有接口上做增量改動(dòng)而不是推倒重來(lái)。下一篇文章我會(huì)把雙緩沖隊(duì)列日志系統(tǒng)的完整實(shí)現(xiàn)代碼展開(kāi)講包括后臺(tái)線程的調(diào)度細(xì)節(jié)、文件滾動(dòng)策略的具體寫(xiě)法以及如何把日志量級(jí)擴(kuò)展到更高。如果你現(xiàn)在遇到日志性能上的問(wèn)題建議先按這篇文章的設(shè)計(jì)思路把手里的同步日志替換成異步雙緩沖版親身體會(huì)一下“日志不再拖后腿”的差別。 雙緩沖隊(duì)列異步日志系統(tǒng)：高并發(fā)場(chǎng)景下徹底解決同步日志阻塞問(wèn)題
1. 先別急著一股腦寫(xiě)文件同步日志為什么扛不住生產(chǎn)環(huán)境先說(shuō)結(jié)論再聊細(xì)節(jié)日志系統(tǒng)最容易被低估也最容易被埋雷。很多項(xiàng)目剛開(kāi)始的時(shí)候日志就是到處printf或者更“規(guī)范”一點(diǎn)接個(gè)log4j、spdlog級(jí)別的庫(kù)線上跑一跑也沒(méi)覺(jué)得有什么問(wèn)題。但等流量上來(lái)高并發(fā)場(chǎng)景一壓第一塊倒下的往往不是業(yè)務(wù)代碼而是看似人畜無(wú)害的日志鏈路。我們做雙緩沖隊(duì)列異步日志系統(tǒng)要解決的核心痛點(diǎn)很簡(jiǎn)單日志寫(xiě)入不再阻塞業(yè)務(wù)線程。同步日志為什么會(huì)阻塞因?yàn)閣rite()到磁盤(pán)并不便宜。一個(gè)日志條目看起來(lái)只是一行字符串但這條字符串從用戶(hù)態(tài)的日志緩沖區(qū)到內(nèi)核的文件系統(tǒng)緩存再到真正的磁盤(pán)設(shè)備中間隔著至少兩道拷貝還伴隨一次系統(tǒng)調(diào)用。生產(chǎn)環(huán)境里無(wú)論是機(jī)械硬盤(pán)還是 SSD單次寫(xiě)入的小 IO 都遠(yuǎn)沒(méi)有想象中的快。日志一多、高頻一寫(xiě)業(yè)務(wù)線程就被迫排隊(duì)等磁盤(pán)。我舉個(gè)真實(shí)場(chǎng)景某線上服務(wù)需要記錄每次請(qǐng)求的完整參數(shù)和響應(yīng)體單個(gè)請(qǐng)求撐死幾十行日志但 QPS 上了幾千之后同步日志的磁盤(pán)寫(xiě)壓力瞬間拉滿(mǎn)接口平均耗時(shí)從 2ms 漲到了 40ms最夸張的時(shí)候業(yè)務(wù)線程被日志卡的連心跳包都發(fā)不出去。后來(lái)把策略改成“攢一批再寫(xiě)”問(wèn)題才算緩解。這就是異步日志的核心思路把日志寫(xiě)入從業(yè)務(wù)線程上搬走交給專(zhuān)門(mén)的線程去處理。業(yè)務(wù)線程只負(fù)責(zé)把日志內(nèi)容往內(nèi)存里一放就返回磁盤(pán)寫(xiě)入由后臺(tái)線程異步完成。聽(tīng)起來(lái)簡(jiǎn)單但實(shí)現(xiàn)上有很多講究尤其是“怎么把日志內(nèi)容安全高效地交到后臺(tái)線程”這一步選型不同效果天差地別。雙緩沖隊(duì)列就是這條鏈路里比較經(jīng)典、也比較容易理解的一種實(shí)現(xiàn)方案。如果你現(xiàn)在正被“日志寫(xiě)入拖慢接口”“日志一多系統(tǒng)就卡頓”“日志模塊與業(yè)務(wù)模塊共用鎖導(dǎo)致死等”這些問(wèn)題困擾這篇文章適合你。我會(huì)從設(shè)計(jì)思路講到接口封裝再到部署使用把雙緩沖日志系統(tǒng)的“上半場(chǎng)”講透。2. 雙緩沖隊(duì)列的工作機(jī)制把“寫(xiě)日志”和“寫(xiě)磁盤(pán)”拆開(kāi)2.1 兩段式緩沖一個(gè)正寫(xiě)一個(gè)在刷雙緩沖隊(duì)列這個(gè)名字關(guān)鍵在于“雙”和“隊(duì)列”。“緩沖”比較好理解就是一塊預(yù)先分配好的內(nèi)存。日志內(nèi)容先落在這塊內(nèi)存里攢多了再一次性寫(xiě)入磁盤(pán)。為什么要攢因?yàn)橐淮蝫rite()寫(xiě)入 1MB 數(shù)據(jù)和分 1 萬(wàn)次每次寫(xiě) 100 字節(jié)兩者的 IO 效率完全是兩個(gè)量級(jí)。批量寫(xiě)不僅能大大減少系統(tǒng)調(diào)用的次數(shù)還能讓磁盤(pán)的寫(xiě)模式更規(guī)整性能提升非常明顯?！半p緩沖”指的是這塊預(yù)分配內(nèi)存有兩份。一份被業(yè)務(wù)線程用來(lái)寫(xiě)入日志稱(chēng)為“待寫(xiě)緩沖區(qū)”或“當(dāng)前緩沖區(qū)”另一份被后臺(tái)線程用來(lái)讀取并刷入磁盤(pán)稱(chēng)為“待刷緩沖區(qū)”。當(dāng)“當(dāng)前緩沖區(qū)”寫(xiě)滿(mǎn)了或者到了固定時(shí)間系統(tǒng)會(huì)執(zhí)行一次緩沖區(qū)交換swap把業(yè)務(wù)線程寫(xiě)滿(mǎn)的這塊換成后臺(tái)線程手里的那塊。交換之后業(yè)務(wù)線程繼續(xù)往新?lián)Q來(lái)的空緩沖區(qū)里寫(xiě)后臺(tái)線程則拿著裝滿(mǎn)日志的緩沖區(qū)去刷磁盤(pán)。圖景大概是這樣業(yè)務(wù)線程 后臺(tái)線程 | | | 寫(xiě)入Buffer A | |-------------| | Buffer A滿(mǎn) | | 交換 | |-------------| | 寫(xiě)入Buffer B | | | 刷Buffer A到磁盤(pán) | |------------- Disk簡(jiǎn)化成文字描述就是業(yè)務(wù)線程永遠(yuǎn)只面對(duì)一塊“可以寫(xiě)”的內(nèi)存寫(xiě)完一塊就換一塊完全不碰磁盤(pán) IO。后臺(tái)線程永遠(yuǎn)只面對(duì)一塊“已經(jīng)寫(xiě)滿(mǎn)”的內(nèi)存刷完一塊就換一塊完全不阻塞業(yè)務(wù)線程。兩者之間只有一次極短的交換操作需要同步。2.2 為什么是“雙”緩沖而不是單緩沖或多緩沖單緩沖的方案看起來(lái)也能用一塊緩沖區(qū)寫(xiě)滿(mǎn)了就刷盤(pán)刷盤(pán)期間業(yè)務(wù)線程等著。但問(wèn)題在于“寫(xiě)滿(mǎn)后刷盤(pán)”這個(gè)動(dòng)作是阻塞的而且刷盤(pán)耗時(shí)不定。一旦磁盤(pán)繁忙業(yè)務(wù)線程就卡住了和同步日志沒(méi)有本質(zhì)區(qū)別只是把fprintf換成了memcpy仍然治標(biāo)不治本。多緩沖方案呢理論上可以準(zhǔn)備 N 塊緩沖區(qū)寫(xiě)滿(mǎn)一塊就換下一塊后臺(tái)線程依次刷。這能進(jìn)一步降低交換頻率內(nèi)存占用也更高。但在大部分場(chǎng)景下兩塊緩沖區(qū)已經(jīng)足夠只要后臺(tái)線程刷盤(pán)的平均速度大于業(yè)務(wù)線程寫(xiě)入的平均速度兩塊就能循環(huán)起來(lái)。如果后臺(tái)線程的消費(fèi)速度跟不上說(shuō)明系統(tǒng)已經(jīng)到了日志量過(guò)載的狀態(tài)即使準(zhǔn)備更多緩沖區(qū)也只是延緩問(wèn)題并不能消除問(wèn)題。這里有個(gè)很多人會(huì)忽略的點(diǎn)雙緩沖系統(tǒng)里的交換是“一次性”完成的。生產(chǎn)線程與消費(fèi)線程之間只共享一個(gè)狀態(tài)指針一次 swap 操作只需要幾納秒到幾十納秒的臨界區(qū)保護(hù)。對(duì)比直接用std::queue存日志的逐條入隊(duì)方案雙緩沖避免了高頻的鎖競(jìng)爭(zhēng)把鎖的粒度從“每條日志”降到了“每批日志”這是它能扛高吞吐的根本原因。另外雙緩沖天然支持延遲刷新。很多時(shí)候日志峰值只出現(xiàn)在一秒內(nèi)的某幾百毫秒中其他時(shí)間業(yè)務(wù)線程并不忙。如果每寫(xiě)一條就通知后臺(tái)線程來(lái)取線程喚醒、上下文切換的成本反而會(huì)拖垮性能。雙緩沖方案可以設(shè)定“緩沖區(qū)未滿(mǎn)就定時(shí)刷”比如每 1 秒強(qiáng)制交換一次保證日志延遲可控且不會(huì)出現(xiàn)長(zhǎng)時(shí)間無(wú)輸出。2.3 雙緩沖的兩個(gè)隱藏風(fēng)險(xiǎn)設(shè)計(jì)時(shí)繞不開(kāi)第一個(gè)風(fēng)險(xiǎn)是日志丟失。異步意味著業(yè)務(wù)線程返回時(shí)日志還沒(méi)落盤(pán)如果此時(shí)進(jìn)程崩潰或者被kill -9最后一段還在內(nèi)存里的日志就沒(méi)了。這個(gè)問(wèn)題沒(méi)法完全規(guī)避只能降低損失。常見(jiàn)做法是后臺(tái)線程定期刷盤(pán)并且支持外部顯式調(diào)用Flush()在需要保命的關(guān)鍵節(jié)點(diǎn)比如服務(wù)收到終止信號(hào)后強(qiáng)制把所有緩沖數(shù)據(jù)落盤(pán)。第二個(gè)風(fēng)險(xiǎn)是背壓?jiǎn)栴}。如果日志生產(chǎn)速度長(zhǎng)期超過(guò)消費(fèi)速度緩沖區(qū)很快會(huì)處于“寫(xiě)滿(mǎn)-交換-刷盤(pán)-再寫(xiě)滿(mǎn)”的循環(huán)表現(xiàn)為磁盤(pán)持續(xù)高負(fù)載系統(tǒng)整體性能下降。此時(shí)不能無(wú)限等下去常見(jiàn)策略是當(dāng)兩緩沖都占滿(mǎn)且后臺(tái)線程來(lái)不及刷時(shí)要么直接丟棄未來(lái)日志并按計(jì)數(shù)報(bào)錯(cuò)要么將當(dāng)前緩沖區(qū)擴(kuò)容一擋臨時(shí)救急。我一般推薦前者因?yàn)槿罩玖窟^(guò)載時(shí)保留完整性的優(yōu)先級(jí)低于保證業(yè)務(wù)可用性而且丟失提示本身也是重要日志。3. 核心接口設(shè)計(jì)Buffer、隊(duì)列交換與 AsyncLogger設(shè)計(jì)雙緩沖日志系統(tǒng)時(shí)最重要的是把三個(gè)角色拆清楚Buffer負(fù)責(zé)存儲(chǔ)字節(jié)流BufferQueue負(fù)責(zé)管理兩個(gè) Buffer 的交換與調(diào)度AsyncLogger負(fù)責(zé)向上層業(yè)務(wù)提供日志寫(xiě)入 API同時(shí)管理后臺(tái)線程的生命周期。3.1 Buffer 的核心字段與內(nèi)存使用Buffer本質(zhì)是一塊預(yù)分配內(nèi)存加上讀寫(xiě)游標(biāo)。我常用的定義大概是class Buffer { public: explicit Buffer(size_t capacity) { data_.reserve(capacity); } void Append(const char* log, size_t len) { if (len WritableBytes()) { return; // 或觸發(fā)擴(kuò)容 / 丟棄策略 } data_.insert(data_.end(), log, log len); } void Reset() { data_.clear(); } bool Empty() { return data_.empty(); } size_t WritableBytes() { return data_.capacity() - data_.size(); } const char* Data() { return data_.data(); } size_t Size() { return data_.size(); } private: std::vectorchar data_; };注意這里我用的是std::vector而不是裸指針加char[]。生產(chǎn)級(jí)日志系統(tǒng)對(duì)性能苛刻通常會(huì)直接用預(yù)分配的char[]配合size_t游標(biāo)甚至用mmap映射文件。但std::vector足夠滿(mǎn)足絕大多數(shù)業(yè)務(wù)系統(tǒng)的日志壓力而且內(nèi)存管理更安全。真正要緊的是讓 Buffer 的容量在初始化時(shí)一次定好盡量避免運(yùn)行期擴(kuò)容——擴(kuò)容可能觸發(fā)內(nèi)存搬移而且擴(kuò)容期間的操作會(huì)引入額外的不確定性。Buffer 容量取多大這個(gè)沒(méi)有標(biāo)準(zhǔn)答案。我個(gè)人的經(jīng)驗(yàn)值是單條日志平均長(zhǎng)度按 256 字節(jié)估如果 QPS 峰值為 1 萬(wàn)每秒日志量約為 2.5MB那么每塊 Buffer 設(shè)為 8MB 左右比較合適兩塊就是 16MB。日志量小的服務(wù)4MB 也已經(jīng)足夠了。內(nèi)存是便宜的資源不必太摳但也不要拍腦袋選個(gè) 1GB —— 那會(huì)讓緩存的優(yōu)勢(shì)變成內(nèi)存的壓力。3.2 BufferQueue 的交換邏輯BufferQueue是雙緩沖結(jié)構(gòu)的中樞。它內(nèi)部維護(hù)兩個(gè) Buffer 指針并在合適的時(shí)機(jī)執(zhí)行交換。class BufferQueue { public: explicit BufferQueue(size_t buffer_capacity) : buffer_capacity_(buffer_capacity), current_(new Buffer(buffer_capacity)), next_(new Buffer(buffer_capacity)) {} void Append(const char* data, size_t len) { std::lock_guardstd::mutex lock(mutex_); if (current_-WritableBytes() len) { Swap(); } current_-Append(data, len); } std::shared_ptrBuffer TakeForFlush() { std::lock_guardstd::mutex lock(mutex_); if (current_-Empty() next_-Empty()) { return nullptr; } Swap(); return std::shared_ptrBuffer swap_result_; } private: void Swap() { std::swap(current_, next_); // 這里同時(shí)喚醒消費(fèi)線程 } size_t buffer_capacity_; std::unique_ptrBuffer current_; std::unique_ptrBuffer next_; std::mutex mutex_; std::condition_variable cond_; };這段邏輯里有幾個(gè)微妙的地方第一Append時(shí)發(fā)現(xiàn)當(dāng)前緩沖區(qū)寫(xiě)不下一條日志立刻交換然后把日志寫(xiě)到新緩沖區(qū)上。這意味著next_可能已經(jīng)在積累數(shù)據(jù)了交換前它會(huì)被重置。這里有一個(gè)取舍如果next_里還有沒(méi)來(lái)得及被后臺(tái)線程刷盤(pán)的數(shù)據(jù)交換會(huì)造成日志順序錯(cuò)亂或數(shù)據(jù)覆蓋。所以更嚴(yán)謹(jǐn)?shù)膶?xiě)法是當(dāng)Append時(shí)current_寫(xiě)不下且next_非空即后臺(tái)線程還沒(méi)取走過(guò)要介入“等待消費(fèi)線程完成一次 flush”的流程。我在實(shí)現(xiàn)時(shí)通過(guò)條件變量控制保證交換發(fā)生時(shí)next_一定是已經(jīng)刷完的空 Buffer。第二條件變量的喚醒時(shí)機(jī)。最直接的邏輯是Swap()之后立刻喚醒后臺(tái)線程。但如果每次Append都喚醒日志量一高線程頻繁被喚醒上下文切換成本就上去了。我的做法是只有滿(mǎn)足“當(dāng)前緩沖區(qū)由空變?yōu)榉强铡被颉敖粨Q發(fā)生時(shí)next_中有數(shù)據(jù)”這兩個(gè)條件才喚醒。這能把線程喚醒次數(shù)與日志寫(xiě)入頻率解耦后臺(tái)線程還可以配合定時(shí)策略每 100ms 檢查一次。3.3 AsyncLogger 的對(duì)外接口設(shè)計(jì)對(duì)外接口是我的原則是極簡(jiǎn)。業(yè)務(wù)方不需要理解雙緩沖內(nèi)部機(jī)制他們只需要“初始化、寫(xiě)日志、關(guān)閉”這三個(gè)動(dòng)作。class AsyncLogger { public: static AsyncLogger* Instance(); bool Init(const LogConfig config); void Write(LogLevel level, const char* fmt, ...); void Flush(); void Shutdown(); private: AsyncLogger(); ~AsyncLogger(); void WriteToBuffer(const char* line, size_t len); void FlushThread(); std::unique_ptrBufferQueue queue_; std::thread background_thread_; std::atomicbool running_{false}; LogLevel level_{LOG_INFO}; };Init()初始化配置啟動(dòng)后臺(tái)線程Write()格式化日志寫(xiě)入 BufferQueue返回即代表日志“已受理”Flush()強(qiáng)制刷新緩沖區(qū)用于關(guān)鍵節(jié)點(diǎn)Shutdown()停止后臺(tái)線程刷完所有遺留數(shù)據(jù)安全退出Write()為什么設(shè)計(jì)成可變參數(shù)因?yàn)槲蚁Ｍ罩菊{(diào)用點(diǎn)在形式上盡可能接近原生的printf。業(yè)務(wù)側(cè)配合宏定義使用體驗(yàn)上就像寫(xiě)printf一樣自然#define LOG_DEBUG(...) AsyncLogger::Instance()-Write(LOG_DEBUG, __VA_ARGS__) #define LOG_INFO(...) AsyncLogger::Instance()-Write(LOG_INFO, __VA_ARGS__) #define LOG_ERROR(...) AsyncLogger::Instance()-Write(LOG_ERROR, __VA_ARGS__)在Write()內(nèi)部格式化日志用vsnprintf完成這是一個(gè)常見(jiàn)的性能熱區(qū)。vsnprintf本身不慢但如果每條日志都調(diào)用在超高并發(fā)場(chǎng)景下仍會(huì)占用大量 CPU。優(yōu)化的思路是把格式化拆成兩步先在生產(chǎn)線程上完成字符串拼接雙緩沖只負(fù)責(zé)搬運(yùn)已經(jīng)成型的字節(jié)流。后臺(tái)線程不能再做格式化否則格式化開(kāi)銷(xiāo)就從業(yè)務(wù)線轉(zhuǎn)移到了后臺(tái)很快會(huì)成為新的瓶頸。4. 部署與使用指南從配置到線上切換的完整流程4.1 配置項(xiàng)的選擇與建議初始化日志系統(tǒng)時(shí)我給LogConfig設(shè)計(jì)了四個(gè)最關(guān)鍵的配置項(xiàng)日志文件路徑前綴、單塊緩沖區(qū)大小、日志級(jí)別、刷新間隔。配置項(xiàng)推薦值說(shuō)明base_filename日志目錄 文件名前綴例如/var/log/app/server_buffer_capacity4MB ~ 16MB根據(jù) QPS 估算內(nèi)存緊張可降到 1MBlog_levelLOG_INFO或LOG_WARN生產(chǎn)環(huán)境不建議開(kāi) DEBUGflush_interval100ms ~ 1000ms越小日志越實(shí)時(shí)但刷盤(pán)越頻繁這里的核心原則是緩沖容量不是越大越好刷新間隔也不是越小越好。容量太大內(nèi)存里堆積的日志變多一旦崩潰丟的就多刷新間隔太小疊加的批量寫(xiě)效果被削弱。線上我常用的組合是8MB 緩沖區(qū)、200ms 刷新間隔、LOG_INFO級(jí)別。這個(gè)組合在各種服務(wù)上表現(xiàn)都比較均衡。文件切分也建議在設(shè)計(jì)時(shí)就考慮進(jìn)去。日志系統(tǒng)跑久了單個(gè)日志文件無(wú)限增長(zhǎng)是災(zāi)難。我通常會(huì)再提供兩個(gè)參數(shù)max_file_size和max_file_count。當(dāng)單文件超過(guò)max_file_size寫(xiě)入切換到下一個(gè)文件當(dāng)文件數(shù)量超過(guò)max_file_count刪除最老的文件。這樣磁盤(pán)占用能被嚴(yán)格限制在可控范圍內(nèi)。4.2 初始化到寫(xiě)日志的代碼示例以一個(gè)典型服務(wù)的主程序?yàn)槔齣nt main() { LogConfig cfg; cfg.base_filename /var/log/app/order_; cfg.buffer_capacity 8 * 1024 * 1024; // 8MB cfg.log_level LogLevel::LOG_INFO; cfg.flush_interval_ms 200; cfg.max_file_size 512 * 1024 * 1024; // 512MB滾動(dòng) cfg.max_file_count 10; if (!AsyncLogger::Instance()-Init(cfg)) { std::cerr init logger failed std::endl; return 1; } LOG_INFO(server started, enabled modules: %s, core,order,pay); // 業(yè)務(wù)邏輯... LOG_DEBUG(request%s, response%s, req_str, resp_str); // 程序退出前 AsyncLogger::Instance()-Shutdown(); return 0; }注意Shutdown()之間的業(yè)務(wù)邏輯如果存在長(zhǎng)期運(yùn)行的線程日志系統(tǒng)必須是線程安全的。我在Write()內(nèi)部用了BufferQueue::Append()上的鎖所以多線程寫(xiě)日志不會(huì)互相干擾。對(duì)于日志順序要求很高的場(chǎng)景順序僅由鎖獲取的順序決定——大多數(shù)業(yè)務(wù)場(chǎng)景不需要關(guān)心這一點(diǎn)。有個(gè)體驗(yàn)上的細(xì)節(jié)日志文件里的時(shí)間戳格式。建議輸出格式帶上精確到毫秒的時(shí)間戳、線程 ID 和日志級(jí)別。后臺(tái)服務(wù)排查問(wèn)題特別是偶發(fā)問(wèn)題缺少線程 ID 會(huì)讓上下文追蹤變得非常痛苦。格式類(lèi)似2025-01-18 14:23:45.678 [12345] INFO request accepted, traceabc1234.3 進(jìn)程優(yōu)雅退出時(shí)的日志處理進(jìn)程退出時(shí)的日志處理是最容易被忽略的坑。如果直接調(diào)用exit()后臺(tái)線程可能才格式化完一半日志進(jìn)程就沒(méi)了。正確順序是通知所有業(yè)務(wù)線程不再寫(xiě)日志或至少保證寫(xiě)日志操作已經(jīng)返回調(diào)用Shutdown()在Shutdown()內(nèi)部停止后臺(tái)刷新線程并把隊(duì)列里剩余的所有 Buffer 全部刷盤(pán)最后進(jìn)程退出為什么必須在Shutdown()里“清空所有 Buffer”因?yàn)槊r(shí)可能有兩個(gè)非空 Buffer一個(gè)是正在寫(xiě)入還沒(méi)滿(mǎn)的一個(gè)是交換后還沒(méi)被后臺(tái)線程取走的。如果只刷了當(dāng)前移交的那個(gè) Buffer另一個(gè)殘留的數(shù)據(jù)就丟了。測(cè)試中就很容易出現(xiàn)一種情況平時(shí)日志正常但進(jìn)程退出瞬間最后幾十條日志神秘失蹤根源就在這里。4.4 信號(hào)處理與崩潰保底線上服務(wù)被kill是常事。比如SIGTERM時(shí)一般會(huì)希望優(yōu)雅退出。我的做法是注冊(cè)了信號(hào)處理器在捕捉到SIGTERM和SIGINT后調(diào)用Shutdown()再退出。但對(duì)于SIGKILL和段錯(cuò)誤SIGSEGV進(jìn)程瞬間死亡任何代碼都來(lái)不及執(zhí)行此時(shí)只能依賴(lài)“日志文件最近一次 flush 之后的內(nèi)容未丟失”這一保證。有個(gè)小技巧可以降低崩潰恢復(fù)的代價(jià)日志系統(tǒng)的后臺(tái)線程每次寫(xiě)完一個(gè) Buffer就執(zhí)行一次fdatasync()或者至少是flush()而不是等到文件關(guān)閉時(shí)再刷。這樣崩潰后最多丟失的就是上一次 flush 之后的數(shù)據(jù)。代價(jià)是磁盤(pán) IO 頻率上升但換來(lái)的是日志可靠性。5. 高頻日志場(chǎng)景下最容易踩的坑和調(diào)優(yōu)路徑5.1 問(wèn)題一日志大量丟失而且丟得沒(méi)有規(guī)律很多第一次用異步日志的團(tuán)隊(duì)上線后發(fā)現(xiàn)日志有缺口第一個(gè)懷疑是磁盤(pán) IO 不夠但實(shí)際上經(jīng)常是Buffer 容量太小 生產(chǎn)速度大于消費(fèi)速度的組合。排查思路在Append()里加一個(gè)丟棄計(jì)數(shù)當(dāng)出現(xiàn)“當(dāng)前緩沖區(qū)寫(xiě)不下且next_也沒(méi)法交換”的情況時(shí)直接丟棄該條日志并累計(jì)計(jì)數(shù)。日志系統(tǒng)可以每秒打印一次這個(gè)計(jì)數(shù)到標(biāo)準(zhǔn)輸出或單獨(dú)的文件。如果丟包率持續(xù)增長(zhǎng)說(shuō)明日志量與 Buffer 容量不匹配。調(diào)優(yōu)手段有兩個(gè)方向增大單塊 Buffer 容量讓攢批的窗口更長(zhǎng)增加后臺(tái)刷新線程數(shù)量或提高刷新頻率注意方向 2 有一個(gè)副作用線程數(shù)量增加意味著刷新更頻繁可能削弱批量寫(xiě)效果。我個(gè)人的經(jīng)驗(yàn)是先嘗試把刷新間隔從 200ms 調(diào)整到 100ms如果還不夠再考慮擴(kuò)容 Buffer一般不推薦加第二個(gè)后臺(tái)線程除非數(shù)據(jù)量真的到了單線程刷盤(pán)上限。5.2 問(wèn)題二雙緩沖交換時(shí)鎖競(jìng)爭(zhēng)激烈日志線程本身成為瓶頸業(yè)務(wù)線程在調(diào)用Write()時(shí)最終都會(huì)進(jìn)入BufferQueue::Append()。當(dāng)日志量大時(shí)這把鎖就成了高頻熱點(diǎn)。雖然我的設(shè)計(jì)里鎖只保護(hù)了一次 append 加一次可能的 swap但 QPS 極高的服務(wù)依然能把這把鎖的競(jìng)爭(zhēng)壓力拉滿(mǎn)。應(yīng)對(duì)辦法有幾個(gè)按性?xún)r(jià)比排序用更精細(xì)的鎖替代std::mutex比如std::shared_mutex在日志量極高時(shí)寫(xiě)鎖其實(shí)不多只在交換的時(shí)候大部分是讀鎖。每個(gè)業(yè)務(wù)線程獨(dú)立的小 Buffer先寫(xiě)入線程本地緩沖積攢到一定閾值再合并到主雙緩沖隊(duì)列。這個(gè)方案稍微復(fù)雜但能大幅降低鎖競(jìng)爭(zhēng)。接受現(xiàn)狀只把日志級(jí)別開(kāi)關(guān)在生產(chǎn)環(huán)境關(guān)掉80% 的日志量來(lái)自 DEBUG生產(chǎn)環(huán)境把級(jí)別調(diào)到 INFO 以上絕大部分性能問(wèn)題自然消失我推薦從第 3 步開(kāi)始。很多團(tuán)隊(duì)上線時(shí)忘了關(guān) DEBUG日志量爆炸式增長(zhǎng)最后怪異步日志系統(tǒng)不行。實(shí)際上把 DEBUG 一關(guān)系統(tǒng)壓力立減 80%。5.3 問(wèn)題三日志內(nèi)容里包含二進(jìn)制、亂碼或超長(zhǎng)行日志系統(tǒng)最常見(jiàn)的使用誤區(qū)是把任意二進(jìn)制數(shù)據(jù)塞進(jìn)日志文本。比如記錄網(wǎng)絡(luò)上報(bào)文的原始字節(jié)或者記錄一個(gè)包含\n的字符串。這些數(shù)據(jù)會(huì)導(dǎo)致日志文件結(jié)構(gòu)被破壞后續(xù)按行解析時(shí)自然錯(cuò)亂。我的做法是在Write()時(shí)對(duì)非打印字符做轉(zhuǎn)義處理。尤其注意\n、\r、\0這幾個(gè)字符轉(zhuǎn)成\\n、\\r之類(lèi)的可見(jiàn)文本。如果業(yè)務(wù)確實(shí)需要記錄完整的二進(jìn)制 dump建議單獨(dú)設(shè)計(jì)一個(gè)WriteBinary()接口走十六進(jìn)制編碼再寫(xiě)文本日志而不是硬塞。另外設(shè)置單條日志的最大長(zhǎng)度。通常一條日志超過(guò) 4KB 就已經(jīng)很夸張了遇到超長(zhǎng)內(nèi)容寧可截?cái)嘁膊荒苋嗡鼡伪?Buffer。vsnprintf本身就支持傳入長(zhǎng)度上限超出部分返回的長(zhǎng)度大于實(shí)際寫(xiě)入長(zhǎng)度你可以據(jù)此判斷是否發(fā)生截?cái)嗖⒀a(bǔ)一個(gè)“日志超長(zhǎng)截?cái)唷钡臉?biāo)記。5.4 問(wèn)題四日志線程退出時(shí)隊(duì)列里還有數(shù)據(jù)沒(méi)來(lái)得及寫(xiě)這個(gè)問(wèn)題在“4.3 進(jìn)程優(yōu)雅退出”里提過(guò)。但還有一種特殊情況后臺(tái)線程在刷最后一個(gè) Buffer 時(shí)業(yè)務(wù)線程仍然在搶鎖寫(xiě)日志兩者互相等待甚至死鎖。我處理的辦法是Shutdown()先把running_原子變量置為false這樣業(yè)務(wù)線程再調(diào)用Write()時(shí)直接放棄寫(xiě)入并返回。接著后臺(tái)線程拿到隊(duì)列鎖把剩下的 Buffer 全部刷盤(pán)。這樣保證了退出路徑上沒(méi)有新的數(shù)據(jù)生成也不會(huì)卡住主程序。5.5 性能數(shù)據(jù)參考與容量估算在常見(jiàn)的高配服務(wù)器上普通 SSD 磁盤(pán)雙緩沖異步日志能實(shí)現(xiàn)百萬(wàn)級(jí)日志行每秒的寫(xiě)入能力。更保守地講和同步日志相比任何一條fprintf直接落盤(pán)的方案切換到雙緩沖異步方案后日志側(cè)性能都能提升一到兩個(gè)數(shù)量級(jí)。給一個(gè)我實(shí)際線上服務(wù)的配置參考業(yè)務(wù)HTTP 網(wǎng)關(guān)高峰期 QPS 1.2 萬(wàn)每請(qǐng)求約產(chǎn)生 8 條日志日志寫(xiě)入峰值約 10 萬(wàn)條/秒文本量約 30~40 MB/s配置雙緩沖各 16MB刷新間隔 100ms日志等級(jí) INFO實(shí)測(cè)結(jié)果業(yè)務(wù)接口 P99 耗時(shí)波動(dòng)小于 1ms日志線程 CPU 占用約 12%這組數(shù)據(jù)可以當(dāng)作一個(gè)估算基線如果你們的日志量是這個(gè)規(guī)模的 5 到 10 倍就該考慮引入多級(jí)緩沖或者直接上專(zhuān)業(yè)的日志采集框架了。5.6 快速故障排查表現(xiàn)象可能原因排查手段日志文件出現(xiàn)缺口Buffer 容量不足 / 刷新線程未跟上檢查丟棄計(jì)數(shù)擴(kuò)容 Buffer 或調(diào)短刷新間隔日志線程 CPU 過(guò)高格式化在后臺(tái)線程執(zhí)行 / 鎖競(jìng)爭(zhēng)嚴(yán)重確保格式化在生產(chǎn)線程完成關(guān) DEBUG 日志日志亂碼或錯(cuò)行二進(jìn)制數(shù)據(jù)未轉(zhuǎn)義在 Write() 中加入轉(zhuǎn)義邏輯限制單條長(zhǎng)度退出時(shí)最后日志丟失Shutdown 未清空剩余 Buffer檢查 Shutdown 實(shí)現(xiàn)確保刷完所有 Buffer日志按小時(shí)延遲刷新間隔過(guò)大 / 文件緩存未刷調(diào)小 flush_interval 或加入定時(shí) flush6. 用了一段時(shí)間之后的幾點(diǎn)體會(huì)雙緩沖日志系統(tǒng)已經(jīng)在我們這邊服務(wù)里平穩(wěn)跑了挺長(zhǎng)時(shí)間最大的感受是“日志”和“業(yè)務(wù)”終于不再互相牽扯。以前同步日志時(shí)代每次線上問(wèn)題排查都要祈禱日志別把系統(tǒng)拖慢切到異步之后日志只是安靜地把該記的記下來(lái)業(yè)務(wù)線程完全不用關(guān)心磁盤(pán)的脾氣。如果只看設(shè)計(jì)雙緩沖方案的代碼量并不大核心邏輯可能兩三百行就能寫(xiě)完。但真正值錢(qián)的不是代碼而是對(duì)邊角情況的處理。比如交換時(shí) Buffer 的狀態(tài)判斷、Shutdown 時(shí)清理隊(duì)列的邏輯、超長(zhǎng)日志的截?cái)嗯c轉(zhuǎn)義這些細(xì)節(jié)決定了系統(tǒng)在線上是否可靠。文檔里不會(huì)告訴你這些坑只有實(shí)際踩過(guò)才知道。還有一點(diǎn)個(gè)人建議日志系統(tǒng)的代碼最好保持簡(jiǎn)單、可讀、少依賴(lài)。它不像業(yè)務(wù)模塊那樣圍繞架構(gòu)演進(jìn)穩(wěn)定和可靠永遠(yuǎn)排在第一位。就算將來(lái)要升級(jí)也盡量在現(xiàn)有接口上做增量改動(dòng)而不是推倒重來(lái)。下一篇文章我會(huì)把雙緩沖隊(duì)列日志系統(tǒng)的完整實(shí)現(xiàn)代碼展開(kāi)講包括后臺(tái)線程的調(diào)度細(xì)節(jié)、文件滾動(dòng)策略的具體寫(xiě)法以及如何把日志量級(jí)擴(kuò)展到更高。如果你現(xiàn)在遇到日志性能上的問(wèn)題建議先按這篇文章的設(shè)計(jì)思路把手里的同步日志替換成異步雙緩沖版親身體會(huì)一下“日志不再拖后腿”的差別。