【开发日志】第十四周：编写异步函数跟踪方案

[chenzhiy2001]

背景

Rust 等语言的异步运行时采用了 Cooperating scheduling，因此是一套 non-preemptive 的系统，可能出现某个异步任务运行过久的情况。

目标

我们希望找到这样的异步任务，从而帮助开发者减少异步代码的运行时长。

预期成果

操作系统异步任务的火焰图

方法

Rust 编译器会将异步代码分割成多个嵌套的Future。但是根据 石尚峰学长的工作，跟踪所有的 Future 比较困难。

考虑到异步运行时（具体来说，是异步运行时的executor）会将几个 Future 打包成一个 task 来运行，跟踪所有 task 的执行时间也能达到我们的目标。

因此，我们不试图跟踪所有 Future，而是跟踪 Task+尽可能多的 Future。

就算有的 Future 被 inline 了也不影响达到我们的目标，因为被inline的Future的上一层 Future 或者 上一层 Task 是能跟踪到的，根据高层 Future/Task 的执行时长我们仍然能找到执行时间过长的异步代码。所以跟踪 Task 可以起到“兜底”的作用。

跟踪 Task + Future (以 async-std 为例)

主函数以外的 Task 都是由形如 _<async_std..task..builder..SupportTaskLocals<F> as.. 的函数创建的，且每一个这样的函数都对应一个 Task。因此，给这些函数的调用和返回指令插桩，即可获得这个 Task 的执行时长。

对于 async/await 生成的 Future，跟踪形如 _<core..future..from_generator..GenFuture<T> as.. 的函数的调用和返回时间。

对于用户自定义的Future（比如用 impl 记号实现的），跟踪形如 USER_IMPLMENTED_FUTURE as core..future..future..Future 的函数的调用和返回时间。

对于异步代码块和异步闭对应的匿名Future（这些匿名Future都嵌套在Task里），跟踪形如 ASYNC_FUNC_NAME::_{{closure}} 的函数的调用和返回时间。

如果还有其他来源的 Future，同样找到它们对应的的创建函数的调用/返回时间即可。

除了调用和返回时间，我们还利用栈回溯记录这些函数在栈内的深度，从而分析出这些 Task/Future 的嵌套关系。

有了上述调用时间+返回时间+嵌套关系，我们就可以画出火焰图了。

跟踪 zCore 的例子

chenzhiy2001/zCore@bec0cf7 （怀疑栈回溯的深度是错的，因此暂时没去画火焰图，但是大致流程走通了）

How to Run
=====================
0. setup environment. see <https://livingshade.github.io/ebpf-doc/zcore/> for detail. NOTE: download clang-**12** at <https://github.com/llvm/llvm-project/releases/tag/llvmorg-12.0.1>
1. install `rustfilt` and `grep`
2. cd zCore && cargo clean
3. cargo other-test --arch=riscv64
4. rm async.log
5. cargo qemu --arch=riscv64 | tee -a async.log
6. (todo) filter async logs like [entry] function name, transform them into dumped_data.txt in <https://github.com/asrlabncku/Rust-Async-Context-Tracer>
7. (todo) use <https://github.com/asrlabncku/Rust-Async-Context-Tracer> to generate flame graph




How it works
======================
A. [host C program + system] probe at those patterns, both entry and exit (they are all patters of function names)
    1. `"_<async_std..task..builder..SupportTaskLocals<F> as core..future..future..Future>::poll::_{{closure}}"`
    2. `"_<core..future..from_generator..GenFuture<T> as core..future..future..Future>::poll"`
    3. `".*::_\{\{closure\}\}"`
    4. `".*as core..future..future..Future>::poll"`

B. [bpf program] when such functions entered/exited, collect timestamp(like 408.532238273), function depth and thread id

C. [bpf program] output a record file called dumped_data.txt like this
reading {thread id}.dat
timestamp   {thread id}: [entry/exit] {function name}(function address) depth: {depth}

example of such record file:
reading 5257.dat
408.532238273   5257: [entry] std::rt::lang_start::_{{closure}}(636a04ffabb5) depth: 0
408.532242401   5257: [entry] once_cell::imp::initialize_or_wait::_{{closure}}(636a05068c15) depth: 1
408.532243204   5257: [exit ] once_cell::imp::initialize_or_wait::_{{closure}}(636a05068c15) depth: 1

D. [tool from the paper] post-process, see paper

已知问题

• release模式理论上也是可以跟踪的，但是暂未尝试
• join! select! 宏无法跟踪（摘录自 https://github.com/asrlabncku/Rust-Async-Context-Tracer，具体原因未知）
• 如果用 kprobe 实现这个方案，某个函数触发时我们只知道它的内存地址，但是不知道它的函数名。如果用QEMU实现这个方案，我们没法在函数退出时打断点。

参考资料

• CAT: Context Aware Tracing for Rust Asynchronous Programs
• https://cubele.github.io/probe-docs/async-probe/
• https://livingshade.github.io/ebpf-doc/zcore/

[chenzhiy2001]

1. 写实施方案，说明对于这个项目我们应该要怎么做
   1. 目前想到的主要问题：
      1. 基于内核 switch 函数和异步运行时信息，将内核执行流拆分为不同内核线程/协程
      2. 闭包的函数签名是 {{closure}}，如何反推回源代码？（我能想到的是zjp学长的函数签名版本工具）
      3. function exit 的 addr2line
      4. 跟踪工具不能跟踪它本身，否则会死循环