Databend 全链路追踪

全链路追踪意味着能够追踪到每一个调用请求的完整调用链路、收集性能数据并反馈异常。Databend 使用 tracing 赋能可观测性,实现全链路追踪。

Databend 与 Tracing

初步了解 Databend 怎么实现全链路追踪。

初识 Tracing

1.png

Tracing 是由 Tokio 团队维护的 Rust 应用跟踪框架,用来收集结构化的、基于事件的诊断信息。

项目地址:https://github.com/tokio-rs/tracing

示例:

use tracing::{info, Level};
use tracing_subscriber;

fn main() {
    let collector = tracing_subscriber::fmt()
        // filter spans/events with level TRACE or higher.
        .with_max_level(Level::TRACE)
        // build but do not install the subscriber.
        .finish();

    tracing::collect::with_default(collector, || {
        info!("This will be logged to stdout");
    });
    info!("This will _not_ be logged to stdout");
}

Databend 中的 Tracing

Databend 的 tracing-subscriber 被统一整合在 common/tracing,由 query 和 meta 共用。

// Use env RUST_LOG to initialize log if present.
// Otherwise use the specified level.
let directives = env::var(EnvFilter::DEFAULT_ENV).unwrap_or_else(|_x| level.to_string());
let env_filter = EnvFilter::new(directives);
let subscriber = Registry::default()
    .with(env_filter)                # 根据环境变量过滤
    .with(JsonStorageLayer)          # 利用 tracing-bunyan-formatter 格式化为 json
    .with(stdout_logging_layer)      # 标准输出
    .with(file_logging_layer)        # 输出到文件,默认位于 `_logs` 目录下
    .with(jaeger_layer);             # opentelemetry-jaeger

#[cfg(feature = "console")]
let subscriber = subscriber.with(console_subscriber::spawn()); # tokio console

tracing::subscriber::set_global_default(subscriber)
    .expect("error setting global tracing subscriber");

具体到内部的 tracing 记录,大致有两类:

  • 普通:与其他 log 方式一样,利用 info!、debug! 来收集信息。
use common_tracing::tracing;

tracing::info!("{:?}", conf);
tracing::info!("DatabendQuery {}", *databend_query::DATABEND_COMMIT_VERSION);
  • Instruments:在调用函数时创建并进入 tracing span(跨度),span 表示程序在特定上下文中执行的时间段。
use common_tracing::tracing::debug_span;
#[tracing::instrument(level = "debug", skip_all)]
async fn read(&mut self) -> Result<Option<DataBlock>> {
    ...
        fetched_metadata = read_metadata_async(&mut self.reader)
            .instrument(debug_span!("parquet_source_read_meta"))
            .await
            .map_err(|e| ErrorCode::ParquetError(e.to_string()))?;
    ...
}

示例:

{
  "v": 0,
  "name": "databend-query-test_cluster@0.0.0.0:3307",
  "msg": "Shutdown server.",
  "level": 30,
  "hostname": "dataslime",
  "pid": 53341,
  "time": "2022-05-11T00:51:56.374807359Z",
  "target": "databend_query",
  "line": 153,
  "file": "query/src/bin/databend-query.rs"
}

观测 Databend 追踪的方式

Databend 原生提供了多种观测方式,以方便诊断和调试:

  • http tracing :访问 localhost:8080/v1/logs(根据配置)

  • stdout/filelog :检查终端输出或 _logs 目录(根据配置)

  • system.tracing 表 :执行 select * from system.tracing limit 20;

  • jaeger :运行 jaeger ,访问 http://127.0.0.1:16686/

  • console :按特定方式构建后,运行 tokio-console

Jaeger 分布式追踪

使用 Jaeger 对 Databend 进行全链路追踪。

Opentelemetry & Jaeger

OpenTelemetry 是工具、API 和 SDK 的集合。使用它来检测、生成、收集和导出遥测数据(度量、日志和追踪),以帮助您分析软件的性能和行为。Jaeger 是一个开源的端到端分布式追踪系统。由 Uber 捐赠给 CNCF 。它可以用于监视基于微服务的分布式系统,提供以下能力:

  • 分布式上下文传播
  • 分布式事务监视
  • 根本原因分析
  • 服务依赖性分析
  • 性能/延迟优化
2.png

Step by Step

遵循下述步骤,即可使用 Jaeger 探索 Databend :

  • 构建二进制程式:cargo build(可以使用 --bin 指定)
  • 将日志级别设定为 DEBUG ,运行需要调试的应用程式。例如,LOG_LEVEL=DEBUG ./databend-query
  • 运行 jaeger :docker run -d -p6831:6831/udp -p6832:6832/udp -p16686:16686 jaegertracing/all-in- one:latest
  • 打开 http://127.0.0.1:16686/ 以查看 jaeger 收集的信息

结果探索

3.png

x 轴是执行时刻,y 轴是持续的时间,圆点反映 span 的聚集程度。
执行下述语句即可得到上图所示追踪结果:

CREATE TABLE t1(a INT);
INSERT INTO t1 VALUES(1);
INSERT INTO t1 SELECT * FROM t1;

Timeline

下图是点击最大的圆点得到的追踪情况:

4.png

使用 timeline 模式来展现 tracing 的各个跨度之间的关系。以时间为主线进行分析,方便使用者观看在某个时间点观看程序信息。

点开第一个跨度,可以看到这是执行 INSERT INTO t1 SELECT *FROM t1 查询时的情况。

5.png

Graph

切换到 graph 模式,可以看到各个 span 之间的调用链,每个 span 具体用时 ,以及百分比。

6.png

通过这个视图使用者很容易知道系统瓶颈,快速定位问题。

Compare

连起来的各个部分形成整个 trace 的调用链。因为比较时一般会比较两个相同类型的调用,所以看到的会是重合后的视图。

7.png

对于颜色的一个说明:

  • 深绿色,表示这个 span 只存在于 trace-B 中,A 没有这个 span
  • 深红色,表示这个 span 只存在于 trace-A 中,B 没有这个 span
  • 浅绿色,表示这个 span 在 trace-B(右边这个)的数量多
  • 浅红色,表示这个 span 在 trace-A(左边这个)的数量多

tokio-console 诊断

tokio-console 诊断

tokio-rs 团队出品的诊断和调试工具,可以帮助我们诊断与 tokio 运行时相关的问题。

console 是什么

8.png

tokio-console 是专为异步程序设计的调试与诊断工具,能够列出 tokio 的任务,提供对程序的任务和资源的实时、易于导航的视图,总结了它们的当前状态和历史行为。主要包含以下组件:

  • 传输诊断数据的协议
  • 用于收集诊断数据的仪器
  • 当然,用于展示和探索诊断数据的实用工具\

项目地址:https://github.com/tokio-rs/console

Step by Step

  • 使用特定的 rustflags 和 features 来构建:RUSTFLAGS="--cfg tokio_unstable" cargo build --features tokio-console ,也可以只构建单个二进制程式,使用 --bin 进行指定。
  • 将日志级别设定为 TRACE ,运行需要调试的应用程式 LOG_LEVEL=TRACE databend-query 或者 databend-meta --single --log-level=TRACE。可以使用 TOKIO_CONSOLE_BIND 指定端口,以避免潜在的端口抢占问题。
  • 运行 tokio-console,默认连接到 http://127.0.0.1:6669

结果探索

任务
先看什么是 tokio 任务:

  • 任务是一个轻量级的、非阻塞的执行单元。类似操作系统的线程,但是是由 tokio 运行时管理,一般叫做“绿色线程”,与 Go 的 goroutine,Kotlin 的 coroutine 类似。
  • 任务是协同调度的。大多数操作系统实现抢占式多任务。操作系统允许每个线程运行一段时间,然后抢占它,暂停该线程并切换到另一个线程。另一方面,任务实现协同多任务。一个任务被允许运行直到它让出执行权,运行时会切换到执行下一个任务。
9.png

基础视图

通过左右切换,可以得到总忙时间或轮询次数等指标对任务进行排序。控制台通过高亮来提示较大差异,比如从毫秒到秒的切换。

10.png

控制台还实现了一个“警告”系统。通过监视应用程序中任务的运行时操作,控制台可以检测可能提示 bug 或性能问题的行为模式,并突出显示这些行为模式供用户分析。比如已经运行了很长时间而没有让步的任务,唤醒的次数比被其他任务唤醒的次数还要多的任务。

任务视图

上下切换选中任务,enter 查看关于每个任务的翔实数据,比如轮询持续时间的直方图。

11.png

不仅列出任务。console 还会插入异步互斥和信号量等资源。Tokio Console 的资源详细信息视图显示了哪些任务已经进入临界区,哪些任务正在等待获得访问权限。

还能做什么

还能做什么

与分布式追踪和日志系统相关的一些其他内容。

可观测性 + +

目前还有一系列关于可观测性和 Tracing 的 Issue 有待解决:

  • Integrate tokio metrics for query task based tokio runtime monitoring #4205
  • Configure on jaeger tracing address similar to metrics api server #3633
  • Summary of todos about distributed tracing #1227
  • Query traces and analysis, based on user behavior. #1177
  • Http stack traces #1085
  • Shuffle read/write metrics #1004

另外,更进一步的考量是,如何基于可观测性来自动/半自动地发现问题并对系统进行调优。了解更多

了解更多

Tracing

Jaeger

tokio-console

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 214,922评论 6 497
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 91,591评论 3 389
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 160,546评论 0 350
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,467评论 1 288
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,553评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,580评论 1 293
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,588评论 3 414
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,334评论 0 270
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,780评论 1 307
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,092评论 2 330
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,270评论 1 344
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,925评论 5 338
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,573评论 3 322
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,194评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,437评论 1 268
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,154评论 2 366
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,127评论 2 352

推荐阅读更多精彩内容