[[379907]]

本文轉(zhuǎn)載自微信公眾號「真沒什么邏輯」，作者 Draveness 。轉(zhuǎn)載本文請聯(lián)系真沒什么邏輯公眾號。

『看看論文』是一系列分析計算機和軟件工程領域論文的文章，我們在這個系列的每一篇文章中都會閱讀一篇來自 OSDI、SOSP 等頂會中的論文，這里不會事無巨細地介紹所有的細節(jié)，而是會篩選論文中的關(guān)鍵內(nèi)容，如果你對相關(guān)的論文非常感興趣，可以直接點擊鏈接閱讀原文。

本文要介紹的是 2018 年 ATC 期刊中的論文 —— NanoLog: A Nanosecond Scale Logging System[^1]，該論文實現(xiàn)的 NanoLog 是高性能的日志系統(tǒng)，與 C++ 社區(qū)中的其他日志系統(tǒng)，例如：spdlog、glog 和 Boost Log 相比，它的性能可以高出 1 ~ 2 個數(shù)量級，我們在這篇文章中來簡要分析 NanoLog 的設計與實現(xiàn)原理。

日志是系統(tǒng)可觀測性的重要一環(huán)，相信很多工程師都有線上出問題臨時加日志查問題的經(jīng)歷，作者剛剛又重新經(jīng)歷了這一過程，稍有經(jīng)驗的開發(fā)者都會在系統(tǒng)中加入很多日志方便生產(chǎn)環(huán)境的問題排查，更有經(jīng)驗的開發(fā)者會謹慎地在系統(tǒng)中(尤其是低延遲的實時系統(tǒng))添加日志，因為打印日志這件看起來簡單的事情實際上會帶來很大的額外開銷。

打印日志是一件簡單的事情，幾乎所有的工程師在踏上編程之路的第一天起就學會了如何使用 printf 等函數(shù)向標準輸出打印字符串，在 99% 的程序中使用這種做法都不會帶來性能問題，只是在生產(chǎn)環(huán)境中我們會使用結(jié)構(gòu)化的、容易解析的格式替代 printf，例如：在日志中加入時間戳、文件名和行數(shù)等信息。

圖 1 - 常見的日志系統(tǒng)

但是剩下 1% 的程序要求超低延遲的系統(tǒng)，它們對響應時間的要求可能是微秒甚至納秒級別的。在這種場景下，如果仍然需要日志系統(tǒng)提供可觀測性，我們需要深入研究向標準輸出或者文件寫日志的細節(jié)，例如：使用緩沖區(qū)、異步寫入文件以及減少反射等動態(tài)特性的使用，除此之外，我們還要保證日志輸出的順序、避免消息丟失或者截斷。

spdlog、glog 和 Boost Log 已經(jīng)能夠滿足絕大多數(shù)應用程序的需求，但是對于這些延遲機器敏感的應用程序，打印日志需要的幾微秒可能會顯著地增加請求的處理時間影響程序的性能，而今天分享的 NanoLog 是一個可以在納秒尺度打印日志的系統(tǒng)。

架構(gòu)設計

NanoLog 能在毫秒尺度打印日志是因為它能夠在編譯期間提取靜態(tài)日志消息并在離線階段處理日志的格式化等問題。其核心優(yōu)化都建立在以下兩個條件上：

• 開發(fā)者可直接閱讀的格式化日志不一定要在應用程序運行時直接生成，我們可以在運行期間記錄日志的動態(tài)參數(shù)并在運行后按需生成;
• 日志消息中的絕大部分信息都是靜態(tài)冗余的，只有少數(shù)參數(shù)會發(fā)生變化，我們可以在編譯期間獲取日志的靜態(tài)內(nèi)容并僅在后處理器中打印一次;

正是因為大多數(shù)日志都遵循上述特性，所以 NanoLog 可以在它們的基礎上實現(xiàn)納秒尺度的日志打印。NanoLog 的不同設計方式?jīng)Q定了它與傳統(tǒng)日志模塊會在架構(gòu)上有很大的差異，它由以下三個組件構(gòu)成：

圖 2 - NanoLog 系統(tǒng)架構(gòu)

• 預處理器：在編譯期間從源代碼提取日志消息、將原始日志語句替換成優(yōu)化過的代碼并為每條日志消息生成壓縮、字典輔助函數(shù);
• 運行時庫：在緩沖區(qū)中緩存多個線程打印的日志并使用預處理階段生成的輔助函數(shù)輸出壓縮后的二進制日志;
• 解碼器：利用預處理階段生成的包含靜態(tài)信息的字典解碼日志，獲取可以被人類閱讀的日志;

傳統(tǒng)的日志系統(tǒng)都僅包含運行時，我們只需要在開發(fā)時引入頭文件、鏈接靜態(tài)庫或者動態(tài)庫并在代碼中指定的位置輸出日志，日志系統(tǒng)會程序運行期間將日志打印到標準輸出或者指定文件。

但是 NanoLog 打破了上述這種傳統(tǒng)的設計，為了減少運行時的開銷，我們將一部分操作遷移到了編譯期間和運行后，這也遵循工作質(zhì)量守恒定律：工作不會憑空消失，它只會從運行時轉(zhuǎn)移到程序生命周期的其他階段，NanoLog 就使用了下面的操作降低了日志系統(tǒng)的開銷：

• 在編譯時重寫了日志語句移除靜態(tài)信息并將昂貴的格式化操作推遲到代碼運行后的階段，這能夠在運行時減少大量的計算和 I/O 帶寬需求;
• 為每個日志消息編譯了特定代碼，能夠高效地處理動態(tài)參數(shù)，避免在運行時解析日志消息并編碼參數(shù)類型;
• 使用輕量級的壓縮算法以及不保序的日志減少運行時的 I/O 和處理時間;
• 使用后處理組合壓縮的日志數(shù)據(jù)和編譯時提取的靜態(tài)信息生成可讀的日志;

實現(xiàn)原理

這一節(jié)我們將簡要分析 NanoLog 系統(tǒng)中三大組件，即預處理、運行時和后處理的具體實現(xiàn)原理。

預處理

NanoLog 使用 Python 來實現(xiàn)預處理器，程序的入口在 processor/parser 中，它會掃描用戶的源文件、生成元數(shù)據(jù)文件和修改后的源代碼，接下來會將這些修改后的代碼編譯到 .so 或者 .a 文件中，而不是編譯初始的代碼。除此之外，預處理器還會讀取生成的所有元數(shù)據(jù)文件、生成 C++ 源代碼并編譯到 NanoLog 的運行時庫和最后的用戶程序中：

圖 3 - 預處理器

它會為源代碼中的每個 NANO_LOG 生成兩條語句，即 record 和 compress，其中前者記錄日志中的動態(tài)參數(shù)，后者壓縮記錄的數(shù)據(jù)減少程序的 I/O 時間。下面是預處理器生成的 record 函數(shù)：

inline void __syang0__fl__E32374s3237424642lf__s46cc__100__(NanoLog::LogLevel level, const char* fmtStr , const char* arg0, int arg1, int arg2, double arg3) { 
    extern const uint32_t __fmtId__E32374s3237424642lf__s46cc__100__; 
 
    if (level > NanoLog::getLogLevel()) 
        return; 
 
    uint64_t timestamp = PerfUtils::Cycles::rdtsc(); 
    size_t str0Len = 1 + strlen(arg0);; 
    size_t allocSize = sizeof(arg1) + sizeof(arg2) + sizeof(arg3) +  str0Len +  sizeof(NanoLogInternal::Log::UncompressedEntry); 
    NanoLogInternal::Log::UncompressedEntry *re = reinterpret_cast<NanoLogInternal::Log::UncompressedEntry*>(NanoLogInternal::RuntimeLogger::reserveAlloc(allocSize)); 
 
    re->fmtId = __fmtId__E32374s3237424642lf__s46cc__100__; 
    re->timestamp = timestamp; 
    re->entrySize = static_cast<uint32_t>(allocSize); 
 
    char *buffer = re->argData; 
 
    // Record the non-string arguments 
    NanoLogInternal::Log::recordPrimitive(buffer, arg1); 
 NanoLogInternal::Log::recordPrimitive(buffer, arg2); 
 NanoLogInternal::Log::recordPrimitive(buffer, arg3); 
 
    // Record the strings (if any) at the end of the entry 
    memcpy(buffer, arg0, str0Len); buffer += str0Len;*(reinterpret_cast<std::remove_const<typename std::remove_pointer<decltype(arg0)>::type>::type*>(buffer) - 1) = L'\0'; 
 
    // Make the entry visible 
    NanoLogInternal::RuntimeLogger::finishAlloc(allocSize); 
} 

每個函數(shù)都包含特定的 fmtId，日志的壓縮和解壓也都會用到這里生成的標識符，上述函數(shù)還會為參數(shù)分配內(nèi)存空間并按照順序調(diào)用 recordPrimitive 將所有參數(shù)記錄到緩沖區(qū)中。壓縮使用的 compress 也遵循類似的邏輯：

inline ssize_t 
compressArgs__E32374s3237424642lf__s46cc__100__(NanoLogInternal::Log::UncompressedEntry *re, char* out) { 
    char *originalOutPtr = out; 
 
    // Allocate nibbles 
    BufferUtils::TwoNibbles *nib = reinterpret_cast<BufferUtils::TwoNibbles*>(out); 
    out += 2; 
 
    char *args = re->argData; 
 
    // Read back all the primitives 
    int arg1; std::memcpy(&arg1, args, sizeof(int)); args +=sizeof(int); 
 int arg2; std::memcpy(&arg2, args, sizeof(int)); args +=sizeof(int); 
 double arg3; std::memcpy(&arg3, args, sizeof(double)); args +=sizeof(double); 
 
    // Pack all the primitives 
    nib[0].first = 0x0f & static_cast<uint8_t>(BufferUtils::pack(&out, arg1)); 
 nib[0].second = 0x0f & static_cast<uint8_t>(BufferUtils::pack(&out, arg2)); 
 nib[1].first = 0x0f & static_cast<uint8_t>(BufferUtils::pack(&out, arg3)); 
 
    if (true) { 
        // memcpy all the strings without compression 
        size_t stringBytes = re->entrySize - (sizeof(arg1) + sizeof(arg2) + sizeof(arg3) +  0) 
                                            - sizeof(NanoLogInternal::Log::UncompressedEntry); 
        if (stringBytes > 0) { 
            memcpy(out, args, stringBytes); 
            out += stringBytes; 
        } 
    } 
 
    return out - originalOutPtr; 
} 

日志的記錄和壓縮函數(shù)都是 Python 的預處理器分析源代碼生成的，工程師在開始時使用的 NANO_LOG 會被預處理器展開成新的代碼，該預處理器與 C++ 的預處理器有非常相似的功能，只是這里需要展開的代碼過于復雜，我們很難在 C++ 中使用預處理器實現(xiàn)。

運行時

應用程序靜態(tài)鏈接的 NanoLog 運行時會通過線程上的緩沖區(qū)解耦記錄動態(tài)參數(shù)的低延時 record 操作和磁盤 I/O 等高延遲操作。線程上的緩沖區(qū)會存儲 record 方法調(diào)用的結(jié)果，這些數(shù)據(jù)對后臺的壓縮線程也是可見的：

圖 4 - 運行時

線程上用于暫存數(shù)據(jù)的緩沖區(qū)是程序提升性能的關(guān)鍵，我們要盡可能滿足避免鎖競爭和緩存一致性帶來的額外開銷，暫存緩沖區(qū)使用環(huán)形隊列和單生產(chǎn)者的消費者模型降低數(shù)據(jù)的同步開銷。

圖 5 - 環(huán)形隊列

環(huán)形隊列是一個連續(xù)的、使用固定大小緩存的數(shù)據(jù)結(jié)構(gòu)，它的頭尾是相連的，非常適合緩存數(shù)據(jù)流，Linux 內(nèi)核就使用這種數(shù)據(jù)結(jié)構(gòu)作為 Socket 的讀寫緩沖區(qū)[^2]，而音視頻也會使用環(huán)形隊列暫存剛剛收到還沒有被解碼的數(shù)據(jù)。

struct __kfifo { 
 unsigned int in; 
 unsigned int out; 
 unsigned int mask; 
 unsigned int esize; 
 void  *data; 
}; 

運行時不僅通過無鎖環(huán)形隊列提升性能，還需要解決環(huán)形隊列中的日志消費問題。為了提高后臺線程的處理能力，運行時會將日志的組裝推遲到后處理并壓縮日志數(shù)據(jù)減少 I/O 高延遲帶來的影響。

后處理

后處理器的實現(xiàn)相對比較簡單，因為每條日志都包含特定的標識符，后處理器會根據(jù)該標識符在壓縮后的日志頭中找到編譯時生成的相關(guān)信息，并根據(jù)這些信息展開和解壓日志。

需要注意的是，因為在運行期間每個線程都有自己的暫存緩沖區(qū)存儲日志，所以 NanoLog 最終打印的日志不能嚴格保證時間順序，它只能保證日志輸出的順序在大體上是有序的。

總結(jié)

NanoLog 是設計非常有趣、值得學習的日志系統(tǒng)，但是它并不適合所有的項目，它將原本運行時需要完成的工作轉(zhuǎn)移到了編譯期間和后處理階段，減輕了程序運行時的負擔，但是其輸出的二進制日志是無法直接閱讀的，這也增加了開發(fā)者處理日志的工作量。

雖然論文中提到，日志分析引擎基本都會收集、解析并分析工程師可以直接閱讀的日志，而大多數(shù)的時間都花費在了日志的讀取和解析上，使用二進制的日志不僅能夠減少讀取和解析的時間，還能減少昂貴的 I/O 和使用的帶寬，但是這點在我們的系統(tǒng)中是否是優(yōu)點就見仁見智了。

日志使用二進制的輸出格式確實能夠降低多方面的成本，但是它不僅需要日志收集和解析系統(tǒng)的支持，還犧牲了開發(fā)者本地調(diào)試的體驗，而如果沒有自動收集并解壓日志的模塊，手動解壓線上日志排查問題是非常糟糕的體驗，不過在極端的性能場景下我們可能也沒有太多的選擇，哪怕犧牲體驗可能也要上。