FATAL src/ReplaySession.cc:1180:check_ticks_consistency()

[tysmith]

This was originally detected recording replaying with rr commit d4127932.

I was able to trigger the issue with the recording with the latest commit.

[FATAL src/ReplaySession.cc:1180:check_ticks_consistency()]
 (task 2849748 (rec:2844373) at time 169820)
 -> Assertion `ticks_now == trace_ticks' failed to hold. ticks mismatch for 'SYSCALL: futex'; expected 186277, got 186214
Tail of trace dump:
{
  real_time:25672139.219905 global_time:169800, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:2843695, ticks:21390887
rax:0xffffffffffffffda rbx:0x7f62cb08efa0 rcx:0xffffffffffffffff rdx:0xc9 rsi:0x7f62cb88af10 rdi:0x2 rbp:0x7f62cb08efa0 rsp:0x7f62cb08ed40 r8:0x0 r9:0xc9 r10:0x7f62d3ae5622 r11:0x246 r12:0x7f62cb88af10 r13:0xc9 r14:0x0 r15:0x7f62fb4088a0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f62cb88f700 gs_base:0x0
}
{
  real_time:25672139.219911 global_time:169801, event:`SYSCALLBUF_RESET' tid:2843695, ticks:21390887
}
{
  real_time:25672139.219955 global_time:169802, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:2843695, ticks:21390887
rax:0xc9 rbx:0x7f62cb08efa0 rcx:0xffffffffffffffff rdx:0xc9 rsi:0x7f62cb88af10 rdi:0x2 rbp:0x7f62cb08efa0 rsp:0x7f62cb08ed40 r8:0x0 r9:0xc9 r10:0x7f62d3ae5622 r11:0x246 r12:0x7f62cb88af10 r13:0xc9 r14:0x0 r15:0x7f62fb4088a0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f62cb88f700 gs_base:0x0
}
{
  real_time:25672139.220095 global_time:169803, event:`SYSCALLBUF_FLUSH' tid:2843695, ticks:21403469
  { syscall:'getpid', ret:0x2b6421, size:0x10 }
}
{
  real_time:25672139.220098 global_time:169804, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:2843695, ticks:21403469
rax:0xffffffffffffffda rbx:0x7f62cb08efa0 rcx:0xffffffffffffffff rdx:0xc9 rsi:0x7f62cb88af10 rdi:0x2 rbp:0x7f62cb08efa0 rsp:0x7f62cb08ed40 r8:0x0 r9:0xc9 r10:0x7f62d3ae5622 r11:0x246 r12:0x7f62cb88af10 r13:0xc9 r14:0x0 r15:0x7f62fb4088a0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f62cb88f700 gs_base:0x0
}
{
  real_time:25672139.220099 global_time:169805, event:`SYSCALLBUF_RESET' tid:2843695, ticks:21403469
}
{
  real_time:25672139.220143 global_time:169806, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:2843695, ticks:21403469
rax:0xc9 rbx:0x7f62cb08efa0 rcx:0xffffffffffffffff rdx:0xc9 rsi:0x7f62cb88af10 rdi:0x2 rbp:0x7f62cb08efa0 rsp:0x7f62cb08ed40 r8:0x0 r9:0xc9 r10:0x7f62d3ae5622 r11:0x246 r12:0x7f62cb88af10 r13:0xc9 r14:0x0 r15:0x7f62fb4088a0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f62cb88f700 gs_base:0x0
}
{
  real_time:25672139.220296 global_time:169807, event:`SYSCALLBUF_FLUSH' tid:2843695, ticks:21416382
  { syscall:'futex', ret:0x1, size:0x14 }
  { syscall:'getpid', ret:0x2b6421, size:0x10 }
}
{
  real_time:25672139.220298 global_time:169808, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:2843695, ticks:21416382
rax:0xffffffffffffffda rbx:0x7f62cb08efa0 rcx:0xffffffffffffffff rdx:0xc9 rsi:0x7f62cb88af10 rdi:0x2 rbp:0x7f62cb08efa0 rsp:0x7f62cb08ed40 r8:0x0 r9:0xc9 r10:0x7f62d3ae5622 r11:0x246 r12:0x7f62cb88af10 r13:0xc9 r14:0x0 r15:0x7f62fb4088a0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f62cb88f700 gs_base:0x0
}
{
  real_time:25672139.220300 global_time:169809, event:`SYSCALLBUF_RESET' tid:2843695, ticks:21416382
}
{
  real_time:25672139.220344 global_time:169810, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:2843695, ticks:21416382
rax:0xc9 rbx:0x7f62cb08efa0 rcx:0xffffffffffffffff rdx:0xc9 rsi:0x7f62cb88af10 rdi:0x2 rbp:0x7f62cb08efa0 rsp:0x7f62cb08ed40 r8:0x0 r9:0xc9 r10:0x7f62d3ae5622 r11:0x246 r12:0x7f62cb88af10 r13:0xc9 r14:0x0 r15:0x7f62fb4088a0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f62cb88f700 gs_base:0x0
}
{
  real_time:25672139.220486 global_time:169811, event:`SYSCALLBUF_FLUSH' tid:2843695, ticks:21429098
  { syscall:'getpid', ret:0x2b6421, size:0x10 }
}
{
  real_time:25672139.220489 global_time:169812, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:2843695, ticks:21429098
rax:0xffffffffffffffda rbx:0x7f62cb08efa0 rcx:0xffffffffffffffff rdx:0xc9 rsi:0x7f62cb88af10 rdi:0x2 rbp:0x7f62cb08efa0 rsp:0x7f62cb08ed40 r8:0x0 r9:0xc9 r10:0x7f62d3ae5622 r11:0x246 r12:0x7f62cb88af10 r13:0xc9 r14:0x0 r15:0x7f62fb4088a0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f62cb88f700 gs_base:0x0
}
{
  real_time:25672139.220491 global_time:169813, event:`SYSCALLBUF_RESET' tid:2843695, ticks:21429098
}
{
  real_time:25672139.220544 global_time:169814, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:2843695, ticks:21429098
rax:0xc9 rbx:0x7f62cb08efa0 rcx:0xffffffffffffffff rdx:0xc9 rsi:0x7f62cb88af10 rdi:0x2 rbp:0x7f62cb08efa0 rsp:0x7f62cb08ed40 r8:0x0 r9:0xc9 r10:0x7f62d3ae5622 r11:0x246 r12:0x7f62cb88af10 r13:0xc9 r14:0x0 r15:0x7f62fb4088a0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f62cb88f700 gs_base:0x0
}
{
  real_time:25672139.220645 global_time:169815, event:`SYSCALLBUF_FLUSH' tid:2843695, ticks:21430211
  { syscall:'futex', ret:0x1, size:0x14 }
}
{
  real_time:25672139.220647 global_time:169816, event:`SCHED' tid:2843695, ticks:21430211
rax:0x5590d3315390 rbx:0x0 rcx:0x0 rdx:0x7f62fb7a4340 rsi:0x5590d32fb2e0 rdi:0x5590d33153b8 rbp:0x7f62cb88e210 rsp:0x7f62cb88e1e0 r8:0x7f62c4000b60 r9:0x5590cdf3d7b0 r10:0x0 r11:0x0 r12:0x7ffd096dbc7e r13:0x7ffd096dbc7f r14:0x7ffd096dbd30 r15:0x7f62cb88ef80 rip:0x7f62dbd83851 eflags:0x206 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffff09 fs_base:0x7f62cb88f700 gs_base:0x0
}
{
  real_time:25672139.220649 global_time:169817, event:`SYSCALLBUF_RESET' tid:2843695, ticks:21430211
}
{
  real_time:25672139.220653 global_time:169818, event:`SYSCALL: futex' (state:EXITING_SYSCALL) tid:2844373, ticks:146074
rax:0x0 rbx:0x5590ce283b8c rcx:0xffffffffffffffff rdx:0x2 rsi:0x80 rdi:0x5590ce283b08 rbp:0x5590ce283b78 rsp:0x7f628bae3308 r8:0x0 r9:0xffffffff r10:0x0 r11:0x246 r12:0x5590ce283b9c r13:0x5590ce283b08 r14:0x5590ce283ba4 r15:0x7f628bae3380 rip:0x7f62fb799170 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xca fs_base:0x7f628bae4700 gs_base:0x0
}
{
  real_time:25672139.221080 global_time:169819, event:`SYSCALLBUF_FLUSH' tid:2844373, ticks:186277
  { syscall:'futex', ret:0x1, size:0x14 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
}
{
  real_time:25672139.221084 global_time:169820, event:`SYSCALL: futex' (state:ENTERING_SYSCALL) tid:2844373, ticks:186277
rax:0xffffffffffffffda rbx:0x7f6295f30fa0 rcx:0xffffffffffffffff rdx:0x0 rsi:0x89 rdi:0x5590ce283ba4 rbp:0x7f6295f30fa0 rsp:0x7f6295f30d40 r8:0x0 r9:0xffffffff r10:0x7f628bae3470 r11:0x246 r12:0x5590ce283b9c r13:0x5590ce283b08 r14:0x5590ce283ba4 r15:0x7f628bae3380 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xca fs_base:0x7f628bae4700 gs_base:0x0
}
{
  real_time:25672139.221086 global_time:169821, event:`SYSCALLBUF_RESET' tid:2844373, ticks:186277
}
=== Start rr backtrace:
rr(_ZN2rr9GdbServer15emergency_debugEPNS_4TaskE+0x15b)[0x5607cb1fbebb]
rr(+0x185eda)[0x5607cb1e3eda]
rr(+0x1860df)[0x5607cb1e40df]
rr(_ZN2rr13ReplaySession23check_ticks_consistencyEPNS_10ReplayTaskERKNS_5EventE+0x1e4)[0x5607cb14d774]
rr(_ZN2rr13ReplaySession11replay_stepERKNS0_15StepConstraintsE+0x942)[0x5607cb14d302]
rr(+0x1005fe)[0x5607cb15e5fe]
rr(_ZN2rr13ReplayCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0x57a)[0x5607cb15f5ba]
rr(main+0x199)[0x5607cb0aa939]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0x7f24a5afd083]
rr(_start+0x2e)[0x5607cb0aabee]
=== End rr backtrace

[rocallahan]

Is this related to #3686? Is it a recording of the same test?

[tysmith]

No this is a different test, different machine, different rr build.

[rocallahan]

Sorry Tyson, I dropped the ball on this one. Like #3686 this is not actionable as-is.

[tysmith]

No problem, if I see it again I'll let you know.