Rust 語言的全鏈路追蹤庫 tracing

Datenlord發表於2022-12-23
Rust

Rust 語言的全鏈路追蹤庫 tracing

在一個應用程式或庫的開發過程中，除了其本身的邏輯以外，開發人員還需要做很多額外的工作，以保證編寫的程式碼可以正確的執行，或者在出錯時可以快速定位到錯誤的位置以及原因，這就需要引入一些額外的工具，trace 就是其中特別好用的一種，下文我將會簡單介紹 trace，並以 Rust 為例，演示 trace 在 Rust 中的使用方法。

可觀測性

Logs、Metrics 和 Traces 並稱為可觀測性三大支柱，透過分析它們輸出的資料，開發人員能夠更好的觀測到系統的執行狀況，更快的定位問題，從而提高系統的可靠性。

p1.png

日誌(Logs)

日誌作為最常用的可觀測性資料來源之一，相信多數開發者都比較熟悉。其本質上就是一種帶有時間戳的離散事件記錄，通常用於記錄系統的執行狀態，日誌的使用十分簡單，只需要在程式碼中需要報告資訊的點新增一行程式碼，就可以將這些資訊輸出到控制檯或檔案中，但是日誌也有很大的缺點，它的輸出是離散的，這意味著在記錄的時候，無法將日誌資訊相互關聯，也無法知道日誌資訊的上下文，尤其是在多執行緒的環境下，最終輸出的資訊比較混亂，不便於檢索和分析。

指標(Metrics)

指標是一種定量衡量，例如平均值、比率和百分比等。其值始終為數字而非文字，可以透過數學方法統計和分析，其主要用於描述系統執行狀態的資料，比如 CPU 的使用率、記憶體的使用率、磁碟的使用率等，這些資料可以用來監控系統的執行狀態，也可以用來預警。

追蹤(Traces)

追蹤是一種用於記錄系統中一次請求的完整生命週期的資料，它可以記錄下一個請求從開始到結束的所有資訊，包括請求的發起者、接收者、請求的路徑、請求的狀態、請求的耗時、請求的錯誤資訊等，這些資訊可以用來分析系統的效能瓶頸，也可以用來分析系統的錯誤。追蹤本質上也是一種日誌，他與日誌的資料結構十分相似，但是它能夠提供比日誌更豐富的資訊。特別是在分散式系統中，追蹤能夠跨越多個服務，彙總出一次請求的完整資訊，讓開發人員能夠更方便的找到系統中的問題。

Rust 中的 Trace

Rust 社群中比較有名的 trace 實現有三個：

  • tracing 由 tokio 團隊維護，目前使用最廣泛，生態也比較完善
  • rustracing 使用人數相對較少
  • minitrace tikv 團隊打造，效能最好

接下來就以 tracing 為例，介紹一下 trace 的核心概念以及使用方法：

Span

Span 可以說是 trace 中最關鍵的概念之一，它表示的是一個過程，也就是一段時間內發生的所有事件的集合，其資料結構中包含著 Span 的開始時間和結束時間，在分析資料是可以藉助工具直觀的看到某次請求或操作的耗時情況。在同一個 trace 流程中的所有 span 都共享這相同的 Trace Id ，每個 Span 也有著自己的 Span Id，並且 Span 還支援巢狀，巢狀的 Span 中也會儲存著相應的父子關係，最終可以靠這些資訊，將請求的完整生命週期串聯起來，並且不會與相同時間段內的其他請求產生干擾。

use tracing::{span, Level};

fn main() {
    let span = span!(Level::INFO, "span");
    let _enter = span.enter();
    // enter 後進入該 span 的上下文
    // 可以記錄資訊到 span 中
} // 離開作用域後，_enter 被 drop，對應的 span 在此結束

以上程式碼是建立並使用一個 Span 最簡單的方式，除此以外還有幾種不同的方式

#[instrument] // tracing 會為當前函式自動建立 span ，該 span 名與函式相同，並且整個函式都在該 span 的上下文內
fn do_something() {
    // some event
    let span = span!(Level::INFO, "external function");
    span.in_scope(|| some_external_function()); //對於無法新增 #[instrument] 的外部函式，也可以使用 in_scope 方法讓其在 span 的上下文中執行
}

#[instrument] // 此方法同樣對非同步函式適用
async fn do_something_async() {
    let future = async {
        // some async code
    };
    let span = span!(Level::INFO, "future");
    future.instrument(span).await; // 也可以在 future .await 之前將 span 附加給 future
}

// async 程式碼中要避免以下情況
async fn some_async_code() {
    let span = span!(Level::INFO, "span");
    let _enter = span.enter();
    // 此處進入 span 的上下文，直到 _enter 被 drop 後才會結束
    async_fn().await; // .await 時，task 可能會讓出當前執行緒的執行權，而此時 _enter 還沒有 drop，因此可能會錯誤的記錄到其他 task 的 enent.
}

Event

Event 與日誌類似，表示的是某一個時間點發生的事件，但與日誌不同的是，Event 可以將資訊記錄到 Span 的上下文中，這樣在分析資料時，可以直接檢視 Span 中發生的所有事件。

use tracing::{event, info, span, Level};

fn main() {
    event!(Level::INFO, "event"); // 在 span 的上下文之外記錄一個 Leval 為 INFO 的 event

    let span = span!(Level::INFO, "span");
    let _enter = span.enter();

    event!(Level::INFO, "event"); // 在 span 的上下文內記錄 event

    info!("something with info level"); // 也可以使用和 log 相同的形式記錄 event
}

Collector

以上的示例不會有任何可見的輸出，因為我們還沒有配置 Collector，tracing 中所有的 Span 和 Event 都是透過 Collector 來收集的，Collector 會將 Span 和 Event 以一定的格式輸出到指定的地方，比如 stdout、stderr、檔案、網路等。tracing-subscriber 的 fmt 模組提供了一個 Collector ，可以方便的輸出事件資訊。

use tracing::info;
use tracing_subscriber;

fn main() {
    // 初始化全域性 Collector
    tracing_subscriber::fmt::init();

    info!("Hello, world!");
}

執行上面這段程式碼，可以在終端中看到一條 INFO 級別的事件，如果需要將 Trace 資訊傳送到其他地方，就要用到其他的 Collector 實現，比如 tracing-appender 這個 crate，可以將 Trace 資訊輸出到檔案中。

在 Rust 中使用 tracing 的完整示例

use std::{thread::sleep, time::Duration};

use tracing::{debug, info, info_span, instrument};

#[instrument]
fn expensive_work(secs: u64) {
    debug!("doing expensive work");
    sleep(Duration::from_secs(secs));
    debug!("done with expensive work");
}

fn main() {
    tracing_subscriber::fmt()
        // enable everything
        .with_max_level(tracing::Level::TRACE)
        // sets this to be the default, global collector for this application.
        .init();
    let span = info_span!("root");
    let _enter = span.enter();

    info!("some info in the root span");

    expensive_work(1);
}

執行以上程式碼將會的到以下輸出

2022-12-01T02:50:59.425475Z  INFO root: tracing_example: some info in the root span
2022-12-01T02:50:59.425518Z DEBUG root:expensive_work{secs=1}: tracing_example: doing expensive work
2022-12-01T02:51:00.425722Z DEBUG root:expensive_work{secs=1}: tracing_example: done with expensive work

每個事件都已相同的格式輸出，此輸出模式下，與 log 的輸出十分相似，但 tracing 輸出的內容多出了 span 相關的資訊。由 instrument 生成的 span 還自動新增了函式的引數資訊。下面介紹的 OpenTelemetry 和 Jaeger，還可以讓我們更加直觀的檢視 Span 之間的時間關係。

Trace 的標準化

想要讓 Trace 跨越多個服務，整合到多種不同的語言，那就必須要規定大家相互呼叫的規範，要遵守一套相同的協議，才能讓 Trace 的資料在不同的系統中都能夠正常傳遞，Trace 早期誕生了兩種規範，分別是 OpenTracing 和 OpenCensus，後來為了規範的統一，OpenTracing 和 OpenCensus 合併成了 OpenTelemetry，現在已經成為了 Trace 的事實標準。OpenTelemetry 提供了不同語言的 SDK，可以方便的整合到不同的系統中，對於 Rust ，它提供了一系列相關的 crate 用於整合。tracing 也提供了 tracing-OpenTelemetry 用來將其收集到的資訊傳送到相容 OpenTelemetry 的分散式追蹤系統中。

Trace 資料的視覺化分析

Jaeger 是受到 Dapper 和 OpenZipkin 啟發的開源分散式跟蹤系統，由 Uber 開發，現已捐贈給 CNCF。Jaeger 透過收集 Trace 資料，將其視覺化展示，方便開發者分析系統的問題。下圖為 Jaeger 部署的示例。

p2.png

要將 Trace 資料傳送給 Jaeger，需要在我們的應用中新增 jaeger-client 。OpenTelemetry 提供的 crate 中，就包括了響應的 jaeger-clinet 實現: opentelemetry-jaeger。它會將 Span 資訊以 UDP 包的形式傳送到 jaeger-agent，jaeger-agent 將一段時間內的資料打包分批傳送到 jaeger-collector，再由 jaeger-collector 把資料存入資料庫內，我們在 jaeger 的 UI 中就可以查詢到這些資料。

OpenTelemetry 的倉庫中也提供了以上流程的示例，我們可以直接執行這個示例，然後在 jaeger 的前端我們就可以得到下圖的內容:

p3.png

有了這些資料，開發人員就能夠快速定位到請求的主要耗時部分，也能夠透過其中包含的事件獲取到請求內的訊息記錄。

總結

對於大多數同步程式，用 Log 就能夠滿足需求，並且使用起來也足夠簡單，但是一旦涉及到非同步程式或其他的一些複雜產隔閡，Log 就會變得不那麼好用了，一段時間內的 Log 資訊可能來自於多個不同的處理流程，難以快速方便的獲取我們需要的資訊，而 Trace 則能夠很好的解決這個問題。

相關文章