使用 ftrace

ftrace 是一种调试工具,用于了解 Linux 内核中的情况。以下部分详细介绍了 ftrace 的基本功能、ftrace 与 atrace(捕获内核事件)如何配合使用,以及动态 ftrace。

如需详细了解 systrace 中没有的 ftrace 高级功能,请参阅 ftrace 文档:<kernel tree>/Documentation/trace/ftrace.txt

使用 atrace 捕获内核事件

atrace (frameworks/native/cmds/atrace) 使用 ftrace 捕获内核事件,而 systrace.py(在较高版本的 Catapult 中为 run_systrace.py)使用 adb 在设备上运行 atrace。atrace 会执行以下操作:

  • 通过设置属性 (debug.atrace.tags.enableflags) 来设置用户模式跟踪。
  • 通过写入相应的 ftrace sysfs 节点来启用所需的 ftrace 功能。不过,由于 ftrace 支持的功能更多,您可以自行设置一些 sysfs 节点,然后使用 atrace。

您可以使用 atrace 将该属性设置为适当的值,但启动时跟踪除外。该属性是一个位掩码,除了查看相应的标头(在不同的 Android 版本之间会有所变化),没有确定正确值更好的办法了。

启用 ftrace 事件

ftrace sysfs 节点位于 /sys/kernel/tracing 中,轨迹事件在 /sys/kernel/tracing/events 中被划分为多个类别。

如需按类别启用事件,请使用以下命令:

echo 1 > /sys/kernel/tracing/events/irq/enable

如需按事件启用事件,请使用以下命令:

echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

如果通过写入 sysfs 节点启用了额外的事件,这些事件将不会被 atrace 重置。Qualcomm 设备启动的常见模式是启用 kgsl (GPU) 和 mdss(显示流水线)跟踪点,然后使用 atrace 或 systrace

adb shell "echo 1 > /sys/kernel/tracing/events/mdss/enable"
adb shell "echo 1 > /sys/kernel/tracing/events/kgsl/enable"
./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html

您还可以在不使用 atrace 或 systrace 的情况下单独使用 ftrace,这在需要仅限内核的跟踪记录(或者您已经花时间手动写入用户模式跟踪属性)时很有帮助。如需只运行 ftrace,请执行以下操作:

  1. 将缓冲区大小设置为足以用于您跟踪的值:
    echo 96000 > /sys/kernel/tracing/buffer_size_kb
    
  2. 启用跟踪:
    echo 1 > /sys/kernel/tracing/tracing_on
    
  3. 运行您的测试,然后停用跟踪:
    echo 0 > /sys/kernel/tracing/tracing_on
    
  4. 转储跟踪:
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output
    

trace_output 以文本形式提供跟踪记录。如需使用 Catapult 将其可视化,请从 GitHub 获取 Catapult 代码库并运行 trace2html:

catapult/tracing/bin/trace2html ~/path/to/trace_file

默认情况下,此操作会将 trace_file.html 写入同一目录中。

关联事件

同时查看 Catapult 可视化内容和 ftrace 日志通常很有帮助,例如,某些 ftrace 事件(尤其是特定于供应商的事件)未经 Catapult 可视化。不过,Catapult 的时间戳与跟踪记录中的第一个事件或 atrace 所转储的特定时间戳相关,而原始的 ftrace 时间戳则基于 Linux 内核中的特定绝对时钟源。

如需从 Catapult 事件中查找特定的 ftrace 事件,请执行以下操作:

  1. 打开原始的 ftrace 日志。最新版本的 systrace 中的跟踪记录默认经过压缩:
    • 如果您使用 --no-compress 捕获 systrace 跟踪记录,跟踪记录会位于 html 文件中以 BEGIN TRACE 开头的部分。
    • 否则,请运行 Catapult 树 (tracing/bin/html2trace) 中的 html2trace,以解压缩跟踪记录。
  2. 在 Catapult 可视化内容中查找相对时间戳。
  3. 在跟踪记录的开头找到包含 tracing_mark_sync 的行。该行应该与以下内容相似:
    <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286
    

    如果此行不存在(或者您在未使用 atrace 的情况下使用 ftrace),时间将为相对于 ftrace 日志中第一个事件的时间。
    1. 将相对时间戳(以毫秒为单位)添加到 parent_ts(以秒为单位)中的值。
    2. 搜索新时间戳。

执行这些步骤之后,您应该会找到(或至少非常接近于找到)要找的事件。

使用动态 ftrace

当 systrace 和标准 ftrace 不能满足需求时,还有最后一种可用资源:动态 ftrace。动态 ftrace 涉及在启动后重写内核代码,因此出于安全考虑,它在正式版内核中不可用。不过,2015 和 2016 版中的每个严重性能错误最终都使用动态 ftrace 找出了根本原因。它在调试不可中断休眠方面的功能尤其强大,因为每次命中触发不可中断休眠的函数时,都可以在内核中获得堆栈轨迹。您还可以调试已停用中断和抢占的部分,这对证实问题非常有帮助。

如需开启动态 ftrace,请修改内核的 defconfig:

  1. 移除 CONFIG_STRICT_MEMORY_RWX(如果存在)。如果您使用的是 3.18 或更新版本以及 arm64,则不存在。
  2. 添加以下内容:CONFIG_DYNAMIC_FTRACE=y、CONFIG_FUNCTION_TRACER=y、CONFIG_IRQSOFF_TRACER=y、CONFIG_FUNCTION_PROFILER=y 和 CONFIG_PREEMPT_TRACER=y
  3. 重新编译和启动新内核。
  4. 运行以下命令以检查可用的跟踪工具:
    cat /sys/kernel/tracing/available_tracers
    
  5. 确认命令是否返回 functionirqsoffpreemptoffpreemptirqsoff
  6. 运行以下命令以确保动态 ftrace 正常运行:
    cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>
    

完成这些步骤之后,动态 ftrace、函数分析器、irqsoff 分析器以及 preemptoff 分析器便处于可用状态。我们强烈建议您在使用之前阅读有关这些主题的 ftrace 文档,因为它们虽然功能强大,但比较复杂。irqsoff 和 preemptoff 主要用于确认驱动程序是否会使中断或抢占处于关闭状态的时间过长。

函数分析器是诊断性能问题的最佳选择,通常用于查找函数被调用的位置。

对于此问题,每次使用 Pixel XL 拍摄 HDR + 照片后立即旋转取景器时都会造成卡顿。我们使用函数分析器不到一个小时就调试了该问题。如需按照示例操作,请下载跟踪记录的 .zip 文件(该文件还包含本部分中提及的其他跟踪记录),解压缩该文件,然后在浏览器中打开 trace_30898724.html 文件。

跟踪记录显示,cameraserver 进程中的多个线程在系统调用 ion_client_destroy 时遭到屏蔽而进入不可中断休眠状态。该函数为高开销函数,只应偶尔调用,因为 ion 客户端应涵盖多次分配。最初是将原因归咎于 Halide 中的 Hexagon 代码,它确实是其中一个原因(它为每个 ion 分配创建了新的客户端,并在分配被释放时破坏相应客户端,其代价太高了)。通过针对所有 Hexagon 分配使用单个 ion 客户端,情况得以改善,但卡顿问题并没有得到解决。

此时,我们需要知道 ion_client_destroy 的调用方,这要用到函数分析器:

  1. 由于编译器有时会对函数进行重命名,因此需要使用以下命令确认 ion_client_destroy 是否存在:
    cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
    
  2. 确认存在之后,将其用作 ftrace 过滤器:
    echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
    
  3. 开启函数分析器:
    echo function > /sys/kernel/tracing/current_tracer
    
  4. 开启每次调用过滤器函数时的堆栈轨迹:
    echo func_stack_trace > /sys/kernel/tracing/trace_options
    
  5. 增加缓冲区大小:
    echo 64000 > /sys/kernel/tracing/buffer_size_kb
    
  6. 开启跟踪功能:
    echo 1 > /sys/kernel/tracing/trace_on
    
  7. 运行测试并获取跟踪记录:
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace
    
  8. 查看跟踪,以查看大量堆栈跟踪记录:
        cameraserver-643   [003] ...1    94.192991: ion_client_destroy <-ion_release
        cameraserver-643   [003] ...1    94.192997: <stack trace>
     => ftrace_ops_no_ops
     => ftrace_graph_call
     => ion_client_destroy
     => ion_release
     => __fput
     => ____fput
     => task_work_run
     => do_notify_resume
     => work_pending
     

根据 ion 驱动程序的检查结果,我们可以发现,有个正在关闭 /dev/ion fd 的用户空间函数(而非随机内核驱动程序)正在大量发送 ion_client_destroy。通过在 Android 代码库中搜索 \"/dev/ion\",我们发现一些供应商驱动程序的操作与 Hexagon 驱动程序一样,每次需要新的 ion 分配时,就会打开/关闭 /dev/ion(创建和销毁新 ion 客户端)。通过将这些更改为在进程的生命周期中使用单个 ion 客户端,我们修复了该 bug。


如果函数分析器的数据不够具体,您可以结合使用 ftrace 跟踪点和函数分析器。启用 ftrace 事件的方式与平常完全相同,这些事件将与您的跟踪记录相互交错。如果您要调试的特定函数偶尔出现长时间的不可中断休眠,如下方法会非常有用:给要调试的函数设置 ftrace 过滤器,启用跟踪点,然后进行跟踪。您可以使用 trace2html 解析生成的跟踪记录,找到要找的事件,然后在原始跟踪记录中获得临近的堆栈轨迹。

使用 lockstat

有时,只有 ftrace 还不够,您还非常需要调试貌似内核锁争用的情况。还有一种内核选项值得尝试:CONFIG_LOCK_STAT。这是最后一种方法,因为要在 Android 设备上使用该方法非常困难,原因是它会使内核的大小超出大多数设备可以处理的范围。

不过,lockstat 使用调试锁定基础架构,这对很多其他应用都有帮助。负责设备启动的每个人都应知道如何在每台设备上使用该选项,因为到时您可能会想,“要是能开启 LOCK_STAT,我就可以在 5 分钟(而不是 5 天)内判断是不是这方面的问题”。

在这个问题中,当所有内核以最大负载运行非 SCHED_FIFO 线程时,SCHED_FIFO 线程便会终止。我们的跟踪记录显示,VR 应用中的某个 fd 存在严重的锁争用,但是我们无法轻松确定相关 fd。如需按照示例操作,请下载跟踪记录的 .zip 文件(该文件还包含本部分中提及的其他跟踪记录),解压缩该文件,然后在浏览器中打开 trace_30905547.html 文件。

我们假设 ftrace 本身是锁争用的原因,在此情况下,低优先级的线程在能够释放锁之前,会开始写入 ftrace 管道,然后导致抢占。这是最糟糕的一种情况。一些优先级极低的线程写入 ftrace 标记,同时另一些优先级较高的线程在 CPU 上自旋以模拟设备满载,两者导致了情况恶化。

由于无法使用 ftrace 进行调试,因此我们运行了 LOCK_STAT,然后关闭了应用的所有其他跟踪功能。结果表明,锁争用确实来自 ftrace,因为当 ftrace 不运行时,锁跟踪记录中没有出现任何争用情况。


如果您可以使用配置选项启动内核,则锁跟踪与 ftrace 类似:

  1. 启用跟踪:
    echo 1 > /proc/sys/kernel/lock_stat
    
  2. 运行您的测试。
  3. 停用跟踪:
    echo 0 > /proc/sys/kernel/lock_stat
    
  4. 转储您的跟踪记录:
    cat /proc/lock_stat > /data/local/tmp/lock_stat
    

如需获取解读生成的输出结果方面的帮助,请参阅 lockstat 文档:<kernel>/Documentation/locking/lockstat.txt

使用供应商跟踪点

首先使用上游跟踪点,但有时需要使用供应商跟踪点:

  { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, {
        { OPT,      "events/mdss/enable" },
        { OPT,      "events/sde/enable" },
        { OPT,      "events/mali_systrace/enable" },
    } },

跟踪点可以通过 HAL 服务扩展,这样您就可以添加设备专用的跟踪点/类别。跟踪点与 perfetto、atrace/systrace 以及设备上的系统跟踪应用集成。

用于实现跟踪点/类别的 API 有:

  • listCategories()generates (vec<TracingCategory> categories);
  • enableCategories(vec<string> categories) generates (Status status);
  • disableAllCategories() generates (Status status);
如需了解详情,请参阅 AOSP 中的 HAL 定义和默认实现。