Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ticks mismatch (aarch64) #3649

Closed
eggyal opened this issue Nov 24, 2023 · 5 comments
Closed

Ticks mismatch (aarch64) #3649

eggyal opened this issue Nov 24, 2023 · 5 comments

Comments

@eggyal
Copy link

eggyal commented Nov 24, 2023

Encountered the following during rr replay (on 6.5.11-407.asahi.fc39.aarch64+16k, using 920add3 to workaround #3568):

[FATAL src/ReplaySession.cc:1184:check_ticks_consistency()] 
 (task 2215440 (rec:2195269) at time 4901)
 -> Assertion `ticks_now == trace_ticks' failed to hold. ticks mismatch for 'PATCH_SYSCALL'; expected 28650421, got 28650422
Tail of trace dump:
{
  real_time:190548.120124 global_time:4881, event:`SYSCALL: ioctl' (state:EXITING_SYSCALL) tid:2195269, ticks:23739280
x[0]:0xffffffffffffffe7 x[1]:0x5401 x[2]:0xffffe8c81ea0 x[3]:0xffffe8c81ee8 x[4]:0xffff715dfb40 x[5]:0xffffe8c81d90 x[6]:0xffffe8c81d90 x[7]:0x70000000 x[8]:0x1d x[9]:0x0 x[10]:0xfffffffffffffff9 x[11]:0x101010101010101 x[12]:0x0 x[13]:0x0 x[14]:0x0 x[15]:0x70010000 x[16]:0xaaab5d1ad528 x[17]:0xffff712a3cb0 x[18]:0x1 x[19]:0x687ffd50 x[20]:0xaaab5d0e6688 x[21]:0x0 x[22]:0x0 x[23]:0x1 x[24]:0x0 x[25]:0x0 x[26]:0x0 x[27]:0x0 x[28]:0x0 x[29]:0x687ffc10 x[30]:0xffff71555d60 sp:0x687ffbe0 pc:0x70000004 pstate:0x80001000
  { tid:2195269, addr:0xffffe8c81ea0, length:0x24 }
}
{
  real_time:190548.120136 global_time:4882, event:`SYSCALL: ioctl' (state:ENTERING_SYSCALL) tid:2195269, ticks:23739523
x[0]:0x2 x[1]:0x5401 x[2]:0xffffe8c81ea0 x[3]:0xffffe8c81ee8 x[4]:0xffff715dfb40 x[5]:0xffffe8c81d90 x[6]:0xffffe8c81d90 x[7]:0x70000000 x[8]:0x1d x[9]:0x0 x[10]:0xfffffffffffffff9 x[11]:0x101010101010101 x[12]:0x0 x[13]:0x0 x[14]:0x0 x[15]:0x70010000 x[16]:0xaaab5d1ad528 x[17]:0xffff712a3cb0 x[18]:0x1 x[19]:0x687ffd50 x[20]:0xaaab5d0e65e8 x[21]:0x0 x[22]:0x0 x[23]:0x1 x[24]:0x0 x[25]:0x0 x[26]:0x0 x[27]:0x0 x[28]:0x0 x[29]:0x687ffc10 x[30]:0xffff71555d60 sp:0x687ffbe0 pc:0x70000004 pstate:0x80001000
}
{
  real_time:190548.120145 global_time:4883, event:`SYSCALL: ioctl' (state:EXITING_SYSCALL) tid:2195269, ticks:23739523
x[0]:0xffffffffffffffe7 x[1]:0x5401 x[2]:0xffffe8c81ea0 x[3]:0xffffe8c81ee8 x[4]:0xffff715dfb40 x[5]:0xffffe8c81d90 x[6]:0xffffe8c81d90 x[7]:0x70000000 x[8]:0x1d x[9]:0x0 x[10]:0xfffffffffffffff9 x[11]:0x101010101010101 x[12]:0x0 x[13]:0x0 x[14]:0x0 x[15]:0x70010000 x[16]:0xaaab5d1ad528 x[17]:0xffff712a3cb0 x[18]:0x1 x[19]:0x687ffd50 x[20]:0xaaab5d0e65e8 x[21]:0x0 x[22]:0x0 x[23]:0x1 x[24]:0x0 x[25]:0x0 x[26]:0x0 x[27]:0x0 x[28]:0x0 x[29]:0x687ffc10 x[30]:0xffff71555d60 sp:0x687ffbe0 pc:0x70000004 pstate:0x80001000
  { tid:2195269, addr:0xffffe8c81ea0, length:0x24 }
}
{
  real_time:190548.120260 global_time:4884, event:`SYSCALLBUF_FLUSH' tid:2195269, ticks:23782180
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0x0, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0x0, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0x0, size:0x110 }
  { syscall:'statx', ret:0xfffffffffffffffe, size:0x110 }
  { syscall:'statx', ret:0x0, size:0x110 }
  { syscall:'statx', ret:0x0, size:0x110 }
  { syscall:'futex', ret:0x0, size:0x14 }
  { syscall:'openat', ret:0x3, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xc, size:0x1c }
  { syscall:'read', ret:0x8, size:0x18, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
}
{
  real_time:190548.120274 global_time:4885, event:`PATCH_SYSCALL' tid:2195269, ticks:23782180
x[0]:0xaaab5d1b1518 x[1]:0xaaab5c683c30 x[2]:0x4 x[3]:0x0 x[4]:0xaaab5cc76bfc x[5]:0xaaab9aa2b764 x[6]:0x6374652f x[7]:0x761 x[8]:0xae x[9]:0x40 x[10]:0xd x[11]:0x101010101010101 x[12]:0x10f0 x[13]:0xffff71560168 x[14]:0xffffffffffffffff x[15]:0x1fff x[16]:0xaaab5d1ad750 x[17]:0xffff71286ac0 x[18]:0x1 x[19]:0xaaab5d1b1538 x[20]:0xaaab5d1b1518 x[21]:0xaaab5d1bd000 x[22]:0x10 x[23]:0x1 x[24]:0xaaab5d1b10a0 x[25]:0xaaab9aaada00 x[26]:0xffffe8c824c0 x[27]:0x0 x[28]:0x0 x[29]:0xffffe8c82240 x[30]:0xaaab5c683c48 sp:0xffffe8c82240 pc:0xffff71286ac8 pstate:0x80001000
  { tid:2195269, addr:0xffff71438508, length:0x38 }
  { tid:2195269, addr:0xffff71286ac8, length:0x4 }
}
{
  real_time:190548.120275 global_time:4886, event:`SYSCALLBUF_RESET' tid:2195269, ticks:23782180
}
{
  real_time:190548.120288 global_time:4887, event:`SYSCALLBUF_FLUSH' tid:2195269, ticks:23782208
  { syscall:'getuid', ret:0x3e9, size:0x10 }
}
{
  real_time:190548.120299 global_time:4888, event:`PATCH_SYSCALL' tid:2195269, ticks:23782208
x[0]:0x3e9 x[1]:0xaaab5c683c30 x[2]:0x4 x[3]:0x0 x[4]:0xaaab5cc76bfc x[5]:0xaaab9aa2b764 x[6]:0x6374652f x[7]:0x761 x[8]:0xaf x[9]:0x40 x[10]:0xd x[11]:0x101010101010101 x[12]:0x10f0 x[13]:0xffff71560168 x[14]:0xffffffffffffffff x[15]:0x1fff x[16]:0xaaab5d1ad2d8 x[17]:0xffff71285a00 x[18]:0x1 x[19]:0xaaab5d1b1538 x[20]:0xaaab5d1b1518 x[21]:0x3e9 x[22]:0x10 x[23]:0x1 x[24]:0xaaab5d1b10a0 x[25]:0xaaab9aaada00 x[26]:0xffffe8c824c0 x[27]:0x0 x[28]:0x0 x[29]:0xffffe8c82240 x[30]:0xaaab5c683c50 sp:0xffffe8c82240 pc:0xffff71285a08 pstate:0x40001000
  { tid:2195269, addr:0xffff71438540, length:0x38 }
  { tid:2195269, addr:0xffff71285a08, length:0x4 }
}
{
  real_time:190548.120300 global_time:4889, event:`SYSCALLBUF_RESET' tid:2195269, ticks:23782208
}
{
  real_time:190548.120346 global_time:4890, event:`SYSCALLBUF_FLUSH' tid:2195269, ticks:23812061
  { syscall:'geteuid', ret:0x3e9, size:0x10 }
  { syscall:'getuid', ret:0x3e9, size:0x10 }
  { syscall:'geteuid', ret:0x3e9, size:0x10 }
  { syscall:'getuid', ret:0x3e9, size:0x10 }
  { syscall:'geteuid', ret:0x3e9, size:0x10 }
  { syscall:'futex', ret:0x0, size:0x14 }
  { syscall:'futex', ret:0x0, size:0x14 }
}
{
  real_time:190548.120356 global_time:4891, event:`PATCH_SYSCALL' tid:2195269, ticks:23812061
x[0]:0x0 x[1]:0xaaab5d1c0000 x[2]:0xffffffffffffffd8 x[3]:0xaaab9aa292c0 x[4]:0xaaab9aa29318 x[5]:0x4 x[6]:0xaaab9aa576f0 x[7]:0xde1 x[8]:0xac x[9]:0x50 x[10]:0xaaab9aa57110 x[11]:0xaaab5d1b5768 x[12]:0x0 x[13]:0xffffffff x[14]:0x0 x[15]:0x0 x[16]:0xaaab5d1ad488 x[17]:0xffff71286980 x[18]:0xaaab9aa57390 x[19]:0xaaab9aa291a0 x[20]:0x0 x[21]:0x0 x[22]:0xaaab5ccb7000 x[23]:0x38a x[24]:0x0 x[25]:0xaaab9aaada00 x[26]:0xffffe8c824c0 x[27]:0x0 x[28]:0x0 x[29]:0xffffe8c820e0 x[30]:0xaaab5c8442ec sp:0xffffe8c820e0 pc:0xffff71286988 pstate:0x60001000
  { tid:2195269, addr:0xffff71438578, length:0x38 }
  { tid:2195269, addr:0xffff71286988, length:0x4 }
}
{
  real_time:190548.120358 global_time:4892, event:`SYSCALLBUF_RESET' tid:2195269, ticks:23812061
}
{
  real_time:190548.120373 global_time:4893, event:`SYSCALLBUF_FLUSH' tid:2195269, ticks:23812430
  { syscall:'getpid', ret:0x217f45, size:0x10 }
}
{
  real_time:190548.120383 global_time:4894, event:`PATCH_SYSCALL' tid:2195269, ticks:23812430
x[0]:0xaaab9aa29be0 x[1]:0x20 x[2]:0x0 x[3]:0xaaab9aa29be0 x[4]:0xaaab9aa29c00 x[5]:0xffff71599f70 x[6]:0xaaab9aa291a0 x[7]:0xac1 x[8]:0x116 x[9]:0x130 x[10]:0xaaab9aa57110 x[11]:0xaaab5d1b5768 x[12]:0xe x[13]:0xffffffff x[14]:0x0 x[15]:0x0 x[16]:0xaaab5d1ad4e0 x[17]:0xffff711f8e30 x[18]:0xaaab9aa57390 x[19]:0xaaab9aa29be0 x[20]:0x20 x[21]:0xaaab9aaaa9d0 x[22]:0x2 x[23]:0xffff711f8e30 x[24]:0x7fffffff x[25]:0xaaab9aaada00 x[26]:0xffffe8c824c0 x[27]:0x0 x[28]:0x0 x[29]:0xffffe8c81f90 x[30]:0x7faaab5c845d44 sp:0xffffe8c81f90 pc:0xffff711f8e78 pstate:0x80001000
  { tid:2195269, addr:0xffff714385b0, length:0x38 }
  { tid:2195269, addr:0xffff711f8e78, length:0x4 }
}
{
  real_time:190548.120385 global_time:4895, event:`SYSCALLBUF_RESET' tid:2195269, ticks:23812430
}
{
  real_time:190548.120422 global_time:4896, event:`SYSCALLBUF_FLUSH' tid:2195269, ticks:23825287
  { syscall:'getrandom', ret:0x20, size:0x30, desched:1 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'futex', ret:0x0, size:0x14 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'getpid', ret:0x217f45, size:0x10 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'openat', ret:0x3, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0x31, size:0x41 }
}
{
  real_time:190548.120423 global_time:4897, event:`SYSCALL: fstatat' (state:ENTERING_SYSCALL) tid:2195269, ticks:23825287
x[0]:0x3 x[1]:0xffff7131d730 x[2]:0xffffe8c81e08 x[3]:0x1000 x[4]:0x1 x[5]:0x0 x[6]:0x0 x[7]:0x70000000 x[8]:0x4f x[9]:0x130 x[10]:0xaaab9aa04010 x[11]:0x101010101010101 x[12]:0x10f0 x[13]:0xffff71560168 x[14]:0xffffffffffffffff x[15]:0x70010000 x[16]:0xffff71239400 x[17]:0xffff71229580 x[18]:0xaaab9aa57390 x[19]:0x687ffd50 x[20]:0xffff7136f1f8 x[21]:0xaaab9aa57e40 x[22]:0xaaab9aa58240 x[23]:0xa x[24]:0xaaab9aa58240 x[25]:0x0 x[26]:0x1 x[27]:0x0 x[28]:0xffffe8c821b0 x[29]:0x687ffc10 x[30]:0xffff71555d60 sp:0x687ffbe0 pc:0x70000004 pstate:0x80001000
}
{
  real_time:190548.120424 global_time:4898, event:`SYSCALLBUF_RESET' tid:2195269, ticks:23825287
}
{
  real_time:190548.120433 global_time:4899, event:`SYSCALL: fstatat' (state:EXITING_SYSCALL) tid:2195269, ticks:23825287
x[0]:0x0 x[1]:0xffff7131d730 x[2]:0xffffe8c81e08 x[3]:0x1000 x[4]:0x1 x[5]:0x0 x[6]:0x0 x[7]:0x70000000 x[8]:0x4f x[9]:0x130 x[10]:0xaaab9aa04010 x[11]:0x101010101010101 x[12]:0x10f0 x[13]:0xffff71560168 x[14]:0xffffffffffffffff x[15]:0x70010000 x[16]:0xffff71239400 x[17]:0xffff71229580 x[18]:0xaaab9aa57390 x[19]:0x687ffd50 x[20]:0xffff7136f1f8 x[21]:0xaaab9aa57e40 x[22]:0xaaab9aa58240 x[23]:0xa x[24]:0xaaab9aa58240 x[25]:0x0 x[26]:0x1 x[27]:0x0 x[28]:0xffffe8c821b0 x[29]:0x687ffc10 x[30]:0xffff71555d60 sp:0x687ffbe0 pc:0x70000004 pstate:0x80001000
  { tid:2195269, addr:0xffffe8c81e08, length:0x80 }
}
{
  real_time:190548.123703 global_time:4900, event:`SYSCALLBUF_FLUSH' tid:2195269, ticks:28650421
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x1000, size:0x1010, desched:1 }
  { syscall:'read', ret:0x382, size:0x392, desched:1 }
  { syscall:'read', ret:0x0, size:0x10, desched:1 }
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'futex', ret:0x0, size:0x14 }
}
{
  real_time:190548.123718 global_time:4901, event:`PATCH_SYSCALL' tid:2195269, ticks:28650421
x[0]:0xffffffffffffff9c x[1]:0xaaab9ab01540 x[2]:0x0 x[3]:0x1d x[4]:0xaaab5cc714da x[5]:0xaaab9ab01554 x[6]:0x666e6f637469672e x[7]:0x6769666e6f637469 x[8]:0x30 x[9]:0x4 x[10]:0x0 x[11]:0x0 x[12]:0xffffff9f x[13]:0xffffffc0 x[14]:0xaaab5cd87a4e x[15]:0x56 x[16]:0xaaab5d1ad790 x[17]:0xffff7129fca0 x[18]:0x1 x[19]:0x0 x[20]:0xffffe8c81ed0 x[21]:0xaaab5cc714d0 x[22]:0x0 x[23]:0xaaab5cc76b28 x[24]:0xaaab9aa56248 x[25]:0xaaab9aaada00 x[26]:0xffffe8c824c0 x[27]:0x0 x[28]:0x0 x[29]:0xffffe8c81e30 x[30]:0x4aaab5c68ae24 sp:0xffffe8c81e30 pc:0xffff7129fcbc pstate:0x80001000
  { tid:2195269, addr:0xffff714385e8, length:0x38 }
  { tid:2195269, addr:0xffff7129fcbc, length:0x4 }
}
{
  real_time:190548.123734 global_time:4902, event:`SYSCALLBUF_RESET' tid:2195269, ticks:28650421
}
=== Start rr backtrace:
/usr/local/bin/rr(_ZN2rr9GdbServer15emergency_debugEPNS_4TaskE+0xe0)[0x48a2f0]
/usr/local/bin/rr[0x49b09c]
/usr/local/bin/rr[0x49ba7c]
/usr/local/bin/rr(_ZN2rr13ReplaySession23check_ticks_consistencyEPNS_10ReplayTaskERKNS_5EventE+0x194)[0x51c0a8]
/usr/local/bin/rr(_ZN2rr13ReplaySession11replay_stepERKNS0_15StepConstraintsE+0x430)[0x5230b0]
/usr/local/bin/rr(_ZN2rr14ReplayTimeline19replay_step_forwardENS_10RunCommandE+0x84)[0x53b9d8]
/usr/local/bin/rr(_ZN2rr9GdbServer14debug_one_stepERNS_10GdbRequestE+0x1f4)[0x487658]
/usr/local/bin/rr(_ZN2rr9GdbServer12serve_replayERKNS0_15ConnectionFlagsE+0x584)[0x488654]
/usr/local/bin/rr[0x518c18]
/usr/local/bin/rr(_ZN2rr13ReplayCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0x444)[0x519ec4]
/usr/local/bin/rr(main+0x168)[0x4339a8]
/lib64/libc.so.6(+0x309dc)[0xfffee29309dc]
/lib64/libc.so.6(__libc_start_main+0x9c)[0xfffee2930ab0]
/usr/local/bin/rr(_start+0x30)[0x434f30]
=== End rr backtrace
@eggyal
Copy link
Author

eggyal commented Nov 24, 2023

Ah, every time I rr replay, the tick mismatch occurs at a different syscall.

@eggyal eggyal changed the title Ticks mismatch for 'PATCH_SYSCALL' (aarch64) Ticks mismatch (aarch64) Nov 24, 2023
@eggyal
Copy link
Author

eggyal commented Nov 25, 2023

Following Debugging divergence:

In a failed replay, try following the emergency debugger instructions to get a stack. Are you somewhere suspicious, e.g. that might be manipulating memory shared outside the trace?

(gdb) where
#0  0x0000000070000024 in syscall_untraced_record_only ()
#1  0x0000fffeec8f5d60 in _raw_syscall () at /home/anm-la/rr/src/preload/raw_syscall.S:161
#2  0x0000fffeec8f2af4 in untraced_syscall_full (a3=0, stack_param_1=0, stack_param_2=0, syscall_instruction=0x70000020, a5=0, a4=0, a2=8192, a1=1882276198, a0=0, syscallno=63) at /home/anm-la/rr/src/preload/syscallbuf.c:449
#3  sys_read (call=) at /home/anm-la/rr/src/preload/syscallbuf.c:2901
#4  0x0000fffeec8f5b90 in syscall_hook (call=0xfffeea96fd50) at /home/anm-la/rr/src/preload/syscallbuf.c:4234
#5  syscall_hook (call=0xfffeea96fd50) at /home/anm-la/rr/src/preload/syscallbuf.c:4218
#6  0x0000fffeec8f0324 in _syscall_hook_trampoline () at /home/anm-la/rr/src/preload/syscall_hook.S:804
#7  0x0000fffeec8f0424 in _syscall_hook_trampoline_raw () at /home/anm-la/rr/src/preload/syscall_hook.S:978
#8  0x0000fffeec694da8 in __GI___libc_read (nbytes=8192, buf=0xfffee0000ca0, fd=0) at ../sysdeps/unix/sysv/linux/read.c:26
#9  __GI___libc_read (fd=0, buf=0xfffee0000ca0, nbytes=8192) at ../sysdeps/unix/sysv/linux/read.c:24
#10 0x0035aaab15a52a60 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Doesn't look particularly suspicious to me, but I'm not familiar enough to rule it out? The debuggee is named mmap_clone_... however—if that indicates some mmap could be at play, then that could certainly be something "that might be manipulating memory shared outside the trace"?

@eggyal
Copy link
Author

eggyal commented Nov 25, 2023

With some logging:

[ReplaySession] [event 5684] 2195261: replaying SYSCALLBUF_FLUSH; state  (none)
[ReplaySession]     (syscllbufsz:0, abrtcmt:0, locked:0)
[ReplaySession] Prepared 312 bytes of syscall records
[ReplaySession] Adding breakpoint
[Task] resuming execution of 2263651 with PTRACE_CONT tick_period -1 wait 0
[Task] Flushing registers for tid 2263651 { ip:0x7000000c args:(0x17,0xfffee0000ca0,0x2000,0,0xfffeeab7ce78,281470212031496) orig_syscall: 63 syscallno: 1002 orig_arg1: 0 }
[Task] Changing syscall to 63
[Task] going into blocking wait for 2263651 ...
[Task]   Task 2263651 changed status to 0xb7f (STOP-SIGSEGV)
[Task]   (refreshing register cache)
[Task] Requesting registers from tracee 2263651
[ReplaySession] Removing breakpoint 0xb7f (STOP-SIGSEGV)
[ReplaySession] [event 5685] 2195261: replaying SYSCALL: read; state ENTERING_SYSCALL
[ReplaySession]     (syscllbufsz:312, abrtcmt:0, locked:0)
[Task] resuming execution of 2263651 with PTRACE_SYSEMU tick_period -1 wait 0
[Task] Flushing registers for tid 2263651 { ip:0xfffeec8f050c args:(0xfffffffffffffff0,0xfffeea96fbf8,0x27,0xfffffffffffffff0,0xfffffffffffffff0,98) orig_syscall: 63 syscallno: 98 orig_arg1: 0 }
[Task] going into blocking wait for 2263651 ...
[Task]   Task 2263651 changed status to 0x57f (STOP-SIGTRAP)
[Task]   (refreshing register cache)
[Task] Requesting registers from tracee 2263651
[FATAL src/ReplaySession.cc:1184:check_ticks_consistency()] 
 (task 2263651 (rec:2195261) at time 5685)
 -> Assertion `ticks_now == trace_ticks' failed to hold. ticks mismatch for 'SYSCALL: read'; expected 1701293, got 1701294

@khuey
Copy link
Collaborator

khuey commented Nov 25, 2023

Doesn't look particularly suspicious to me, but I'm not familiar enough to rule it out?

The suspicious part (if any) would be frames 10 or lower, everything that's visible is just rr internals unfortunately.

@eggyal
Copy link
Author

eggyal commented Nov 25, 2023

Hadn't completely digested that RR isn't yet fully working on Asahi. Will close this.

@eggyal eggyal closed this as not planned Won't fix, can't repro, duplicate, stale Nov 25, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants