rr-debugger / rr

Record and Replay Framework
http://rr-project.org/
Other
9.22k stars 588 forks source link

Several register mismatch on replay #3577

Open GitMensch opened 1 year ago

GitMensch commented 1 year ago
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] rbx 0x70002000 != 0xf4d000 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] rcx 0xfffffffffffffff0 != 0xffffffffffffffff (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] rdx 0x70002000 != 0x2ca0 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] rsi 0xfffffffffffffff0 != 0x24000 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] rdi 0x5d3 != 0xf4d000 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] rbp 0x7fffb253ab00 != 0x7f9842202398 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] r8 0 != 0x3 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] r9 0 != 0x77 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] r10 0 != 0xfff (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] r12 0x30 != 0xf29000 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] r13 0x7f983d5938e0 != 0xfffffffffffff000 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] r14 0x7fffb253ab30 != 0xf26360 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] r15 0x7fffb253b214 != 0x6b10 (replaying vs. recorded)
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] rip 0x7f984249a72a != 0x7f984214439b (replaying vs. recorded)
[FATAL src/Registers.cc:409:compare_register_files()]
 (task 1009042 (rec:1006965) at time 2542)
 -> Assertion `!bail_error || match' failed to hold. Fatal register mismatch (ticks/rec:85207326/85130277)
Tail of trace dump:
{
  real_time:1509913.217593 global_time:2522, event:`SYSCALLBUF_FLUSH' tid:1006965, ticks:5396121
  { syscall:'write', ret:0xee, size:0x10, desched:1 }
}
{
  real_time:1509913.217596 global_time:2523, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:1006965, ticks:5396121
rax:0xffffffffffffffda rbx:0x7000202e rcx:0xffffffffffffffff rdx:0x2010 rsi:0x7000203e rdi:0x7 rbp:0x7 rsp:0x681ffd60 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x7000203e r13:0x7000404e r14:0x2010 r15:0xf15956 rip:0x7000000e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7f98422fc740 gs_base:0x0
}
{
  real_time:1509913.217784 global_time:2524, event:`SYSCALL: read' (state:EXITING_SYSCALL) tid:1006965, ticks:5396121
rax:0x2d rbx:0x7000202e rcx:0xffffffffffffffff rdx:0x2010 rsi:0x7000203e rdi:0x7 rbp:0x7 rsp:0x681ffd60 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x7000203e r13:0x7000404e r14:0x2010 r15:0xf15956 rip:0x7000000e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7f98422fc740 gs_base:0x0
  { tid:1006965, addr:0x7000202e, length:0x8 }
  { tid:1006965, addr:0x7000203e, length:0x2010 }
}
{
  real_time:1509913.217786 global_time:2525, event:`SYSCALLBUF_ABORT_COMMIT' tid:1006965, ticks:5396121
}
{
  real_time:1509913.217849 global_time:2526, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:ENTERING_SYSCALL) tid:1006965, ticks:5396130
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x2010 rsi:0xf15956 rdi:0x7 rbp:0x7fffb252b970 rsp:0x681ffe10 r8:0x0 r9:0x7 r10:0x0 r11:0x246 r12:0x2d r13:0xf0bc00 r14:0xf0ecc0 r15:0xf0bcc0 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x3ea fs_base:0x7f98422fc740 gs_base:0x0
}
{
  real_time:1509913.217851 global_time:2527, event:`SYSCALLBUF_RESET' tid:1006965, ticks:5396130
}
{
  real_time:1509913.217869 global_time:2528, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:EXITING_SYSCALL) tid:1006965, ticks:5396130
rax:0x2d rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x2010 rsi:0xf15956 rdi:0x7 rbp:0x7fffb252b970 rsp:0x681ffe10 r8:0x0 r9:0x7 r10:0x0 r11:0x246 r12:0x2d r13:0xf0bc00 r14:0xf0ecc0 r15:0xf0bcc0 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7f98422fc740 gs_base:0x0
  { tid:1006965, addr:0x7000200d, length:0x1 }
}
{
  real_time:1509913.218047 global_time:2529, event:`SYSCALLBUF_FLUSH' tid:1006965, ticks:5402838
  { syscall:'gettimeofday', ret:0x0, size:0x20 }
  { syscall:'sendto', ret:0x1, size:0x10, desched:1 }
  { syscall:'write', ret:0xa, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'gettimeofday', ret:0x0, size:0x20 }
  { syscall:'write', ret:0x9f, size:0x10, desched:1 }
}
{
  real_time:1509913.218051 global_time:2530, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:1006965, ticks:5402838
rax:0xffffffffffffffda rbx:0x7000209e rcx:0xffffffffffffffff rdx:0x2010 rsi:0x700020ae rdi:0x7 rbp:0x7 rsp:0x681ffd60 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x700020ae r13:0x700040be r14:0x2010 r15:0xf0cbd6 rip:0x7000000e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7f98422fc740 gs_base:0x0
}
{
  real_time:1509913.270047 global_time:2531, event:`SYSCALL: read' (state:EXITING_SYSCALL) tid:1006965, ticks:5402838
rax:0x3af rbx:0x7000209e rcx:0xffffffffffffffff rdx:0x2010 rsi:0x700020ae rdi:0x7 rbp:0x7 rsp:0x681ffd60 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x700020ae r13:0x700040be r14:0x2010 r15:0xf0cbd6 rip:0x7000000e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7f98422fc740 gs_base:0x0
  { tid:1006965, addr:0x7000209e, length:0x8 }
  { tid:1006965, addr:0x700020ae, length:0x2010 }
}
{
  real_time:1509913.270051 global_time:2532, event:`SYSCALLBUF_ABORT_COMMIT' tid:1006965, ticks:5402838
}
{
  real_time:1509913.270128 global_time:2533, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:ENTERING_SYSCALL) tid:1006965, ticks:5402847
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x2010 rsi:0xf0cbd6 rdi:0x7 rbp:0x7fffb252bc90 rsp:0x681ffe10 r8:0x0 r9:0x7 r10:0x0 r11:0x246 r12:0x3af r13:0xf0bc00 r14:0xf0ecc0 r15:0xf0bcc0 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x3ea fs_base:0x7f98422fc740 gs_base:0x0
}
{
  real_time:1509913.270130 global_time:2534, event:`SYSCALLBUF_RESET' tid:1006965, ticks:5402847
}
{
  real_time:1509913.270147 global_time:2535, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:EXITING_SYSCALL) tid:1006965, ticks:5402847
rax:0x3af rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x2010 rsi:0xf0cbd6 rdi:0x7 rbp:0x7fffb252bc90 rsp:0x681ffe10 r8:0x0 r9:0x7 r10:0x0 r11:0x246 r12:0x3af r13:0xf0bc00 r14:0xf0ecc0 r15:0xf0bcc0 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7f98422fc740 gs_base:0x0
  { tid:1006965, addr:0x7000200d, length:0x1 }
}
{
  real_time:1509913.274135 global_time:2536, event:`SYSCALLBUF_FLUSH' tid:1006965, ticks:9732556
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
}
{
  real_time:1509913.274155 global_time:2537, event:`PATCH_SYSCALL' tid:1006965, ticks:9732556
rax:0x0 rbx:0xf1d0c0 rcx:0x1 rdx:0x1 rsi:0x7f983dc525e0 rdi:0xf1d080 rbp:0x7fffb252d120 rsp:0x7fffb252d0c8 r8:0x0 r9:0x0 r10:0xf1d570 r11:0x7f98421fac80 r12:0x7fffb252d1d0 r13:0x7f983d765760 r14:0x0 r15:0x3 rip:0x7f983d762a40 eflags:0x10206 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_base:0x7f98422fc740 gs_base:0x0
  { tid:1006965, addr:0x7f984228240a, length:0x63 }
  { tid:1006965, addr:0x7f983d762a40, length:0x6 }
}
{
  real_time:1509913.274157 global_time:2538, event:`SYSCALLBUF_RESET' tid:1006965, ticks:9732556
}
{
  real_time:1509913.382643 global_time:2539, event:`SYSCALLBUF_FLUSH' tid:1006965, ticks:85130277
  { syscall:'rrcall_rdtsc', ret:0x833f20e, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'getuid', ret:0x308b, size:0x10 }
  { syscall:'gettimeofday', ret:0x0, size:0x28, replay_assist:1 }
  { syscall:'rrcall_rdtsc', ret:0x8360504, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1, replay_assist:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'time', ret:0x64dc85f2, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'getuid', ret:0x308b, size:0x10 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8376a9c, size:0x18, replay_assist:1 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1, replay_assist:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c, replay_assist:1 }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10, replay_assist:1 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1, replay_assist:1 }
  { syscall:'rrcall_rdtsc', ret:0x8381e74, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c, replay_assist:1 }
  { syscall:'read', ret:0x1, size:0x11, desched:1, replay_assist:1 }
  { syscall:'close', ret:0x0, size:0x10, replay_assist:1 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1, replay_assist:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8388748, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1, replay_assist:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b, replay_assist:1 }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x8393388, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8399ae4, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x83a46c6, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x83aae6e, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x83b574a, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x83bbb6c, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'getuid', ret:0x308b, size:0x10 }
  { syscall:'rrcall_rdtsc', ret:0x83c7c78, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x83ce338, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x83d8c60, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x83df0ae, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x83e99a4, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x83efe2a, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x83faa6a, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x84014ce, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x840c12a, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'getuid', ret:0x308b, size:0x10 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8412d26, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'getuid', ret:0x308b, size:0x10 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x841f312, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x842a9a4, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8431552, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x843c454, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8442c86, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x844d546, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8453e08, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x845e7e2, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8464d0a, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'time', ret:0x64dc85f2, size:0x10 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'getuid', ret:0x308b, size:0x10 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x84773e8, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x848255c, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8488a34, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x8493ec4, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x849a3e8, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x84a4dd4, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x84ab2ca, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x84b678a, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x84bccc0, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'getuid', ret:0x308b, size:0x10 }
  { syscall:'rrcall_rdtsc', ret:0x84c9056, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x84d02c6, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x84db050, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x84e1686, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x84ec2ee, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x84f282e, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x84fd07a, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8503c92, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x850e770, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'getuid', ret:0x308b, size:0x10 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x851505a, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'getuid', ret:0x308b, size:0x10 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x852178c, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x852c27a, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x85328d0, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x853d302, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8543772, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x854dfdc, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8554eb8, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'rrcall_rdtsc', ret:0x855f7e6, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0xfffffffffffffffe, size:0x10, desched:1 }
  { syscall:'gettimeofday', ret:0x0, size:0x28 }
  { syscall:'rrcall_rdtsc', ret:0x8565c08, size:0x18 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x1, size:0x11, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'getpid', ret:0xf5d75, size:0x10 }
  { syscall:'write', ret:0x123, size:0x10, desched:1 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0x2e, size:0x3e }
  { syscall:'read', ret:0x30, size:0x40, desched:1 }
}
{
  real_time:1509913.382649 global_time:2540, event:`SYSCALL: brk' (state:ENTERING_SYSCALL) tid:1006965, ticks:85130277
rax:0xffffffffffffffda rbx:0xf4d000 rcx:0xffffffffffffffff rdx:0x2ca0 rsi:0x24000 rdi:0xf4d000 rbp:0x7f9842202398 rsp:0x7fffb253a6e8 r8:0x3 r9:0x77 r10:0xfff r11:0x246 r12:0xf29000 r13:0xfffffffffffff000 r14:0xf26360 r15:0x6b10 rip:0x7f984214439b eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xc fs_base:0x7f98422fc740 gs_base:0x0
}
{
  real_time:1509913.382651 global_time:2541, event:`SYSCALLBUF_RESET' tid:1006965, ticks:85130277
}
{
  real_time:1509913.382707 global_time:2542, event:`SYSCALL: brk' (state:EXITING_SYSCALL) tid:1006965, ticks:85130277
rax:0xf4d000 rbx:0xf4d000 rcx:0xffffffffffffffff rdx:0x2ca0 rsi:0x24000 rdi:0xf4d000 rbp:0x7f9842202398 rsp:0x7fffb253a6e8 r8:0x3 r9:0x77 r10:0xfff r11:0x246 r12:0xf29000 r13:0xfffffffffffff000 r14:0xf26360 r15:0x6b10 rip:0x7f984214439b eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xc fs_base:0x7f98422fc740 gs_base:0x0
  { map_file:"<ZERO>", addr:0xf29000, length:0x24000, prot_flags:"rw-p", file_offset:0x0, device:0, inode:0, data_file:"", data_offset:0x0, file_size:0x24000 }
}
{
  real_time:1509913.382825 global_time:2543, event:`SYSCALLBUF_FLUSH' tid:1006965, ticks:85139532
  { syscall:'read', ret:0x6ab8, size:0x6ac8, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0x2e, size:0x3e }
  { syscall:'read', ret:0x5c, size:0x6c, desched:1 }
  { syscall:'read', ret:0x3a0, size:0x3b0, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0x2e, size:0x3e }
  { syscall:'read', ret:0x5c, size:0x6c, desched:1 }
  { syscall:'read', ret:0x2f2, size:0x302, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x8, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0x2e, size:0x3e }
  { syscall:'read', ret:0x5c, size:0x6c, desched:1 }
  { syscall:'read', ret:0x18a2, size:0x18b2, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
}
=== Start rr backtrace:
/tmp/rr/build/bin/rr(_ZN2rr9GdbServer15emergency_debugEPNS_4TaskE+0xf0)[0x4a7f40]
/tmp/rr/build/bin/rr[0x4bb7ae]
/tmp/rr/build/bin/rr[0x4bba4b]
/tmp/rr/build/bin/rr(_ZN2rr9Registers22compare_register_filesEPNS_10ReplayTaskEPKcRKS0_S4_S6_NS_16MismatchBehaviorE+0x7c)[0x53d3dc]
/tmp/rr/build/bin/rr(_ZN2rr10ReplayTask13validate_regsEj+0x196)[0x557b16]
/tmp/rr/build/bin/rr(_ZN2rr13ReplaySession18try_one_trace_stepEPNS_10ReplayTaskERKNS0_15StepConstraintsE+0x12b)[0x54a18b]
/tmp/rr/build/bin/rr(_ZN2rr13ReplaySession11replay_stepERKNS0_15StepConstraintsE+0x153)[0x54c203]
/tmp/rr/build/bin/rr(_ZN2rr14ReplayTimeline19replay_step_forwardENS_10RunCommandE+0x94)[0x5662a4]
/tmp/rr/build/bin/rr(_ZN2rr9GdbServer14debug_one_stepERNS_10GdbRequestE+0x318)[0x4a4818]
/tmp/rr/build/bin/rr(_ZN2rr9GdbServer12serve_replayERKNS0_15ConnectionFlagsE+0xa5b)[0x4a618b]
/tmp/rr/build/bin/rr[0x540de5]
/tmp/rr/build/bin/rr(_ZN2rr13ReplayCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0x5ea)[0x541d0a]
/tmp/rr/build/bin/rr(main+0x181)[0x446481]
/usr/lib64/libc.so.6(+0x3feb0)[0x7f1f52c3feb0]
/usr/lib64/libc.so.6(__libc_start_main+0x80)[0x7f1f52c3ff60]
/tmp/rr/build/bin/rr(_start+0x25)[0x448cc5]
=== End rr backtrace

happening with current master on Rocky 9 (completely updated) with kernel 5.14.0-284.25.1.el9_2.x86_64 on a Intel(R) Xeon(R) Gold 6242. All test pass but #3032 (replay fails, sadly the system update did not help).

khuey commented 1 year ago

Can you describe the workload here and/or provide a copy of the failing trace?

GitMensch commented 1 year ago

It seems to abort on the first real db access via libclntsh (Oracle Client); the last library loaded was libnque19.so... this reminds me of #3001...

Here's the backtrace from the emergency debugger:

#0  0x00007f5d1f86472a in do_breakpoint (value=31023104) at /tmp/rr/src/preload/syscallbuf.c:1332
#1  0x00007f5d1f864b34 in commit_raw_syscall (syscallno=<optimized out>, record_end=<optimized out>, ret=48)
    at /tmp/rr/src/preload/syscallbuf.c:1444
#2  0x00007f5d1f86aa2a in syscall_hook (call=0x681fffa0) at /tmp/rr/src/preload/syscallbuf.c:4234
#3  syscall_hook (call=0x681fffa0) at /tmp/rr/src/preload/syscallbuf.c:4218
#4  0x00007f5d1f8642f3 in _syscall_hook_trampoline () at /tmp/rr/src/preload/syscall_hook.S:308
#5  0x00007f5d1f86435d in __morestack () at /tmp/rr/src/preload/syscall_hook.S:443
#6  0x00007f5d1f864379 in _syscall_hook_trampoline_48_3d_00_f0_ff_ff () at /tmp/rr/src/preload/syscall_hook.S:462
#7  0x00007f5d1f53eaf8 in read () from /usr/lib64/libc.so.6
#8  0x00007f5d1a664abb in lxldLoadBoot () from /opt/oracle/product/cli19/lib/libclntshcore.so.19.1
#9  0x00007f5d1a668d68 in lxlinit () from /opt/oracle/product/cli19/lib/libclntshcore.so.19.1
#10 0x00007f5d1aa7d9f7 in nzdsinls () from /opt/oracle/product/cli19/lib/libnnz19.so
#11 0x00007f5d1aa7d64e in nzdsinitp () from /opt/oracle/product/cli19/lib/libnnz19.so
#12 0x00007f5d1aa7e6a3 in nzdsInitialize_int () from /opt/oracle/product/cli19/lib/libnnz19.so
#13 0x00007f5d1caacb67 in nszgetpwcred_int () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#14 0x00007f5d1caaca8d in nszgetpwcred () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#15 0x00007f5d1b686b20 in kpuauthxa () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#16 0x00007f5d1b6849fa in kpuauth () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1

Does that help?

khuey commented 1 year ago

If you can share the trace privately I can do the rdrand check again.

If you record with RR_COPY_ALL_FILES=1 in the environment does replay work?

GitMensch commented 1 year ago

If you record with RR_COPY_ALL_FILES=1 in the environment does replay work?

No.

If you can share the trace privately I can do the rdrand check again.

I try to minimize that test program, pack, upload and then send a link to that (to which address, please)?

But does I understand this correctly that we'd need something like https://github.com/systemd/systemd/issues/17112 in the Oracle Instant client then? Isn't it possible to have a dummy rdrand in the LD_PRELOAD that RR does during recording instead?

khuey commented 1 year ago

If you can share the trace privately I can do the rdrand check again.

I try to minimize that test program, pack, upload and then send a link to that (to which address, please)?

khuey@pernos.co

But does I understand this correctly that we'd need something like systemd/systemd#17112 in the Oracle Instant client then?

Possibly.

Isn't it possible to have a dummy rdrand in the LD_PRELOAD that RR does during recording instead?

It depends on how exactly the code is using rdrand, if it in fact is. If it's calling into some function we might be able to interpose something with LD_PRELOAD. If it's just executing the CPU instruction we can't really do anything.

GitMensch commented 1 year ago

OK, reduced the execution and trace and sent link by mail.

If nothing helps then we may be able to check with Oracle support if there's anything we can do, but in this case we likely need a bit more information where / how the issue happens.

GitMensch commented 1 year ago

With the address provided by @khuey:

Breakpoint 2, 0x00007f9ce5562a20 in r0_x86_rdrand () from /opt/oracle/product/cli19/lib/libnnz19.so
(rr) bt
#0  0x00007f9ce5562a20 in r0_x86_rdrand () from /opt/oracle/product/cli19/lib/libnnz19.so
#1  0x00007f9ce55675ce in r1_entr_ctx_gather_rdrand () from /opt/oracle/product/cli19/lib/libnnz19.so
#2  0x00007f9ce5562b5c in R1_ENTR_CTX_gather () from /opt/oracle/product/cli19/lib/libnnz19.so
#3  0x00007f9ce55238aa in r0_rand_entr_gather () from /opt/oracle/product/cli19/lib/libnnz19.so
#4  0x00007f9ce5523b09 in r0_rand_entr_ctrl () from /opt/oracle/product/cli19/lib/libnnz19.so
#5  0x00007f9ce552607c in lock_ctrl () from /opt/oracle/product/cli19/lib/libnnz19.so
#6  0x00007f9ce5518897 in r_ck_entropy_new () from /opt/oracle/product/cli19/lib/libnnz19.so
#7  0x00007f9ce54bbd83 in ri_cr_rng_init () from /opt/oracle/product/cli19/lib/libnnz19.so
#8  0x00007f9ce54b929f in ri_cr_ctx_get_info () from /opt/oracle/product/cli19/lib/libnnz19.so
#9  0x00007f9ce5655cf2 in r_ck_random_base_set_normal_entropy_source () from /opt/oracle/product/cli19/lib/libnnz19.so
#10 0x00007f9ce5655d75 in r_ck_random_base_set_mode () from /opt/oracle/product/cli19/lib/libnnz19.so
#11 0x00007f9ce55d5848 in r_ck_random_hmac_set_params () from /opt/oracle/product/cli19/lib/libnnz19.so
#12 0x00007f9ce5519250 in r_ck_random_hmac_new () from /opt/oracle/product/cli19/lib/libnnz19.so
#13 0x00007f9ce54bbd83 in ri_cr_rng_init () from /opt/oracle/product/cli19/lib/libnnz19.so
#14 0x00007f9ce54ba62d in ri_cr_random_auto_init () from /opt/oracle/product/cli19/lib/libnnz19.so
#15 0x00007f9ce54ba59e in R_CR_random_bytes () from /opt/oracle/product/cli19/lib/libnnz19.so
#16 0x00007f9ce566d49e in ztca_RSAAdpGetRandom () from /opt/oracle/product/cli19/lib/libnnz19.so
#17 0x00007f9ce566d9d7 in ztca_GetRandomMC () from /opt/oracle/product/cli19/lib/libnnz19.so
#18 0x00007f9ce566d8fc in ztca_GetRandom () from /opt/oracle/product/cli19/lib/libnnz19.so
#19 0x00007f9ce566f39b in ztcr2rnd () from /opt/oracle/product/cli19/lib/libnnz19.so
#20 0x00007f9ce77999c9 in naedhpk () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#21 0x00007f9ce61a58d3 in naeccn () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#22 0x00007f9ce61bedf5 in na_csrd () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#23 0x00007f9ce61bf7f1 in na_client () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#24 0x00007f9ce61b851c in naconnect () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#25 0x00007f9ce6164467 in nsnadoconn () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#26 0x00007f9ce6160531 in nsnaconn () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#27 0x00007f9ce6105bd7 in nscall () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#28 0x00007f9ce619820d in niotns () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#29 0x00007f9ce61a2f3d in osncon () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#30 0x00007f9ce6041d27 in kpuadef () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#31 0x00007f9ce60278b9 in upiini () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#32 0x00007f9ce6040503 in kpuatch () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
#33 0x00007f9ce601b925 in OCIServerAttach () from /opt/oracle/product/cli19/lib/libclntsh.so.19.1
...
(rr) disas
Dump of assembler code for function r0_x86_rdrand:
=> 0x00007f9ce5562a20 <+0>:     rdrand %rax
   0x00007f9ce5562a24 <+4>:     ret
End of assembler dump.
(rr) up
#1  0x00007f9ce55675ce in r1_entr_ctx_gather_rdrand () from /opt/oracle/product/cli19/lib/libnnz19.so
(rr) disas
Dump of assembler code for function r1_entr_ctx_gather_rdrand:
   0x00007f9ce5567580 <+0>:     push   %r13
   0x00007f9ce5567582 <+2>:     mov    %ecx,%r13d
   0x00007f9ce5567585 <+5>:     push   %r12
   0x00007f9ce5567587 <+7>:     mov    %rdx,%r12
   0x00007f9ce556758a <+10>:    push   %rbp
   0x00007f9ce556758b <+11>:    push   %rbx
   0x00007f9ce556758c <+12>:    mov    %rdi,%rbx
   0x00007f9ce556758f <+15>:    sub    $0x18,%rsp
   0x00007f9ce5567593 <+19>:    mov    0x501ac7(%rip),%eax        # 0x7f9ce5a69060 <has_rand>
   0x00007f9ce5567599 <+25>:    mov    0x10(%rdi),%rbp
   0x00007f9ce556759d <+29>:    test   %eax,%eax
   0x00007f9ce556759f <+31>:    js     0x7f9ce5567638 <r1_entr_ctx_gather_rdrand+184>
   0x00007f9ce55675a5 <+37>:    test   %eax,%eax
   0x00007f9ce55675a7 <+39>:    jne    0x7f9ce55675c0 <r1_entr_ctx_gather_rdrand+64>
   0x00007f9ce55675a9 <+41>:    movl   $0x0,(%r8)
   0x00007f9ce55675b0 <+48>:    add    $0x18,%rsp
   0x00007f9ce55675b4 <+52>:    xor    %eax,%eax
   0x00007f9ce55675b6 <+54>:    pop    %rbx
   0x00007f9ce55675b7 <+55>:    pop    %rbp
   0x00007f9ce55675b8 <+56>:    pop    %r12
   0x00007f9ce55675ba <+58>:    pop    %r13
   0x00007f9ce55675bc <+60>:    ret
   0x00007f9ce55675bd <+61>:    nopl   (%rax)
   0x00007f9ce55675c0 <+64>:    mov    %r8,0x8(%rsp)
   0x00007f9ce55675c5 <+69>:    mov    %esi,0x4(%rsp)
   0x00007f9ce55675c9 <+73>:    call   0x7f9ce5562a20 <r0_x86_rdrand>
=> 0x00007f9ce55675ce <+78>:    test   %rax,%rax
   0x00007f9ce55675d1 <+81>:    mov    %rax,%rdi
   0x00007f9ce55675d4 <+84>:    mov    0x8(%rsp),%r8
   0x00007f9ce55675d9 <+89>:    je     0x7f9ce55675a9 <r1_entr_ctx_gather_rdrand+41>
   0x00007f9ce55675db <+91>:    cmp    0x0(%rbp),%rax
   0x00007f9ce55675df <+95>:    je     0x7f9ce55675a9 <r1_entr_ctx_gather_rdrand+41>
   0x00007f9ce55675e1 <+97>:    xor    %ecx,%ecx
   0x00007f9ce55675e3 <+99>:    test   %r13d,%r13d
   0x00007f9ce55675e6 <+102>:   mov    %rax,0x0(%rbp)
   0x00007f9ce55675ea <+106>:   mov    0x4(%rsp),%esi
   0x00007f9ce55675ee <+110>:   je     0x7f9ce556760c <r1_entr_ctx_gather_rdrand+140>
   0x00007f9ce55675f0 <+112>:   lea    -0x1(%r13),%ecx
   0x00007f9ce55675f4 <+116>:   mov    $0x24924925,%edx
   0x00007f9ce55675f9 <+121>:   mov    $0x38,%r9d
   0x00007f9ce55675ff <+127>:   mov    %ecx,%eax
   0x00007f9ce5567601 <+129>:   shr    $0x3,%eax
   0x00007f9ce5567604 <+132>:   mul    %edx
   0x00007f9ce5567606 <+134>:   imul   %r9d,%edx
   0x00007f9ce556760a <+138>:   sub    %edx,%ecx
   0x00007f9ce556760c <+140>:   shr    %cl,%rdi
   0x00007f9ce556760f <+143>:   mov    %r12,%rdx
   0x00007f9ce5567612 <+146>:   mov    %r8,%rcx
   0x00007f9ce5567615 <+149>:   mov    %dil,(%r12)
   0x00007f9ce5567619 <+153>:   movl   $0x4,(%r8)
   0x00007f9ce5567620 <+160>:   add    $0x18,%rsp
   0x00007f9ce5567624 <+164>:   mov    %rbx,%rdi
   0x00007f9ce5567627 <+167>:   pop    %rbx
   0x00007f9ce5567628 <+168>:   pop    %rbp
   0x00007f9ce5567629 <+169>:   pop    %r12
   0x00007f9ce556762b <+171>:   pop    %r13
   0x00007f9ce556762d <+173>:   jmp    0x7f9ce5562d20 <r1_entr_health_test_default>
   0x00007f9ce5567632 <+178>:   nopw   0x0(%rax,%rax,1)
   0x00007f9ce5567638 <+184>:   mov    $0x1e,%edi
   0x00007f9ce556763d <+189>:   mov    %r8,0x8(%rsp)
   0x00007f9ce5567642 <+194>:   mov    %esi,0x4(%rsp)
   0x00007f9ce5567646 <+198>:   call   0x7f9ce549d5b0 <r1_cpuid_has_feature>
   0x00007f9ce556764b <+203>:   mov    0x8(%rsp),%r8
   0x00007f9ce5567650 <+208>:   mov    %eax,0x501a0a(%rip)        # 0x7f9ce5a69060 <has_rand>
   0x00007f9ce5567656 <+214>:   mov    0x4(%rsp),%esi
   0x00007f9ce556765a <+218>:   jmp    0x7f9ce55675a5 <r1_entr_ctx_gather_rdrand+37>
End of assembler dump.

So I guess one could LD_PRELOAD a dummy function to work around this specific case? Not sure what it should do though to mimic that "valid"...

khuey commented 1 year ago

Is source code provided for libnnz19.so? Or do you just have binaries?

khuey commented 1 year ago

Also, are you recording this in a virtualized environment? CPUID faulting isn't being used, which would probably fix this.

GitMensch commented 1 year ago

Is source code provided for libnnz19.so? Or do you just have binaries?

As always: Oracle only provides binaries... It should be possible to use a decompiler like https://github.com/avast/retdec, if necessary.

Also, are you recording this in a virtualized environment? CPUID faulting isn't being used, which would probably fix this.

Yes, VMWare. Do you have any suggestion how to possibly get this working there?

khuey commented 1 year ago

Based on https://communities.vmware.com/t5/VMware-Workstation-Pro/Is-it-possible-to-quot-mask-quot-the-CPUID-in-Workstation/td-p/2167959 I suspect putting

cpuid.1.edx="-0--:----:----:----:----:----:----:----"

in the configuration of the VM in question would disable rdrand in it. But I haven't tested this.

khuey commented 1 year ago

If that does work then after rebooting cat /proc/cpuinfo | grep rdrand should be empty.

bernhardu commented 1 year ago

If enabling this support is not possible, as a workaround, maybe running gdb inside the recording and setting $pc below the rdrand instruction might work? Or replacing it by nop? (I tried it with a real target, kcalc with removed environment QT_NO_CPU_FEATURE, unfortunately this still failed after replacing all rdrand/rdseed instructions in QtCore.)

Details ```cpp $ cat rdrand-test.c /* gcc -mrdrnd -g -O2 rdrand-test.c -o rdrand-test */ #include #include int main() { int val = 0; _rdrand32_step(&val); printf("%d\n", val); } $ $ rr record gdb -q --args ./rdrand-test ... $ rr replay -a gdb-25 Reading symbols from ./rdrand-test... (gdb) tb main Temporary breakpoint 1 at 0x1050: file rdrand-test.c, line 12. (gdb) run Starting program: /home/bernhard/rdrand-test [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". Temporary breakpoint 1, main () at rdrand-test.c:12 12 _rdrand32_step(&val); (gdb) disassemble main quit Dump of assembler code for function main: => 0x0000555555555050 <+0>: sub $0x18,%rsp 0x0000555555555054 <+4>: rdrand %esi 0x0000555555555057 <+7>: lea 0xfa6(%rip),%rdi # 0x555555556004 ... End of assembler dump. (gdb) b *0x0000555555555054 Breakpoint 2 at 0x555555555054: file /usr/lib/gcc/x86_64-linux-gnu/12/include/x86gprintrin.h, line 128. (gdb) cont Continuing. Breakpoint 2, _rdrand32_step (__P=0x7fffffffdadc) at /usr/lib/gcc/x86_64-linux-gnu/12/include/x86gprintrin.h:128 128 return __builtin_ia32_rdrand32_step (__P); (gdb) display/i $pc 1: x/i $pc => 0x555555555054 : rdrand %esi (gdb) set $pc = 0x0000555555555057 (gdb) cont Continuing. -9224 [Inferior 1 (process 149905) exited normally] (gdb) q $ $ rr record gdb -q --args ./rdrand-test ... $ rr replay -a gdb-27 Reading symbols from ./rdrand-test... (gdb) tb main Temporary breakpoint 1 at 0x1050: file rdrand-test.c, line 12. (gdb) run Starting program: /home/bernhard/rdrand-test [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". Temporary breakpoint 1, main () at rdrand-test.c:12 12 _rdrand32_step(&val); (gdb) disassemble /r main Dump of assembler code for function main: => 0x0000555555555050 <+0>: 48 83 ec 18 sub $0x18,%rsp 0x0000555555555054 <+4>: 0f c7 f6 rdrand %esi 0x0000555555555057 <+7>: 48 8d 3d a6 0f 00 00 lea 0xfa6(%rip),%rdi # 0x555555556004 ... End of assembler dump. (gdb) set *(int*)0x0000555555555054 = 0x48909090 (gdb) disassemble /r main Dump of assembler code for function main: => 0x0000555555555050 <+0>: 48 83 ec 18 sub $0x18,%rsp 0x0000555555555054 <+4>: 90 nop 0x0000555555555055 <+5>: 90 nop 0x0000555555555056 <+6>: 90 nop 0x0000555555555057 <+7>: 48 8d 3d a6 0f 00 00 lea 0xfa6(%rip),%rdi # 0x555555556004 ... End of assembler dump. (gdb) detach Detaching from program: /home/bernhard/rdrand-test, process 150301 [Inferior 1 (process 150301) detached] -9224 (gdb) q $ ```
GitMensch commented 1 year ago

Whoa. Recording GDB executing something with using its live-patching...

And do you know what: that even WORKS :-) [but replay is a bit slow]

$ cat ./r0_x86_rdrand.ret.gdb
set breakpoint pending on
break r0_x86_rdrand
commands
  silent
  return
  continue
end
run

$ /tmp/rr/build/bin/rr gdb --batch -x ~/r0_x86_rdrand.ret.gdb --args cobcrun PROG ARG1 ARG2 ARG3
$ /tmp/rr/build/bin/rr replay
Application done

How to use that with preloading? The following doesn't work:

$ echo "void r0_x86_rdrand () {}" | gcc --shared -x c -o $HOME/r0_x86_rdrand.none.so -
$ LD_PRELOAD=$HOME/r0_x86_rdrand.none.so /tmp/rr/build/bin/rr cobcrun PROG ARG1 ARG2 ARG3
$ /tmp/rr/build/bin/rr replay
[ERROR src/Registers.cc:299:maybe_print_reg_mismatch()] rbx 0x70002000 != 0x2325000 (replaying vs. recorded)
bernhardu commented 1 year ago

Nice to hear it is working. Yes I felt it being kind of slow too - maybe just using gdbserver inside the recording and having gdb itself outside could help here 😃.

About the LD_PRELOAD trick - isn't this just expected to work on a shared library boundary? Or should this work between function calls in the same shared library too?

GitMensch commented 1 year ago

Yes, LD_PRELOAD only work for dynamic calls, but the r0_x86_rdrand function and its calls are embedded - so either binary patching is needed or use of GDB.

Yes I felt it being kind of slow too - maybe just using gdbserver inside the recording and having gdb itself outside could help here

Of course - and that does run faster, and works fine to replay :-)

$ cat $HOME/r0_x86_rdrand.gdbserver-ret.gdb
# needs to be sourced after "set sysroot /" and "target remote :port"
set breakpoint pending on
break r0_x86_rdrand
commands
  silent
  return
  continue
end
# difference from starting under GDB - gdbserver already started the program, so don't run
continue

$ gdb --batch -ex "set sysroot /" -ex "target remote :12345" -x $HOME/r0_x86_rdrand.gdbserver-ret.gdb &  # possibly use separate terminal instead of async - in any case this will start gdb and will wait for a server on that port
$ /tmp/rr/build/bin/rr gdbserver :12345 cobcrun PROG ARG1 ARG2 ARG3
$ /tmp/rr/build/bin/rr replay
(rr) c
Continuing.
Process cobcrun created; pid = 1675522
Listening on port 12345
Remote debugging from host ::1, port 40444

Application done

Child exited with status 0

Program received signal SIGKILL, Killed.
0x0000000070000002 in syscall_traced ()
(rr) q
$$ /tmp/rr/build/bin/rr ps
PID     PPID    EXIT    CMD
1675519 --      0       gdbserver :12345 cobcrun PROG ARG1 ARG2 ARG3
1675520 1675519 -9      (forked without exec)
1675521 1675519 -9      (forked without exec)
1675522 1675519 0       /bin/bash -c exec cobcrun PROG ARG1 ARG2 ARG3

but... as the replay now replays gdbserver - how do I get to debug the executable? Can I instruct rr to only replay the program that was controlled by GDB actual "cobcrun" (and where is that)?

rr replay -p 1675522 starts, as expected, "bash", not cobcrun

Just setting breakpoints (as I do on a normal replay) don't work, I guess I need to run the execution until the actual program starts and then switch GDB to that, but I don't know how to achieve that. Using catch exec results in "warning: Error inserting catchpoint 1: Your system does not support this type".

Any hints how to actually "replay" the process?

Note: the same happens when recording gdb, which has

$ rr ps gdb-9
PID     PPID    EXIT    CMD
679447  --      0       gdb --batch -x ~/r0_x86_rdrand.ret.gdb --args cobcrun PROG ARG1 ARG2 ARG3
679449  679447  0       iconv -l
679451  679447  0       /bin/bash -c exec cobcrun PROG ARG1 ARG2 ARG3
679452  679447  -9      (forked without exec)
679453  679447  -9      (forked without exec)
bernhardu commented 1 year ago

but... as the replay now replays gdbserver - how do I get to debug the executable? Can I instruct rr to only replay the program that was controlled by GDB actual "cobcrun" (and where is that)?

rr replay -p 1675522 starts, as expected, "bash", not cobcrun

Just setting breakpoints (as I do on a normal replay) don't work, I guess I need to run the execution until the actual program starts and then switch GDB to that, but I don't know how to achieve that. Using catch exec results in "warning: Error inserting catchpoint 1: Your system does not support this type".

Any hints how to actually "replay" the process?

I guess you get to a Program stopped. This marks just the end of the bash execution. Afterwards the execed program takes over. So just -goto behind that in the trace. See the example below and more details here

And beware of the TRAP signals originally intended for the recorded gdb, but also received by the replaying gdb 😀

Replay of my gdb-25 recording from yesterday ```gdb $ rr ps gdb-25 PID PPID EXIT CMD 149897 -- 0 gdb -q --args ./rdrand-test 149898 149897 0 iconv -l 149905 149897 0 /bin/bash -c exec /home/bernhard/rdrand-test 149906 149897 -9 (forked without exec) 149907 149897 -9 (forked without exec) $ $ rr replay --debugger-option=-q -p 149905 gdb-25 ---> Reached target process 149905 at event 4693. (rr) cont Continuing. Program stopped. 0x00007ffff7e37917 in __GI_execve () at ../sysdeps/unix/syscall-template.S:120 120 ../sysdeps/unix/syscall-template.S: Datei oder Verzeichnis nicht gefunden. (rr) when Current event: 5124 (rr) q $ $ rr replay --debugger-option=-q -p 149905 -g 6000 gdb-25 ---> Reached target process 149905 at event 6680. (rr) b *(main+14) Breakpoint 1 at 0x55555555505e: file rdrand-test.c, line 13. (rr) cont Program received signal SIGTRAP, Trace/breakpoint trap. (rr) cont Program received signal SIGTRAP, Trace/breakpoint trap. (rr) cont Breakpoint 1, 0x000055555555505e in main () at rdrand-test.c:13 13 printf("%d\n", val); (rr) when Current event: 14301 (rr) ```
GitMensch commented 1 year ago

That sounds good and from the wiki I now also know of ps dump | grep -P "SYSCALL: exec.+EXITING_SYSCALL" (leads to the exact same number as starting + cont + when).

And beware of the TRAP signals originally intended for the recorded gdb, but also received by the replaying gdb 😀

... that is what's happening when I use that - I do see the right symbols being loaded (cobcrun instead of gdbserver), but then I got pages of

Program received signal SIGTRAP, Trace/breakpoint trap.
dl_open_worker_begin (a=0x7ffffffed3b0) at dl-open.c:755
755     in dl-open.c
(rr)
Continuing.

Program received signal SIGTRAP, Trace/breakpoint trap.
dl_open_worker_begin (a=0x7ffffffed3b0) at dl-open.c:755
755     in dl-open.c

then pages of

Program received signal SIGTRAP, Trace/breakpoint trap.
0x00007ffff2f62a21 in r0_x86_rdrand () from /opt/oracle/product/cli19/lib/libnnz19.so
(rr)
Continuing.

Program received signal SIGTRAP, Trace/breakpoint trap.
0x00007ffff2f62a21 in r0_x86_rdrand () from /opt/oracle/product/cli19/lib/libnnz19.so

followed by pages of the first...

and finally by pages of

rogram received signal SIGTRAP, Trace/breakpoint trap.
_dl_close_worker (map=map@entry=0x5d2600, force=force@entry=false) at dl-close.c:766
766     in dl-close.c
(rr)
Continuing.

Program received signal SIGTRAP, Trace/breakpoint trap.
_dl_close_worker (map=map@entry=0x5d1e60, force=force@entry=false) at dl-close.c:766
766     in dl-close.c

To work around those:

# no-common-traps.gdb
set breakpoint pending on

# break dl_main
break rtld.c:1185
commands
 silent
 continue
end
break rtld.c:2548
commands
 silent
 continue
end

# break dl_open_worker_begin
break dl-open.c:489
commands
 silent
 continue
end
break dl-open.c:755
commands
 silent
 continue
end

# break _dl_close_worker
break dl-close.c:139
commands
 silent
 continue
end
# needs to be additional executed manual once
break dl-close.c:766
commands
 silent
 continue
end

# needs to be executed manual, when triggered the first time
#break r0_x86_rdrand
#commands
# silent
# continue
#end

Then rr replay --debugger-option=-q -p 3631757 -g 2119 with a source /home/me/no-common-traps.gdb (somehow I could not do that on the command line) did the trick. The important thing was to not set a breakpoint for the function that the gdbserver recording "took out" but instead set that manually and accept to not be able to reverse-continue before that.

GitMensch commented 1 year ago

in the configuration of the VM in question would disable rdrand in it

So there's no way that rr could claim during report and replay "not supported"?

khuey commented 1 year ago

Complaining that rdrand is available is overkill if the tracee doesn't actually use rdrand, and there's no way for rr to determine if the tracee does use rdrand.

Did you try that configuration snippet? Did it work?

GitMensch commented 1 year ago

As I'm not in control of the virtualizer it is not easy to do the adjustments. If anything then rr may error on recording a rdrand call, but as I've understood: "rr is fast because it does not check every call".

Inspecting the code flow, I've found that before rdrand is called the first time libnnz checks first for its availability with a call to r1_cpuid_has_feature() which calls r1_cpuid()->r0_cpuid()->r0_x86_cpuid(), which finally does the cpuid call [which likely would say "isn't available" if adjusted in the vm config].

According to https://en.wikipedia.org/wiki/RDRAND there's a specific call and a specific setting of bit 30 of the ECX register - but I guess the rr record cannot tinker with that, can it?

...

more assembler debugging showed that there's a global variable int has_rand, which is -1 when the functions in that library start and only if this is < 0 the cpuid check is done, and after it is done it is set to 1 (a watchpoint showed that happens in r1_entr_meth_ctrl_rdrand), so a debug "interop" only has to set this variable to zero.

And this is a global variable, which is visible before the functions from that library are even called. Within the debugger I can get its address p &has_rand and then set it directly p * (int *) 0x7ffff3469060 = 0 - and there's no call to rdrand any more (simplifies the "debugging during recording" part a while making it more robust).

Any idea how I can set this from outside? dlsym() didn't help (neither with passing the main handle, nor with passing an handle explicit dlopen'd from libnzz19.so - nm shows that has_rand is a local data symbol...

khuey commented 1 year ago

According to https://en.wikipedia.org/wiki/RDRAND there's a specific call and a specific setting of bit 30 of the ECX register - but I guess the rr record cannot tinker with that, can it?

rr record does tinker with that ... if the CPU we're running on supports CPUID faulting (meaning you're running on a bare metal Intel Ivy Bridge or later CPU, or a VM inside a hypervisor (KVM or Xen) that knows how to expose this feature).