search

rr-debugger / rr

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

RR crash in PerfCounters::read_ticks #2615

Open malhanvishal opened 4 years ago

malhanvishal commented 4 years ago

In a multithreaded program, rr record crashes randomly (and passes sometimes too) with following stack trace Please let me know for any ideas/suggestions?

rr(rr::dump_rr_stack()+0x3b)[0x5f229b] rr(rr::GdbServer::emergency_debug(rr::Task)+0x325)[0x504d95] rr[0x513c64] rr(rr::PerfCounters::read_ticks(rr::Task)+0x11d)[0x52f8fd] rr(rr::Task::did_waitpid(rr::WaitStatus)+0x19f)[0x5d26bf] rr(rr::Task::wait(double)+0x48f)[0x5d341f] rr(rr::Scheduler::reschedule(rr::Switchable)+0x14f)[0x5b436f] rr(rr::RecordSession::record_step()+0xdc)[0x5400ec] rr(rr::RecordCommand::run(std::vector<std::cxx11::basic_string<char, std::char_traits, std::allocator >, std::allocator<std::cxx11::basic_string<char, std::char_traits, std::allocator > > >&)+0x1011)[0x535e21] rr(main+0x353)[0x4ac743] /lib64/libc.so.6(__libc_start_main+0xf5)[0x7f4ee24ee6e5]

uname -a: Linux lxserv01 4.4.73-5-default #1 SMP Tue Jul 4 15:33:39 UTC 2017 (b7ce4e4) x86_64 x86_64 x86_64 GNU/Linux

rr --version rr version 5.3.0

rocallahan commented 4 years ago

There should be some console output too?

malhanvishal commented 4 years ago

{ real_time:9755683.017222 global_time:28805, event:SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:20447703 rax:0x0 rbx:0x7fadd99e35c0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x14e000 rdi:0x7fadd936a000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99e35c0 r9:0x7fadd99e35c0 r10:0x7fadd99e35c0 r11:0x246 r12:0x0 r13:0x7fadd6562000 r14:0x0 r15:0x7fadd6951308 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755683.017255 global_time:28806, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:20447775 rax:0xffffffffffffffda rbx:0x7fadd99e3000 rcx:0xffffffffffffffff rdx:0x1 rsi:0x1000 rdi:0x7fadd97bd000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd95967c8 r9:0x7fadd9596888 r10:0x7fadd99e3000 r11:0x246 r12:0x0 r13:0x7fadd9596000 r14:0x0 r15:0x1 rip:0x7fadd97dcde7 eflags:0x246 cs: 0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755683.017277 global_time:28807, event:`SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:20447775 rax:0x0 rbx:0x7fadd99e3000 rcx:0xffffffffffffffff rdx:0x1 rsi:0x1000 rdi:0x7fadd97bd000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd95967c8 r9:0x7fadd9596888 r10:0x7fadd99e3000 r11:0x246 r12:0x0 r13:0x7fadd9596000 r14:0x0 r15:0x1 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } === Start rr backtrace:

rocallahan commented 4 years ago

There should be message saying ASSERT or FATAL.

malhanvishal commented 4 years ago

Adding a more complete log:

[FATAL /home/roc/rr/rr/src/PerfCounters.cc:893:read_ticks()] (task 24074 (rec:24074) at time 28808) -> Assertion !counting_period || measure_val <= adjusted_counting_period' failed to hold. Detected 4841 ticks, expected no more than 2916 Tail of trace dump: { real_time:9755682.968086 global_time:28788, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:804881 rax:0xffffffffffffffda rbx:0x7fadd99beb40 rcx:0xffffffffffffffff rdx:0x1 rsi:0x1000 rdi:0x7fadd2938000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bcb08 r9:0x7fadd99bcb08 r10:0x7fadd99beb40 r11:0x246 r12:0x0 r13:0x7fadd271c000 r14:0x0 r15:0x7fadd271c758 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.968106 global_time:28789, event:SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:804881 rax:0x0 rbx:0x7fadd99beb40 rcx:0xffffffffffffffff rdx:0x1 rsi:0x1000 rdi:0x7fadd2938000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bcb08 r9:0x7fadd99bcb08 r10:0x7fadd99beb40 r11:0x246 r12:0x0 r13:0x7fadd271c000 r14:0x0 r15:0x7fadd271c758 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.970989 global_time:28790, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:1684518 rax:0xffffffffffffffda rbx:0x7fadd99be5a8 rcx:0xffffffffffffffff rdx:0x1 rsi:0xa000 rdi:0x7fadd307e000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bc080 r9:0x7fadd99bc080 r10:0x7fadd99be5a8 r11:0x246 r12:0x0 r13:0x7fadd293a000 r14:0x0 r15:0x7fadd2961418 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.971012 global_time:28791, event:SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:1684518 rax:0x0 rbx:0x7fadd99be5a8 rcx:0xffffffffffffffff rdx:0x1 rsi:0xa000 rdi:0x7fadd307e000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bc080 r9:0x7fadd99bc080 r10:0x7fadd99be5a8 r11:0x246 r12:0x0 r13:0x7fadd293a000 r14:0x0 r15:0x7fadd2961418 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.972570 global_time:28792, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:2221173 rax:0xffffffffffffffda rbx:0x7fadd99be000 rcx:0xffffffffffffffff rdx:0x1 rsi:0x8000 rdi:0x7fadd35c7000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99be000 r9:0x7fadd99be000 r10:0x7fadd99be000 r11:0x246 r12:0x0 r13:0x7fadd30a1000 r14:0x0 r15:0x7fadd30fb510 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.972592 global_time:28793, event:SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:2221173 rax:0x0 rbx:0x7fadd99be000 rcx:0xffffffffffffffff rdx:0x1 rsi:0x8000 rdi:0x7fadd35c7000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99be000 r9:0x7fadd99be000 r10:0x7fadd99be000 r11:0x246 r12:0x0 r13:0x7fadd30a1000 r14:0x0 r15:0x7fadd30fb510 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.972895 global_time:28794, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:2353946 rax:0xffffffffffffffda rbx:0x7fadd99bfa08 rcx:0xffffffffffffffff rdx:0x1 rsi:0x2000 rdi:0x7fadd3881000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bc080 r9:0x7fadd99bc080 r10:0x7fadd99bfa08 r11:0x246 r12:0x0 r13:0x7fadd35e1000 r14:0x0 r15:0x7fadd35e69b0 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.972916 global_time:28795, event:SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:2353946 rax:0x0 rbx:0x7fadd99bfa08 rcx:0xffffffffffffffff rdx:0x1 rsi:0x2000 rdi:0x7fadd3881000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bc080 r9:0x7fadd99bc080 r10:0x7fadd99bfa08 r11:0x246 r12:0x0 r13:0x7fadd35e1000 r14:0x0 r15:0x7fadd35e69b0 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.972952 global_time:28796, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:2356174 rax:0xffffffffffffffda rbx:0x7fadd99bf000 rcx:0xffffffffffffffff rdx:0x1 rsi:0x1000 rdi:0x7fadd3c91000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bcb08 r9:0x7fadd99bcb08 r10:0x7fadd99bf000 r11:0x246 r12:0x0 r13:0x7fadd3a90000 r14:0x0 r15:0x7fadd3a905a0 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.972973 global_time:28797, event:SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:2356174 rax:0x0 rbx:0x7fadd99bf000 rcx:0xffffffffffffffff rdx:0x1 rsi:0x1000 rdi:0x7fadd3c91000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bcb08 r9:0x7fadd99bcb08 r10:0x7fadd99bf000 r11:0x246 r12:0x0 r13:0x7fadd3a90000 r14:0x0 r15:0x7fadd3a905a0 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.973391 global_time:28798, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:2444482 rax:0xffffffffffffffda rbx:0x7fadd99e1000 rcx:0xffffffffffffffff rdx:0x1 rsi:0x3000 rdi:0x7fadd4550000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99e1000 r9:0x7fadd99e1000 r10:0x7fadd99e1000 r11:0x246 r12:0x0 r13:0x7fadd40b4000 r14:0x0 r15:0x7fadd40be230 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.973413 global_time:28799, event:SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:2444482 rax:0x0 rbx:0x7fadd99e1000 rcx:0xffffffffffffffff rdx:0x1 rsi:0x3000 rdi:0x7fadd4550000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99e1000 r9:0x7fadd99e1000 r10:0x7fadd99e1000 r11:0x246 r12:0x0 r13:0x7fadd40b4000 r14:0x0 r15:0x7fadd40be230 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.974931 global_time:28800, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:3050630 rax:0xffffffffffffffda rbx:0x7fadd99e2108 rcx:0xffffffffffffffff rdx:0x1 rsi:0x9000 rdi:0x7fadd4ce8000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bc080 r9:0x7fadd99bc080 r10:0x7fadd99e2108 r11:0x246 r12:0x0 r13:0x7fadd47ee000 r14:0x0 r15:0x7fadd4804200 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.974955 global_time:28801, event:SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:3050630 rax:0x0 rbx:0x7fadd99e2108 rcx:0xffffffffffffffff rdx:0x1 rsi:0x9000 rdi:0x7fadd4ce8000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bc080 r9:0x7fadd99bc080 r10:0x7fadd99e2108 r11:0x246 r12:0x0 r13:0x7fadd47ee000 r14:0x0 r15:0x7fadd4804200 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.991563 global_time:28802, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:9559562 rax:0xffffffffffffffda rbx:0x7fadd99e3b60 rcx:0xffffffffffffffff rdx:0x1 rsi:0x5e000 rdi:0x7fadd6492000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bc080 r9:0x7fadd99bc080 r10:0x7fadd99e3b60 r11:0x246 r12:0x0 r13:0x7fadd4d01000 r14:0x0 r15:0x7fadd4d84678 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755682.991602 global_time:28803, event:SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:9559562 rax:0x0 rbx:0x7fadd99e3b60 rcx:0xffffffffffffffff rdx:0x1 rsi:0x5e000 rdi:0x7fadd6492000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99bc080 r9:0x7fadd99bc080 r10:0x7fadd99e3b60 r11:0x246 r12:0x0 r13:0x7fadd4d01000 r14:0x0 r15:0x7fadd4d84678 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755683.017176 global_time:28804, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:20447703 rax:0xffffffffffffffda rbx:0x7fadd99e35c0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x14e000 rdi:0x7fadd936a000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99e35c0 r9:0x7fadd99e35c0 r10:0x7fadd99e35c0 r11:0x246 r12:0x0 r13:0x7fadd6562000 r14:0x0 r15:0x7fadd6951308 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755683.017222 global_time:28805, event:SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:20447703 rax:0x0 rbx:0x7fadd99e35c0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x14e000 rdi:0x7fadd936a000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd99e35c0 r9:0x7fadd99e35c0 r10:0x7fadd99e35c0 r11:0x246 r12:0x0 r13:0x7fadd6562000 r14:0x0 r15:0x7fadd6951308 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755683.017255 global_time:28806, event:SYSCALL: mprotect' (state:ENTERING_SYSCALL) tid:24074, ticks:20447775 rax:0xffffffffffffffda rbx:0x7fadd99e3000 rcx:0xffffffffffffffff rdx:0x1 rsi:0x1000 rdi:0x7fadd97bd000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd95967c8 r9:0x7fadd9596888 r10:0x7fadd99e3000 r11:0x246 r12:0x0 r13:0x7fadd9596000 r14:0x0 r15:0x1 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 } { real_time:9755683.017277 global_time:28807, event:`SYSCALL: mprotect' (state:EXITING_SYSCALL) tid:24074, ticks:20447775 rax:0x0 rbx:0x7fadd99e3000 rcx:0xffffffffffffffff rdx:0x1 rsi:0x1000 rdi:0x7fadd97bd000 rbp:0x7ffddcc64970 rsp:0x7ffddcc64828 r8:0x7fadd95967c8 r9:0x7fadd9596888 r10:0x7fadd99e3000 r11:0x246 r12:0x0 r13:0x7fadd9596000 r14:0x0 r15:0x1 rip:0x7fadd97dcde7 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xa fs_base:0x7fadd99b77c0 gs_base:0x0 }

rocallahan commented 4 years ago

Exactly what CPU is this? Is this in a VM? Has rr ever worked in this configuration for you?

malhanvishal commented 4 years ago

This is a SUSE Linux 12 running on Intel(R) Xeon(R) CPU X5680 @ 3.33GHz And yes this configuration is working otherwise.

rocallahan commented 4 years ago

This is pretty old. I thought Westmere worked with rr but it's the first generation that did, so it might be flaky.

According to that message we configured a PMU interrupt for a pretty small number of events, then we got the interrupt but we've executed far more than than we expected.

You could try changing the skid size here to something ridiculous:

  { IntelWestmere, "Intel Westmere", 0x5101c4, 0, 0x50011d, 0, 100, PMU_TICKS_RCB },

i.e. change 100 to 10000 or something like that. That would probably make rr more stable but significantly slower. Let us know if that helps.

malhanvishal commented 4 years ago

Thanks for your help, i shall try that.

Keno commented 4 years ago

I thought Westmere worked with rr but it's the first generation that did, so it might be flaky.

FWIW, we ran rr on a big Westmere box for years until we turned off that box, and didn't run into any kind of hardware issue.

milianw commented 4 days ago

I am running into the same issue, but with AMD Ryzen 9 3900X 12-Core Processor. I have successfully used rr in the past on this machine, but for complex tasks it fails. I built the latest rr from master today and ran the zen_workaround.py script too. My system is Arch based, with currently running 6.11.3-arch1-1 #1 SMP PREEMPT_DYNAMIC Thu, 10 Oct 2024 20:11:06 +0000 x86_64 GNU/Linux

[FATAL src/PerfCounters.cc:1092:read_ticks()] 
 (task 312179 (rec:311690) at time 94898)
 -> Assertion `false' failed to hold. Detected 1305912 ticks, expected no more than 1300248
Tail of trace dump:
{
  real_time:14992.450186 global_time:94878, event:`SYSCALLBUF_FLUSH' tid:311690, ticks:5022773870
  { syscall:'write', ret:0x10, size:0x10, desched:1 }
}
{
  real_time:14992.450191 global_time:94879, event:`SYSCALL: close' (state:ENTERING_SYSCALL) tid:311690, ticks:5022773870
rax:0xffffffffffffffda rbx:0x10 rcx:0xffffffffffffffff rdx:0x10 rsi:0x731dbfffb4fc rdi:0x11a rbp:0x731dbfffb530 rsp:0x731dbfffb4e8 r8:0x1 r9:0x731df6c76f60 r10:0xb7e6 r11:0x246 r12:0x10 r13:0x1 r14:0x731e024d2ff0 r15:0x731dbf153610 rip:0x731df6c1b31e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x3 fs_base:0x731dc00006c0 gs_base:0x0
}
{
  real_time:14992.450196 global_time:94880, event:`SYSCALLBUF_RESET' tid:311690, ticks:5022773870
}
{
  real_time:14992.450229 global_time:94881, event:`SYSCALL: close' (state:EXITING_SYSCALL) tid:311690, ticks:5022773870
rax:0x0 rbx:0x10 rcx:0xffffffffffffffff rdx:0x10 rsi:0x731dbfffb4fc rdi:0x11a rbp:0x731dbfffb530 rsp:0x731dbfffb4e8 r8:0x1 r9:0x731df6c76f60 r10:0xb7e6 r11:0x246 r12:0x10 r13:0x1 r14:0x731e024d2ff0 r15:0x731dbf153610 rip:0x731df6c1b31e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x3 fs_base:0x731dc00006c0 gs_base:0x0
  { tid:311688, addr:0x731e71b5f602, length:0x1 }
}
{
  real_time:14992.450265 global_time:94882, event:`SYSCALL: close' (state:ENTERING_SYSCALL) tid:311690, ticks:5022773870
rax:0xffffffffffffffda rbx:0x10 rcx:0xffffffffffffffff rdx:0x10 rsi:0x731dbfffb4fc rdi:0x11d rbp:0x731dbfffb530 rsp:0x731dbfffb4e8 r8:0x1 r9:0x731df6c76f60 r10:0xb7e6 r11:0x246 r12:0x10 r13:0x1 r14:0x731e024d2ff0 r15:0x731dbf153610 rip:0x731df6c1b31e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x3 fs_base:0x731dc00006c0 gs_base:0x0
}
{
  real_time:14992.450299 global_time:94883, event:`SYSCALL: close' (state:EXITING_SYSCALL) tid:311690, ticks:5022773870
rax:0x0 rbx:0x10 rcx:0xffffffffffffffff rdx:0x10 rsi:0x731dbfffb4fc rdi:0x11d rbp:0x731dbfffb530 rsp:0x731dbfffb4e8 r8:0x1 r9:0x731df6c76f60 r10:0xb7e6 r11:0x246 r12:0x10 r13:0x1 r14:0x731e024d2ff0 r15:0x731dbf153610 rip:0x731df6c1b31e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x3 fs_base:0x731dc00006c0 gs_base:0x0
  { tid:311688, addr:0x731e71b5f605, length:0x1 }
}
{
  real_time:14992.450444 global_time:94884, event:`SCHED' tid:311690, ticks:5023351071
rax:0x0 rbx:0x526000318b14 rcx:0xf4 rdx:0x4 rsi:0xfd rdi:0x731dbeea6990 rbp:0x731dbeea6b00 rsp:0x731dbfffb548 r8:0xfd r9:0x19525 r10:0x731df75ef788 r11:0x391 r12:0xe63b7dd4d00 r13:0x505 r14:0x731dbf159340 r15:0x731dbeea6800 rip:0x731dfffae73e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_base:0x731dc00006c0 gs_base:0x0
}
{
  real_time:14992.450845 global_time:94885, event:`SYSCALLBUF_FLUSH' tid:311688, ticks:1518654663
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'ppoll', ret:0x1, size:0x38 }
  { syscall:'read', ret:0x8, size:0x18, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
}
{
  real_time:14992.450852 global_time:94886, event:`SYSCALL: mmap' (state:ENTERING_SYSCALL) tid:311688, ticks:1518654663
rax:0xffffffffffffffda rbx:0x32 rcx:0xffffffffffffffff rdx:0x3 rsi:0x10000 rdi:0x5190008a0000 rbp:0x7ffeb9f747f0 rsp:0x7ffeb9f747d8 r8:0xffffffffffffffff r9:0x0 r10:0x32 r11:0x246 r12:0xffffffffffffffff r13:0x0 r14:0x5190008a0000 r15:0x7ffeb9f7481c rip:0x731e7151c309 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x731e3f475b00 gs_base:0x0
}
{
  real_time:14992.450858 global_time:94887, event:`SYSCALLBUF_RESET' tid:311688, ticks:1518654663
}
{
  real_time:14992.450909 global_time:94888, event:`SYSCALL: mmap' (state:EXITING_SYSCALL) tid:311688, ticks:1518654663
rax:0x5190008a0000 rbx:0x32 rcx:0xffffffffffffffff rdx:0x3 rsi:0x10000 rdi:0x5190008a0000 rbp:0x7ffeb9f747f0 rsp:0x7ffeb9f747d8 r8:0xffffffffffffffff r9:0x0 r10:0x32 r11:0x246 r12:0xffffffffffffffff r13:0x0 r14:0x5190008a0000 r15:0x7ffeb9f7481c rip:0x731e7151c309 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x731e3f475b00 gs_base:0x0
  { map_file:"<ZERO>", addr:0x5190008a0000, length:0x10000, prot_flags:"rw-p", file_offset:0x0, device:0, inode:0, data_file:"", data_offset:0x0, file_size:0x10000 }
}
{
  real_time:14992.451912 global_time:94889, event:`SYSCALL: mmap' (state:ENTERING_SYSCALL) tid:311688, ticks:1519024714
rax:0xffffffffffffffda rbx:0x32 rcx:0xffffffffffffffff rdx:0x3 rsi:0x10000 rdi:0x523000310000 rbp:0x7ffeb9f71a40 rsp:0x7ffeb9f71a28 r8:0xffffffffffffffff r9:0x0 r10:0x32 r11:0x246 r12:0xffffffffffffffff r13:0x0 r14:0x523000310000 r15:0x7ffeb9f71a6c rip:0x731e7151c309 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x731e3f475b00 gs_base:0x0
}
{
  real_time:14992.451961 global_time:94890, event:`SYSCALL: mmap' (state:EXITING_SYSCALL) tid:311688, ticks:1519024714
rax:0x523000310000 rbx:0x32 rcx:0xffffffffffffffff rdx:0x3 rsi:0x10000 rdi:0x523000310000 rbp:0x7ffeb9f71a40 rsp:0x7ffeb9f71a28 r8:0xffffffffffffffff r9:0x0 r10:0x32 r11:0x246 r12:0xffffffffffffffff r13:0x0 r14:0x523000310000 r15:0x7ffeb9f71a6c rip:0x731e7151c309 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x731e3f475b00 gs_base:0x0
  { map_file:"<ZERO>", addr:0x523000310000, length:0x10000, prot_flags:"rw-p", file_offset:0x0, device:0, inode:0, data_file:"", data_offset:0x0, file_size:0x10000 }
}
{
  real_time:14992.454490 global_time:94891, event:`SYSCALLBUF_FLUSH' tid:311688, ticks:1520156354
  { syscall:'gettimeofday', ret:0x0, size:0x20 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'ppoll', ret:0x1, size:0x38 }
  { syscall:'read', ret:0x8, size:0x18, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'ppoll', ret:0x1, size:0x38 }
  { syscall:'read', ret:0x8, size:0x18, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
}
{
  real_time:14992.454497 global_time:94892, event:`SYSCALL: mmap' (state:ENTERING_SYSCALL) tid:311688, ticks:1520156354
rax:0xffffffffffffffda rbx:0x32 rcx:0xffffffffffffffff rdx:0x3 rsi:0x10000 rdi:0x5190008b0000 rbp:0x7ffeb9f735d0 rsp:0x7ffeb9f735b8 r8:0xffffffffffffffff r9:0x0 r10:0x32 r11:0x246 r12:0xffffffffffffffff r13:0x0 r14:0x5190008b0000 r15:0x7ffeb9f735fc rip:0x731e7151c309 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x731e3f475b00 gs_base:0x0
}
{
  real_time:14992.454503 global_time:94893, event:`SYSCALLBUF_RESET' tid:311688, ticks:1520156354
}
{
  real_time:14992.454550 global_time:94894, event:`SYSCALL: mmap' (state:EXITING_SYSCALL) tid:311688, ticks:1520156354
rax:0x5190008b0000 rbx:0x32 rcx:0xffffffffffffffff rdx:0x3 rsi:0x10000 rdi:0x5190008b0000 rbp:0x7ffeb9f735d0 rsp:0x7ffeb9f735b8 r8:0xffffffffffffffff r9:0x0 r10:0x32 r11:0x246 r12:0xffffffffffffffff r13:0x0 r14:0x5190008b0000 r15:0x7ffeb9f735fc rip:0x731e7151c309 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x731e3f475b00 gs_base:0x0
  { map_file:"<ZERO>", addr:0x5190008b0000, length:0x10000, prot_flags:"rw-p", file_offset:0x0, device:0, inode:0, data_file:"", data_offset:0x0, file_size:0x10000 }
}
{
  real_time:14992.455196 global_time:94895, event:`SYSCALLBUF_FLUSH' tid:311688, ticks:1520423975
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'ppoll', ret:0x1, size:0x38 }
  { syscall:'read', ret:0x8, size:0x18, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'ppoll', ret:0x1, size:0x38 }
  { syscall:'read', ret:0x8, size:0x18, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
}
{
  real_time:14992.455202 global_time:94896, event:`SCHED' tid:311688, ticks:1520423975
rax:0x504000424150 rbx:0x256 rcx:0x320 rdx:0x258 rsi:0x51b0004b7d88 rdi:0x7ffeb9f724c0 rbp:0x51b0004b7d88 rsp:0x7ffeb9f71c20 r8:0x1 r9:0x256 r10:0x0 r11:0xe2c00000000 r12:0x51b0004b7880 r13:0x31f r14:0x255 r15:0x1 rip:0x731e0d1d079b eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_base:0x731e3f475b00 gs_base:0x0
}
{
  real_time:14992.455208 global_time:94897, event:`SYSCALLBUF_RESET' tid:311688, ticks:1520423975
}
{
  real_time:14992.455448 global_time:94898, event:`SCHED' tid:311690, ticks:5024651319
rax:0xe63b7dd4d4e rbx:0x731dbeea6990 rcx:0xf4 rdx:0x731dbeea6a60 rsi:0xfd rdi:0x731dbeea6a58 rbp:0x731dbeea6a70 rsp:0x731dbfffb500 r8:0xfd r9:0x19525 r10:0x731df75ef788 r11:0x391 r12:0x731dbeea6a60 r13:0x2 r14:0x2233 r15:0x1 rip:0x731dfffaf3d9 eflags:0x206 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_base:0x731dc00006c0 gs_base:0x0
}
{
  real_time:14992.456189 global_time:94899, event:`SYSCALLBUF_FLUSH' tid:311688, ticks:1520835784
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'ppoll', ret:0x1, size:0x38 }
  { syscall:'read', ret:0x8, size:0x18, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'write', ret:0x8, size:0x10, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'ppoll', ret:0x1, size:0x38 }
  { syscall:'read', ret:0x8, size:0x18, desched:1 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'ppoll', ret:0x0, size:0x38 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
}
=== Start rr backtrace:
rr(_ZN2rr13dump_rr_stackERNS_8ScopedFdE+0x3d) [0x615f51cac44d]
rr(_ZN2rr15emergency_debugEPNS_4TaskE+0x189) [0x615f51b61939]
rr(_ZN2rr21EmergencyDebugOstreamD2Ev+0x2ca) [0x615f51b67aaa]
rr(_ZN2rr12PerfCounters10read_ticksEPNS_4TaskEPNS0_5ErrorE+0x4ee) [0x615f51b92c4e]
rr(_ZN2rr12PerfCounters4stopEPNS_4TaskEPNS0_5ErrorE+0x38) [0x615f51b97558]
rr(_ZN2rr4Task11did_waitpidENS_10WaitStatusE+0x792) [0x615f51c7d172]
rr(_ZN2rr4Task4waitEd+0x211) [0x615f51c7dbf1]
rr(_ZN2rr4Task16resume_executionENS_13ResumeRequestENS_11WaitRequestENS_12TicksRequestEi+0x828) [0x615f51c7e5a8]
rr(_ZN2rr13ReplaySession16continue_or_stepEPNS_10ReplayTaskERKNS0_15StepConstraintsENS_12TicksRequestENS_13ResumeRequestE+0x48) [0x615f51c15658]
rr(_ZN2rr13ReplaySession20emulate_async_signalEPNS_10ReplayTaskERKNS0_15StepConstraintsElNS_15remote_code_ptrE+0x306) [0x615f51c1d0a6]
rr(_ZN2rr13ReplaySession18try_one_trace_stepEPNS_10ReplayTaskERKNS0_15StepConstraintsE+0x20c) [0x615f51c1ea4c]
rr(_ZN2rr13ReplaySession11replay_stepERKNS0_15StepConstraintsE+0x201) [0x615f51c1ff61]
rr(_ZN2rr14ReplayTimeline19replay_step_forwardENS_10RunCommandE+0xba) [0x615f51c41cfa]
rr(_ZN2rr9GdbServer14debug_one_stepERNS_10GdbRequestE+0x3f4) [0x615f51b4b4f4]
rr(_ZN2rr9GdbServer12serve_replayESt10shared_ptrINS_13ReplaySessionEERKNS0_6TargetEPVbRKNS0_15ConnectionFlagsE+0x8ab) [0x615f51b4cc2b]
rr(_ZN2rr13ReplayCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0x1644) [0x615f51c126d4]
rr(main+0x2cf) [0x615f51ad5b8f]
/usr/lib/libc.so.6(+0x25e08) [0x74e4e4b17e08]
/usr/lib/libc.so.6(__libc_start_main+0x8c) [0x74e4e4b17ecc]
rr(_start+0x25) [0x615f51ad7165]
=== End rr backtrace
Keno commented 4 days ago

Known issue with AMD unfortunately. Their interrupts sometimes take tens of thousands of cycles to deliver for unknown reasons. Complain to AMD if you have the opportunity ;).

milianw commented 4 days ago

Is there a workaround? I initially understood that Zen 1 does support rr with the workaround in place - your message suddenly sounds like it isn't supported... Does this limitation apply to all AMD CPUs, including newer ones?

Keno commented 4 days ago

It's fully supported for record and mostly supported for replay, just occasionally it fails for poorly understood microarchitectural reasons. Anecdotally the newer chips are worse than the older ones, but I don't think anybody has tried to understand the issue in detail.