[[379907]]

本文轉載自微信公眾號「真沒什么邏輯」，作者 Draveness 。轉載本文請聯系真沒什么邏輯公眾號。

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

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

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

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

圖 1 - 常見的日志系統

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

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

架構設計

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

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

正是因為大多數日志都遵循上述特性，所以 NanoLog 可以在它們的基礎上實現納秒尺度的日志打印。NanoLog 的不同設計方式決定了它與傳統日志模塊會在架構上有很大的差異，它由以下三個組件構成：

圖 2 - NanoLog 系統架構

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

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

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

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

實現原理

這一節我們將簡要分析 NanoLog 系統中三大組件，即預處理、運行時和后處理的具體實現原理。

預處理

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

圖 3 - 預處理器

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

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); 
} 

每個函數都包含特定的 fmtId，日志的壓縮和解壓也都會用到這里生成的標識符，上述函數還會為參數分配內存空間并按照順序調用 recordPrimitive 將所有參數記錄到緩沖區中。壓縮使用的 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; 
} 

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

運行時

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

圖 4 - 運行時

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

圖 5 - 環形隊列

環形隊列是一個連續的、使用固定大小緩存的數據結構，它的頭尾是相連的，非常適合緩存數據流，Linux 內核就使用這種數據結構作為 Socket 的讀寫緩沖區[^2]，而音視頻也會使用環形隊列暫存剛剛收到還沒有被解碼的數據。

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

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

后處理

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

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

總結

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

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

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