#request #text-format #tracing #call #logging #spans #programs

reqray

记录使用 tracing 优化的 Rust 程序的“请求 X 射线”

11 个不稳定版本 (3 个破坏性更新)

0.4.3 2022年2月12日
0.4.2 2022年2月12日
0.3.1 2022年2月6日
0.3.0 2021年12月24日
0.1.1 2020年12月20日

#99性能分析 分类中

每月下载量:37

MIT/Apache

52KB
759

Reqray

Build Status Crate Docs

记录使用 tracing 优化的 Rust 程序的“请求 X 射线”。这包括在火焰图中常见的聚合的墙/自用时间,以人类友好的文本格式展示。

要部署它,你不需要复杂的服务,只需将一些本地代码添加到你的已优化的程序中。

这使得以下问题的答案通常很简单

  • 请求的哪个部分花费的时间最多?
  • 我执行了多少个数据库请求?数据库请求聚合是否工作正常?
  • 在请求被错误中断之前,执行进展到什么程度?

它看起来像这样

2022-02-06T20:01:57.103747Z  INFO Call summary of request@examples/nested.rs:51

                        # calls │   ∑ alive ms │    ∑ busy ms │ ∑ own busy ms │ span tree
                    ────────────┼──────────────┼──────────────┼────────────-──┼───────────────────────
                          0 001258.910258.8900.106 ┊ ┬ request
                          0 00187.20487.19019.299 ┊ ├┬ nested
                          0 0010.0360.0210.021 ┊ ┊├─ random
                          1 00075.73861.91261.912 ┊ ┊╰─ repeated
                          0 0020.0510.0270.027 ┊ ├─ repeated
                          0 0011.6441.6320.019 ┊ ├┬ nest_deeply
                          0 0011.6191.6070.025 ┊ ┊╰┬ nest_deeply
                          0 0011.5931.5770.024 ┊ ┊ ╰┬ nest_deeply
                          0 0011.5611.5470.022 ┊ ┊  ╰┬ nest_deeply
                          0 0011.5321.5200.023 ┊ ┊   ╰┬ nest_deeply
                          0 0011.5041.4920.023 ┊ ┊    ╰┬ nest_deeply
                          0 0011.4761.4630.025 ┊ ┊     ╰┬ nest_deeply
                          0 0011.4461.4330.025 ┊ ┊      ╰┬ nest_deeply
                          0 0011.4151.4021.402 ┊ ┊       ╰─ nest_deeply
                          0 001169.915169.90517.883 ┊ ╰┬ nested2
                          0 0010.0100.0010.001 ┊  ├─ random
                          1 00088.79376.08176.081 ┊  ├─ repeated
                          0 00170.38670.37719.332 ┊  ╰┬ nested
                          0 0010.0110.0010.001 ┊   ├─ random
                          1 00058.46845.28045.280 ┊   ╰─ repeated
  • 调用次数:在此调用路径中创建的跨度总数。
  • Σ存活毫秒:在此调用路径中的跨度存活的总时间,即新事件和关闭事件之间时间的总和。
  • Σ忙毫秒:在此调用路径中的跨度进入的总时间,即进入和离开事件之间时间的总和。
  • Σ自用忙毫秒:在此调用路径中的跨度进入且没有子跨度进入的总时间。

它在 0.3.x 版本之前是这样的

Dec 20 18:48:32.405  INFO Call summary of request@examples/nested.rs:47

                        # calls │    ∑ wall ms │     ∑ own ms │ span tree
                    ────────────┼──────────────┼──────────────┼───────────────────────
                          0 001377.8860.260 ┊ ┬ request
                          0 001120.70448.896 ┊ ├┬ nested
                          0 0010.0080.008 ┊ ┊├─ random
                          1 00064.34764.347 ┊ ┊╰─ repeated
                          0 0020.1180.118 ┊ ├─ repeated
                          0 0013.8180.049 ┊ ├┬ nest_deeply
                          0 0013.7620.053 ┊ ┊╰┬ nest_deeply
                          0 0013.7020.057 ┊ ┊ ╰┬ nest_deeply
                          0 0013.6370.056 ┊ ┊  ╰┬ nest_deeply
                          0 0013.5740.058 ┊ ┊   ╰┬ nest_deeply
                          0 0013.5030.061 ┊ ┊    ╰┬ nest_deeply
                          0 0013.4350.063 ┊ ┊     ╰┬ nest_deeply
                          0 0013.3650.066 ┊ ┊      ╰┬ nest_deeply
                          0 0013.2923.292 ┊ ┊       ╰─ nest_deeply
                          0 001252.94949.258 ┊ ╰┬ nested2
                          0 0010.0060.006 ┊  ├─ random
                          1 00063.34363.343 ┊  ├─ repeated
                          0 001132.84154.091 ┊  ╰┬ nested
                          0 0010.0070.007 ┊   ├─ random
                          1 00070.87570.875 ┊   ╰─ repeated

设置

为了快速开始,请在 Cargo.toml 中添加/编辑以下 [dependencies]

tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["registry", "env-filter"] }
reqray = "0.4"

并添加/编辑你的跟踪层设置

    use reqray::CallTreeCollector;
    use tracing_subscriber::{EnvFilter, util::SubscriberInitExt, fmt, prelude::*};

    let fmt_layer = fmt::layer()
        .with_target(false);
    let filter_layer = EnvFilter::try_from_default_env()
        .or_else(|_| EnvFilter::try_new("info"))
        .unwrap();

    tracing_subscriber::registry()
    // -----------------------------------------------
        .with(CallTreeCollector::default())
    // -----------------------------------------------
        .with(filter_layer)
        .with(fmt_layer)
        .init();

你可以选择一个更明确的配置,而不是 CallTreeCollector::default()

    // ...
    let call_tree_collector = CallTreeCollectorBuilder::default()
        .max_call_depth(10)
        .build_with_collector(
            LoggingCallTreeCollectorBuilder::default()
                .left_margin(20)
                .build(),
        );

    tracing_subscriber::registry()
        .with(call_tree_collector)
        // ...

tracing-subscriber 0.2 的兼容性

使用 reqray 0.2.x 与 tracing-subscriber 0.2.x 集成。否则,API 应该是相同的。

例如,color_eyre 0.5.x 依赖于 tracing-error 0.1.x,它需要 tracing-subscriber 0.2

开销

我进行了基本的性能测试(见 benches),以检查明显的陷阱 - 我没有发现任何问题。如果你的代码实际上确实与数据库或其他昂贵的东西交互,它应该与跟踪库的日志开销在同一数量级。

在我的不具代表性的示例中,有一些日志语句,实际上没有做其他任何事情,日志开销增加了30-50% - 这大致是实际日志行数在这个情况下添加到日志输出的数量。

一般来说,你应该只对你的程序中的相关调用进行仪表化,而不是每个调用,尤其是那些在CPU密集型循环中的调用。如果你有这些,在调用 CallTreeCollector 之前过滤它们可能是有意义的。

我很想听到实际程序中的实际统计数据!

灵感

在与 Klas Kalass 一起工作时,他为 Java 创建了类似的东西:[Fuava CTProfiler](https://github.com/freiheit-com/fuava_ctprofiler)。

它几乎每天都在证明其非常有用。谢谢你,Klas!

从那时起,我一直在使用复杂的分布式跟踪系统,但它们通常缺乏聚合功能。其他人在此基础上修改了一些有趣的聚合脚本,我自己也变得有些着迷于创建类似的脚本。

谢谢

当我在 issue [tracing#639](https://github.com/tokio-rs/tracing/issues/639) 中建议类似的东西时,我感到非常受欢迎。谢谢你,@hawkw!

同样,Eliza 在 tracing discod 频道中也非常支持和有帮助。谢谢你,Eliza!

贡献

在 [Twitter](https://twitter.com/pkolloch) 或 tracing discord 频道上提供反馈或表示感谢是被欣赏的。

以文档和错误修复形式进行的贡献非常受欢迎。在着手进行大型功能之前,请先与我(例如,通过 issue)开始讨论。

我非常希望对新功能进行测试。在提交 pull request 之前,请运行 cargo test。只需使用 cargo fmt 进行格式化。

也欢迎功能想法 - 只要知道这是一个纯爱好副项目,我不会为这个项目分配太多的带宽。因此,重要的错误修复始终是优先的。

通过提交 pull request,你同意通过项目的所有当前许可证许可你的更改。

依赖关系

~2.2–4MB
~69K SLoC