『看看論文』是一系列分析計算機和軟體工程領域論文的文章，我們在這個系列的每一篇文章中都會閱讀一篇來自 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 和使用的帶寬，但是這點在我們的系統中是否是優點就見仁見智了。
日誌使用二進位的輸出格式確實能夠降低多方面的成本，但是它不僅需要日誌收集和解析系統的支持，還犧牲了開發者本地調試的體驗，而如果沒有自動收集並解壓日誌的模塊，手動解壓線上日誌排查問題是非常糟糕的體驗，不過在極端的性能場景下我們可能也沒有太多的選擇，哪怕犧牲體驗可能也要上。