rr: "replay diverged" assertion replaying an rr recording of QEMU
@khuey is already working on this.
Since Jul 24, 2020.
- Dominant language
- C++
- Stars
- 10.7k
- Forks
- 662
- Avg merge
- 2d 3h
- Merged PRs (30d)
- 2
Description
Using 'rr replay' (with rr built from git, commit 4a4c54b31732d84942, but I also saw this with the year-old 93dd74aeb2b71, so it's not a recent regression) on a recording of a QEMU run, rr crashed like this (reproducibly):
$ ~/src/rr-obj64/bin/rr replay
GNU gdb (Ubuntu 8.1-0ubuntu3.2) 8.1.0.20180409-git
[...]
0x00007f419fb67090 in _start () from /lib64/ld-linux-x86-64.so.2
(rr) c
Continuing.
*** Booting Zephyr OS build zephyr-v2.3.0-1183-ge5628ad0faf3 ***
Hello World! qemu_cortex_a53
[New Thread 16808.16809]
[New Thread 16808.16810]
Thread 1 received signal SIGINT, Interrupt.
__lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
135 ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: No such file or directory.
(rr) c
Continuing.
[ERROR /home/petmay01/src/rr/src/ReplaySession.cc:716:guard_overshoot()] Replay diverged; target registers mismatched:
[FATAL /home/petmay01/src/rr/src/ReplaySession.cc:720:guard_overshoot()]
(task 17272 (rec:16810) at time 10502)
-> Assertion `false' failed to hold. overshot target ticks=1471552604 by 82
Tail of trace dump:
{
real_time:4253978.806406 global_time:10482, event:`SYSCALL: readlinkat' (state:EXITING_SYSCALL) tid:16810, ticks:1458409520
rax:0x1b rbx:0x9 rcx:0xffffffffffffffff rdx:0x7f417e584db0 rsi:0x7f417e584d40 rdi:0xffffffffffffffff rbp
:0x7f417e584db0 rsp:0x7f417e584cb0 r8:0x0 r9:0x0 r10:0x1000 r11:0x246 r12:0x7f417e585fa0 r13:0x7f417e384
ffe r14:0x55ba48ec6c8e r15:0x0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x10b fs_base:0x7f417ed86700 gs_base:0x0
{ tid:16810, addr:0x7f417e584db0, length:0x1b }
}
{
real_time:4253978.828618 global_time:10483, event:`SYSCALLBUF_FLUSH' tid:16810, ticks:1461590793
{ syscall:'fstat', ret:0x0, size:0xa0 }
{ syscall:'read', ret:0x149, size:0x159 }
{ syscall:'read', ret:0x0, size:0x10 }
[...]
{
real_time:4253978.899762 global_time:10503, event:`EXIT' tid:16810, ticks:1471552604
{ tid:16810, addr:0x7f417ed869d0, length:0x4 }
}
=== Start rr backtrace:
/home/petmay01/src/rr-obj64/bin/rr(_ZN2rr13dump_rr_stackEv+0x44)[0x55adc3e97e94]
/home/petmay01/src/rr-obj64/bin/rr(_ZN2rr9GdbServer15emergency_debugEPNS_4TaskE+0x1a2)[0x55adc3cdce14]
/home/petmay01/src/rr-obj64/bin/rr(+0x36bda0)[0x55adc3d0eda0]
/home/petmay01/src/rr-obj64/bin/rr(_ZN2rr21EmergencyDebugOstreamD1Ev+0x62)[0x55adc3d0effa]
/home/petmay01/src/rr-obj64/bin/rr(+0x44c183)[0x55adc3def183]
/home/petmay01/src/rr-obj64/bin/rr(_ZN2rr13ReplaySession20emulate_async_signalEPNS_10ReplayTaskERKNS0_15StepConstraintsEl+0xcc8)[0x55adc3df042c]
/home/petmay01/src/rr-obj64/bin/rr(_ZN2rr13ReplaySession18try_one_trace_stepEPNS_10ReplayTaskERKNS0_15StepConstraintsE+0x158)[0x55adc3df2c48]
/home/petmay01/src/rr-obj64/bin/rr(_ZN2rr13ReplaySession11replay_stepERKNS0_15StepConstraintsE+0x169)[0x55adc3df4089]
/home/petmay01/src/rr-obj64/bin/rr(_ZN2rr14ReplayTimeline19replay_step_forwardENS_10RunCommandEl+0x106)[0x55adc3e10194]
/home/petmay01/src/rr-obj64/bin/rr(_ZN2rr9GdbServer14debug_one_stepERNS_10GdbRequestE+0x59b)[0x55adc3cda0e1]
/home/petmay01/src/rr-obj64/bin/rr(_ZN2rr9GdbServer12serve_replayERKNS0_15ConnectionFlagsE+0x548)[0x55adc3cdbf4a]
/home/petmay01/src/rr-obj64/bin/rr(+0x446dc8)[0x55adc3de9dc8]
/home/petmay01/src/rr-obj64/bin/rr(_ZN2rr13ReplayCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0x400)[0x55adc3dea806]
/home/petmay01/src/rr-obj64/bin/rr(main+0x21b)[0x55adc3eb381a]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7)[0x7fafd8602b97]
/home/petmay01/src/rr-obj64/bin/rr(_start+0x2a)[0x55adc3c412ea]
=== End rr backtrace
Launch gdb with
gdb '-l' '10000' '-ex' 'set sysroot /' '-ex' 'target extended-remote 127.0.0.1:17272' /home/petmay01/.local/share/rr/qemu-system-aarch64-2/mmap_hardlink_3_qemu-system-aarch64
I'll attach a script of the session produced with "script" (which will have the parts that I've elided with [...] in the transcript above.)
Might be relevant: I ended the 'rr record' session by sending a SIGKILL to the process-under-debug (the bug I'm trying to investigate is why less aggressive methods of killing QEMU aren't working in this particular situation :-)). I think 'rr replay' should be able to cope with that, though.
Aside: rr produced so much output to the terminal in the "tail of trace dump" section that the part that told me what had actually happened ended up completely out of the screen session's scrollback buffer -- it would be more useful to dump debug output of this volume to a file and just quote the filename in the terminal output, I think.
rr.script.txt
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Assessment
This issue has not been assessed yet.