此页面由 Cloud Translation API 翻译。

使用 JTRACE 调试内核崩溃

概览

简介

JTRACE 是一个简单、轻量级的“以防万一”跟踪系统，旨在通过记录开发者添加的插桩生成的一系列跟踪事件记录，并在发生内核 panic 时自动回放这些记录，帮助开发者调试内核崩溃和自发重启。目的是让开发者能够在内核代码中的几乎任何位置创建轨迹记录，从而获得除了寄存器转储和堆栈轨迹之外的其他信息，以帮助了解导致崩溃的事件序列。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_use_mono_timestamps`	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	false
`jtrace_use_mono_timestamps`	false	false

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

示例

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

--args 'jtrace_enabled=true'

如需将此存储空间扩展到 64KB 并改用小记录，参数将为：

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

如需启用包含大型记录（替换默认值）的永久跟踪，并为每个 CPU 的 4 个最后事件记录存储空间（也替换默认值），从而请求 4KB 的存储空间，请将以下内容添加到 fx set 行中。

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

请注意，persistent 周围需要有 ""。

添加轨迹点

要求

如需向文件添加轨迹点，用户必须在要添加轨迹点的每个文件中添加以下 #include 语句，以便包含 jtrace 标头。

#include <lib/jtrace/jtrace.h>

如果找不到包含文件，您可能需要将头文件添加到模块的 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 宏来添加轨迹点。每个轨迹点必须指定字符串字面量“tag”，并且可以指定配置的轨迹条目记录支持的通用参数数量。在配置了持久跟踪的情况下，代码段必须是字符串字面量，才能在重新启动后保持有效。

无需指定通用参数，如果省略，则默认为 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 后，每当发生内核 panic 时，系统都会自动转储跟踪缓冲区的内容，以及寄存器转储和回溯。

用户还可以使用内核 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 配置为永久性时，通常使用小记录，否则使用大记录。不过，用户可以替换此行为，并在任一情况下强制使用小型或大型记录。

小条目

小型轨迹条目会记录以下字段。

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

小轨迹条目目前每个占用 24 字节的存储空间。

大型条目

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

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

每个小轨迹条目目前占用 72 字节的存储空间。

每个 CPU 的最后事件记录

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

在尝试调试单个 CPU 的挂起问题时，此功能会很有用，尤其是当挂起问题导致触发 HW WDT 时。如果某个 CPU 卡住了较长时间，其他 CPU 的轨迹事件可能会快速将卡住的 CPU 中的事件从轨迹缓冲区中刷出，尤其是当缓冲区位于永久性 RAM 中且较小时。通过为卡住的 CPU 单独提供最后事件记录，开发者可以了解卡住的 CPU 在停止响应之前执行的最后跟踪点。

如需启用每个 CPU 的最后事件记录，请将 jtrace_last_entry_storage 配置参数设置为等于目标硬件中存在的 CPU 数量。请注意，如果此数值过低，则系统将永远不会记录大于等于配置数值的 CPU ID 的最后事件记录。如果该数量过高，则部分条目将永远不会记录任何记录，并且轨迹缓冲区中预留的部分存储空间将被浪费。

持久跟踪

概览

有时，开发者可能会不幸地发现自己需要调试整个系统挂起问题。当这些情况发生时，很难获得任何洞见，因为系统状态或导致问题发生的原因无法观察到。在这种情况下，持久跟踪可能有所帮助。

配置为永久跟踪后，轨迹缓冲区会放置在引导加载程序提供给内核的特殊“永久 RAM”中。通常，这是一个物理 RAM 区域，可保证在系统启动时不会被引导加载程序触及，这意味着可以将信息放入该区域，使其能够在系统完全硬件重置后保留下来。

用法

如需启用持久跟踪，请将 jtrace_enabled 设置为值 "persistent”。发生挂起后，请重新启动系统（通过 HW WDT 或目标中的手动重置线）。系统重新启动后，如果成功恢复了已恢复的轨迹缓冲区，则可以通过从串行 shell 中执行 k jtrace -r 来转储该缓冲区。请注意，永久性 RAM 通常只是引导加载程序链搁置的一部分 DRAM，并且在早期引导加载程序重新启用动态 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

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

注意事项

JTRACE 系统本身具有一些副作用和限制，用户应予以留意。

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