如何利用ftrace精确跟踪特定进程调度信息

网上已经有很多阐述ftrace原理和使用方法的文章，本文不会面面俱到的介绍所有涉及的原理和方法，只会聚焦在阐述ftrace的event tracing机制，以及如何利用该机制（包括其他一些方法配合）去跟踪某个进程的调度信息。本文的分析基于处理器为ARM64的多核手机平台，linux版本为msm-4.19，为了行文方便，我们还是先回顾下ftrace的基本概念。

一、 ftrace基本原理

图1-1 ftrace框架

一句话总结：各类tracer往ftrace主框架注册，不同的trace则在不同的probe点把信息通过probe函数给送到ring buffer中，再由暴露在用户态debufs实现相关控制。

对不同tracer来说

1）需要实现probe点（需要跟踪的代码侦测点），有的probe点需要静态代码实现，有的probe点借助编译器在运行时动态替换，event tracing属于前者；

2）还要实现具体的probe函数，把需要记录的信息送到ring buffer中；

3）增加debugfs 相关的文件，实现信息的解析和控制。

而ring buffer 和debugfs的通用部分的管理由框架负责。

二、ftrace event tracing原理介绍

图2-1 ftrace event tracing原理

 

其它一些 trace 工具也具有相似的工作流程，需要一个 probe 点，一个 probe 函数，一种保存 log 信息的机制，还有用于户进行交互的接口（分别对应图中 A、B、C、D 点）。它们发现可以利用 function trace 的后两部分，也就是环形缓存的管理和用户交互接口部分的代码，只需要实现自己的 probe 点和 probe 函数就可以了。于是在 function trace 进入内核 mainline 后，kprobe 也借用了该机制。

1.  tracepoint 的实现原理

tracepoint 是早就存在于内核当中的一种 trace 工具，具体原理不再详细展开，示例代码大家可参照内核源码 sample/tracepoints/相关内容。需要使用小于3.9版本的内核来看。原因是linux不期望开发人员直接使用 tracepoint，而应该使用更高层的 event tracing，但是有两个宏（DECLARE_TRACE和DEFINE_TRACE）会被trace event使用，需要看下。

（1） DECLARE_TRACE

该宏在<linux/tracepoint.h>被定义。

trace_##name最终调用__DO_TRACE宏将信息送到ring buffer中。

reg/unregister_trace_subsys_event 负责注册或注销 probe 函数，probe 函数的原型由 TP_PROTO 宏给出。例如：wakeup相关tracer则是调用了register_trace_sched_wakeup。

使用 tracepoint 需要自己实现 probe 函数，event tracing通过一套通用的机制省去了内核模块/驱动自己实现probe函数的麻烦。

• __DO_TRACE

 

该(it_func_ptr)->func和(tp)->funcs在enable event的时候会被赋值，下文会有展开描述。

（2） DEFINE_TRACE

定义了__tpstrtab_##name字符串变量和struct tracepoint __tracepoint_##name。当然二者都放在了链接脚本专门的p里（详见include/asm-generic/vmlinux.lds.h）。编译后可查看system.map去查看具体的变量位置。

2. event tracing的实现原理

event tracing 可以理解为 tracepoint 加 function trace 的接口组合而成，提供了接口给内核开发者，让其快速的定义信息保存的格式以及如何打印出来。具体原理可参照samples/trace_events/下的例子。

（1）TRACE_EVENT

该宏可以实现probe点、probe函数、event的格式，以及event打印出来的格式。

第1次通过包含include/linux/tracepoint.h，将其展开成DECLARE_TRACE。

第2次通过include/trace/trace_events.h，将其展开成DECLARE_EVENT_CLASS，而在该头文件中DECLARE_EVENT_CLASS会被多次展开。

第3次通过包含include/trace/define_trace.h，将其展开成DEFINE_TRACE

其中，include/linux/和include/trace/define_trace.h必须显示被使用者显式包含。

总结下：

• trace_##name，是放置probe点的函数实现，如果该event enable则调用注册进来的trace_event_raw_event_##call

• trace_raw_output_##call，是输出信息的函数实现（cat trace时输出）

• trace_event_raw_event_##call，是probe函数

（2）trace_##name

细节参见上文宏展开结果。

（3）trace_raw_output_##call

该函数在cat trace文件节点的时候会被调用。

（4）trace_event_raw_event_##call

综上，通过上述宏展开，得到：

3. 关键流程梳理

（1）定义event

使用TRACE_EVENT宏定义event的原型、信息打印格式等。参见上文描述。

（2）记录event

代码中静态埋点，调用trace_##name，放置probe点。参见上文描述。

（3）使能event

假设tracefs已经提前挂载好（可以通过cat /proc/mounts | grep tracefs命令查看）

tracefs /sys/kernel/debug/tracing tracefs rw,seclabel,relatime 0 0

对应命令：

echo 1 > /sys/kernel/debug/tracing/events/<one_trace_event>/enable

对应关键代码流程：

将上文描述的展开后的宏里面的trace_event_raw_event_##call注册到struct tracepoint_func中进去

（4）输出event

对应命令：

对应关键代码流程：

print_trace_fmt函数代码截图：

funcs->trace，参见上文被赋值成trace_raw_output_##call了。

三、使用ftrace event tracing跟踪特定进程调度原理

本章我们主要介绍手机平台实现精准跟踪特定进程调度使用的一些技巧。因为我们最终还是要借助systrace这个ftrace前端，所以简单介绍ftrace相关tag，包括Java层和Native层如何使用ftrace接口。同时我们要简单研究下调度相关的trace event以及filter功能，这是解决实际问题的关键。

1. Android systrace tag list

使用atrace –list即可查看所有支持的tag list。

2.  用户态如何使用ftrace

有时候我们还要把用户态信息和内核信息同步起来，可以通过 trace_marker 实现。

（1）使用trace_marker

Systrace利用ftrace提供了如下两个接口供用户程序调用：

• Java层：Trace.traceBegin(tag, name)/Trace.traceEnd(tag)

• Native层 ：ATRACE_BEGIN(name)/ATRACE_END()

当然，也可以根据特定需求，直接利用systrace现成的tag（即还可以使用systrace 设置tag和手动设置sched调度的event filfter搭配起来用）。如果想关闭用户态的信息打印也是可以的。

（2）开关trace_marker

查看：

cat options/markers

打开：

echo 1 > options/markers

关闭：

echo 0 > options/markers

 

3. Android Linux状态

 

（1）Android状态转移

图3-1 Android进程状态转移

1）Runnable -> Running：就绪态的进程获得了CPU的时间片，进入运行态；

2）Running -> Runnable: 运行态的进程在时间片用完后，必须出让CPU，进入就绪态；

3）Running -> Blocked：当进程请求资源的使用权(如外设)或等待事件发生(如I/O完成)时，由运行态转换为阻塞态；

4）Blocked -> Runnable：当进程已经获取所需资源的使用权或者等待事件已完成时，中断处理程序必须把相应进程的状态由阻塞态转为就绪态。

（2）Linux原生状态信息

4. 调度相关events分析

可以通过cat available_events | grep sched:命令或者ls events/sched/去查看内核已经实现调度相关的events。结合上文的进程状态分析，我们从中挑选events如下：

这些trace events足够我们分析线程级别的调度信息。

5.  event的filter功能

为实现问题进程的跟踪，我们需要使用event的filter功能。

（1）event filter语法简单介绍

field-name relation-operatior value     

• 对于数字域，可以使用操作符==, !=, <, <=, >, >=, &

• 对于字符串域，可以使用==, !=, ~。目前字符串只支持完全匹配，且最多可以组合16个条件。”~”支持通配符(*,?)。

例子：

（2）event filter format

可以先通过该event目录下的format查看event消息格式。

我们依次分析根据上文所有需要跟踪的events，可以根据comm（包括pre_comm，next_comm）和PID等设置过滤条件。

剩下就是把相关events enable就可以了，细节本文就不展开了。

四、实际例子

1. 实际问题

我们在实际的项目中曾经遇到过低概率问题，那个问题是相机切换模式时预览卡顿并出现闪退。我们第一反应肯定是直接打开systrace去抓取trace回来，但面临个问题：

1）问题低概率出现，复现一次不容易，需要一次复现就抓到问题现场；

2）抓取log量还是过大（即使只用“sched”和“camera”），问题场景对负载敏感；

3）问题复现后，需要手动停止，这块手动操作要到10几秒到1分钟不等，需要抓取log量尽可能短，以便抓到出问题时的现场，不然ring buffer被覆盖会导致前功尽弃。

2. 问题分析

问题关键是要让ftrace记录时间尽可能长，很自然能想到的措施：

1）增大ftrace buffer；

2）减少ftrace记录的内容，同时要保证足够问题分析。

虽然该问题概率低，但好消息是只要压测时间足够久，还是能复现出来。通过分析规律，我们发现每次相机切换时，都有AlgoInterface::init出现，重点怀疑该对应的进程调度异常，经确认该方法会对应“APSRoutine”的进程异常。

所以解决问题的关键就变成：

1）利用ftrace event tracing的过滤功能，跟踪“APSRoutine”进程，具体的events的filter设置参见上一章内容；

2）要知道对应的用户态操作，所以必须要打开trace_marker开关（但trace_marker不支持过滤功能，这点比较遗憾，不然可以让记录的内容更少）；

3）在Java层crash的地方加hook，crash时抓取ftrace。

所以做了这样满足上述条件的小工具。后续我们还可以将其完善，做成支持抓取任意Java/Native层特定进程调度相关log的功能。

这样我们就把ftrace event tracing的原理及一个基于ftrace的小工具解决实际问题的实践介绍完了，由于时间和个人水平有限，难免有出错的地方，如有还请大家帮忙指出。

参考材料

[1] 进程状态的切换，袁辉辉

[2] ftrace 中 eventtracing 的实现原理，普侯

[3] 史上最长的宏定义，Kernel Exploring

[4] https://www.kernel.org/doc/html/latest/trace/events.html

扫码关注
“内核工匠”微信公众号
Linux 内核黑科技 | 技术文章 | 精选教程