此页面由 Cloud Translation API 翻译。

使用 JTRACE 调试内核崩溃

概览

定义

JTRACE 是一种简单轻量级的“用例”跟踪系统调试内核崩溃和自发重新启动时，开发者添加的插桩生成的一系列跟踪事件记录；并在发生内核崩溃时自动播放目的让开发者能够从几乎任何位置创建跟踪记录为他们提供更多信息，而不仅仅是注册转储和堆栈轨迹，以帮助了解事件的顺序这也会导致崩溃JTRACE 的有用属性包括：

无锁环形缓冲区数据结构：创建跟踪事件永远不会块，并且永远不会尝试获取任何锁，使其可用于在早期初始化期间、在任意锁内、硬 IRQ 期间使用，以及在内核代码中的几乎任何位置。
开销低：创建跟踪事件是一项相对便宜的操作，因此能够以最少的时间对性能敏感型代码进行插桩造成干扰。
（可选）重新启动后持久化：在平台允许的情况下，可以指定 JTRACE 配置为使用一些通常用于崩溃日志的永久性 RAM 有助于调试涉及自发重新启动的问题，由触发硬件监控计时器引起的。

不是

JTRACE 不是生产跟踪系统。默认情况下，已停用，并且绝不能在正式版 build 中启用。Trace 点不会留在代码中，已经签到。JTRACE 的典型用法涉及开发者将跟踪点添加到重现崩溃，然后修改现有跟踪点或添加然后不断重复，直到找到根源，才引发了错误。这个 bug 出现后，发现、理解和修复后，添加跟踪点的代码是已舍弃。

配置

使用通过 fx set 设置的构建参数来控制 JTRACE 的配置。目前可以指定 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	false

build 配置完成后，只需重新构建并部署新内核即可您的目标，以便开始使用 JTRACE。

示例

若要启用具有大型记录和大小为 32KB 的 storage，请将以下代码添加到 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="永久"jtrace_last_entry_storage=4 jtrace_use_large_entries=true”

请注意，persistent 左右需要 ""。

添加跟踪点

要求

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

#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");
}

这里展示了标记的 trace 语句应如下所示：跟踪缓冲区最终显示的时间。

[   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`	第一个 32 位参数的值 (`i`)
`00000006`	第二个 32 位参数的值 (`foo`)
`00000001`	第 3 个 32 位参数的值 (`bar`)
`00000000`	第 4 个 32 位参数的值 (0)
`ffffffff0024c720`	第一个 64 位参数的值 (`ptr1`)
`ffffff9519077e60`	第二个 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]

跟踪记录条目

跟踪条目在编译时可配置为“大”或“small” 记录（请参阅配置）。轨迹缓冲区中的所有记录具有相同的配置大小无法将小型记录与大型文件大型条目是小型条目的超集。也就是说，大型条目包含小型记录包含的所有字段，外加一些额外记录。

由于可用于存储的永久性 DRAM（通常）数量有限，系统时，将 JTRACE 配置为则其他情况下会使用大型记录。也就是说，用户可能会覆盖并在任一情况下强制记录小型或大型记录。

小条目

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

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

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

大型条目

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

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

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

每个 CPU 的最后事件记录

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

在尝试调试个别 CPU 的挂起问题时，此功能会很有用，特别是在会导致触发硬件 WDT 的情况下。如果 CPU 卡住的时间过长，很可能是因为从另一个 CPU 快速刷新事件。跟踪缓冲区，尤其是当缓冲区较小，因为它位于或永久性 RAM针对卡住的 CPU，单独的最后事件记录让开发者知道在它之前由卡住的 CPU 执行的最后一个跟踪点已停止响应。

如需启用每个 CPU 的最后事件记录，请设置 jtrace_last_entry_storage configuration 参数设置为等于 CPU 数量。请注意，如果此数字过低，如果 CPU ID 大于等于所配置的数量，则一律不记录。如果编号为则某些条目永远不会记录到日志，而另一些条目的跟踪缓冲区中预留的存储空间将会浪费。

持久性跟踪

概览

开发者偶尔可能会发现自己处于一种不幸的境地，需要调试整个系统挂起出现这种情况时因为观察广告资源状态的所有功能或者导致它的前因后果，就会丢失。在这种情况下，或许能有所帮助

在配置持久跟踪后，跟踪缓冲区将放置在特殊的“永久性 RAM”中由引导加载程序提供给内核的操作通常情况下，这是物理 RAM 的区域，肯定不会，这意味着将信息存放在系统。

用法

如需启用持久性跟踪，请将 jtrace_enabled 设置为值 "persistent”。发生挂起后，请重新启动系统（通过 HW WDT 或目标）。系统重新启动后，如果恢复的跟踪缓冲区已成功恢复，可以通过从k jtrace -r 串行 shell。请注意，永久性 RAM 通常只是 DRAM 的一部分，被放在引导加载程序链旁，它可能会在使用过程中出现损坏早期阶段的引导加载程序重新启用动态 RAM 刷新。通过跟踪系统将尽一切努力从恢复的缓冲区，如果需要，回退到该区域的十六进制转储，解读此转储的结果时，因为重新启动可能造成损坏

目前，并非所有目标都支持直接内存映射永久性 RAM 这种情况下，该区域通常非常小目前，只有 ARM64 目标支持这些区域，因此目前不支持持续跟踪适用于 x64 系统。jtrace_target_buffer_size 值由用户只是在请求存储空间，并不能保证有足够的存储空间来支持请求。如果没有，跟踪系统将尽可能多地占用存储空间，预订广告资源启动后，用户可以对 JTRACE 子系统。k jtrace -i对于在具有 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 的信息。
在环形缓冲区中预留条目槽会使用原子，获取/释放内存顺序语义。根据内存顺序而这可能会影响某些错误的可重现性，同时进行 JTRACE 处理的 CPU 可能会突然无法重新排序跨越 JTRACE 的点。
使用持久性跟踪时，写入 JTRACE 缓冲区的记录必须可以立即从缓存一直刷新到物理内存在自发重新启动后正常运行。正确配置 persistent_ram_allocation_granularity 值应阻止这些缓存清除操作与其他内容重叠请注意，将条目写入跟踪缓冲区将产生一个从缓存强制到物理 RAM 的额外数据量增加比平常更频繁