Replaying a Wine recording triggers Assertion 'ticks_now == trace_ticks', mmap with MAP_PRIVATE #3972
Description
After @Keno 's patch finally went in some form into Wine I found there still happen diversions.
So I tried to bisect and found Wine was changing how a shared memory between wineserver and the gui processes get mapped. Unfortunately there were a few more commits making this one not alone revertable.
But I could strip it down to this modification to wine to make replaying work again by using the previous mapping flag MAP_SHARED instead of MAP_PRIVATE:
--- a/dlls/ntdll/unix/virtual.c
+++ b/dlls/ntdll/unix/virtual.c
@@ -2351,7 +2351,13 @@ static NTSTATUS map_file_into_view( struct file_view *view, int fd, size_t start
/* changes to the file are not guaranteed to be visible in read-only MAP_PRIVATE mappings,
* but they are on Linux so we take advantage of it */
#ifdef __linux__
+ if (vprot & SEC_FILE) {
flags |= MAP_PRIVATE;
+ } else {
+ flags |= MAP_SHARED;
+ prot &= ~PROT_WRITE;
+ //ERR("fd=%d flags=0x%x prot=0x%x vprot=0x%x:%d\n", fd, flags, prot, vprot, __LINE__);
+ }
#else
flags |= MAP_SHARED;
prot &= ~PROT_WRITE;This is what I got, but there was no relation to a shared memory visible:
[FATAL src/ReplaySession.cc:1278:check_ticks_consistency()]
(task 1131280 (rec:1131219) at time 151589)
-> Assertion `ticks_now == trace_ticks' failed to hold. ticks mismatch for 'SYSCALL: read'; expected 24071991, got 24071980
So I tried prove this shared memory being the issue by spraying such calls syscall(-1, 0, 0); in the functions shown by the emergency shell and reached that way function shared_object_get_id in Wine, with a better to follow register mismatch:
[FATAL src/ReplayTask.cc:130:validate_regs()]
(task 1123897 (rec:1123824) at time 170377)
-> Assertion `!comparison.mismatch_count' failed to hold. Mismatched registers, replay vs rec: r12 (nil) != 0x18
104 lock.id = object->id;
0x00007f7e41638440 <+127>: mov 0x8(%rbx),%r12
0x00007f7e41638444 <+131>: mov %r12,-0x40(%rbp)
There the memory in question looks like this:
(gdb) print/x *(const shared_object_t *) 0x7ffffe9e0ef8
$5 = {seq = 0x6, id = 0x0, shm = {desktop = {flags = 0xfefefefe, cursor = {x = 0xfefefefe, y = 0xfefefefe, last_change = 0xfefefefe, clip = {left = 0xfefefefe, top = 0xfefefefe, right = 0xfefefefe,
bottom = 0xfefefefe}}, keystate = {0xfe <repeats 256 times>}, monitor_serial = 0xfefefefefefefefe}, queue = {hooks_count = {0xfefefefe <repeats 17 times>}, wake_mask = 0xfefefefe, wake_bits = 0xfefefefe,
changed_mask = 0xfefefefe, changed_bits = 0xfefefefe}, input = {foreground = 0xfefefefe, active = 0xfefefefe, focus = 0xfefefefe, capture = 0xfefefefe, menu_owner = 0xfefefefe, move_size = 0xfefefefe,
caret = 0xfefefefe, caret_rect = {left = 0xfefefefe, top = 0xfefefefe, right = 0xfefefefe, bottom = 0xfefefefe}, cursor = 0xfefefefe, cursor_count = 0xfefefefe, keystate = {0xfe <repeats 256 times>},
keystate_lock = 0xfefefefe}}}
When I replay the wineserver to short before the diversion I see this state of the mapping:
(rr) print/x *(const shared_object_t *)0x7f872e6d0ef8
$1 = {seq = 0xe, id = 0x18, shm = {desktop = {flags = 0x0, cursor = {x = 0x0, y = 0x0, last_change = 0x0, clip = {left = 0x0, top = 0x0, right = 0x0, bottom = 0x0}}, keystate = {0x0 <repeats 41 times>, 0x80, 0x0,
0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x80, 0x0, 0x0, 0x55 <repeats 204 times>}, monitor_serial = 0x5555555555555555}, queue = {hooks_count = {0x0 <repeats 17 times>}, wake_mask = 0x0, wake_bits = 0x8000,
changed_mask = 0x0, changed_bits = 0x8000}, input = {foreground = 0x0, active = 0x0, focus = 0x0, capture = 0x0, menu_owner = 0x0, move_size = 0x0, caret = 0x0, caret_rect = {left = 0x0, top = 0x0,
right = 0x0, bottom = 0x0}, cursor = 0x0, cursor_count = 0x0, keystate = {0x0 <repeats 21 times>, 0x80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x80, 0x0, 0x0, 0x55 <repeats 224 times>},
keystate_lock = 0x55555555}}}
So it looks like this mapping was not propagating changes to the memory in wineserver to the wine process, which seems to show some initial state of it.
To make things more complicated this shared memory is created by wineserver by creating a temporary file and sending the fd through a socket to the wine process.
I tried to replicate this in a rr testcase, but unfortunately this is not showing the issue, so there is maybe more to it:
mmap_private_from_fd_via_socket.c.txt
I had made some tests a while ago for this issue and was seeing it at Intel hardware too, so it seems no AMD related thing.
Is this probably a known issue in rr?
Any hints how to continue from here?
PS.: To speed up things I am just recording wineserver and the wine process I am interested in. But the issue appears also when recording the whole tree.
rr record bash -c "wineserver -k; wineserver -p60; rr record --nested=release wine wineconsole cmd /c \"timeout /t 10\" & sleep 8s; echo start; WINEDLLOVERRIDES=winemenubuilder.exe=n WINEDEBUG=+pid,+timestamp wine winemine; sleep 1s; wineserver -k; sleep 1s"```