search

rr-debugger / rr

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

Assertion `!counting_period || measure_val <= adjusted_counting_period' failed to hold #2092

Closed froydnj closed 7 years ago

froydnj commented 7 years ago

Saw this while running tests with a fresh checkout of rr master. System is Ubuntu 16.04, kernel 4.4.0-89 on a Core i7 6850K. This assertion fires on a couple of different tests; nearly all of the other tests are OK, though several tests dealing with async signals appear to be hanging. The same assertion fires while trying to record Firefox on this machine.

Output from the test runner (much improved, this is great!) follows:

602: Test 'timer' FAILED: : error during recording:
602: --------------------------------------------------
602: [FATAL /home/froydnj/src/rr/src/PerfCounters.cc:767:read_ticks() errno: SUCCESS] 
602:  (task 22713 (rec:22713) at time 459)
602:  -> Assertion `!counting_period || measure_val <= adjusted_counting_period' failed to hold. Detected 9275 ticks, expected no more than 5137
602: [FATAL /home/froydnj/src/rr/src/log.cc:356:emergency_debug() errno: SUCCESS] Can't resume execution from invalid state
602: 2626
602: TracerPid: 0
602: Uid:   1000    1000    1000    1000
602: Gid:   1000    1000    1000    1000
602: FDSize:    64
602: Groups:    4 24 27 30 46 113 128 129 131 1000 
602: NStgid:    22640
602: NSpid: 22640
602: NSpgid:    22526
602: NSsid: 13024
602: VmPeak:      920588 kB
602: VmSize:      796468 kB
602: VmLck:        0 kB
602: VmPin:        0 kB
602: VmHWM:    37860 kB
602: VmRSS:    33464 kB
602: VmData:      768988 kB
602: VmStk:      132 kB
602: VmExe:     2344 kB
602: VmLib:     5416 kB
602: VmPTE:      172 kB
602: VmPMD:       16 kB
602: VmSwap:           0 kB
602: HugetlbPages:         0 kB
602: Threads:   1
602: SigQ:  5/256394
602: SigPnd:    0000000000000000
602: ShdPnd:    0000000000000000
602: SigBlk:    0000000000000000
602: SigIgn:    0000000000000000
602: SigCgt:    0000000180006000
602: CapInh:    0000000000000000
602: CapPrm:    0000000000000000
602: CapEff:    0000000000000000
602: CapBnd:    0000003fffffffff
602: CapAmb:    0000000000000000
602: Seccomp:   0
602: Cpus_allowed:  100
602: Cpus_allowed_list: 8
602: Mems_allowed:  00000000,00000001
602: Mems_allowed_list: 0
602: voluntary_ctxt_switches:   246
602: nonvoluntary_ctxt_switches:    534
602: ====== /proc/22640/stack
602: [<0000000000000000>] inet_csk_accept+0x271/0x350
602: [<0000000000000000>] inet_accept+0x3c/0x130
602: [<0000000000000000>] SYSC_accept4+0x103/0x210
602: [<0000000000000000>] SyS_accept+0x10/0x20
602: [<0000000000000000>] entry_SYSCALL_64_fastpath+0x16/0x71
602: [<0000000000000000>] 0xffffffffffffffff
602: ====== /proc/22713/status
602: Name:  timer-RIWbUW97O
602: State: t (tracing stop)
602: Tgid:  22713
602: Ngid:  0
602: Pid:   22713
602: PPid:  22640
602: TracerPid: 22640
602: Uid:   1000    1000    1000    1000
602: Gid:   1000    1000    1000    1000
602: FDSize:    1024
602: Groups:    4 24 27 30 46 113 128 129 131 1000 
602: NStgid:    22713
602: NSpid: 22713
602: NSpgid:    22526
602: NSsid: 13024
602: VmPeak:       13948 kB
602: VmSize:       13948 kB
602: VmLck:        0 kB
602: VmPin:        0 kB
602: VmHWM:     3692 kB
602: VmRSS:     3692 kB
602: VmData:        2420 kB
602: VmStk:        0 kB
602: VmExe:       12 kB
602: VmLib:     2236 kB
602: VmPTE:       48 kB
602: VmPMD:       16 kB
602: VmSwap:           0 kB
602: HugetlbPages:         0 kB
602: Threads:   1
602: SigQ:  5/256394
602: SigPnd:    0000000000000000
602: ShdPnd:    0000000000002000
602: SigBlk:    0000000000000000
602: SigIgn:    0000000000000000
602: SigCgt:    0000000180002200
602: CapInh:    0000000000000000
602: CapPrm:    0000000000000000
602: CapEff:    0000000000000000
602: CapBnd:    0000003fffffffff
602: CapAmb:    0000000000000000
602: Seccomp:   2
602: Cpus_allowed:  100
602: Cpus_allowed_list: 8
602: Mems_allowed:  00000000,00000001
602: Mems_allowed_list: 0
602: voluntary_ctxt_switches:   748
602: nonvoluntary_ctxt_switches:    1
602: ====== /proc/22713/stack
602: [<0000000000000000>] ptrace_stop+0x16e/0x2a0
602: [<0000000000000000>] get_signal+0x34a/0x600
602: [<0000000000000000>] do_signal+0x37/0x6f0
602: [<0000000000000000>] exit_to_usermode_loop+0x8c/0xd0
602: [<0000000000000000>] prepare_exit_to_usermode+0x26/0x30
602: [<0000000000000000>] retint_user+0x8/0x10
602: [<0000000000000000>] 0xffffffffffffffff
602: ====== gdb -p 22640 -ex 'set confirm off' -ex 'set height 0' -ex 'thread apply all bt' -ex q </dev/null 2>&1
602: GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
602: Copyright (C) 2016 Free Software Foundation, Inc.
602: License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
602: This is free software: you are free to change and redistribute it.
602: There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
602: and "show warranty" for details.
602: This GDB was configured as "x86_64-linux-gnu".
602: Type "show configuration" for configuration details.
602: For bug reporting instructions, please see:
602: <http://www.gnu.org/software/gdb/bugs/>.
602: Find the GDB manual and other documentation resources online at:
602: <http://www.gnu.org/software/gdb/documentation/>.
602: For help, type "help".
602: Type "apropos word" to search for commands related to "word".
602: Attaching to process 22640
602: Reading symbols from /home/froydnj/src/rr/bin/rr...done.
602: Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libdl-2.23.so...done.
602: done.
602: Reading symbols from /lib/x86_64-linux-gnu/librt.so.1...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/librt-2.23.so...done.
602: done.
602: Reading symbols from /usr/lib/x86_64-linux-gnu/libcapnp-0.5.3.so...(no debugging symbols found)...done.
602: Reading symbols from /usr/lib/x86_64-linux-gnu/libkj-0.5.3.so...(no debugging symbols found)...done.
602: Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...Reading symbols from /usr/lib/debug/.build-id/27/f189ef8db8c3734c6a678e6ef3cb0b206d58b2.debug...done.
602: done.
602: [Thread debugging using libthread_db enabled]
602: Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
602: Reading symbols from /usr/lib/x86_64-linux-gnu/libstdc++.so.6...(no debugging symbols found)...done.
602: Reading symbols from /lib/x86_64-linux-gnu/libm.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libm-2.23.so...done.
602: done.
602: Reading symbols from /lib/x86_64-linux-gnu/libgcc_s.so.1...(no debugging symbols found)...done.
602: Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libc-2.23.so...done.
602: done.
602: Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/ld-2.23.so...done.
602: done.
602: 0x00007f8108eda76d in accept () at ../sysdeps/unix/syscall-template.S:84
602: 84 ../sysdeps/unix/syscall-template.S: No such file or directory.
602: 
602: Thread 1 (Thread 0x7f8109b9c740 (LWP 22640)):
602: #0  0x00007f8108eda76d in accept () at ../sysdeps/unix/syscall-template.S:84
602: #1  0x000000000046fc47 in rr::GdbConnection::await_debugger (this=0xd7da10, 
602:     listen_fd=...) at /home/froydnj/src/rr/src/GdbConnection.cc:70
602: #2  0x00000000004836b1 in rr::await_connection (t=t@entry=0xd7e6c0, listen_fd=..., 
602:     features=...) at /home/froydnj/src/rr/src/GdbServer.cc:1430
602: #3  0x000000000048d4d5 in rr::GdbServer::emergency_debug (t=t@entry=0xd7e6c0)
602:     at /home/froydnj/src/rr/src/GdbServer.cc:1630
602: #4  0x000000000049a706 in rr::emergency_debug (t=<optimized out>)
602:     at /home/froydnj/src/rr/src/log.cc:355
602: #5  rr::EmergencyDebugOstream::~EmergencyDebugOstream (this=<optimized out>, 
602:     __in_chrg=<optimized out>) at /home/froydnj/src/rr/src/log.cc:377
602: #6  0x00000000004ad4a8 in rr::PerfCounters::read_ticks (this=this@entry=0xd7e6e8, 
602:     t=t@entry=0xd7e6c0) at /home/froydnj/src/rr/src/PerfCounters.cc:768
602: #7  0x0000000000530b5c in rr::Task::did_waitpid (this=this@entry=0xd7e6c0, status=...)
602:     at /home/froydnj/src/rr/src/Task.cc:1522
602: #8  0x0000000000531878 in rr::Task::wait (this=0xd7e6c0, interrupt_after_elapsed=3)
602:     at /home/froydnj/src/rr/src/Task.cc:1387
602: #9  0x000000000051e136 in rr::Scheduler::reschedule (this=this@entry=0xd7c588, 
602:     switchable=<optimized out>) at /home/froydnj/src/rr/src/Scheduler.cc:380
602: #10 0x00000000004b9c63 in rr::RecordSession::record_step (this=0xd7c420)
602:     at /home/froydnj/src/rr/src/RecordSession.cc:1802
602: #11 0x00000000004b22d7 in rr::record (flags=..., args=...)
602:     at /home/froydnj/src/rr/src/RecordCommand.cc:362
602: #12 rr::RecordCommand::run (this=0x64d240 <rr::RecordCommand::singleton>, args=...)
602:     at /home/froydnj/src/rr/src/RecordCommand.cc:474
602: #13 0x0000000000552336 in main (argc=7, argv=0x7ffda7f7ac48)
602:     at /home/froydnj/src/rr/src/main.cc:236
602: Detaching from program: /home/froydnj/src/rr/bin/rr, process 22640
602: ====== gdb '-l' '10000' '-ex' 'set sysroot /' '-ex' 'target extended-remote 127.0.0.1:22713' -ex 'set confirm off' -ex 'set height 0' -ex 'info registers' -ex 'thread apply all bt' -ex q /tmp/rr-test-timer-RIWbUW97O/timer-RIWbUW97O
602:  </dev/null 2>&1
602: GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
602: Copyright (C) 2016 Free Software Foundation, Inc.
602: License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
602: This is free software: you are free to change and redistribute it.
602: There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
602: and "show warranty" for details.
602: This GDB was configured as "x86_64-linux-gnu".
602: Type "show configuration" for configuration details.
602: For bug reporting instructions, please see:
602: <http://www.gnu.org/software/gdb/bugs/>.
602: Find the GDB manual and other documentation resources online at:
602: <http://www.gnu.org/software/gdb/documentation/>.
602: For help, type "help".
602: Type "apropos word" to search for commands related to "word"...
602: Reading symbols from /tmp/rr-test-timer-RIWbUW97O/timer-RIWbUW97O...done.
602: Remote debugging using 127.0.0.1:22713
602: Reading symbols from /home/froydnj/src/rr/bin/../lib/rr/librrpreload.so...done.
602: Reading symbols from /lib/x86_64-linux-gnu/librt.so.1...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/librt-2.23.so...done.
602: done.
602: Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...Reading symbols from /usr/lib/debug/.build-id/27/f189ef8db8c3734c6a678e6ef3cb0b206d58b2.debug...done.
602: done.
602: Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libc-2.23.so...done.
602: done.
602: Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libdl-2.23.so...done.
602: done.
602: Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/ld-2.23.so...done.
602: done.
602: start_commit_buffered_syscall (syscallno=186, record_end=0x7f55a798abbe, blockness=-2)
602:     at /home/froydnj/src/rr/src/preload/syscallbuf.c:751
602: 751        return 0;
602: rax            0x1b90  7056
602: rbx            0x681fffa0  1746927520
602: rcx            0x0 0
602: rdx            0xfffffffe  4294967294
602: rsi            0x7f55a798abbe  140005860748222
602: rdi            0xba    186
602: rbp            0x7f55a798abbe  0x7f55a798abbe
602: rsp            0x681ffe38  0x681ffe38
602: r8             0x7f55a7989000  140005860741120
602: r9             0x7f55a798abae  140005860748206
602: r10            0xba    186
602: r11            0xba    186
602: r12            0x400b80    4197248
602: r13            0x7ffeaf2b4170  140731837268336
602: r14            0x0 0
602: r15            0x0 0
602: rip            0x7f55a7ab1fb9  0x7f55a7ab1fb9 <start_commit_buffered_syscall+25>
602: eflags         0x206   [ PF IF ]
602: cs             0x33    51
602: ss             0x2b    43
602: ds             0x0 0
602: es             0x0 0
602: fs             0x0 0
602: gs             0x0 0
602: fs_base        0x7f55a7a8a700  0x7f55a7a8a700
602: gs_base        0x0 0x0
602: 
602: Thread 1 (Thread 22713.22713):
602: #0  start_commit_buffered_syscall (syscallno=186, record_end=0x7f55a798abbe, 
602:     blockness=-2) at /home/froydnj/src/rr/src/preload/syscallbuf.c:751
602: #1  0x00007f55a7ab2939 in sys_generic_nonblocking (call=call@entry=0x681fffa0)
602:     at /home/froydnj/src/rr/src/preload/syscallbuf.c:996
602: #2  0x00007f55a7ab2da8 in syscall_hook_internal (call=0x681fffa0)
602:     at /home/froydnj/src/rr/src/preload/syscallbuf.c:2493
602: #3  syscall_hook (call=0x681fffa0)
602:     at /home/froydnj/src/rr/src/preload/syscallbuf.c:2548
602: #4  0x00007f55a7ab1b3a in _syscall_hook_trampoline ()
602:     at /home/froydnj/src/rr/src/preload/syscall_hook.S:282
602: #5  0x00007f55a7ab1b6a in __morestack ()
602:     at /home/froydnj/src/rr/src/preload/syscall_hook.S:417
602: #6  0x00007f55a7ab1b70 in _syscall_hook_trampoline_48_3d_01_f0_ff_ff ()
602:     at /home/froydnj/src/rr/src/preload/syscall_hook.S:423
602: #7  0x00007f55a71ce49f in syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
602: #8  0x0000000000400deb in sys_gettid () at /home/froydnj/src/rr/src/test/util.h:170
602: #9  0x0000000000401326 in main () at /home/froydnj/src/rr/src/test/timer.c:81
602: Detaching from program: /tmp/rr-test-timer-RIWbUW97O/timer-RIWbUW97O, process 22713
602: --------------------------------------------------
602: record.out:
602: --------------------------------------------------
602: --------------------------------------------------
602: Test timer failed, leaving behind /tmp/rr-test-timer-RIWbUW97O
602: To replay the failed test, run
602:   _RR_TRACE_DIR=/tmp/rr-test-timer-RIWbUW97O rr replay

and from a different test:

692: Test 'check_lost_interrupts' FAILED: : error during recording:
692: --------------------------------------------------
692: [FATAL /home/froydnj/src/rr/src/PerfCounters.cc:767:read_ticks() errno: SUCCESS] 
692:  (task 17408 (rec:17408) at time 550)
692:  -> Assertion `!counting_period || measure_val <= adjusted_counting_period' failed to hold. Detected 15068 ticks, expected no more than 8033
692: [FATAL /home/froydnj/src/rr/src/log.cc:356:emergency_debug() errno: SUCCESS] Can't resume execution from invalid state
692: 7352
692: TracerPid: 0
692: Uid:   1000    1000    1000    1000
692: Gid:   1000    1000    1000    1000
692: FDSize:    64
692: Groups:    4 24 27 30 46 113 128 129 131 1000 
692: NStgid:    17357
692: NSpid: 17357
692: NSpgid:    22526
692: NSsid: 13024
692: VmPeak:      929104 kB
692: VmSize:      796468 kB
692: VmLck:        0 kB
692: VmPin:        0 kB
692: VmHWM:    34340 kB
692: VmRSS:    33412 kB
692: VmData:      768988 kB
692: VmStk:      132 kB
692: VmExe:     2344 kB
692: VmLib:     5416 kB
692: VmPTE:      168 kB
692: VmPMD:       16 kB
692: VmSwap:           0 kB
692: HugetlbPages:         0 kB
692: Threads:   1
692: SigQ:  3/256394
692: SigPnd:    0000000000000000
692: ShdPnd:    0000000000000000
692: SigBlk:    0000000000000000
692: SigIgn:    0000000000000000
692: SigCgt:    0000000180006000
692: CapInh:    0000000000000000
692: CapPrm:    0000000000000000
692: CapEff:    0000000000000000
692: CapBnd:    0000003fffffffff
692: CapAmb:    0000000000000000
692: Seccomp:   0
692: Cpus_allowed:  002
692: Cpus_allowed_list: 1
692: Mems_allowed:  00000000,00000001
692: Mems_allowed_list: 0
692: voluntary_ctxt_switches:   581
692: nonvoluntary_ctxt_switches:    1210
692: ====== /proc/17357/stack
692: [<0000000000000000>] inet_csk_accept+0x271/0x350
692: [<0000000000000000>] inet_accept+0x3c/0x130
692: [<0000000000000000>] SYSC_accept4+0x103/0x210
692: [<0000000000000000>] SyS_accept+0x10/0x20
692: [<0000000000000000>] entry_SYSCALL_64_fastpath+0x16/0x71
692: [<0000000000000000>] 0xffffffffffffffff
692: ====== /proc/17408/status
692: Name:  check_lost_inte
692: State: t (tracing stop)
692: Tgid:  17408
692: Ngid:  0
692: Pid:   17408
692: PPid:  17357
692: TracerPid: 17357
692: Uid:   1000    1000    1000    1000
692: Gid:   1000    1000    1000    1000
692: FDSize:    1024
692: Groups:    4 24 27 30 46 113 128 129 131 1000 
692: NStgid:    17408
692: NSpid: 17408
692: NSpgid:    22526
692: NSsid: 13024
692: VmPeak:       11720 kB
692: VmSize:       11720 kB
692: VmLck:        0 kB
692: VmPin:        0 kB
692: VmHWM:     3016 kB
692: VmRSS:     3016 kB
692: VmData:        2280 kB
692: VmStk:        0 kB
692: VmExe:        4 kB
692: VmLib:     2208 kB
692: VmPTE:       40 kB
692: VmPMD:       16 kB
692: VmSwap:           0 kB
692: HugetlbPages:         0 kB
692: Threads:   1
692: SigQ:  3/256394
692: SigPnd:    0000000000000000
692: ShdPnd:    0000000000000000
692: SigBlk:    0000000000000000
692: SigIgn:    0000000000000000
692: SigCgt:    0000000180000000
692: CapInh:    0000000000000000
692: CapPrm:    0000000000000000
692: CapEff:    0000000000000000
692: CapBnd:    0000003fffffffff
692: CapAmb:    0000000000000000
692: Seccomp:   2
692: Cpus_allowed:  002
692: Cpus_allowed_list: 1
692: Mems_allowed:  00000000,00000001
692: Mems_allowed_list: 0
692: voluntary_ctxt_switches:   1753
692: nonvoluntary_ctxt_switches:    0
692: ====== /proc/17408/stack
692: [<0000000000000000>] ptrace_stop+0x16e/0x2a0
692: [<0000000000000000>] get_signal+0x34a/0x600
692: [<0000000000000000>] do_signal+0x37/0x6f0
692: [<0000000000000000>] exit_to_usermode_loop+0x8c/0xd0
692: [<0000000000000000>] prepare_exit_to_usermode+0x26/0x30
692: [<0000000000000000>] retint_user+0x8/0x10
692: [<0000000000000000>] 0xffffffffffffffff
692: ====== gdb -p 17357 -ex 'set confirm off' -ex 'set height 0' -ex 'thread apply all bt' -ex q </dev/null 2>&1
692: GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
692: Copyright (C) 2016 Free Software Foundation, Inc.
692: License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
692: This is free software: you are free to change and redistribute it.
692: There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
692: and "show warranty" for details.
692: This GDB was configured as "x86_64-linux-gnu".
692: Type "show configuration" for configuration details.
692: For bug reporting instructions, please see:
692: <http://www.gnu.org/software/gdb/bugs/>.
692: Find the GDB manual and other documentation resources online at:
692: <http://www.gnu.org/software/gdb/documentation/>.
692: For help, type "help".
692: Type "apropos word" to search for commands related to "word".
692: Attaching to process 17357
692: Reading symbols from /home/froydnj/src/rr/bin/rr...done.
692: Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libdl-2.23.so...done.
692: done.
692: Reading symbols from /lib/x86_64-linux-gnu/librt.so.1...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/librt-2.23.so...done.
692: done.
692: Reading symbols from /usr/lib/x86_64-linux-gnu/libcapnp-0.5.3.so...(no debugging symbols found)...done.
692: Reading symbols from /usr/lib/x86_64-linux-gnu/libkj-0.5.3.so...(no debugging symbols found)...done.
692: Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...Reading symbols from /usr/lib/debug/.build-id/27/f189ef8db8c3734c6a678e6ef3cb0b206d58b2.debug...done.
692: done.
692: [Thread debugging using libthread_db enabled]
692: Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
692: Reading symbols from /usr/lib/x86_64-linux-gnu/libstdc++.so.6...(no debugging symbols found)...done.
692: Reading symbols from /lib/x86_64-linux-gnu/libm.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libm-2.23.so...done.
692: done.
692: Reading symbols from /lib/x86_64-linux-gnu/libgcc_s.so.1...(no debugging symbols found)...done.
692: Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libc-2.23.so...done.
692: done.
692: Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/ld-2.23.so...done.
692: done.
692: 0x00007f6e2de7c76d in accept () at ../sysdeps/unix/syscall-template.S:84
692: 84 ../sysdeps/unix/syscall-template.S: No such file or directory.
692: 
692: Thread 1 (Thread 0x7f6e2eb3e740 (LWP 17357)):
692: #0  0x00007f6e2de7c76d in accept () at ../sysdeps/unix/syscall-template.S:84
692: #1  0x000000000046fc47 in rr::GdbConnection::await_debugger (this=0x20dea60, 
692:     listen_fd=...) at /home/froydnj/src/rr/src/GdbConnection.cc:70
692: #2  0x00000000004836b1 in rr::await_connection (t=t@entry=0x20df710, listen_fd=..., 
692:     features=...) at /home/froydnj/src/rr/src/GdbServer.cc:1430
692: #3  0x000000000048d4d5 in rr::GdbServer::emergency_debug (t=t@entry=0x20df710)
692:     at /home/froydnj/src/rr/src/GdbServer.cc:1630
692: #4  0x000000000049a706 in rr::emergency_debug (t=<optimized out>)
692:     at /home/froydnj/src/rr/src/log.cc:355
692: #5  rr::EmergencyDebugOstream::~EmergencyDebugOstream (this=<optimized out>, 
692:     __in_chrg=<optimized out>) at /home/froydnj/src/rr/src/log.cc:377
692: #6  0x00000000004ad4a8 in rr::PerfCounters::read_ticks (this=this@entry=0x20df738, 
692:     t=t@entry=0x20df710) at /home/froydnj/src/rr/src/PerfCounters.cc:768
692: #7  0x0000000000530b5c in rr::Task::did_waitpid (this=this@entry=0x20df710, status=...)
692:     at /home/froydnj/src/rr/src/Task.cc:1522
692: #8  0x0000000000531878 in rr::Task::wait (this=0x20df710, interrupt_after_elapsed=3)
692:     at /home/froydnj/src/rr/src/Task.cc:1387
692: #9  0x000000000051e136 in rr::Scheduler::reschedule (this=this@entry=0x20dd5d8, 
692:     switchable=<optimized out>) at /home/froydnj/src/rr/src/Scheduler.cc:380
692: #10 0x00000000004b9c63 in rr::RecordSession::record_step (this=0x20dd470)
692:     at /home/froydnj/src/rr/src/RecordSession.cc:1802
692: #11 0x00000000004b22d7 in rr::record (flags=..., args=...)
692:     at /home/froydnj/src/rr/src/RecordCommand.cc:362
692: #12 rr::RecordCommand::run (this=0x64d240 <rr::RecordCommand::singleton>, args=...)
692:     at /home/froydnj/src/rr/src/RecordCommand.cc:474
692: #13 0x0000000000552336 in main (argc=8, argv=0x7ffc53c63e58)
692:     at /home/froydnj/src/rr/src/main.cc:236
692: Detaching from program: /home/froydnj/src/rr/bin/rr, process 17357
692: ====== gdb '-l' '10000' '-ex' 'set sysroot /' '-ex' 'target extended-remote 127.0.0.1:17408' -ex 'set confirm off' -ex 'set height 0' -ex 'info registers' -ex 'thread apply all bt' -ex q /tmp/rr-test-check_lost_interrupts-xiueyooV9/check_lost_interrupts-xiueyooV9
692:  </dev/null 2>&1
692: GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
692: Copyright (C) 2016 Free Software Foundation, Inc.
692: License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
692: This is free software: you are free to change and redistribute it.
692: There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
692: and "show warranty" for details.
692: This GDB was configured as "x86_64-linux-gnu".
692: Type "show configuration" for configuration details.
692: For bug reporting instructions, please see:
692: <http://www.gnu.org/software/gdb/bugs/>.
692: Find the GDB manual and other documentation resources online at:
692: <http://www.gnu.org/software/gdb/documentation/>.
692: For help, type "help".
692: Type "apropos word" to search for commands related to "word"...
692: Reading symbols from /tmp/rr-test-check_lost_interrupts-xiueyooV9/check_lost_interrupts-xiueyooV9...done.
692: Remote debugging using 127.0.0.1:17408
692: Reading symbols from /home/froydnj/src/rr/bin/../lib/rr/librrpreload.so...done.
692: Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...Reading symbols from /usr/lib/debug/.build-id/27/f189ef8db8c3734c6a678e6ef3cb0b206d58b2.debug...done.
692: done.
692: Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libc-2.23.so...done.
692: done.
692: Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libdl-2.23.so...done.
692: done.
692: Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/ld-2.23.so...done.
692: done.
692: 0x000000000040093f in do_some_ticks ()
692:     at /home/froydnj/src/rr/src/test/check_lost_interrupts.c:10
692: 10     dummy += i % 99;
692: rax            0x0 0
692: rbx            0x0 0
692: rcx            0x357   855
692: rdx            0x8 8
692: rsi            0x0 0
692: rdi            0x3 3
692: rbp            0x7ffe443483e0  0x7ffe443483e0
692: rsp            0x7ffe443483e0  0x7ffe443483e0
692: r8             0x400a30    4196912
692: r9             0x7f823e15eab0  140197364099760
692: r10            0x130   304
692: r11            0x3 3
692: r12            0x4006c0    4196032
692: r13            0x7ffe443484e0  140730042713312
692: r14            0x0 0
692: r15            0x0 0
692: rip            0x40093f    0x40093f <do_some_ticks+40>
692: eflags         0x202   [ IF ]
692: cs             0x33    51
692: ss             0x2b    43
692: ds             0x0 0
692: es             0x0 0
692: fs             0x0 0
692: gs             0x0 0
692: fs_base        0x7f823e31c700  0x7f823e31c700
692: gs_base        0x0 0x0
692: 
692: Thread 1 (Thread 17408.17408):
692: #0  0x000000000040093f in do_some_ticks ()
692:     at /home/froydnj/src/rr/src/test/check_lost_interrupts.c:10
692: #1  0x000000000040097c in main ()
692:     at /home/froydnj/src/rr/src/test/check_lost_interrupts.c:18
692: Detaching from program: /tmp/rr-test-check_lost_interrupts-xiueyooV9/check_lost_interrupts-xiueyooV9, process 17408
692: --------------------------------------------------
692: record.out:
692: --------------------------------------------------
692: --------------------------------------------------
692: Test check_lost_interrupts failed, leaving behind /tmp/rr-test-check_lost_interrupts-xiueyooV9
692: To replay the failed test, run
692:   _RR_TRACE_DIR=/tmp/rr-test-check_lost_interrupts-xiueyooV9 rr replay

and a third test:

890: Test 'async_signal_syscalls_1000' FAILED: : error during recording:
890: --------------------------------------------------
890: [FATAL /home/froydnj/src/rr/src/PerfCounters.cc:767:read_ticks() errno: SUCCESS] 
890:  (task 3986 (rec:3986) at time 130)
890:  -> Assertion `!counting_period || measure_val <= adjusted_counting_period' failed to hold. Detected 1434 ticks, expected no more than 1211
890: 111    do-rel.h: No such file or directory.
890: [FATAL /home/froydnj/src/rr/src/log.cc:356:emergency_debug() errno: SUCCESS] Can't resume execution from invalid state
890: :  1000    1000    1000    1000
890: FDSize:    64
890: Groups:    4 24 27 30 46 113 128 129 131 1000 
890: NStgid:    3965
890: NSpid: 3965
890: NSpgid:    22526
890: NSsid: 13024
890: VmPeak:      929104 kB
890: VmSize:      795444 kB
890: VmLck:        0 kB
890: VmPin:        0 kB
890: VmHWM:    33172 kB
890: VmRSS:    33164 kB
890: VmData:      768988 kB
890: VmStk:      132 kB
890: VmExe:     2344 kB
890: VmLib:     5416 kB
890: VmPTE:      164 kB
890: VmPMD:       16 kB
890: VmSwap:           0 kB
890: HugetlbPages:         0 kB
890: Threads:   1
890: SigQ:  1/256394
890: SigPnd:    0000000000000000
890: ShdPnd:    0000000000000000
890: SigBlk:    0000000000000000
890: SigIgn:    0000000000000000
890: SigCgt:    0000000180006000
890: CapInh:    0000000000000000
890: CapPrm:    0000000000000000
890: CapEff:    0000000000000000
890: CapBnd:    0000003fffffffff
890: CapAmb:    0000000000000000
890: Seccomp:   0
890: Cpus_allowed:  080
890: Cpus_allowed_list: 7
890: Mems_allowed:  00000000,00000001
890: Mems_allowed_list: 0
890: voluntary_ctxt_switches:   201
890: nonvoluntary_ctxt_switches:    123
890: ====== /proc/3965/stack
890: [<0000000000000000>] inet_csk_accept+0x271/0x350
890: [<0000000000000000>] inet_accept+0x3c/0x130
890: [<0000000000000000>] SYSC_accept4+0x103/0x210
890: [<0000000000000000>] SyS_accept+0x10/0x20
890: [<0000000000000000>] entry_SYSCALL_64_fastpath+0x16/0x71
890: [<0000000000000000>] 0xffffffffffffffff
890: ====== /proc/3986/status
890: Name:  async_signal_sy
890: State: t (tracing stop)
890: Tgid:  3986
890: Ngid:  0
890: Pid:   3986
890: PPid:  3965
890: TracerPid: 3965
890: Uid:   1000    1000    1000    1000
890: Gid:   1000    1000    1000    1000
890: FDSize:    1024
890: Groups:    4 24 27 30 46 113 128 129 131 1000 
890: NStgid:    3986
890: NSpid: 3986
890: NSpgid:    22526
890: NSsid: 13024
890: VmPeak:       12920 kB
890: VmSize:       12920 kB
890: VmLck:        0 kB
890: VmPin:        0 kB
890: VmHWM:     2852 kB
890: VmRSS:     2852 kB
890: VmData:        2276 kB
890: VmStk:        0 kB
890: VmExe:        8 kB
890: VmLib:     2236 kB
890: VmPTE:       44 kB
890: VmPMD:       16 kB
890: VmSwap:           0 kB
890: HugetlbPages:         0 kB
890: Threads:   1
890: SigQ:  1/256394
890: SigPnd:    0000000000000000
890: ShdPnd:    0000000000000000
890: SigBlk:    0000000000000000
890: SigIgn:    0000000000000000
890: SigCgt:    0000000000000000
890: CapInh:    0000000000000000
890: CapPrm:    0000000000000000
890: CapEff:    0000000000000000
890: CapBnd:    0000003fffffffff
890: CapAmb:    0000000000000000
890: Seccomp:   2
890: Cpus_allowed:  080
890: Cpus_allowed_list: 7
890: Mems_allowed:  00000000,00000001
890: Mems_allowed_list: 0
890: voluntary_ctxt_switches:   307
890: nonvoluntary_ctxt_switches:    0
890: ====== /proc/3986/stack
890: [<0000000000000000>] ptrace_stop+0x16e/0x2a0
890: [<0000000000000000>] get_signal+0x34a/0x600
890: [<0000000000000000>] do_signal+0x37/0x6f0
890: [<0000000000000000>] exit_to_usermode_loop+0x8c/0xd0
890: [<0000000000000000>] prepare_exit_to_usermode+0x26/0x30
890: [<0000000000000000>] retint_user+0x8/0x10
890: [<0000000000000000>] 0xffffffffffffffff
890: ====== gdb -p 3965 -ex 'set confirm off' -ex 'set height 0' -ex 'thread apply all bt' -ex q </dev/null 2>&1
890: GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
890: Copyright (C) 2016 Free Software Foundation, Inc.
890: License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
890: This is free software: you are free to change and redistribute it.
890: There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
890: and "show warranty" for details.
890: This GDB was configured as "x86_64-linux-gnu".
890: Type "show configuration" for configuration details.
890: For bug reporting instructions, please see:
890: <http://www.gnu.org/software/gdb/bugs/>.
890: Find the GDB manual and other documentation resources online at:
890: <http://www.gnu.org/software/gdb/documentation/>.
890: For help, type "help".
890: Type "apropos word" to search for commands related to "word".
890: Attaching to process 3965
890: Reading symbols from /home/froydnj/src/rr/bin/rr...done.
890: Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libdl-2.23.so...done.
890: done.
890: Reading symbols from /lib/x86_64-linux-gnu/librt.so.1...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/librt-2.23.so...done.
890: done.
890: Reading symbols from /usr/lib/x86_64-linux-gnu/libcapnp-0.5.3.so...(no debugging symbols found)...done.
890: Reading symbols from /usr/lib/x86_64-linux-gnu/libkj-0.5.3.so...(no debugging symbols found)...done.
890: Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...Reading symbols from /usr/lib/debug/.build-id/27/f189ef8db8c3734c6a678e6ef3cb0b206d58b2.debug...done.
890: done.
890: [Thread debugging using libthread_db enabled]
890: Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
890: Reading symbols from /usr/lib/x86_64-linux-gnu/libstdc++.so.6...(no debugging symbols found)...done.
890: Reading symbols from /lib/x86_64-linux-gnu/libm.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libm-2.23.so...done.
890: done.
890: Reading symbols from /lib/x86_64-linux-gnu/libgcc_s.so.1...(no debugging symbols found)...done.
890: Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libc-2.23.so...done.
890: done.
890: Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/ld-2.23.so...done.
890: done.
890: 0x00007fd4a419d76d in accept () at ../sysdeps/unix/syscall-template.S:84
890: 84 ../sysdeps/unix/syscall-template.S: No such file or directory.
890: 
890: Thread 1 (Thread 0x7fd4a4e5f740 (LWP 3965)):
890: #0  0x00007fd4a419d76d in accept () at ../sysdeps/unix/syscall-template.S:84
890: #1  0x000000000046fc47 in rr::GdbConnection::await_debugger (this=0x15fdab0, 
890:     listen_fd=...) at /home/froydnj/src/rr/src/GdbConnection.cc:70
890: #2  0x00000000004836b1 in rr::await_connection (t=t@entry=0x15fe760, listen_fd=..., 
890:     features=...) at /home/froydnj/src/rr/src/GdbServer.cc:1430
890: #3  0x000000000048d4d5 in rr::GdbServer::emergency_debug (t=t@entry=0x15fe760)
890:     at /home/froydnj/src/rr/src/GdbServer.cc:1630
890: #4  0x000000000049a706 in rr::emergency_debug (t=<optimized out>)
890:     at /home/froydnj/src/rr/src/log.cc:355
890: #5  rr::EmergencyDebugOstream::~EmergencyDebugOstream (this=<optimized out>, 
890:     __in_chrg=<optimized out>) at /home/froydnj/src/rr/src/log.cc:377
890: #6  0x00000000004ad4a8 in rr::PerfCounters::read_ticks (this=this@entry=0x15fe788, 
890:     t=t@entry=0x15fe760) at /home/froydnj/src/rr/src/PerfCounters.cc:768
890: #7  0x0000000000530b5c in rr::Task::did_waitpid (this=this@entry=0x15fe760, status=...)
890:     at /home/froydnj/src/rr/src/Task.cc:1522
890: #8  0x0000000000531878 in rr::Task::wait (this=0x15fe760, interrupt_after_elapsed=3)
890:     at /home/froydnj/src/rr/src/Task.cc:1387
890: #9  0x000000000051e136 in rr::Scheduler::reschedule (this=this@entry=0x15fc628, 
890:     switchable=<optimized out>) at /home/froydnj/src/rr/src/Scheduler.cc:380
890: #10 0x00000000004b9c63 in rr::RecordSession::record_step (this=0x15fc4c0)
890:     at /home/froydnj/src/rr/src/RecordSession.cc:1802
890: #11 0x00000000004b22d7 in rr::record (flags=..., args=...)
890:     at /home/froydnj/src/rr/src/RecordCommand.cc:362
890: #12 rr::RecordCommand::run (this=0x64d240 <rr::RecordCommand::singleton>, args=...)
890:     at /home/froydnj/src/rr/src/RecordCommand.cc:474
890: #13 0x0000000000552336 in main (argc=9, argv=0x7fffec81a588)
890:     at /home/froydnj/src/rr/src/main.cc:236
890: Detaching from program: /home/froydnj/src/rr/bin/rr, process 3965
890: ====== gdb '-l' '10000' '-ex' 'set sysroot /' '-ex' 'target extended-remote 127.0.0.1:3986' -ex 'set confirm off' -ex 'set height 0' -ex 'info registers' -ex 'thread apply all bt' -ex q /tmp/rr-test-async_signal_syscalls_1000-bxDwvIVkk/async_signal_syscalls-bxDwvIVkk
890:  </dev/null 2>&1
890: GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
890: Copyright (C) 2016 Free Software Foundation, Inc.
890: License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
890: This is free software: you are free to change and redistribute it.
890: There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
890: and "show warranty" for details.
890: This GDB was configured as "x86_64-linux-gnu".
890: Type "show configuration" for configuration details.
890: For bug reporting instructions, please see:
890: <http://www.gnu.org/software/gdb/bugs/>.
890: Find the GDB manual and other documentation resources online at:
890: <http://www.gnu.org/software/gdb/documentation/>.
890: For help, type "help".
890: Type "apropos word" to search for commands related to "word"...
890: Reading symbols from /tmp/rr-test-async_signal_syscalls_1000-bxDwvIVkk/async_signal_syscalls-bxDwvIVkk...done.
890: Remote debugging using 127.0.0.1:3986
890: Reading symbols from /home/froydnj/src/rr/bin/../lib/rr/librrpreload.so...done.
890: Reading symbols from /lib/x86_64-linux-gnu/librt.so.1...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/librt-2.23.so...done.
890: done.
890: Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...Reading symbols from /usr/lib/debug/.build-id/27/f189ef8db8c3734c6a678e6ef3cb0b206d58b2.debug...done.
890: done.
890: Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libc-2.23.so...done.
890: done.
890: Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libdl-2.23.so...done.
890: done.
890: Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/ld-2.23.so...done.
890: done.
890: elf_dynamic_do_Rela (skip_ifunc=<optimized out>, lazy=0, nrelative=<optimized out>, 
890:     relsize=30576, reladdr=<optimized out>, map=0x7f48441244e8) at do-rel.h:111
890: rax            0x7f48437815f0  139948346316272
890: rbx            0x7f4843783e88  139948346326664
890: rcx            0x7f4843b27ce8  139948350143720
890: rdx            0x7f48437e0c00  139948346706944
890: rsi            0x7f4843768d80  139948346215808
890: rdi            0x7ffdec00e250  140728562934352
890: rbp            0x7ffdec00e2c0  0x7ffdec00e2c0
890: rsp            0x7ffdec00e1a0  0x7ffdec00e1a0
890: r8             0x7f4843784680  139948346328704
890: r9             0x7f48437847b8  139948346329016
890: r10            0x22    34
890: r11            0x7f48441244e8  139948356420840
890: r12            0x7f48441244e8  139948356420840
890: r13            0x7f4843765000  139948346200064
890: r14            0x7f48441244e8  139948356420840
890: r15            0x5 5
890: rip            0x7f4843f60600  0x7f4843f60600 <_dl_relocate_object+912>
890: eflags         0x206   [ PF IF ]
890: cs             0x33    51
890: ss             0x2b    43
890: ds             0x0 0
890: es             0x0 0
890: fs             0x0 0
890: gs             0x0 0
890: fs_base        0x7f4844122700  0x7f4844122700
890: gs_base        0x0 0x0
890: 
890: Thread 1 (Thread 3986.3986):
890: #0  elf_dynamic_do_Rela (skip_ifunc=<optimized out>, lazy=0, 
890:     nrelative=<optimized out>, relsize=30576, reladdr=<optimized out>, 
890:     map=0x7f48441244e8) at do-rel.h:111
890: #1  _dl_relocate_object (scope=<optimized out>, reloc_mode=<optimized out>, 
890:     consider_profiling=<optimized out>, consider_profiling@entry=0) at dl-reloc.c:258
890: #2  0x00007f4843f580db in dl_main (phdr=<optimized out>, phnum=<optimized out>, 
890:     user_entry=<optimized out>, auxv=<optimized out>) at rtld.c:2109
890: #3  0x00007f4843f6d632 in _dl_sysdep_start (
890:     start_argptr=start_argptr@entry=0x7ffdec00e4d0, 
890:     dl_main=dl_main@entry=0x7f4843f561e0 <dl_main>) at ../elf/dl-sysdep.c:249
890: #4  0x00007f4843f55c2a in _dl_start_final (arg=0x7ffdec00e4d0) at rtld.c:323
890: #5  _dl_start (arg=0x7ffdec00e4d0) at rtld.c:429
890: #6  0x00007f4843f54c38 in _start () from /lib64/ld-linux-x86-64.so.2
890: #7  0x0000000000000002 in ?? ()
890: #8  0x00007ffdec01073a in ?? ()
890: #9  0x00007ffdec01075c in ?? ()
890: #10 0x0000000000000000 in ?? ()
890: Detaching from program: /tmp/rr-test-async_signal_syscalls_1000-bxDwvIVkk/async_signal_syscalls-bxDwvIVkk, process 3986
890: --------------------------------------------------
890: record.out:
890: --------------------------------------------------
890: --------------------------------------------------
890: Test async_signal_syscalls_1000 failed, leaving behind /tmp/rr-test-async_signal_syscalls_1000-bxDwvIVkk
890: To replay the failed test, run
890:   _RR_TRACE_DIR=/tmp/rr-test-async_signal_syscalls_1000-bxDwvIVkk rr replay
khuey commented 7 years ago

Upgrade your kernel package to 4.4.0-93 or higher.