rr-debugger / rr-debugger/rr

FATAL check_ticks_consistency() issue

Open
#2,967 26 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
C++
Stars
10.7k
Forks
662
Avg merge
2d 3h
Merged PRs (30d)
2

Description

On a Ryzen 5950 running NixOS, attempting to replay a trace:

[rr 2247369 14618] INFO [rr 2247369 14620][disable_drivers_from_conflicts] [rr 2247369 14622]Disabling vive because we have survive[rr 2247369 14624]
[rr 2247369 23583]ERROR [rr 2247369 23585][is_json_ok] [rr 2247369 23587]Config file was loaded but JSON is not parsed![rr 2247369 23589]
[rr 2247369 23593] INFO [rr 2247369 23595][add_from_devices] [rr 2247369 23597]Skipping disabled driver vive[rr 2247369 23599]
[rr 2247369 23603] INFO [rr 2247369 23605][add_from_devices] [rr 2247369 23607]Skipping disabled driver vive[rr 2247369 23609]
[rr 2247369 23613] INFO [rr 2247369 23615][add_from_devices] [rr 2247369 23617]Skipping disabled driver vive[rr 2247369 23619]
[rr 2247369 43803]ERROR [rr 2247369 43805][is_json_ok] [rr 2247369 43807]Config file was loaded but JSON is not parsed![rr 2247369 43809]
[rr 2247369 43813]DEBUG [rr 2247369 43815][xrt_gfx_provider_create_system] [rr 2247369 43817]Doing init 0x1bc1e50[rr 2247369 43819]
[rr 2247369 43825] WARN [rr 2247369 43827][compositor_check_and_prepare_xdev] [rr 2247369 43829]Had to fill in meshuv on xdev 'Valve Index (libsurvive)', this should be done in the driver.[rr 2247369 43831]
[rr 2247369 45827]DEBUG [rr 2247369 45829][vk_select_physical_device] [rr 2247369 45831]Choosing Vulkan device index[rr 2247369 45833]
[rr 2247369 45837]DEBUG [rr 2247369 45839][vk_select_physical_device] [rr 2247369 45841]Available GPUs[rr 2247369 45843]
[rr 2247369 45847]DEBUG [rr 2247369 45849][vk_print_device_info_debug] [rr 2247369 45851]GPU index 0
	name: llvmpipe (LLVM 12.0.1, 256 bits)
	vendor: 0x10005
	product: 0x0000
	apiVersion: 1.1.168
	driverVersion: 0.0.1[rr 2247369 45853]
[rr 2247369 45857]DEBUG [rr 2247369 45859][vk_print_device_info_debug] [rr 2247369 45861]Selected GPU: 0
	name: llvmpipe (LLVM 12.0.1, 256 bits)
	vendor: 0x10005
	product: 0x0000
	apiVersion: 1.1.168
	driverVersion: 0.0.1[rr 2247369 45863]
[rr 2247369 45869]ERROR [rr 2247369 45871][vk_build_device_extensions] [rr 2247369 45873]VkPhysicalDevice does not support required extension VK_KHR_external_memory_fd[rr 2247369 45875]
[rr 2247369 45879]ERROR [rr 2247369 45881][compositor_check_vulkan_caps] [rr 2247369 45883]vk_create_device: VK_ERROR_EXTENSION_NOT_PRESENT	
Failed to create VkDevice.[rr 2247369 45885]
[rr 2247369 45889]ERROR [rr 2247369 45891][xrt_gfx_provider_create_system] [rr 2247369 45893]Failed to init compositor 0x1bc1e50[rr 2247369 45895]
[rr 2247369 45899]DEBUG [rr 2247369 45901][comp_shaders_close] [rr 2247369 45903]Shaders destroyed![rr 2247369 45905]
[FATAL /build/source/src/ReplaySession.cc:1104:check_ticks_consistency()] 
 (task 2402419 (rec:2247369) at time 46175)
 -> Assertion `ticks_now == trace_ticks' failed to hold. ticks mismatch for 'SYSCALL: poll'; expected 123103765, got 123103762
Tail of trace dump:
{
  real_time:383992.337218 global_time:46155, event:`SYSCALL: poll' (state:ENTERING_SYSCALL) tid:2247369, ticks:102351062
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0xea60 rsi:0x4 rdi:0x1b89350 rbp:0x681ffe60 rsp:0x681ffe10 r8:0x0 r9:0xea60 r10:0x0 r11:0x246 r12:0xea60 r13:0x1b89350 r14:0x1b83800 r15:0x0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0x7fe98aedff40 gs_base:0x0
}
{
  real_time:383992.337237 global_time:46156, event:`SYSCALLBUF_RESET' tid:2247369, ticks:102351062
}
{
  real_time:383992.337291 global_time:46157, event:`SYSCALL: poll' (state:EXITING_SYSCALL) tid:2247369, ticks:102351062
rax:0x1 rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0xea60 rsi:0x4 rdi:0x1b89350 rbp:0x681ffe60 rsp:0x681ffe10 r8:0x0 r9:0xea60 r10:0x0 r11:0x246 r12:0xea60 r13:0x1b89350 r14:0x1b83800 r15:0x0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0x7fe98aedff40 gs_base:0x0
  { tid:2247369, addr:0x1b89350, length:0x20 }
}
{
  real_time:383992.345732 global_time:46158, event:`SYSCALLBUF_FLUSH' tid:2247369, ticks:106501602
  { syscall:'poll', ret:0x1, size:0x30 }
  # ..several thousand lines of this repeated..
  { syscall:'poll', ret:0x1, size:0x30 }
}
{
  real_time:383992.379297 global_time:46175, event:`SYSCALL: poll' (state:ENTERING_SYSCALL) tid:2247369, ticks:123103765
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0xea60 rsi:0x4 rdi:0x1b89350 rbp:0x681ffe60 rsp:0x681ffe10 r8:0x0 r9:0xea60 r10:0x0 r11:0x246 r12:0xea60 r13:0x1b89350 r14:0x1b83800 r15:0x0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0x7fe98aedff40 gs_base:0x0
}
{
  real_time:383992.379316 global_time:46176, event:`SYSCALLBUF_RESET' tid:2247369, ticks:123103765
}
[FATAL /build/source/src/log.cc:402:emergency_debug()] (session doesn't look interactive, aborting emergency debugging)
=== Start rr backtrace:
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_ZN2rr13dump_rr_stackEv+0x44)[0x6a288b]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_ZN2rr15notifying_abortEv+0x53)[0x6a2842]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_ZN2rr12FatalOstreamD1Ev+0x30)[0x501c4e]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr[0x501f8e]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_ZN2rr21EmergencyDebugOstreamD1Ev+0x62)[0x5021fc]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_ZN2rr13ReplaySession23check_ticks_consistencyEPNS_10ReplayTaskERKNS_5EventE+0x128)[0x5eb7e0]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_ZN2rr13ReplaySession11replay_stepERKNS0_15StepConstraintsE+0x893)[0x5ef715]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_ZN2rr14ReplayTimeline19replay_step_forwardENS_10RunCommandEl+0xe9)[0x60d1bf]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_ZN2rr9GdbServer14debug_one_stepERNS_10GdbRequestE+0x555)[0x4ceb2d]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_ZN2rr9GdbServer12serve_replayERKNS0_15ConnectionFlagsE+0x521)[0x4d0d77]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr[0x5e465f]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_ZN2rr13ReplayCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0x417)[0x5e5147]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(main+0x227)[0x6bde3f]
/nix/store/9bh3986bpragfjmr32gay8p95k91q4gy-glibc-2.33-47/lib/libc.so.6(__libc_start_main+0xd0)[0x7f8193de5780]
/nix/store/siwpnh29dbm39d1w1ad4qvn9g2i2vdpb-rr-unstable-2020-10-10/bin/rr(_start+0x2a)[0x43157a]
=== End rr backtrace

Possibly relevant: the program I'm debugging attempts to connect to a Valve Index VR headset (though I believe unsuccessfully).

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with src/ReplaySession.cc:1104 and check_ticks_consistency(), then review the replay trace around the SYSCALL: poll tick mismatch. The report also points to src/log.cc:402 and a Ryzen 5950 running NixOS while connecting to a Valve Index. Done should mean the supplied trace can be replayed without the fatal tick-consistency assertion.

Written by the indexing model from the issue text.

Assessment

Tech stack
cpp, linux
Domain
devtools, operating-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.