在 几个月前 的这篇博客文章中,我介绍了 Julia 的一项新功能,它允许用户使用 rr
时间旅行调试器轻松地提交错误报告(如果你还没有阅读那篇文章,请阅读一下,否则你可能无法理解这篇文章的其余内容)。自 Julia 1.5 在一个多月前正式发布以来,已有十多位用户利用此功能向我们发送详细的错误报告。到目前为止,一切按计划进行。
在这篇文章中,我想讲述一下问题 #37524 的故事,这是我们收到的几个 rr
跟踪中最不寻常的一个。正如这篇文章的标题所暗示的那样,最终的问题是内存故障。但是,应广大要求,为了消除使用魔法的任何传言,我认为一步步分析这个问题可能值得。
调试 rr
跟踪时,通常首先要做的就是将它回放至崩溃点,以环顾四周(有时崩溃原因从程序在崩溃位置的状态就能明显看出,有时则需要更多历史记录)。在本例中,最初的调查由我的同事 Tim Besard 完成。下载跟踪并开始回放,他应该会看到以下内容。请注意,此记录大约快了 20 倍(实际运行时间约为两分钟),并在最后进行了轻微编辑,以仅关注相关输出。
因此,很明显,提交错误报告的用户正在进行某种循环过程(可能是一个机器学习训练过程),并在几千次迭代之后,出现了一些问题。该问题报告了以下输出
signal (11): Segmentation fault
in expression starting at julia-crash.jl:76
jl_is_concrete_type at /buildworker/worker/package_linux64/build/src/julia.h:1222 [inlined]
jl_apply_tuple_type_v_ at /buildworker/worker/package_linux64/build/src/jltypes.c:1381 [inlined]
jl_apply_tuple_type at /buildworker/worker/package_linux64/build/src/jltypes.c:1389
arg_type_tuple at /buildworker/worker/package_linux64/build/src/gf.c:1853
jl_lookup_generic_ at /buildworker/worker/package_linux64/build/src/gf.c:2361 [inlined]
jl_apply_generic at /buildworker/worker/package_linux64/build/src/gf.c:2394
jl_apply at /buildworker/worker/package_linux64/build/src/julia.h:1690 [inlined]
do_apply at /buildworker/worker/package_linux64/build/src/builtins.c:655
update! at Knn2.jl:48
update! at Knn2.jl:106
unknown function (ip: 0x7f0483dd8205)
[snip]
但实际上,我们得到的是一个内部 rr
错误
[FATAL /home/keno/rr/src/ReplaySession.cc:636:check_pending_sig()]
(task 17107 (rec:7760) at time 51911)
-> Assertion `false' failed to hold. Replaying `SIGNAL: SIGSEGV(det)': expecting tracee signal or trap, but instead at
`write' (ticks: 144040993972)
Tail of trace dump:
[snip]
{ syscall:'clock_gettime', ret:0x0, size:0x20 }
}
{
real_time:38257.585221 global_time:51911, event:`SIGNAL: SIGSEGV(det)' tid:7760, ticks:143998759917
rax:0x436487c0 rbx:0x7f0490b74330 rcx:0xb479 rdx:0x435f2dc8 rsi:0x435f2dc0 rdi:0x435f2dc0 rbp:0x7fff6ca71250 rsp:0x7fff
6ca71230 r8:0x1 r9:0x7f0490b74330 r10:0x1007f0490b784d0 r11:0x4364d190 r12:0x0 r13:0x7f0490b88c70 r14:0x7f047daf36d0 r1
5:0xb479 rip:0x7f049e2ba8e3 eflags:0x10287 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_b
ase:0x7f0499f49240 gs_base:0x0
}
{
real_time:38257.585223 global_time:51912, event:`SYSCALLBUF_RESET' tid:7760, ticks:143998759917
}
这时,Tim 让我接手,因为这种情况不应该发生。现在,这里显示的错误信息可能看起来有点吓人,但让我们逐部分解析它。实际的错误信息是
Replaying `SIGNAL: SIGSEGV(det)': expecting tracee signal or trap, but instead at
`write' (ticks: 144040993972)
这是什么意思?首先快速回顾一下 rr
的工作原理:它会记录内核(或任何其他非确定性来源)对进程内存所做的任何修改。然后,在这些修改之间,它依赖于处理器的确定性来生成位精确相同的输出状态,前提是输入内存状态相同。在每个事件中,rr
还记录完整的传入和传出寄存器状态。传入寄存器状态并非严格要求(因为它将从之前的输入状态确定性计算得出),但它对于某些分析目的很有用,并且允许额外检查回放是否正在正确进行。
现在,发生的事情是,rr
预期会得到一个确定性 ((det)
) 段错误(即由指令执行引起的段错误,而不是由其他进程(例如,使用 kill -SIGSEGV
)异步发送的段错误)。但是,我们并没有看到这个段错误,而是到了另一个地方:but instead at 'write'
。在回放过程中,rr
发现自己被告知要执行 write
系统调用,而不是看到崩溃。我们已经看到了程序的输出行为(基本上每个循环执行一次写入),因此可以合理地推测,在回放过程中,它反而成功完成了循环,并到达了下一个 write
系统调用(这将是 rr
监督程序从被跟踪进程重新获得控制权的第一个执行点)。用 rr
的行话来说,我们称之为“偏差”:回放过程中采用的执行路径与记录过程中实际发生的执行路径不同的情况。偏差通常是由 rr
错误引起的,导致未观察到的内存修改(例如,内核内存修改行为模型不完善),但也可能存在更微妙的问题(例如,CPU 微体系结构错误)。因此,我开始着手调试这种偏差。有一些常见的偏差候选者是我首先寻找的。按照优先级顺序,它们是
可能在 rr
中测试不足的异常系统调用,因此 rr
对内核行为的模型可能不完整。
可能在静默修改用户空间内存的异常或专有设备/设备驱动程序/内核扩展(绝对不应该这样做,而且可能存在安全问题,但令人惊讶的是,许多不良驱动程序确实会这样做)。
可能以前没有经过测试的异常 CPU 或微体系结构(例如,已知旧的 Silvermont Atom 芯片存在此类微体系结构错误)。
但是,查看原始跟踪(使用 rr dump
获得的事件日志)并查询硬件详细信息,没有发现任何特别可疑之处,因此我开始分析跟踪本身。在上面的列表中,我剪掉了段错误之前的事件,但在这里列出它们以供参考,这样我们就可以谈论一下它们
{
real_time:38257.562367 global_time:51903, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:7760, ticks:143983372177
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x4 rsi:0x7f046a9a0338 rdi:0xd rbp:0xd rsp:0x681ffe10 r8:0x0 r9:0x7f0490095f90 r10:0x7f0475ad7bb0 r11:0x246 r12:0x0 r13:0x7f046a9a0338 r14:0x4 r15:0x7f046a9a0338 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f0499f49240 gs_base:0x0
}
{
real_time:38257.562369 global_time:51904, event:`SYSCALLBUF_RESET' tid:7760, ticks:143983372177
}
{
real_time:38257.562395 global_time:51905, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:7760, ticks:143983372177
rax:0x4 rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x4 rsi:0x7f046a9a0338 rdi:0xd rbp:0xd rsp:0x681ffe10 r8:0x0 r9:0x7f0490095f90 r10:0x7f0475ad7bb0 r11:0x246 r12:0x0 r13:0x7f046a9a0338 r14:0x4 r15:0x7f046a9a0338 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f0499f49240 gs_base:0x0
}
{
real_time:38257.562444 global_time:51906, event:`SYSCALLBUF_FLUSH' tid:7760, ticks:143983372944
{
real_time:38257.562448 global_time:51907, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:7760, ticks:143983372944
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f047ba39840 rdi:0xd rbp:0xd rsp:0x681ffe10 r8:0x0 r9:0x7f0490095f90 r10:0x7f0475ad7bb0 r11:0x246 r12:0x0 r13:0x7f047ba39840 r14:0x1 r15:0x7f047ba39840 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f0499f49240 gs_base:0x0
}
{
real_time:38257.562449 global_time:51908, event:`SYSCALLBUF_RESET' tid:7760, ticks:143983372944
}
{
real_time:38257.562475 global_time:51909, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:7760, ticks:143983372944
rax:0x1 rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f047ba39840 rdi:0xd rbp:0xd rsp:0x681ffe10 r8:0x0 r9:0x7f0490095f90 r10:0x7f0475ad7bb0 r11:0x246 r12:0x0 r13:0x7f047ba39840 r14:0x1 r15:0x7f047ba39840 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f0499f49240 gs_base:0x0
}
{
real_time:38257.585211 global_time:51910, event:`SYSCALLBUF_FLUSH' tid:7760, ticks:143998759917
}
{
real_time:38257.585221 global_time:51911, event:`SIGNAL: SIGSEGV(det)' tid:7760, ticks:143998759917
rax:0x436487c0 rbx:0x7f0490b74330 rcx:0xb479 rdx:0x435f2dc8 rsi:0x435f2dc0 rdi:0x435f2dc0 rbp:0x7fff6ca71250 rsp:0x7fff
6ca71230 r8:0x1 r9:0x7f0490b74330 r10:0x1007f0490b784d0 r11:0x4364d190 r12:0x0 r13:0x7f0490b88c70 r14:0x7f047daf36d0 r1
5:0xb479 rip:0x7f049e2ba8e3 eflags:0x10287 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_b
ase:0x7f0499f49240 gs_base:0x0
}
让我们从解释一些术语开始。虽然 rr
确实跟踪经过的挂钟时间 (real_time
,如上所示),但这种“时间”的概念完全是信息性的。它不是将时间划分为小时、秒和分钟,而是将时间划分为 events
、tid
(内核为每个任务分配的线程 ID;在 ID 重复使用的情况下,会计算一个额外的 serial
计数器,但不会保存)和 ticks
。events
是进程记录树中对导致进程内存外部修改的事件(例如,系统调用或信号)的全局线性排序,而 ticks
是对每个任务(认为是每个线程或每个 tid
)的向前进度度量。确切的度量标准取决于 CPU 微体系结构和可用的测量硬件。有效选择例如是 已执行指令数
或 已执行条件分支数
,但理论上,只要能够唯一标识执行中的特定点(例如,与寄存器状态结合使用),任何稳定的、可靠的向前进度计数就足够了(例如,已执行指令数可以很容易地起作用,而已执行条件分支在大多数情况下可以起作用,因为该计数与指令指针结合使用形成一个单调递增的配对)。
好的,所以查看事件日志,我们基本上看到了我们已经知道的:它执行了很多 write 系统调用(以打印循环编号),大量计算(1430 亿个条件分支),最终它应该崩溃。我们还知道,在事件 51909
(最后一个写入之前应该是段错误),回放中的事情还基本正常。我们不能说内存内容是否已经发生偏差,但至少我们知道,寄存器状态和执行的指令数与记录过程中发生的情况位精确相同。
调查偏差的一种好方法是在怀疑偏差发生之前在内存中四处查看,并查看哪些内存修改可能造成了偏差。通常,我只是转到之前的事件,但在我们的例子中,最后两个事件之间有 1500 万个条件分支,这距离相当远。相反,我修改了一个 快速命令,它允许我们直接跳转到特定滴答计数。在本例中,我任意选择了 143998750000
,大约是在记录时段错误发生之前 10000 个滴答。让我们去那里看看
$ rr replay -g 51908 --serve-files .
[snip]
0x0000000070000002 in ?? ()
(rr) when
Current event: 51909
(rr) when-ticks
Current tick: 143983372944
(rr) seek-ticks 143998750000
(rr) when-ticks
Current tick: 143998750000
(rr) when
Current event: 51911
(rr)
跟踪告诉我们,它预计段错误将发生在地址 rip:0x7f049e2ba8e3
处,所以让我们看看那里
(rr) disas 0x7f049e2ba8e3
Dump of assembler code for function jl_apply_tuple_type:
[snip]
0x00007f049e2ba8e0 <+96>: mov (%rax),%r10
0x00007f049e2ba8e3 <+99>: mov -0x8(%r10),%r9
[snip]
好的,所以这是一个从 r10
加载的。幸运的是,r10
在跟踪中被记录下来:r10:0x1007f0490b784d0
。经验丰富的调试人员会很快认出这个指针太宽了。具体来说,通常,对于用户空间指针,高字节为 0x00
,但这里为 0x01
(gdb 会删除前导零)。有时,未使用的指针位用于存储额外信息,但至少 julia 本身只使用未使用的低位位来实现此目的,而不是高位位。也就是说,此跟踪包含大量外部本机库(包括一个完整的 python 环境),因此某些外部库可能使用了此类指针标记技术。让我们做进一步的调查。我尝试做的第一件事是查看高位手动清除后的指针,以查看它是否是一个有效的 Julia 对象,或者只是一个不知何故从
(rr) p jl_(0x7f0490b784d0)
Array{Any, 1}
$1 = void
(rr)
好的,所以这实际上是指向一个 julia 对象(类型 Array{Any, 1}
)的指针,其高位被神秘地设置了。对于垃圾数据来说,看起来像有效的指针并不意外。垃圾数据通常来自未初始化的内存重复使用,如果以前在该内存位置存在此类指针,则肯定可能会获取有效指针的一部分。为了进一步缩小范围,让我们收集更多信息。我们距离段错误应该发生的位置还有 10000 个滴答,但让我们看看当前进程中正在发生什么
(rr) bt
#0 type_hash (kj=<optimized out>, failed=failed@entry=0x7fff6ca7102c)
at /buildworker/worker/package_linux64/build/src/jltypes.c:1003
#1 0x00007f049e2b5856 in typekey_hash (nofail=0, n=<optimized out>, key=0x435f2dc8,
tn=0x7f0490b99000 <jl_system_image_data+150848>) at /buildworker/worker/package_linux64/build/src/jltypes.c:1013
#2 lookup_type (tn=0x7f0490b99000 <jl_system_image_data+150848>, key=0x435f2dc8, n=46200)
at /buildworker/worker/package_linux64/build/src/jltypes.c:623
#3 0x00007f049e2b9655 in inst_datatype_inner (dt=<optimized out>, p=<optimized out>, p@entry=0x435f2dc0,
iparams=iparams@entry=0x435f2dc8, ntp=<optimized out>, cacheable=cacheable@entry=1, stack=stack@entry=0x0,
env=0x0) at /buildworker/worker/package_linux64/build/src/jltypes.c:1158
#4 0x00007f049e2bbefc in jl_inst_concrete_tupletype (p=p@entry=0x435f2dc0)
at /buildworker/worker/package_linux64/build/src/jltypes.c:1399
#5 0x00007f049e2d856c in jl_f_tuple (F=<optimized out>, args=0x42f54590, nargs=46200)
at /buildworker/worker/package_linux64/build/src/builtins.c:729
(rr) p jl_(((jl_value_t**)0x42f54590)[0])
Array{Any, (2,)}[
Array{Float64, (1,)}[9.3902],
0.00922841]
$2 = void
(rr) p jl_(((jl_value_t**)0x42f54590)[1])
Array{Any, (2,)}[
Array{Float64, (1,)}[13.5571],
0.01415]
$3 = void
(rr) p jl_(((jl_value_t**)0x42f54590)[20000])
Array{Any, (2,)}[
Array{Float64, (1,)}[58.965],
1.40691]
$4 = void
好的,所以我们目前正在尝试分配一个包含 42600
个元素的元组,所有元素都是 2 元素数组(类型为 Array{Any, 1}
)。由于 10000 小于 42600
,因此它很可能也是我们在记录时崩溃的运算(还记得崩溃位置是 jl_apply_tuple
吗?它是新元组类型分配的一部分)。但是,我们还没有完全解释清楚。如果我们在崩溃位置设置断点
(rr) b *0x7f049e2ba8e3
Breakpoint 1 at 0x7f049e2ba8e3: file /buildworker/worker/package_linux64/build/src/julia.h, line 1222.
(rr) c
Continuing.
[FATAL /home/keno/rr/src/ReplaySession.cc:636:check_pending_sig()]
我们只是再次得到偏差,所以它实际上并没有到达这个执行点,而是在更早的时候就发生了偏差(但恰好在那里崩溃了)。我们可以找到发生的事情吗?回顾汇编代码,我们看到 r10
是从 rax
加载的,我们也有:rax:0x436487c0
。那里现在是什么(记住我们距离崩溃还有 10000 个滴答)?
(rr) p *(void**)0x436487c0
$5 = (void *) 0x7f0490b784d0
(rr) p jl_($5)
Array{Any, 1}
$6 = void
这正是我们在崩溃期间看到的指针,但高位没有设置。接下来我们可能想问的是,对这个内存位置发生了哪些(记录的)更改
(rr) awatch *(void**)0x436487c0
Hardware access (read/write) watchpoint 1: *(void**)0x436487c0
(rr) c
Continuing.
Thread 1 hit Hardware access (read/write) watchpoint 1: *(void**)0x436487c0
Value = (void *) 0x7f0490b784d0 <jl_system_image_data+16912>
0x00007f049e2b584e in typekey_hash (nofail=0, n=<optimized out>, key=0x435f2dc8,
tn=0x7f0490b99000 <jl_system_image_data+150848>) at /buildworker/worker/package_linux64/build/src/jltypes.c:1013
1013 /buildworker/worker/package_linux64/build/src/jltypes.c: No such file or directory.
typekey_eq (key=key@entry=0x435f2dc8, n=n@entry=46200, tt=<optimized out>, tt=<optimized out>)
at /buildworker/worker/package_linux64/build/src/jltypes.c:560
560 in /buildworker/worker/package_linux64/build/src/jltypes.c
(rr)
Continuing.
[FATAL /home/keno/rr/src/ReplaySession.cc:636:check_pending_sig()]
(task 19490 (rec:7760) at time 51911)
-> Assertion `false' failed to hold. Replaying `SIGNAL: SIGSEGV(det)': expecting tracee signal or trap, but instead at `write' (ticks: 144040993972)
我们看到类型缓存中有一些访问,然后是偏差。反过来呢?(注意,偏差使 rr
进程崩溃,因此我们必须首先回到相同的执行点——幸运的是,由于这是一个记录,所以一切都稳定,因此我们可以直接 seek-ticks
返回到之前的位置)。
(rr) awatch *(void**)0x436487c0
Hardware access (read/write) watchpoint 1: *(void**)0x436487c0
(rr) rc
Continuing.
Thread 1 hit Hardware access (read/write) watchpoint 1: *(void**)0x436487c0
Old value = (void *) 0x7f0490b784d0 <jl_system_image_data+16912>
New value = (void *) 0x0
jl_svecset (x=0x7f0490b784d0 <jl_system_image_data+16912>, i=<optimized out>, t=<optimized out>)
at /buildworker/worker/package_linux64/build/src/julia.h:840
840 /buildworker/worker/package_linux64/build/src/julia.h: No such file or directory.
(rr) bt
#0 jl_svecset (x=0x7f0490b784d0 <jl_system_image_data+16912>, i=<optimized out>, t=<optimized out>)
at /buildworker/worker/package_linux64/build/src/julia.h:840
#1 jl_f_tuple (F=<optimized out>, args=0x42f54590, nargs=46200)
at /buildworker/worker/package_linux64/build/src/builtins.c:728
为了便于参考,以下是我们当前所在的 Julia 1.5 分支中的相关函数
JL_CALLABLE(jl_f_tuple)
{
[snip]
}
else {
jl_svec_t *types = jl_alloc_svec_uninit(nargs);
JL_GC_PUSH1(&types);
for (i = 0; i < nargs; i++)
jl_svecset(types, i, jl_typeof(args[i]));
tt = jl_inst_concrete_tupletype(types);
[snip]
}
代码相当简单:它只是遍历传入的tuple
参数,并获取每个参数的类型(以便它可以创建一个与参数匹配的适当元组类型)。显然,我们刚刚计算了传入数组之一的类型,并将其设置到svec中。我们可以找出我们刚刚计算其类型的数组
(rr) disas
0x00007f049e2d8530 <+240>: mov -0x8(%r12,%r13,1),%rax
0x00007f049e2d8535 <+245>: mov -0x8(%rax),%rax
0x00007f049e2d8539 <+249>: and $0xfffffffffffffff0,%rax
0x00007f049e2d853d <+253>: test %rax,%rax
0x00007f049e2d8540 <+256>: mov %rax,(%r14,%r13,1)
=> 0x00007f049e2d8544 <+260>: je 0x7f049e2d8553 <jl_f_tuple+275>
(rr) rsi
(rr) rsi
(rr) rsi
(rr) rsi
=> 0x00007f049e2d8535 <+245>: mov -0x8(%rax),%rax
0x00007f049e2d8539 <+249>: and $0xfffffffffffffff0,%rax
0x00007f049e2d853d <+253>: test %rax,%rax
0x00007f049e2d8540 <+256>: mov %rax,(%r14,%r13,1)
0x00007f049e2d8544 <+260>: je 0x7f049e2d8553 <jl_f_tuple+275>
(rr) p /x $rax
$5 = 0x7f0478f5aa10
(rr) p jl_($rax)
Array{Any, (2,)}[
Array{Float64, (1,)}[43.1183],
0.86978]
$6 = void
我们也可以观察这个数组的类型指针,看看是否有任何意外情况会影响它
(rr) p &((uint64_t**)0x7f0478f5aa10)[-1]
$9 = (void **) 0x7f0478f5aa08
(rr) p jl_((uint64_t)*$9 & ~0x3)
Array{Any, 1}
(注意,我们屏蔽了低位,正如上面提到的,julia
确实使用了这些位 - 并且如果我们查看汇编代码,代码会执行相同的操作)。
回顾一下:我们找到了一个可疑的指针0x1007f0490b784d0
,注意到它从0x436487c0
加载,然后我们发现它之前是通过从某个数组对象加载类型指针来设置的。然后我们发现,该数组对象的地址是0x7f0478f5aa10
,这意味着它的类型指针位于0x7f0478f5aa08
(该值最终会传播到崩溃位置)。我们进一步发现,至少在回放中,0x7f0478f5aa08
处的值正确指向Array{Any, 1}
类型,没有任何可疑的高位翻转。
让我们进一步查看对0x7f0478f5aa08
处此类型标签的所有内存访问(按时间倒序),看看是否发现任何可疑情况
(rr) awatch *0x7f0478f5aa08
Hardware access (read/write) watchpoint 6: *0x7f0478f5aa08
(rr) command 6
when
when-ticks
c
end
(rr) rc
Continuing.
(rr) bt
Thread 1 hit Hardware access (read/write) watchpoint 6: *0x7f0478f5aa08
Value = -1867021101
0x00007f049e2d8535 in jl_f_tuple (F=<optimized out>, args=0x42f54590, nargs=46200)
at /buildworker/worker/package_linux64/build/src/builtins.c:728
728 /buildworker/worker/package_linux64/build/src/builtins.c: No such file or directory.
#0 0x00007f049e2d8535 in jl_f_tuple (F=<optimized out>, args=0x42f54590, nargs=46200)
at /buildworker/worker/package_linux64/build/src/builtins.c:728
[snip]
Current event: 51911
Current tick: 143998538325
Thread 1 hit Hardware access (read/write) watchpoint 6: *0x7f0478f5aa08
Value = -1867021101
jl_isa (x=0x7f0478f5aa10, t=t@entry=0x7f0490b784d0 <jl_system_image_data+16912>)
at /buildworker/worker/package_linux64/build/src/subtype.c:2064
2064 /buildworker/worker/package_linux64/build/src/subtype.c: No such file or directory.
#0 jl_isa (x=0x7f0478f5aa10, t=t@entry=0x7f0490b784d0 <jl_system_image_data+16912>)
at /buildworker/worker/package_linux64/build/src/subtype.c:2064
#1 0x00007f049e2cd91c in sig_match_simple (lensig=<optimized out>, va=1, sig=<optimized out>, n=46201,
args=0x42f54590, arg1=0x7f0492cdab30 <jl_system_image_data+35022960>)
at /buildworker/worker/package_linux64/build/src/typemap.c:173
#2 jl_typemap_entry_assoc_exact (ml=<optimized out>, arg1=arg1@entry=0x7f0492cdab30 <jl_system_image_data+35022960>,
args=args@entry=0x42f54590, n=n@entry=46201, world=world@entry=27833)
at /buildworker/worker/package_linux64/build/src/typemap.c:675
#3 0x00007f049e2c914c in jl_typemap_assoc_exact (world=27833, offs=<optimized out>, n=46201, args=0x42f54590,
arg1=0x7f0492cdab30 <jl_system_image_data+35022960>, ml_or_cache=<optimized out>)
at /buildworker/worker/package_linux64/build/src/julia_internal.h:1075
#4 jl_lookup_generic_ (world=27833, callsite=<optimized out>, nargs=46201, args=0x42f54590,
F=0x7f0492cdab30 <jl_system_image_data+35022960>) at /buildworker/worker/package_linux64/build/src/gf.c:2342
#5 jl_apply_generic (F=0x7f0492cdab30 <jl_system_image_data+35022960>, args=args@entry=0x42f54590, nargs=46200)
at /buildworker/worker/package_linux64/build/src/gf.c:2394
#6 0x00007f049e2d8f04 in jl_apply (nargs=<optimized out>, args=0x42f54588)
at /buildworker/worker/package_linux64/build/src/julia.h:1690
#7 do_apply (args=<optimized out>, nargs=<optimized out>, iterate=0x7f0493df96f0 <jl_system_image_data+52974640>,
F=<optimized out>) at /buildworker/worker/package_linux64/build/src/builtins.c:655
[snip]
Current event: 51911
Current tick: 143998396840
Thread 1 hit Hardware access (read/write) watchpoint 6: *0x7f0478f5aa08
Value = -1867021101
jl_isa (x=0x7f0478f5aa10, t=t@entry=0x7f0490b784d0 <jl_system_image_data+16912>)
at /buildworker/worker/package_linux64/build/src/subtype.c:2064
2064 in /buildworker/worker/package_linux64/build/src/subtype.c
#0 jl_isa (x=0x7f0478f5aa10, t=t@entry=0x7f0490b784d0 <jl_system_image_data+16912>)
at /buildworker/worker/package_linux64/build/src/subtype.c:2064
#1 0x00007f049e2cd91c in sig_match_simple (lensig=<optimized out>, va=1, sig=<optimized out>, n=46201,
args=0x52409d10, arg1=0x7f0492cdab30 <jl_system_image_data+35022960>)
at /buildworker/worker/package_linux64/build/src/typemap.c:173
Current event: 51911
Current tick: 143984580058
Thread 1 hit Hardware access (read/write) watchpoint 6: *0x7f0478f5aa08
Value = -1867021101
0x00007f049e2d8535 in jl_f_tuple (F=<optimized out>, args=0x4179f790, nargs=46100)
at /buildworker/worker/package_linux64/build/src/builtins.c:728
728 /buildworker/worker/package_linux64/build/src/builtins.c: No such file or directory.
#0 0x00007f049e2d8535 in jl_f_tuple (F=<optimized out>, args=0x4179f790, nargs=46100)
at /buildworker/worker/package_linux64/build/src/builtins.c:728
[snip]
Current event: 51839
Current tick: 143756648123
这给了我们很多信息。基本上,我们查看了几次类型标签,试图在事件 51911 期间分配元组,但除此之外,从事件 51839 开始,没有任何东西读取或写入它。我们还知道,在事件 51839 期间,它一定仍然具有正确的值,否则我们会在那里看到崩溃。此时,我们基本上已经了解了完整的事件经过
在事件 51839 之后,某个时候,数组本身的类型标签(位于内存位置0x7f0478f5aa08
)或类型指针在类型 svec 中的值(位于内存位置0x436487c0
)的高字节的最低位发生了翻转。这会导致类型缓存查找(我们看到的type_hash
函数)失败。结果,程序尝试为此元组分配一个新的类型,然后崩溃,因为它试图实际查看被破坏的类型指针。观察到的段错误随之产生。在回放期间,该位不会翻转,类型缓存查找成功,程序正常运行。
什么问题会导致这种位翻转?我们已经检查了像奇怪的内核或奇怪的设备这样的明显解释,这留下了更模糊的原因:CPU 微架构问题(现代 CPU 从它们的 ISA 到其他内部表示基本上是 JIT - 这偶尔会出现错误 - 只需在英特尔勘误表中查找“复杂微架构条件”这个短语),有故障的内存,宇宙射线或类似问题。特别是单比特翻转通常指向硬件问题,因为软件倾向于至少以 8 位单元覆盖(除非它执行读-更新-写循环,例如由于错误的指针,但只是作为实际观察,软件引起的差异倾向于主要是更大单元大小的错误写入)。关于这个问题,我要求提供两项额外的证据:同一程序的另一个记录以及在原始机器上的回放尝试。
如果回放也在原始机器上失败(确实如此),这表明存在微架构问题(当然不能保证,但至少执行完全相同的指令序列有重新触发此类问题的可能性)。至于第二个记录,它以完全相同的方式失败:某个指针高字节的低位发生翻转。这强烈暗示了有故障的内存,因为故障发生在两个运行中的同一比特位置,如果内存单元的特定比特发生退化(例如,以这样一种方式,电荷随着时间的推移泄漏到其中,或者该比特所在的数据线存在某些损坏),可能会发生这种情况。特别是,如果问题是由辐射引起的(也许用户的办公室碰巧位于物理系聚变反应堆之上),我们不会期望偏向任何特定的比特索引。
在令我满意的排除了这些其他问题后,我关闭了报告,并附上我的结论,并鼓励用户在其机器上运行 memtest。事实上,第二天我收到了以下屏幕截图
报告的错误正是我们预期的:内存位置的高字节(第二高的十六进制数)的低位发生 0->1 位翻转。由于所有失败的内存地址都设置了0x5c
地址位,因此我们可以假设发生翻转的位是数组本身的位(其地址以0x8
结尾,即高双字位于0xc
处),而不是类型标签在 svec 中的副本(其地址以0x0
结尾),但没有一个检测到的错误完全匹配我们识别出的两个潜在目标地址之一的地址偏移量(尽管屏幕截图中的测试并未运行完成,因此它可能已经找到一个)。对错误的进一步分析将需要物理访问 DRAM,也许还需要电子显微镜,但我们不必走到这一步,因为我们已经确定这不是 Julia 的错误,用户可能将更换他们的机器。
经过大约一个小时的工作(再加上 2-3 个小时来添加seek-to-ticks
功能,编写、测试、上游等),我们设法远程且确凿地诊断出报告的崩溃是由用户机器上的有故障的内存引起的。即使rr
跟踪不包含崩溃的真正原因,它仍然是一个分析此问题的宝贵工具。记录中缺少的错误位翻转已经排除了 99% 的崩溃可能情况,并且对跟踪的仔细分析提供了足够的线索来消除大多数剩余情况。引用夏洛克·福尔摩斯的话
当你排除了不可能的事物,无论剩下的是什么,无论多么不可思议,它都必须是真相。
没有rr
,人们可能会倾向于将无法解释的崩溃归咎于不良硬件、宇宙射线或地板下居住的妖精。在这里,我们能够相当令人信服地得出结论,问题确实是内存故障。我喜欢说rr
将调试问题变成了数据分析问题,在这里,就像经常发生的那样,最具洞察力的部分是弄清楚缺少哪些数据。