此页面由 Cloud Translation API 翻译。

使用 JTRACE 调试内核崩溃

概览

简介

JTRACE 是一个简单的轻量级“即时”跟踪系统，旨在记录由开发者添加的插桩生成的一系列跟踪事件记录，并在出现内核崩溃时自动回放这些记录，从而帮助开发者调试内核崩溃和自发重启。这样做的目的是让开发者能够从内核代码中的几乎任何位置创建跟踪记录，从而为他们提供更多信息（而不仅仅是寄存器转储和堆栈轨迹），从而有助于了解导致崩溃的事件序列。JTRACE 的实用属性包括：

无锁环形缓冲区数据结构：创建跟踪事件永远不会阻塞，也绝不会尝试获取任何锁，使其可供在早期初始化、任意锁内、硬 IRQ 期间以及内核代码中的几乎其他位置使用。
开销低：创建轨迹事件是一项相对开销的操作，因此可以对性能敏感的代码进行插桩，从而最大限度地减少时间中断。
在重新启动后可选的持久性存储：在平台允许的情况下，可以将 JTRACE 配置为使用一些通常用于崩溃日志存储的持久性 RAM，以协助调试涉及自发重新启动的问题，这些问题通常由触发硬件监控计时器计时器所致。

它不是

JTRACE 不是生产跟踪系统。默认情况下，它完全处于停用状态，绝不在正式版 build 中启用。开发者在已签入的更改时不应留在代码中。JTRACE 的典型用法包括开发者向其代码中添加跟踪点、重现崩溃问题，然后修改现有跟踪点或添加新的跟踪点，并不断重复，直到找出导致相应 bug 的根源。发现、理解并修复 bug 后，系统会舍弃添加跟踪点的代码。

配置

JTRACE 的配置使用通过 fx set 设置的 build 参数控制。目前，您可以指定 4 个选项。它们是：

名称	类型	备注
`jtrace_enabled`	三州	在设置为 `true` 或 `"persistent"` 时启用 JTRACE。默认处于停用状态。
`jtrace_target_buffer_size`	uint32_t	控制为跟踪缓冲区预留的 RAM 容量。
`jtrace_last_entry_storage`	uint32_t	控制为每个 CPU 的上次事件记录预留的 RAM 容量。
`jtrace_use_large_entries`	bool	控制使用大型还是小型跟踪条目。

默认情况下，JTRACE 处于停用状态，并且不包含在内核 build 中。如需启用 JTRACE，用户可以将 jtrace_enabled build 参数设置为 true 或 "persistent" 的值，以启用 JTRACE 并将其配置为进行永久性跟踪。

如果选择持久性跟踪，则 jtrace_target_buffer_size 必须是内核配置的 persistent_ram_allocation_granularity 值的倍数（默认为 128 字节）。

如果用户未明确指定，则系统会根据是否选择永久性跟踪记录来选择其他每个配置参数的默认值。

名称	非永久性默认值	永久性默认值
`jtrace_target_buffer_size`	32768	4096
`jtrace_last_entry_storage`	0	0
`jtrace_use_large_entries`	true	否

配置 build 后，只需重新构建并将新内核部署到目标，即可开始使用 JTRACE。

示例

如需启用包含大型记录和 32KB 存储空间的非永久性跟踪，请将以下代码添加到 fx set 行。

--args 'jtrace_enabled=true'

要将此存储空间扩展到 64KB 并改用小型记录，参数应如下所示：

--args 'jtrace_enabled=true jtrace_target_buffer_size=65536 jtrace_use_large_entries=false'

如需启用包含大型记录（覆盖默认值）和存储 4 个 CPU 上最后的事件记录（也覆盖默认值）的持久性跟踪，请求 4KB 的存储空间，请将以下代码添加到 fx set 行。

--args 'jtrace_enabled="persistent" jtrace_last_entry_storage=4 jtrace_use_large_entries=true'

请注意，大约在 persistent 前后需要 ""。

添加跟踪点

要求

为了向文件添加跟踪点，用户必须添加 jtrace 标头，方法是在要添加跟踪点的每个文件中添加以下 #include 语句。

#include <lib/jtrace/jtrace.h>

如果未找到 include 文件，可能需要将头文件添加到模块的 BUILD.gn 文件的 deps 部分。

deps = [ "//zircon/kernel/lib/jtrace:headers" ] # If deps has not been declared yet.
deps += [ "//zircon/kernel/lib/jtrace:headers" ] # If deps has already been declared.

JTRACE 宏。

现可通过调用 JTRACE 宏添加跟踪点。每个跟踪点均必须指定一个字符串字面量“标记”，并且可以指定所配置的轨迹条目记录支持的尽可能多的通用参数。在配置永久性跟踪的情况下，标记必须是字符串字面量，以便在重新启动后保持有效。

通用参数无需指定，如果省略，则默认为 0。此外，指定通用参数时，无需进行类型转换。如果参数字段足够大，可以存储该值，小型跟踪条目有单个 32 位参数的空间，而大型跟踪条目有四个 32 位参数的空间，后跟两个 64 位参数。

以下是针对大型条目配置跟踪时使用跟踪的示例。

#include <lib/jtrace/jtrace.h>

struct MyStruct {
  void *ptr1, *ptr2;
  uint32_t foo, bar;
};

void MyFunction(const MyStruct* args, uint32_t num_args) {
  JTRACE("(num_args, args)", num_args, 0, 0, 0, args);

  for (uint32_t i = 0; i < num_args; ++i) {
    const auto& a = args[i];
    JTRACE("Before (i, foo, bar, 0, ptr1, ptr2)", i, a.foo, a.bar, 0, a.ptr1, a.ptr2);
    zx_status_t status = DoAThingWithMyStruct(a);
    JTRACE("After (status)", status);
  }

  JTRACE("Finished");
}

下面是跟踪缓冲区最终显示时带有“Before”标记的跟踪语句之一。

[   7.718998976][cpu 2 tid     3702] : 00000002 00000006 00000001 00000000 ffffffff0024c720 ffffff9519077e60 : (       0.308 uSec) : jtrace_example.cc:MyFunction:12 (Before (i, foo, bar, 0, ptr1, ptr2))

按字段细分数据，结果包括：

字段	说明
`[ 7.718998976]`	跟踪记录条目的时钟单调时间戳
`[cpu 2 tid 3702]`	记录轨迹条目时处于活跃状态的 CPU 和线程的 ID
`00000002`	第 1 个 32 位参数的值 (`i`)
`00000006`	第 2 个 32 位参数的值 (`foo`)
`00000001`	第 3 个 32 位参数的值 (`bar`)
`00000000`	第 4 个 32 位参数的值 (0)
`ffffffff0024c720`	第 1 个 64 位参数的值 (`ptr1`)
`ffffff9519077e60`	第 2 个 64 位参数的值 (`ptr2`)
`( 0.308 uSec)`	自上次显示的跟踪记录条目以来经过的时间
`jtrace_example.cc:MyFunction:12`	跟踪记录条目的文件名、函数名称和行号
`(Before (i, foo, bar, 0, ptr1, ptr2))`	用户的字符串字面量标记

显示跟踪缓冲区的内容

启用 JTRACE 后，每当发生内核崩溃时，系统会自动转储跟踪缓冲区的内容，以及寄存器转储和回溯。

用户还可以使用内核 shell 手动转储跟踪缓冲区的内容。在串行控制台中，只需运行 k jtrace 转储当前的跟踪缓冲区，或运行 k jtrace -r 转储已恢复的永久性跟踪记录缓冲区的内容（如果有）。请注意，在转储实时跟踪缓冲区期间，系统会暂时停用跟踪，并且不会向缓冲区添加新的跟踪条目。对 JTRACE 宏的调用将被视为空操作。

示例

下面是一个跟踪缓冲区的转储示例，该缓冲区配置为使用小型条目（具有 4kB 存储空间和 4 个每 CPU 的最后事件记录）。系统使用两个 JTRACE 宏对系统调用进入和退出进行了插桩测试。该标记用于保存正在进行的系统调用的字符串字面量名称，而第一个通用参数用于记录一个布尔值，指示轨迹是标记系统调用的开始还是结束。

JTRACE: Recovered 166/166 entries
[  17.431102506][cpu 0] : 00000001 : (    0.000 uSec) : (futex_wait)
[  17.431107979][cpu 0] : 00000000 : (    5.473 uSec) : (nanosleep)
[  17.431109757][cpu 0] : 00000001 : (    1.778 uSec) : (nanosleep)
[  17.431118119][cpu 0] : 00000000 : (    8.362 uSec) : (futex_wake)
[  17.431131543][cpu 0] : 00000001 : (   13.424 uSec) : (futex_wake)
[  17.431134424][cpu 0] : 00000000 : (    2.881 uSec) : (futex_wake)
<snip>
[  17.437545001][cpu 3] : 00000001 : (    1.443 uSec) : (object_wait_async)
[  17.437547341][cpu 3] : 00000000 : (    2.340 uSec) : (port_wait)
[  17.437548263][cpu 3] : 00000001 : (    0.922 uSec) : (port_wait)
[  17.437666664][cpu 3] : 00000000 : (  118.401 uSec) : (channel_read_etc)
[  17.437668850][cpu 3] : 00000001 : (    2.186 uSec) : (channel_read_etc)
[  17.437678993][cpu 3] : 00000000 : (   10.143 uSec) : (debug_send_command)

JTRACE: Last recorded per-CPU events.
[  17.437001443][cpu 0] : 00000000 : (    0.000 uSec) : (futex_wait)
[  17.436016989][cpu 1] : 00000000 : (    0.000 uSec) : (channel_call_etc_noretry)
[  17.437066990][cpu 2] : 00000000 : (    0.000 uSec) : (futex_wait)
[  17.437678993][cpu 3] : 00000000 : (    0.000 uSec) : (debug_send_command)

JTRACE: Last log timestamp [  17.437678993]

以下是同一个示例，这次配置了大型记录。

JTRACE: Recovered 47/47 entries
[  24.270872973][cpu 2 tid     1301] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       0.000 uSec) : syscalls.cc:do_syscall_post:84 (channel_read_etc)
[  24.270875158][cpu 2 tid     1301] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       2.185 uSec) : syscalls.cc:do_syscall_pre:59 (object_wait_async)
[  24.270879083][cpu 2 tid     1301] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       3.925 uSec) : syscalls.cc:do_syscall_post:84 (object_wait_async)
[  24.270886634][cpu 2 tid     1301] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       7.551 uSec) : syscalls.cc:do_syscall_pre:59 (port_wait)
[  24.273031016][cpu 1 tid     1295] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (    2144.382 uSec) : syscalls.cc:do_syscall_pre:59 (channel_write_etc)
[  24.273057126][cpu 1 tid     1295] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (      26.110 uSec) : syscalls.cc:do_syscall_post:84 (channel_write_etc)
<snip>
[  24.273871139][cpu 1 tid     2735] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       5.089 uSec) : syscalls.cc:do_syscall_post:84 (object_wait_async)
[  24.273875048][cpu 1 tid     2735] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       3.909 uSec) : syscalls.cc:do_syscall_pre:59 (port_wait)
[  24.273876820][cpu 1 tid     2735] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       1.772 uSec) : syscalls.cc:do_syscall_post:84 (port_wait)
[  24.274000887][cpu 1 tid     2735] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (     124.067 uSec) : syscalls.cc:do_syscall_pre:59 (channel_read_etc)
[  24.274003866][cpu 1 tid     2735] : 00000001 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       2.979 uSec) : syscalls.cc:do_syscall_post:84 (channel_read_etc)
[  24.274019066][cpu 1 tid     2735] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (      15.200 uSec) : syscalls.cc:do_syscall_pre:59 (debug_send_command)

JTRACE: Last recorded per-CPU events.
[  24.269107951][cpu 0 tid     2475] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       0.000 uSec) : syscalls.cc:do_syscall_pre:59 (debug_read)
[  24.274019066][cpu 1 tid     2735] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       0.000 uSec) : syscalls.cc:do_syscall_pre:59 (debug_send_command)
[  24.273785974][cpu 2 tid     1902] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       0.000 uSec) : syscalls.cc:do_syscall_pre:59 (port_wait)
[  24.154375056][cpu 3 tid    28770] : 00000000 00000000 00000000 00000000 0000000000000000 0000000000000000 : (       0.000 uSec) : syscalls.cc:do_syscall_pre:59 (futex_wait)

JTRACE: Last log timestamp [  24.274019066]

跟踪记录条目

轨迹条目可以在编译时配置为“大”或“小”记录（请参阅配置）。跟踪缓冲区中的所有记录都具有相同的配置大小。无法将小型记录与大型记录混用。大型条目是小型条目的超集。换句话说，大型条目包含小型记录包含的所有字段，以及一些额外的记录。

由于系统可用的永久性 DRAM（通常）数量有限，因此在将 JTRACE 配置为持久性时，通常使用小记录，否则使用大记录。也就是说，用户可以替换此行为，并在这两种情况下强制使用小型或大型记录。

小型条目

小型跟踪记录条目会记录以下字段。

时间戳：记录将轨迹条目添加到缓冲区的时间的时间戳。以滴答声为单位记录，但在转储缓冲区时转换为时钟单调时间轴。
CPU Id：创建跟踪记录条目的 CPU 的 ID。
标记：指向开发者提供的用于协助调试的 C 字符串字面量的指针。
a：开发者提供的单个 32 位通用字段，用于协助调试。

每个小型跟踪记录条目目前占用 24 个字节的存储空间。

大型条目

大型条目扩展小型条目，并添加以下字段。

文件：跟踪点位置的文件名。
行：跟踪点位置文件中的行号。
函数：跟踪点位置的函数名称。
TID：创建跟踪记录条目的线程的数字线程 ID。
[a-d]：开发者提供的四个 32 位通用字段（而不是小记录的字段），用于协助调试。
[e-f]：开发者提供的两个 64 位通用字段，用于协助调试。

每个小型跟踪记录条目目前占用 72 字节的存储空间。

按 CPU 计算的最终事件记录

除了主跟踪缓冲区之外，还可以将 JTRACE 配置为单独存储每个 CPU 记录的最后事件。启用后，系统会在主轨迹缓冲区转储完成后，单独转储这些记录。

此功能可用于调试单个 CPU 挂起，尤其是当这些挂起导致触发硬件 WDT 时。如果某个 CPU 长时间卡住，其他 CPU 的跟踪事件可能会快速将卡住的 CPU 中的事件从跟踪缓冲区中刷新出跟踪缓冲区，尤其是当缓冲区因位于永久性 RAM 而较小时。通过针对卡住 CPU 的单独最后事件记录，开发者可以了解卡住的 CPU 在停止响应之前执行的最后一个跟踪点。

如需启用按 CPU 计算的最后事件记录，请将 jtrace_last_entry_storage configuration 参数设置为等于目标硬件中存在的 CPU 数量。请注意，如果此数字太小，则对于 CPU ID 大于等于配置的数字，系统永远不会记录最后一个事件。如果这个数字过高，则有些条目永远不会有记录，并且轨迹缓冲区中预留的某些存储空间将被浪费。

永久性跟踪

概览

有时，开发者可能会发现自己不幸地需要对系统完全挂起的问题进行调试。当发生这种情况时，可能很难获得任何数据洞见，因为观察系统状态或导致系统状态的所有能力都将丢失。在这种情况下，持续跟踪可能会有所帮助。

配置用于永久跟踪后，跟踪缓冲区将放置在引导加载程序提供给内核的特殊“永久性 RAM”中。通常情况下，这是一个物理 RAM 区域，系统启动时引导加载程序一定不会访问该区域，这意味着可以将信息放入设法在系统完全重置硬件后继续保留的区域。

用法

如需启用持久性跟踪，请将 jtrace_enabled 设置为值 "persistent"。挂起后，重新启动系统（通过硬件 WDT 或目标中的手动重置行）。系统重新启动后，如果已恢复的跟踪缓冲区已成功恢复，可以通过串行 shell 执行 k jtrace -r 来转储该跟踪缓冲区。请注意，永久性 RAM 通常只是由引导加载程序链预留的 DRAM 的一部分，在早期阶段的引导加载程序重新启用动态 RAM 刷新期间，永久性 RAM 可能会出现损坏。跟踪系统会尽一切努力从已恢复的缓冲区中转储尽可能多的数据，并根据需要回退到区域的十六进制转储，但是，如果重新启动可能导致损坏，则在解读此转储的结果时应格外小心。

目前，并非所有目标都支持直接内存可映射的永久性 RAM 区域，当支持此类区域时，此区域通常非常小。目前，只有 ARM64 目标支持这些区域，因此持久性跟踪目前不适用于 x64 系统。用户配置的 jtrace_target_buffer_size 值只是一个存储请求，无法保证有足够的存储空间来支持该请求。如果没有，跟踪系统将尽可能多地认领存储空间，并释放可预留的存储空间。启动后，用户可以通过从串行控制台运行 k jtrace -i 来对 JTRACE 子系统的当前配置进行示例。例如，在具有 8kB 永久性 RAM 的目标上，请求 32kB 缓冲区可能会导致以下结果。

JTRACE configuration
--------------------
Requested Buffer Size  : 32768
Allocated Buffer Size  : 6144
Allocated Buffer Loc   : 0xffff00023fff8000
Per-CPU last entry cnt : 0
Large entries          : no
Persistent             : yes

请求了 32 kB，但只有 8 kB 可用，其中 2 kB 预先预留给崩溃日志，只留下 6 kB 用于跟踪缓冲区。

注意事项

本质上，JTRACE 系统存在一些副作用和限制，用户应注意。

跟踪记录不必以单调递增的时间戳顺序存在。由于环形缓冲区存储具有无锁定特性，因此系统会首先预留记录槽，然后记录时间戳。缓存未命中和 IRQ 等效应可能会导致两个相邻的跟踪条目实际上具有乱序的时间戳。
从技术层面来讲，由于两个 CPU 同时向记录写入数据，跟踪记录可能会损坏（但极不可能）。为此，CPU 需要预留一个槽并开始向其写入数据，然后遇到长时间的延迟（可能是由抢占导致的）。在此延迟期间，如果记录了足够的条目来封装跟踪缓冲区，则第二个 CPU 可能会声明环缓冲区中与第一个槽位相同的槽位，从而导致记录中记录了来自两个 CPU 的信息。
环形缓冲区中条目槽的预留使用原子方式和获取/释放内存顺序语义。根据目标架构的内存排序细节，这可能会影响某些 bug 的可再现性，因为来自两个不同的 CPU（也是 JTRACE）的读取和写入操作可能突然无法跨 JTRACE 点重新排序。
使用永久性跟踪记录时，必须立即将写入 JTRACE 缓冲区的记录从缓存中刷新到物理内存，以便在自发重启后正确保留。正确配置的 persistent_ram_allocation_granularity 值应该可以防止这些缓存清理操作与其他任何内容重叠，但请注意，向轨迹缓冲区写入条目会导致少量额外数据被强制从缓存写入物理 RAM 而不是平常。