FATAL check_ticks_consistency() issue

[georgewsinger]

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

[rr 2247369 14618]�[32m INFO �[0m[rr 2247369 14620][disable_drivers_from_conflicts] [rr 2247369 14622]Disabling vive because we have survive[rr 2247369 14624]
[rr 2247369 23583]�[31mERROR �[0m[rr 2247369 23585][is_json_ok] [rr 2247369 23587]Config file was loaded but JSON is not parsed![rr 2247369 23589]
[rr 2247369 23593]�[32m INFO �[0m[rr 2247369 23595][add_from_devices] [rr 2247369 23597]Skipping disabled driver vive[rr 2247369 23599]
[rr 2247369 23603]�[32m INFO �[0m[rr 2247369 23605][add_from_devices] [rr 2247369 23607]Skipping disabled driver vive[rr 2247369 23609]
[rr 2247369 23613]�[32m INFO �[0m[rr 2247369 23615][add_from_devices] [rr 2247369 23617]Skipping disabled driver vive[rr 2247369 23619]
[rr 2247369 43803]�[31mERROR �[0m[rr 2247369 43805][is_json_ok] [rr 2247369 43807]Config file was loaded but JSON is not parsed![rr 2247369 43809]
[rr 2247369 43813]�[36mDEBUG �[0m[rr 2247369 43815][xrt_gfx_provider_create_system] [rr 2247369 43817]Doing init 0x1bc1e50[rr 2247369 43819]
[rr 2247369 43825]�[33m WARN �[0m[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]�[36mDEBUG �[0m[rr 2247369 45829][vk_select_physical_device] [rr 2247369 45831]Choosing Vulkan device index[rr 2247369 45833]
[rr 2247369 45837]�[36mDEBUG �[0m[rr 2247369 45839][vk_select_physical_device] [rr 2247369 45841]Available GPUs[rr 2247369 45843]
[rr 2247369 45847]�[36mDEBUG �[0m[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]�[36mDEBUG �[0m[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]�[31mERROR �[0m[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]�[31mERROR �[0m[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]�[31mERROR �[0m[rr 2247369 45891][xrt_gfx_provider_create_system] [rr 2247369 45893]Failed to init compositor 0x1bc1e50[rr 2247369 45895]
[rr 2247369 45899]�[36mDEBUG �[0m[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).

[khuey]

Did you upload this trace to Pernosco?

[georgewsinger]

I've uploaded variants of this trace (previous recordings) to Pernosco, and they all seemed to fail. I'll upload this one now.

[khuey]

Thanks. Is this reproducible if you record with -n (this will be slower)? If so, can you upload that one too please?

[georgewsinger]

If we record with -n, the trace seems to succeed in replaying. I'll try uploading this to Pernosco.

[georgewsinger]

Here's the one that failed initially^

[georgewsinger]

I recorded a similar trace of the same program on another machine, and attempted to upload it:

Running rr traceinfo ./rr/latest-trace
Running 'rr pack'...
Running rr pack ./rr/latest-trace
Copying /usr/lib/x86_64-linux-gnu/libthread_db.so into trace...
Running rr filename ./rr/latest-trace/mmap_pack_18_librt-2.33.so
Running rr filename ./rr/latest-trace/mmap_pack_81_libstdc++.so.6.0.28
Running rr filename ./rr/latest-trace/mmap_pack_135_libdav1d.so.5.1.1
Running rr filename ./rr/latest-trace/mmap_pack_89_driver_simulator.so
Running rr filename ./rr/latest-trace/mmap_pack_125_libcblas.so.3.10.0
Running rr filename ./rr/latest-trace/mmap_pack_137_libmp3lame.so.0.0.0
Running rr filename ./rr/latest-trace/mmap_pack_120_libavutil.so.56.70.100
Running rr filename ./rr/latest-trace/mmap_pack_21_libtheoradec.so.1.1.4
Running rr filename ./rr/latest-trace/mmap_pack_63_libtiff.so.5.7.0
Running rr filename ./rr/latest-trace/mmap_pack_92_libswscale.so.5.9.100
Running rr filename ./rr/latest-trace/mmap_pack_55_libnuma.so.1.0.0
Running rr filename ./rr/latest-trace/mmap_pack_34_libgomp.so.1.0.0
Running rr filename ./rr/latest-trace/mmap_pack_98_libtasn1.so.6.6.1
Running rr filename ./rr/latest-trace/mmap_pack_25_libvpx.so.6.4.0
Running rr filename ./rr/latest-trace/mmap_pack_10_libpcre.so.1.2.12
Running rr filename ./rr/latest-trace/mmap_pack_30_libgstpbutils-1.0.so.0.1804.0
Running rr filename ./rr/latest-trace/mmap_pack_39_libhogweed.so.6.4
Running rr filename ./rr/latest-trace/mmap_pack_29_libgnutls.so.30.30.0
Running rr filename ./rr/latest-trace/mmap_pack_114_libsrt.so.1.4.3
Running rr filename ./rr/latest-trace/mmap_pack_129_libffi.so.8.1.0
Running rr filename ./rr/latest-trace/mmap_pack_80_libsystemd.so.0.30.0
Running rr filename ./rr/latest-trace/mmap_pack_28_libssl.so.1.1
Running rr filename ./rr/latest-trace/mmap_pack_8_libavcodec.so.58.134.100
Running rr filename ./rr/latest-trace/mmap_pack_105_libopenhmd.so.0.1.0
Running rr filename ./rr/latest-trace/mmap_pack_102_libvdpau.so.1.0.0
Running rr filename ./rr/latest-trace/mmap_pack_43_libgcc_s.so.1
Running rr filename ./rr/latest-trace/mmap_pack_20_libgfortran.so.5.0.0
Running rr filename ./rr/latest-trace/mmap_pack_16_libxcb-randr.so.0.1.0
Running rr filename ./rr/latest-trace/mmap_pack_45_libudev.so.1.7.0
Running rr filename ./rr/latest-trace/mmap_pack_134_libva.so.2.1200.0
Running rr filename ./rr/latest-trace/mmap_pack_58_driver_global_scene_solver.so
Running rr filename ./rr/latest-trace/mmap_pack_2_libvulkan_intel.so
Running rr filename ./rr/latest-trace/mmap_pack_97_libgstvideo-1.0.so.0.1804.0
Running rr filename ./rr/latest-trace/mmap_pack_100_libXext.so.6.4.0
Running rr filename ./rr/latest-trace/mmap_pack_67_libXau.so.6.0.0
Running rr filename ./rr/latest-trace/mmap_pack_37_driver_playback.so
Running rr filename ./rr/latest-trace/mmap_pack_103_libX11-xcb.so.1.0.0
Running rr filename ./rr/latest-trace/mmap_pack_122_libnettle.so.8.4
Running rr filename ./rr/latest-trace/mmap_pack_90_libvulkan_radeon.so
Running rr filename ./rr/latest-trace/mmap_pack_17_driver_udp.so
Running rr filename ./rr/latest-trace/mmap_pack_72_poser_kalman_only.so
Running rr filename ./rr/latest-trace/mmap_pack_139_libquadmath.so.0.0.0
Running rr filename ./rr/latest-trace/mmap_pack_110_libXinerama.so.1.0.0
Running rr filename ./rr/latest-trace/mmap_pack_69_poser_dummy.so
Running rr filename ./rr/latest-trace/mmap_pack_99_libunwind.so.8.0.1
Running rr filename ./rr/latest-trace/mmap_pack_57_libblas.so.3.10.0
Running rr filename ./rr/latest-trace/mmap_pack_107_libX11.so.6.4.0
Running rr filename ./rr/latest-trace/mmap_pack_126_libcap.so.2.49
Running rr filename ./rr/latest-trace/mmap_pack_136_libz.so.1.2.11
Running rr filename ./rr/latest-trace/mmap_pack_61_libspeex.so.1.5.1
Running rr filename ./rr/latest-trace/mmap_pack_33_libopencv_core.so.4.5.2
Running rr filename ./rr/latest-trace/mmap_pack_6_libswresample.so.3.9.100
Running rr filename ./rr/latest-trace/mmap_pack_59_libXss.so.1.0.0
Running rr filename ./rr/latest-trace/mmap_pack_124_libdl-2.33.so
Running rr filename ./rr/latest-trace/mmap_pack_5_libhidapi-libusb.so.0.0.0
Running rr filename ./rr/latest-trace/mmap_pack_127_libuvc.so.0.0.6
Running rr filename ./rr/latest-trace/mmap_pack_111_libgmp.so.10.4.1
Running rr filename ./rr/latest-trace/mmap_pack_86_libsurvive.so.0.3
Running rr filename ./rr/latest-trace/mmap_pack_15_libopencv_calib3d.so.4.5.2
Running rr filename ./rr/latest-trace/mmap_pack_113_liblapack.so.3.10.0
Running rr filename ./rr/latest-trace/mmap_pack_130_disambiguator_statebased.so
Running rr filename ./rr/latest-trace/mmap_pack_42_libopencv_features2d.so.4.5.2
Running rr filename ./rr/latest-trace/mmap_pack_46_libbz2.so.1.0.6
Running rr filename ./rr/latest-trace/mmap_pack_74_libIex-2_5.so.25.0.6
Running rr filename ./rr/latest-trace/mmap_pack_65_librrpage.so
Running rr filename ./rr/latest-trace/mmap_pack_76_librrpreload.so
Running rr filename ./rr/latest-trace/mmap_pack_47_libxvidcore.so.4.3
Running rr filename ./rr/latest-trace/mmap_pack_77_libIlmThread-2_5.so.25.0.6
Running rr filename ./rr/latest-trace/mmap_pack_22_libtheoraenc.so.1.1.2
Running rr filename ./rr/latest-trace/mmap_pack_32_libgobject-2.0.so.0.6800.3
Running rr filename ./rr/latest-trace/mmap_pack_52_libbsd.so.0.10.0
Running rr filename ./rr/latest-trace/mmap_pack_109_libpthread-2.33.so
Running rr filename ./rr/latest-trace/mmap_pack_48_liblapacke.so.3.10.0
Running rr filename ./rr/latest-trace/mmap_pack_96_poser_mpfit.so
Running rr filename ./rr/latest-trace/mmap_pack_14_libx265.so.192
Running rr filename ./rr/latest-trace/mmap_pack_31_liborc-0.4.so.0.32.0
Running rr filename ./rr/latest-trace/mmap_pack_44_libopus.so.0.8.0
Running rr filename ./rr/latest-trace/mmap_pack_0_libopencv_videoio.so.4.5.2
Running rr filename ./rr/latest-trace/mmap_pack_133_libopencv_flann.so.4.5.2
Running rr filename ./rr/latest-trace/mmap_pack_123_libprotobuf.so.28.0.3
Running rr filename ./rr/latest-trace/mmap_pack_93_libelf-0.182.so
Running rr filename ./rr/latest-trace/mmap_pack_60_libGLdispatch.so.0.0.0
Running rr filename ./rr/latest-trace/mmap_pack_95_libglib-2.0.so.0.6800.3
Running rr filename ./rr/latest-trace/mmap_pack_53_libopencv_video.so.4.5.2
Running rr filename ./rr/latest-trace/mmap_pack_94_libunistring.so.2.1.0
Running rr filename ./rr/latest-trace/mmap_pack_13_libHalf-2_5.so.25.0.6
Running rr filename ./rr/latest-trace/mmap_pack_62_libgsttag-1.0.so.0.1804.0
Running rr filename ./rr/latest-trace/mmap_pack_82_libgstaudio-1.0.so.0.1804.0
Running rr filename ./rr/latest-trace/mmap_pack_108_libopencv_imgcodecs.so.4.5.2
Running rr filename ./rr/latest-trace/mmap_pack_84_libgstreamer-1.0.so.0.1804.0
Running rr filename ./rr/latest-trace/mmap_pack_73_libvulkan.so.1.2.182
Running rr filename ./rr/latest-trace/mmap_pack_104_libwayland-client.so.0.3.0
Running rr filename ./rr/latest-trace/mmap_pack_75_poser_barycentric_svd.so
Running rr filename ./rr/latest-trace/mmap_pack_101_ld-2.33.so
Running rr filename ./rr/latest-trace/mmap_pack_35_libIlmImf-2_5.so.25.0.6
Running rr filename ./rr/latest-trace/mmap_pack_112_libXrender.so.1.3.0
Running rr filename ./rr/latest-trace/mmap_pack_51_libdw-0.182.so
Running rr filename ./rr/latest-trace/mmap_pack_19_libva-drm.so.2.1200.0
Running rr filename ./rr/latest-trace/mmap_pack_4_libopencv_imgproc.so.4.5.2
Running rr filename ./rr/latest-trace/mmap_pack_121_libjpeg.so.62.3.0
Running rr filename ./rr/latest-trace/mmap_pack_11_libgmodule-2.0.so.0.6800.3
Running rr filename ./rr/latest-trace/mmap_pack_85_libssh.so.4.7.6
Running rr filename ./rr/latest-trace/mmap_pack_79_libxcb.so.1.1.0
Running rr filename ./rr/latest-trace/mmap_pack_26_driver_dummy.so
Running rr filename ./rr/latest-trace/mmap_pack_118_libSDL2-2.0.so.0.14.0
Running rr filename ./rr/latest-trace/mmap_pack_9_libusb-1.0.so.0.3.0
Running rr filename ./rr/latest-trace/mmap_pack_83_libogg.so.0.8.4
Running rr filename ./rr/latest-trace/mmap_pack_64_libgstapp-1.0.so.0.1804.0
Running rr filename ./rr/latest-trace/mmap_pack_1_libEGL.so.1.1.0
Running rr filename ./rr/latest-trace/mmap_pack_128_libgstriff-1.0.so.0.1804.0
Running rr filename ./rr/latest-trace/mmap_pack_54_libvorbis.so.0.4.9
Running rr filename ./rr/latest-trace/mmap_pack_138_libImath-2_5.so.25.0.6
fatal: not a git repository: /home/george/monado/../../.git/modules/submodules/monado
Running rr filename ./rr/latest-trace/mmap_pack_38_libdbus-1.so.3.19.13
Running rr filename ./rr/latest-trace/mmap_pack_71_monado-service
Running rr filename ./rr/latest-trace/mmap_pack_106_libwebp.so.7.1.0
Running rr filename ./rr/latest-trace/mmap_pack_119_libopencv_highgui.so.4.5.2
Running rr filename ./rr/latest-trace/mmap_pack_131_libIexMath-2_5.so.25.0.6
Running rr filename ./rr/latest-trace/mmap_pack_117_libdeflate.so.0
Running rr filename ./rr/latest-trace/mmap_pack_27_libpng16.so.16.37.0
Running rr filename ./rr/latest-trace/mmap_pack_50_libgstbase-1.0.so.0.1804.0
Running rr filename ./rr/latest-trace/mmap_pack_66_libXrandr.so.2.2.0
Running rr filename ./rr/latest-trace/mmap_pack_91_libXcursor.so.1.0.2
Running rr filename ./rr/latest-trace/mmap_pack_132_libcrypto.so.1.1
Running rr filename ./rr/latest-trace/mmap_pack_116_libm-2.33.so
Running rr filename ./rr/latest-trace/mmap_pack_3_libXfixes.so.3.1.0
Running rr filename ./rr/latest-trace/mmap_pack_41_libopencv_dnn.so.4.5.2
Running rr filename ./rr/latest-trace/mmap_pack_87_libXxf86vm.so.1.0.0
Running rr filename ./rr/latest-trace/mmap_pack_36_libavformat.so.58.76.100
Running rr filename ./rr/latest-trace/mmap_pack_78_libp11-kit.so.0.3.0
Running rr filename ./rr/latest-trace/mmap_pack_23_liblzma.so.5.2.5
Running rr filename ./rr/latest-trace/mmap_pack_115_libsoxr.so.0.1.2
Running rr filename ./rr/latest-trace/mmap_pack_68_libmvec-2.33.so
Running rr filename ./rr/latest-trace/mmap_pack_88_libXdmcp.so.6.0.0
Running rr filename ./rr/latest-trace/mmap_pack_49_libopenblasp-r0.3.17.so
Running rr filename ./rr/latest-trace/mmap_pack_56_libXi.so.6.1.0
Running rr filename ./rr/latest-trace/mmap_pack_7_libvorbisenc.so.2.0.12
Running rr filename ./rr/latest-trace/mmap_pack_12_libc-2.33.so
Running rr filename ./rr/latest-trace/mmap_pack_40_libdrm.so.2.4.0
Running rr filename ./rr/latest-trace/mmap_pack_24_driver_vive.so
Running rr filename ./rr/latest-trace/mmap_pack_70_libx264.so.157
Obtaining source file list...
Running rr sources --substitute /nix/store/yb138lg0qwvdaw8fkamx4nda9hbw179j-openblas-0.3.15/lib/libopenblasp-r0.3.15.so=/home/george/monado/result/srcs/openblas/src --substitute /nix/store/fxazk1linhn2yvp02r61brf7abviwk1y-libsurvive-0.3/lib/libsurvive.so.0.3=/home/george/monado/result/srcs/libsurvive/src ./rr/latest-trace
Running git remote --verbose
Traceback (most recent call last):
  File "/home/george/monado/./submodules/pernosco-submit/pernosco-submit", line 636, in <module>
    upload_cmd()
  File "/home/george/monado/./submodules/pernosco-submit/pernosco-submit", line 603, in upload_cmd
    repo_paths = sources.package_source_files(source_dirs, comp_dir_substitutions)
  File "/home/george/monado/submodules/pernosco-submit/pernoscoshared/sources.py", line 312, in package_source_files
    return package_source_files_from_rr_output(source_dirs, rr_sources, comp_dir_substitutions, base.trace_dir, "user", "binary")
  File "/home/george/monado/submodules/pernosco-submit/pernoscoshared/sources.py", line 375, in package_source_files_from_rr_output
    (repo_mount, modified_files) = analyze_repo(repo_path, files)
  File "/home/george/monado/submodules/pernosco-submit/pernoscoshared/sources.py", line 282, in analyze_repo
    return analyze_git_repo(repo_path, files)
  File "/home/george/monado/submodules/pernosco-submit/pernoscoshared/sources.py", line 184, in analyze_git_repo
    remotes = git_remotes(repo_path)
  File "/home/george/monado/submodules/pernosco-submit/pernoscoshared/sources.py", line 116, in git_remotes
    output = base.check_output(['git', 'remote', '--verbose'], cwd=repo_path).decode('utf-8')
  File "/home/george/monado/submodules/pernosco-submit/pernoscoshared/base.py", line 39, in check_output
    return subprocess.check_output(process_args, cwd=cwd, close_fds=close_fds, env=env, stdin=stdin, stderr=stderr)
  File "/nix/store/dqxic3j7csd4ywn94n4smmnz55p039g3-python3-3.9.6/lib/python3.9/subprocess.py", line 424, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/nix/store/dqxic3j7csd4ywn94n4smmnz55p039g3-python3-3.9.6/lib/python3.9/subprocess.py", line 528, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['git', 'remote', '--verbose']' returned non-zero exit status 128.

The trace replays on this machine successfully.

[khuey]

Hrm, ok, I'm not entirely sure why the git remote --verbose in pernosco-submit would fail. Can you modify /home/george/monado/submodules/pernosco-submit/pernoscoshared/sources.py to log repo_path just before line 116 and see if that's a path to a valid git repository?

[georgewsinger]

The repo path evaluates to .. Hmm.

[khuey]

Can you post the output of rr sources on this trace?

[georgewsinger]

The sources from the original trace: https://pastebin.com/xYaX7Whj
The sources from the second trace: https://pastebin.com/uTm3Q4ZB

[georgewsinger]

I've been sparring quite a bit trying to get sources to show up. From the first trace:

Yet according to the sources:

[SourcesCommand] File ./result/srcs/libsurvive/src/./survive.c resolved to /nix/store/mxzh818l8zl9jlsk5xi6gla6zi8njiwi-source/src/survive.c
..
[SourcesCommand] File ./result/srcs/libsurvive/src/survive.c resolved to /nix/store/mxzh818l8zl9jlsk5xi6gla6zi8njiwi-source/src/survive.c

The sources are symlinked into the nix store. From project root:

Perhaps that's the issue? IIRC, sources have to actually be copied into the directory for Pernosco to be able to reach them.

[georgewsinger]

Hmm. Copying the sources over into the local subdirectory (as opposed to using symlinks) yields the same issue.

[rocallahan]

  "files":{
    ".": [

This is unexpected and is probably the problem...

[rocallahan]

resolve_symlinks is not supposed to return relative paths but it looks like it did.

rr/src/SourcesCommand.cc

Line 550 in fd51787

// Returns an empty string if the path does not exist or

[rocallahan]

Let's debug that. This patch to rr should help:

diff --git a/src/SourcesCommand.cc b/src/SourcesCommand.cc
index d6ef89291..39708256b 100644
--- a/src/SourcesCommand.cc
+++ b/src/SourcesCommand.cc
@@ -543,6 +543,9 @@ static bool has_subdir(string& base, const char* suffix) {
 
 static void check_vcs_root(string& path, set<string>* vcs_dirs) {
   if (has_subdir(path, "/.git") || has_subdir(path, "/.hg")) {
+    if (!is_absolute(path)) {
+      FATAL() << "Path " << path << " not absolute";
+    }
     vcs_dirs->insert(path + "/");
   }
 }

Then we (by whom I mean you :-) ) just need to work backwards to figure out which path that's supposed to be absolute is actually relative. The intent is that resolve_symlinks calls check_vcs_root passing only absolute paths. resolved_base is supposed to always be absolute, and where resolved is passed to check_vcs_root, it's the result of resolve_symlinks, which is supposed to always be absolute.

[georgewsinger]

@rocallahan I'll try the patch tomorrow.

Though it was ridiculously difficult to get sources working with nix, we managed to get a working Pernosco trace of a variant of our bug on our NixOS machine. This is cool because it allowed us to paste the working trace to another developer team (who hasn't heard of pernosco, I don't think) to help them fix our bug of interest: https://gitlab.freedesktop.org/monado/monado/-/issues/130#note_1068888

Pernosco has a viral component to it. I can easily see it becoming a standard practice/common courtesy to other teams in open source software development to always post a pernos.co trace alongside a Git Issue/bug report.

@KaneTW and I were discussing this today, but someone from the nix-o-sphere needs to make some helper functions which make adding debug symbols and sources to a project as easy as

# ...
package-dev = enableDebugSymbolsAndSources package;
# ...

[rocallahan]

This is cool because it allowed us to paste the working trace to another developer team (who hasn't heard of pernosco, I don't think)

Will be interesting to see how that goes.

Pernosco has a viral component to it

That is intentional :-)

Yeah Nix does seem to be a source of frustration here and it would be great if there was a systematic solution that makes it easy to use Nix with rr sources and debugging in general.

[khuey]

So it seems like we're through all the pernosco-submit issues and we're back to the original "my recording doesn't replay" problem now?

[rocallahan]

  "files":{
    ".": [

This is unexpected and is probably the problem...

FWIW I discovered the probable source of this issue and fixed it: c168a27

[georgewsinger]

Thanks!

One other question: does rr support tracing programs that use vulkan?

[rocallahan]

I expect that to not work. See #2507

[georgewsinger]

I see. This might explain some of the weird behavior we've seen with these traces. The tracee in this instance is monado-service, which is a VR lib which uses vulkan for processing the images displayed on VR headsets.

[khuey]

I would expect vulkan to blow up pretty obviously with some unsupported ioctls. But if the entire thing is done via fds and shared memory perhaps it could die subtly instead of obviously.

[georgewsinger]

Looks like there's some software rendering implementations of Vulkan out there being worked on (lavapipe & vallium):

• https://www.reddit.com/r/vulkan/comments/m66w4m/what_is_status_of_lavapipe/
• https://www.phoronix.com/scan.php?page=news_item&px=Mesa-Vallium-Soft-Vulkan

Is getting them working with our tracee a step in the right direction towards getting RR traces working here?

[rocallahan]

Sure, a CPU implementation of Vulkan should work fine with rr.

[caitp]

I'm having this issue (also on a 5950x on an Ubuntu Impish system), recorded with and without -n. (while attempting to replay a WebKit/JavaScriptCore shell application failure (rr version 5.5.0)

On Zen CPUs, rr will not work reliably unless you disable the hardware SpecLockMap optimization.

I guess that's probably related huh. Yep, the zen_workaround script fixed it. Awesome.

̶I̶ ̶g̶u̶e̶s̶s̶ ̶t̶h̶e̶ ̶d̶o̶w̶n̶s̶i̶d̶e̶ ̶i̶s̶,̶ ̶s̶t̶e̶p̶p̶i̶n̶g̶ ̶t̶h̶r̶o̶u̶g̶h̶ ̶J̶I̶T̶ ̶c̶o̶d̶e̶ ̶i̶s̶ ̶a̶ ̶c̶h̶a̶l̶l̶e̶n̶g̶e̶ ̶a̶s̶ ̶t̶h̶e̶r̶e̶'̶s̶ ̶n̶o̶ ̶d̶i̶s̶a̶s̶s̶e̶m̶b̶l̶y̶ ̶a̶v̶a̶i̶l̶a̶b̶l̶e̶.̶ No, I'm just an idiot who is too used to lldb, and haven't been using layout asm. This is awesome.

I hope you enjoyed reading @caitp's adventures in using rr