rr icon indicating copy to clipboard operation
rr copied to clipboard
verified publisher icon rr-debugger

Assertion `ticks_now == trace_ticks' failed to hold

Open nbp opened this issue 9 years ago • 16 comments

This issue happens while replaying firefox under rr 4.2.0, rr 4.3.0 fails with a different error message which spew all the different register content.

I can reproduce this issue with some work-in-progress patches on top of firefox, which breaks the load/reload of pages ( https://github.com/nbp/gecko-dev/tree/bugzil.la/js-startup-cache/wip ). Note, firefox crashes quite easily after reloading pages, and I replayed one of these crashed process.

Here is the error message I got while replaying with rr -M replay -a (rr 4.2.0):

…
[rr 2172 113952][Child 2172] WARNING: No inner window available!: file /home/nicolas/mozilla/alternate-dev/dom/base/nsGlobalWindow.cpp, line 10026
[rr 2172 113955][Child 2172] WARNING: No inner window available!: file /home/nicolas/mozilla/alternate-dev/dom/base/nsGlobalWindow.cpp, line 10026
[rr 2172 115132]++DOMWINDOW == 2 (0x1822d10) [pid = 2172] [serial = 2] [outer = 0x173b200]
[FATAL /tmp/nix-build-rr-4.2.0.drv-0/rr-4.2.0-src/src/ReplaySession.cc:742:check_ticks_consistency() errno: 0 'Success'] 
 (task 3747 (rec:2091) at time 124280)
 -> Assertion `ticks_now == trace_ticks' failed to hold. ticks mismatch for 'SYSCALL: setsockopt'; expected 8318556, got 8318560
Launch gdb with
  gdb /home/nicolas/.local/share/rr/firefox-25/mmap_1_hardlink_firefox
and attach to the rr debug server with:
  target remote :3747

Looking at the result of rr dump -b -m -p command as suggested in the issue #1734 , and selecting some events above the one which has a matching global time, I obtain:

{
  real_time:1440395.696222 global_time:124273, event:`SCHED' tid:2084, ticks:4662502892
 rax:0x1 rbx:0x0 rcx:0x1da1e70 rdx:0x7f4ff2e48a70 rsi:0x1 rdi:0x1d75d38 rbp:0x7ffe0c93e890 rsp:0x7ffe0c93e870 r8:0x7ffe0c93e6a0 r9:0x7f4f78de87e0 r10:0x7ffe0c93e570 r11:0x60 r12:0
x4056e0 r13:0x7ffe0c941060 r14:0x0 r15:0x0 rip:0x7f4fe27fb8bc eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_base:0x7f4ff2e48740 gs_base:0
x0
}
{
  real_time:1440395.696243 global_time:124274, event:`SYSCALL: poll' (state:EXITING_SYSCALL) tid:2091, ticks:8287405
 rax:0x1 rbx:0x1d8 rcx:0xffffffffffffffff rdx:0xffffffffffffffff rsi:0x4 rdi:0x7f4fd18761f0 rbp:0x7f4fd1876000 rsp:0x7f4fd23751b8 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x7f4fd237548
0 r13:0xffffffff r14:0x4 r15:0x7f4fd23752d8 rip:0x7000000b eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0x7f4fd2376700 gs_base:0x0
  { addr:0x7f4fd18761e0, length:0x8 }
  { addr:0x7f4fd18761f0, length:0x20 }
}
{
  real_time:1440395.696246 global_time:124275, event:`SYSCALLBUF_ABORT_COMMIT' tid:2091, ticks:8287405
}
{
  real_time:1440395.696526 global_time:124276, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:ENTERING_SYSCALL) tid:2091, ticks:8287415
 rax:0xffffffffffffffda rbx:0x7f4fd18761f0 rcx:0xffffffffffffffff rdx:0xffffffff rsi:0x4 rdi:0x7f4fd2375480 rbp:0x20 rsp:0x7f4fd23751e8 r8:0x0 r9:0x0 r10:0x2 r11:0x246 r12:0x7f4fd
2375480 r13:0x70000009 r14:0x4 r15:0x7f4fd23752d8 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1bc fs_base:0x7f4fd2376700 gs_base:0x0
}
{
  real_time:1440395.696529 global_time:124277, event:`SYSCALLBUF_RESET' tid:2091, ticks:8287415
}
{
  real_time:1440395.696569 global_time:124278, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:EXITING_SYSCALL) tid:2091, ticks:8287415
 rax:0x1 rbx:0x7f4fd18761f0 rcx:0xffffffffffffffff rdx:0xffffffff rsi:0x4 rdi:0x7f4fd2375480 rbp:0x20 rsp:0x7f4fd23751e8 r8:0x0 r9:0x0 r10:0x2 r11:0x246 r12:0x7f4fd2375480 r13:0x7
0000009 r14:0x4 r15:0x7f4fd23752d8 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0x7f4fd2376700 gs_base:0x0
  { addr:0x7f4fd1876005, length:0x1 }
}
{
  real_time:1440395.697022 global_time:124279, event:`SYSCALLBUF_FLUSH' tid:2091, ticks:8318556
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'read', ret:0x1, size:0x11 }
  { 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:'poll', ret:0x1, size:0x30 }
  { 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:'gettimeofday', ret:0x0, size:0x20 }
  { syscall:'gettimeofday', ret:0x0, size:0x20 }
  { syscall:'futex', ret:0x1, size:0x18 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'recvfrom', ret:0x5, size:0x15 }
  { syscall:'recvfrom', ret:0x39, size:0x49 }
}
{
  real_time:1440395.697027 global_time:124280, event:`SYSCALL: setsockopt' (state:ENTERING_SYSCALL) tid:2091, ticks:8318556
 rax:0xffffffffffffffda rbx:0x36 rcx:0xffffffffffffffff rdx:0x4 rsi:0x6 rdi:0x30 rbp:0x7f4fd2375250 rsp:0x7f4fd2374fb0 r8:0x4 r9:0xd1 r10:0x7f4fd2375238 r11:0x246 r12:0x0 r13:0x7ffe0c93ce3f r14:0x3 r15:0x7f4fd23750b0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x36 fs_base:0x7f4fd2376700 gs_base:0x0
}

nbp avatar Aug 12 '16 12:08 nbp

I'd recommend trying rr master. There have been fixes to setsockopt tracing since 4.3.0.

Keno avatar Aug 13 '16 03:08 Keno

Testing with rr master, as of right now, I have the following error:

rr -M -replay -a:

[…]
[rr 25442 14209]2016-08-16 13:57:40.208984 UTC - [Main Thread]: D/ScriptLoader ScriptLoadRequest (2df17e0): Source stream complete (length = 30834)
[rr 25442 14734]2016-08-16 13:57:40.539573 UTC - [Main Thread]: D/ScriptLoader ScriptLoadRequest (2df17e0): Evaluate Source
[rr 25442 14751]2016-08-16 13:57:40.544894 UTC - [Main Thread]: D/ScriptLoader ScriptLoadRequest (2df17e0): Evaluate Source
[rr 25442 14755]2016-08-16 13:57:40.545031 UTC - [Main Thread]: D/ScriptLoader ScriptLoadRequest (2df17e0): Cannot cache anything (rv = 0, script = 7fc43c3b6100, cacheInfo = 0)
[FATAL /tmp/nix-build-rr-4.3.0.drv-0/rr-master-src/src/ReplaySession.cc:835:check_ticks_consistency() errno: SUCCESS] 
 (task 25943 (rec:25496) at time 20358)
 -> Assertion `ticks_now == trace_ticks' failed to hold. ticks mismatch for 'SYSCALL: mmap'; expected 27682, got 27679

rr dump -b -m -p:

[…]
{
  real_time:1553169.579086 global_time:20347, event:`SYSCALLBUF_FLUSH' tid:25485, ticks:1358189
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'futex', ret:0x0, size:0x14 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'gettid', ret:0x638d, size:0x10 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'gettid', ret:0x638d, size:0x10 }
  { 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 }
}
{
  real_time:1553169.579088 global_time:20348, event:`SYSCALL: futex' (state:ENTERING_SYSCALL) tid:25485, ticks:1358189
 rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x89 rdi:0x7fc459efb96c rbp:0x7fc459efb8f0 rsp:0x7fc459efb7f0 r8:0x7fc459efb9a0 r9:0xffffffff r10:0x7fc459efb8a8
 r11:0x246 r12:0x1 r13:0x7fc459efb8a8 r14:0xffffffffffffff92 r15:0x3499c00 rip:0x7fc501edf3d8 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xca fs_base:0x7fc4
59efc700 gs_base:0x0
}
{
  real_time:1553169.579090 global_time:20349, event:`SYSCALLBUF_RESET' tid:25485, ticks:1358189
}
{
  real_time:1553169.585260 global_time:20350, event:`SCHED' tid:25442, ticks:1975551297
 rax:0x110 rbx:0x1a4e920 rcx:0xfe rdx:0x13 rsi:0x0 rdi:0x7fc4f4a6a230 rbp:0x7fffb8675c10 rsp:0x7fffb8675c10 r8:0x7fc4f4a6a2fe r9:0x0 r10:0x7fffb8675d00 r11:0xfff9000000000000 r12:
0x7fffb8676fa8 r13:0x0 r14:0x4d6cc88 r15:0x7fffb8676e78 rip:0x7fc4f18e963f eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_base:0x7fc502535
740 gs_base:0x0
}
{
  real_time:1553169.585267 global_time:20351, event:`SYSCALL: poll' (state:EXITING_SYSCALL) tid:25496, ticks:18472
 rax:0x0 rbx:0x0 rcx:0xffffffffffffffff rdx:0x1388 rsi:0x1 rdi:0x7fc47abfe020 rbp:0x7fc47abfe000 rsp:0x7fc47b7fd510 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x7fc47b7fd7e0 r13:0x1388 r
14:0xfffffffffffffff0 r15:0x7fc47b7fd690 rip:0x7000000e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0x7fc47b7fe700 gs_base:0x0
  { tid:25496, addr:0x7fc47abfe010, length:0x8 }
  { tid:25496, addr:0x7fc47abfe020, length:0x8 }
}
{
  real_time:1553169.585269 global_time:20352, event:`SYSCALLBUF_ABORT_COMMIT' tid:25496, ticks:18472
}
{
  real_time:1553169.585552 global_time:20353, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:ENTERING_SYSCALL) tid:25496, ticks:18482
 rax:0xffffffffffffffda rbx:0x7fc47abfe020 rcx:0xffffffffffffffff rdx:0x1388 rsi:0x1 rdi:0x7fc47b7fd7e0 rbp:0x8 rsp:0x7fc47b7fd540 r8:0x0 r9:0x0 r10:0x4000 r11:0x246 r12:0x7fc47b7
fd7e0 r13:0x1388 r14:0xfffffffffffffff0 r15:0x7fc47b7fd690 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1bc fs_base:0x7fc47b7fe700 gs_base:0x
0
}
{
  real_time:1553169.585570 global_time:20354, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:EXITING_SYSCALL) tid:25496, ticks:18482
 rax:0x0 rbx:0x7fc47abfe020 rcx:0xffffffffffffffff rdx:0x1388 rsi:0x1 rdi:0x7fc47b7fd7e0 rbp:0x8 rsp:0x7fc47b7fd540 r8:0x0 r9:0x0 r10:0x4000 r11:0x246 r12:0x7fc47b7fd7e0 r13:0x138
8 r14:0xfffffffffffffff0 r15:0x7fc47b7fd690 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0x7fc47b7fe700 gs_base:0x0
  { tid:25496, addr:0x7fc47abfe00d, length:0x1 }
}
{
  real_time:1553169.585692 global_time:20355, event:`SYSCALL: close' (state:ENTERING_SYSCALL) tid:25496, ticks:18489
 rax:0xffffffffffffffda rbx:0x18 rcx:0xffffffffffffffff rdx:0x0 rsi:0x1 rdi:0x2b rbp:0x2b rsp:0x7fc47b7fd840 r8:0x0 r9:0x0 r10:0x4000 r11:0x246 r12:0x7fc47b7fd8b0 r13:0xffffffffff
ffff58 r14:0x2 r15:0x0 rip:0x7fc50103dda1 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x3 fs_base:0x7fc47b7fe700 gs_base:0x0
}
{
  real_time:1553169.585730 global_time:20356, event:`SYSCALL: close' (state:EXITING_SYSCALL) tid:25496, ticks:18489
 rax:0x0 rbx:0x18 rcx:0xffffffffffffffff rdx:0x0 rsi:0x1 rdi:0x2b rbp:0x2b rsp:0x7fc47b7fd840 r8:0x0 r9:0x0 r10:0x4000 r11:0x246 r12:0x7fc47b7fd8b0 r13:0xffffffffffffff58 r14:0x2 
r15:0x0 rip:0x7fc50103dda1 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x3 fs_base:0x7fc47b7fe700 gs_base:0x0
}
{
  real_time:1553169.585947 global_time:20357, event:`SYSCALLBUF_FLUSH' tid:25496, ticks:27682
  { syscall:'open', ret:0x2b, size:0x10 }
  { syscall:'fstat', ret:0x0, size:0xa0 }
  { syscall:'read', ret:0xac, size:0xbc }
  { syscall:'read', ret:0x0, size:0x10 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'open', ret:0xfffffffffffffffe, size:0x10 }
  { syscall:'futex', ret:0x0, size:0x14 }
  { syscall:'open', ret:0x2b, size:0x10 }
  { syscall:'fstat', ret:0x0, size:0xa0 }
  { syscall:'read', ret:0x6c, size:0x7c }
  { syscall:'read', ret:0x0, size:0x10 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'open', ret:0xfffffffffffffffe, size:0x10 }
  { syscall:'open', ret:0xfffffffffffffffe, size:0x10 }
  { syscall:'open', ret:0xfffffffffffffffe, size:0x10 }
  { syscall:'open', ret:0xfffffffffffffffe, size:0x10 }
  { syscall:'open', ret:0x2b, size:0x10 }
  { syscall:'read', ret:0x340, size:0x350 }
  { syscall:'fstat', ret:0x0, size:0xa0 }
}
{
  real_time:1553169.585950 global_time:20358, event:`SYSCALL: mmap' (state:ENTERING_SYSCALL) tid:25496, ticks:27682
 rax:0xffffffffffffffda rbx:0x9 rcx:0xffffffffffffffff rdx:0x5 rsi:0x211718 rdi:0x0 rbp:0x2b rsp:0x7fc47b7fc5b8 r8:0x2b r9:0x0 r10:0x802 r11:0x246 r12:0x0 r13:0x211718 r14:0x802 r15:0x7fc47b7fc718 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x7fc47b7fe700 gs_base:0x0
}
[…]

nbp avatar Aug 16 '16 14:08 nbp

I'll see if I can reproduce this with your Firefox branch.

rocallahan avatar Aug 18 '16 03:08 rocallahan

I build your tree (opt build). It didn't work very well --- stopped being able to load pages after the first one --- but it didn't crash. Replay succeeded fine. Can you give me more precise steps to reproduce? Do I need to flip any prefs or use a debug build?

rocallahan avatar Aug 18 '16 05:08 rocallahan

Sorry I should have been more precise.

Firefox does not crash, it sometimes fails to load the script when pages are reloaded. I test with debug builds, and the following environment variable:

I record with:

MOZ_LOG="SRI:6,ScriptLoader:6,timestamp,sync" rr -M record …/dbg/firefox -no-remote -profile …/dbg/tmp/scratch_user

Then I follow the following steps: (sorry this is far from being minimal)

  • visit https://news.ycombinator.com/
  • load the 5 first topic in new tabs.
  • switch to the tab, once it is loaded close it. (x5)
  • reload hacker news
  • load the 5 first topic in new tabs.
  • switch to the tab, once it is loaded close it. (x5)
  • close firefox.

and replay with:

rr -M replay -a

It seems that it might have different intermittent frequencies on different runs. Note, when I managed to get pass this reproduction issue I could reproduce #1758 .

I will make a debug build of rr, and see if I can record the replay.

nbp avatar Aug 18 '16 15:08 nbp

I will make a debug build of rr, and see if I can record the replay.

I guess this is another issue, but I failed to record the rr replay -a, with the following error:

rr: Saving execution to trace directory `/home/nicolas/.local/share/rr/rr-1'.
rr: rr pid 30099 running under parent 30085. Good luck.
[FATAL /tmp/nix-build-rr-4.3.0.drv-0/rr-master-src/src/VirtualPerfCounterMonitor.cc:34:VirtualPerfCounterMonitor() errno: SUCCESS] 
 (task 30099 (rec:30099) at time 60598)
 -> Assertion `attr.sample_period == 0xffffffff' failed to hold. Don't support interrupts yet

nbp avatar Aug 18 '16 15:08 nbp

That looks like you're running rr under rr somehow...

rocallahan avatar Aug 19 '16 10:08 rocallahan

With another run, I have the following issue, which I guess might be related:

[ERROR /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:297:maybe_print_reg_mismatch() errno: SUCCESS] rsi 0x80801 != 0x2 (replaying vs. recorded)
[ERROR /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:297:maybe_print_reg_mismatch() errno: SUCCESS] rdi 0x1 != 0x2 (replaying vs. recorded)
[ERROR /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:297:maybe_print_reg_mismatch() errno: SUCCESS] rbp 0x7fe42e0fb830 != 0x7fe42e0fbc40 (replaying vs. recorded)
[ERROR /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:297:maybe_print_reg_mismatch() errno: SUCCESS] r8 0x18 != 0x5332a0affff0000 (replaying vs. recorded)
[ERROR /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:297:maybe_print_reg_mismatch() errno: SUCCESS] r9 0xffffffff != 0x100000800 (replaying vs. recorded)
[ERROR /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:297:maybe_print_reg_mismatch() errno: SUCCESS] r10 0x6 != 0 (replaying vs. recorded)
[ERROR /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:297:maybe_print_reg_mismatch() errno: SUCCESS] r12 0x7fe42e0fb8b0 != 0xffffffff (replaying vs. recorded)
[ERROR /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:297:maybe_print_reg_mismatch() errno: SUCCESS] r13 0xffffffffffffff58 != 0 (replaying vs. recorded)
[ERROR /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:297:maybe_print_reg_mismatch() errno: SUCCESS] r14 0x1e != 0x7fe428000d30 (replaying vs. recorded)
[ERROR /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:297:maybe_print_reg_mismatch() errno: SUCCESS] r15 0x7fe42e0fb608 != 0x7fe42e0fb8d8 (replaying vs. recorded)
[FATAL /tmp/nix-build-rr-4.3.0-master.drv-0/rr/src/Registers.cc:417:compare_register_files() errno: SUCCESS] 
 (task 6111 (rec:5394) at time 35353)
 -> Assertion `!bail_error || match' failed to hold. Fatal register mismatch (ticks/rec:1413/1865)

I tried to look at dumps, for matching recorded register values and found the following, but the differences between the register does not hint if the failure happened at the ENTERING_SYSCALL or EXITING_SYSCALL.

{
  real_time:1619634.685251 global_time:35348, event:`SYSCALLBUF_RESET' tid:5301, ticks:3242180180
}
{
  real_time:1619634.685281 global_time:35349, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:5301, ticks:3242180180
 rax:0x6c rbx:0x2 rcx:0xffffffffffffffff rdx:0x6c rsi:0x7ffccfd5ef80 rdi:0x2 rbp:0x0 rsp:
0x7ffccfd5eb30 r8:0x7fe514626740 r9:0x6c r10:0x1 r11:0x246 r12:0x7ffccfd5ef80 r13:0x6c r14:0x7fe5133b1540 r15:0x7ffccfd5ec90 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7fe514626740 gs_base:0x0
}
{
  real_time:1619634.690158 global_time:35350, event:`SCHED' tid:5301, ticks:3242693117
 rax:0x94f130 rbx:0x0 rcx:0x0 rdx:0x7fe514626a70 rsi:0x1 rdi:0x94f130 rbp:0x7ffccfd5ad50 rsp:0x7ffccfd5ad40 r8:0x7ffccfd5b630 r9:0x0 r10:0x0 r11:0x0 r12:0x4056e0 r13:0x7ffccfd70230 r14:0x7ffccfd5e1d8 r15:0x0 rip:0x7fe5041f8967 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_base:0x7fe514626740 gs_base:0x0
}
{
  real_time:1619634.690178 global_time:35351, event:`SYSCALL: futex' (state:EXITING_SYSCALL) tid:5394, ticks:936
 rax:0xfffffffffffffff5 rbx:0x0 rcx:0xffffffffffffffff rdx:0x2 rsi:0x80 rdi:0xa4f820 rbp:0x7fe42e0fbcb0 rsp:0x7fe42e0fbbf8 r8:0xa4f820 r9:0x7fe51462c500 r10:0x0 r11:0x246 r12:0x0 r13:0x7ffccfd6c42f r14:0x3 r15:0x7ffccfd6c530 rip:0x7fe513fd2e3c eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xca fs_base:0x7fe42e0fc700 gs_base:0x0
}
{
  real_time:1619634.690336 global_time:35352, event:`SYSCALLBUF_FLUSH' tid:5394, ticks:1865
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'futex', ret:0x0, size:0x14 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
}
{
  real_time:1619634.690345 global_time:35353, event:`SYSCALL: socket' (state:ENTERING_SYSCALL) tid:5394, ticks:1865
 rax:0xffffffffffffffda rbx:0x29 rcx:0xffffffffffffffff rdx:0x0 rsi:0x2 rdi:0x2 rbp:0x7fe42e0fbc40 rsp:0x7fe42e0fb778 r8:0x5332a0affff0000 r9:0x100000800 r10:0x0 r11:0x246 r12:0xffffffff r13:0x0 r14:0x7fe428000d30 r15:0x7fe42e0fb8d8 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x29 fs_base:0x7fe42e0fc700 gs_base:0x0
}
{
  real_time:1619634.690360 global_time:35354, event:`SYSCALLBUF_RESET' tid:5394, ticks:1865
}
{
  real_time:1619634.690390 global_time:35355, event:`SYSCALL: socket' (state:EXITING_SYSCALL) tid:5394, ticks:1865
 rax:0x3f rbx:0x29 rcx:0xffffffffffffffff rdx:0x0 rsi:0x2 rdi:0x2 rbp:0x7fe42e0fbc40 rsp:0x7fe42e0fb778 r8:0x5332a0affff0000 r9:0x100000800 r10:0x0 r11:0x246 r12:0xffffffff r13:0x0 r14:0x7fe428000d30 r15:0x7fe42e0fb8d8 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x29 fs_base:0x7fe42e0fc700 gs_base:0x0
}

nbp avatar Aug 19 '16 10:08 nbp

Hum … interesting finding on my side.

When I compile firefox with clang 3.7, I get the issue listed above. When I compile firefox with gcc 4.8.5, I no longer get any replay -a issues but, I can still reproduce #1758.

The tool chains that I use for compiling can be installed with Nix by using the nix expression from: https://github.com/garbas/nixpkgs-mozilla

For building I spawn a shell with the nix-shell command, which basically change all the environment variable to hide the default one. The following should pull / compile and environment for building firefox with clang 3.7:

$ git clone https://github.com/garbas/nixpkgs-mozilla
$ cd firefox
$ nix-shell ../nixpkgs-mozilla/release.nix -A gecko.x86_64-linux.clang37 --pure
$$ mach build

nbp avatar Aug 19 '16 13:08 nbp

I rebuilt your Gecko tree at revision f50fadf05f3959a021395ac67fb821083cf5bdc9 and tried following the steps of comment https://github.com/mozilla/rr/issues/1771#issuecomment-240763610. Tabs crashed a lot and the replay worked fine. This is with gcc 6.1.1. I'm not sure why you're using such an old gcc version?

rocallahan avatar Aug 22 '16 07:08 rocallahan

My version of clang is 3.8.0. I'll try that...

rocallahan avatar Aug 22 '16 07:08 rocallahan

Basically the same results with clang 3.8.0 here. Note that these are opt builds of rr and Firefox. (cmake -DCMAKE_BUILD_TYPE=Release for rr.)

rocallahan avatar Aug 22 '16 07:08 rocallahan

Ok, then I have no clue, what might go wrong with my clang generated code.

I have not yet tried a Firefox opt build, only debug builds. I have the same issue with both opt/dbg builds of rr.

nbp avatar Aug 22 '16 07:08 nbp

Did you try running the rr tests with your clang build of rr?

rocallahan avatar Aug 22 '16 08:08 rocallahan

I will check.

nbp avatar Aug 22 '16 08:08 nbp

@nbp I guess this old issue can be closed (both because it is quite old and because there were a bunch of updates that likely have actually fixed this issue), do you agree?

GitMensch avatar Jul 26 '21 08:07 GitMensch