在一个应用程序或库的开发过程中,除了其本身的逻辑以外,开发人员还需要做很多额外的工作,以保证编写的代码可以正确的运行,或者在出错时可以快速定位到错误的位置以及原因,这就需要引入一些额外的工具,trace 就是其中特别好用的一种,下文我将会简单介绍 trace,并以 Rust 为例,演示 trace 在 Rust 中的使用方法。
可观测性
Logs、Metrics 和 Traces 并称为可观测性三大支柱,通过分析它们输出的数据,开发人员能够更好的观测到系统的运行状况,更快的定位问题,从而提高系统的可靠性。
日志(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 部署的示例。
要将 Trace 数据发送给 Jaeger,需要在我们的应用中添加 jaeger-client 。OpenTelemetry 提供的 crate 中,就包括了响应的 jaeger-clinet 实现: opentelemetry-jaeger。它会将 Span 信息以 UDP 包的形式发送到 jaeger-agent,jaeger-agent 将一段时间内的数据打包分批发送到 jaeger-collector,再由 jaeger-collector 把数据存入数据库内,我们在 jaeger 的 UI 中就可以查询到这些数据。
OpenTelemetry 的仓库中也提供了以上流程的示例,我们可以直接运行这个示例,然后在 jaeger 的前端我们就可以得到下图的内容:
有了这些数据,开发人员就能够快速定位到请求的主要耗时部分,也能够通过其中包含的事件获取到请求内的消息记录。
总结
对于大多数同步程序,用 Log 就能够满足需求,并且使用起来也足够简单,但是一旦涉及到异步程序或其他的一些复杂情况,Log 就会变得不那么好用了,一段时间内的 Log 信息可能来自于多个不同的处理流程,难以快速方便的获取我们需要的信息,而 Trace 则能够很好的解决这个问题。