PANIC: remove page X from cache Y: page still has mappings!

[waddlesplash]

First reported in the replies to #19360, and there's some analysis already there. This is reproducible on current hrevs, using the test scripts found there and ramfs.

[waddlesplash]

I haven't had a lot of success debugging this so far. It's very intermittent, all my attempts at adding sleeps/spins don't seem to make it much more likely (in fact basically all seem to make it less likely, though it's hard to tell), and it's very optimization-sensitive (I've never gotten it to happen with -O0 yet, with -Og it does after a while, and with -O2 it's more reliable.) But even in the best case it takes multiple minutes or more to reproduce here, on average.

To make matters worse, GDB (and/or VMware's GDB stub) doesn't work correctly on binaries compiled even with -Og. Inspection of "heap" variables works, but any stack variables outside the current frame give bogus values (or worse, misleading ones.) So that does not help either.

[X512]

Is it possible to know what is the page and where it has mappings (team, area name etc.)?

[waddlesplash]

That's already printed in the KDL information, see my analysis on the other ticket, I didn't bother copying it here.

[waddlesplash]

Here's another instance of it: there are 3 running threads at the time of the panic. 118824 is the one that's KDLed, 118827 is in a spin() in delete_area, and 118828 is doing a LookupPage on page fault. But there's a lot of others of course, here's the excerpted list:

thread                 id  state     wait for  object              cpu pri  stack              team  name
0xffffffff903c01c0 118770  waiting   mutex     0xfffffff01681d678    -  10  0xffffffff8276b000118770  perl
0xfffffff0167d1dc0 118775  waiting   cvar:team 0xffffffff8ff4c938    -  10  0xffffffff82351000118770  pthread func
0xfffffff01696ec40 118777  waiting   mutex     0xfffffff0164c2e40    -  10  0xffffffff82775000118770  pthread func
0xfffffff016965500 118781  waiting   cvar:team 0xffffffff8ff4c938    -  10  0xffffffff82789000118770  pthread func
0xfffffff0169662c0 118786  waiting   cvar:team 0xffffffff8ff4c938    -  10  0xffffffff827a2000118770  pthread func
0xfffffff0167d9980 118793  waiting   cvar:team 0xffffffff8ff4c938    -  10  0xffffffff8277f000118770  pthread func
0xfffffff01696a780 118809  waiting   cvar:team 0xffffffff8ff45b38    -  10  0xffffffff827bb000118809  sh
0xffffffff903cc240 118812  waiting   cvar:team 0xffffffff8ff4c938    -  10  0xffffffff827c5000118770  pthread func
0xfffffff0167dd080 118815  waiting   signal                          -  10  0xffffffff827ca000118815  timeout
0xffffffff90671d80 118816  waiting   cvar:team 0xffffffff8ff4bf38    -  10  0xffffffff827a7000118816  sh
0xffffffff903b0f40 118817  waiting   cvar:team 0xffffffff8ff40b38    -  10  0xffffffff827cf000118817  sh
0xffffffff9067de00 118819  waiting   mutex     0xffffffff81b3d8a0    -  10  0xffffffff827ac000118819  sh
0xffffffff90672b40 118820  ready     -                               -  10  0xffffffff827b1000118820  timeout
0xffffffff90139840 118822  waiting   cvar:team 0xffffffff8ff4c938    -  10  0xffffffff827de000118770  pthread func
0xffffffff9067b4c0 118823  waiting   mutex     0xffffffff81b3d8a0    -  10  0xffffffff827e3000118823  filtertest
0xffffffff903c9900 118824  running   -                               1  10  0xffffffff827ed000118824  pthread func
0xfffffff0167d54c0 118825  waiting   mutex     0xffffffff81b3d8a0    -  10  0xffffffff827e8000118825  timeout
0xffffffff90679940 118826  waiting   cvar:team 0xffffffff8ff4c938    -  10  0xffffffff827f2000118770  pthread func
0xfffffff016961040 118827  running   -                               3  10  0xffffffff827f7000118827  pthread func
0xfffffff0167dc2c0 118828  running   -                               0  10  0xffffffff8278e000118828  pthread func

KDL information:

PANIC: remove page 0xffffffff88a0ac30 from cache 0xfffffff01686b428: page still has mappings!

PAGE: 0xffffffff88a0ac30
queue_next,prev: 0xffffffff85501520, 0xffffffff83eaa150
physical_number: 0x120327
cache:           0xfffffff01686b428
cache_offset:    10288
cache_next:      0x0000000000000000
state:           active
wired_count:     0
usage_count:     0
busy:            0
busy_writing:    0
accessed:        0
modified:        0
accessor:        -1
area mappings:
  0xffffffff904e79a0 (10242765)

CACHE 0xfffffff01686b428:
  ref_count:    0
  source:       0x0000000000000000
  type:         RAM
  virtual_base: 0x0
  virtual_end:  0x2430000
  temporary:    1
  lock:         0xfffffff01686b4b8
  lock.holder:  118824
  areas:
  consumers:
  pages:
	1 in cache

AREA: 0xffffffff904e79a0
name:		'heap'
owner:		0x1cff2
id:		0x9c4acd
base:		0x120079da3000
size:		0x2930000
protection:	0x33
page_protection:0x0000000000000000
wiring:		0x0
memory_type:	0x0
cache:		0xfffffff01681d5e8
cache_type:	RAM
cache_offset:	0x0
cache_next:	0x0000000000000000
cache_prev:	0x0000000000000000
page mappings:	10454

kdebug> cache_tree ...
0xfffffff016827800
  0xfffffff0164dac40
  0xfffffff0164c2db0
    0xfffffff01686dd90
    0xfffffff01681d5e8 <--
kdebug> cache ...
CACHE 0xfffffff016827800:
  ref_count:    3
  source:       0x0000000000000000
  type:         RAM
  virtual_base: 0x0
  virtual_end:  0x27f0000
  temporary:    1
  lock:         0xfffffff016827890
  lock.holder:  118828
  areas:
  consumers:
	0xfffffff0164dac40
	0xfffffff0164c2db0
  pages:
	10132 in cache

[waddlesplash]

OK, I think I see something in this: the page's cache_offset is 10288, aka. 0x2830000. That's actually beyond its cache's virtual_end of 0x2430000, but more to the point it's also beyond the presumptive child cache's virtual end of 0x27f0000, and so when merging the caches, we would have completely ignored this page deliberately. That probably explains how it got "left behind".

If the CoW'ed areas are never shrunk after a first fork occurs, then there's a question of how the cache wound up with a that's beyond its end at all. I have swap disabled on this VM, I am pretty sure, so this isn't swap-related.

[waddlesplash]

This looks like it (system booted to desktop with this assert, and only KDLed when I started the test):

PANIC: ASSERT FAILED (../src/system/kernel/vm/VMCache.cpp:806): offset <= virtual_end
Welcome to Kernel Debugging Land...
Thread 250 "perl" running on CPU 3
stack trace for thread 250 "perl"
    kernel stack: 0xffffffff8276e000 to 0xffffffff82773000
      user stack: 0x00007f6ae350f000 to 0x00007f6ae450f000
frame                       caller             <image>:function + offset
 0 ffffffff827726f0 (+  32) ffffffff80156fe0   <kernel_x86_64> arch_debug_call_with_fault_handler + 0x1a
 1 ffffffff82772740 (+  80) ffffffff800b8af8   <kernel_x86_64> debug_call_with_fault_handler + 0x78
 2 ffffffff827727a0 (+  96) ffffffff800ba1e4   <kernel_x86_64> kernel_debugger_loop(char const*, char const*, __va_list_tag*, int) + 0xf4
 3 ffffffff827727f0 (+  80) ffffffff800ba57e   <kernel_x86_64> kernel_debugger_internal(char const*, char const*, __va_list_tag*, int) + 0x6e
 4 ffffffff827728e0 (+ 240) ffffffff800ba917   <kernel_x86_64> panic + 0xb7
 5 ffffffff82772920 (+  64) ffffffff8014e6e1   <kernel_x86_64> VMCache::InsertPage(vm_page*, long) + 0x391
 6 ffffffff82772a80 (+ 352) ffffffff8012f799   <kernel_x86_64> vm_soft_fault(VMAddressSpace*, unsigned long, bool, bool, bool, vm_page**) + 0x519
 7 ffffffff82772b70 (+ 240) ffffffff8013d061   <kernel_x86_64> vm_page_fault + 0x161
 8 ffffffff82772bb0 (+  64) ffffffff8016311e   <kernel_x86_64> x86_page_fault_exception + 0x15e
 9 ffffffff82772f38 (+ 904) ffffffff801589cd   <kernel_x86_64> int_bottom_user + 0xd8
user iframe at 0xffffffff82772f38 (end = 0xffffffff82773000)
 rax 0x106999cc8710        rbx 0x106999c262c0        rcx 0x1678
 rdx 0x223b8               rsi 0x106999c47000        rdi 0x106999ce9450
 rbp 0x7f6ae450d620         r8 0x1069986b1270         r9 0x35
 r10 0x35                  r11 0x0                   r12 0x106999c262c0
 r13 0x106999cc8710        r14 0x10699980a680        r15 0x4000
 rip 0x107d1bd2a46         rsp 0x7f6ae450d5f0     rflags 0x10212
 vector: 0xe, error code: 0x4
10 00007f6ae450d620 (+   0) 00000107d1bd2a46   </boot/system/lib/libroot.so> memcpy + 0x26
11 00007f6ae450d650 (+  48) 00000107d1bdd1d2   </boot/system/lib/libroot.so> realloc + 0xa2
...

[waddlesplash]

Seems this is coming from the "Read-only pages come in the deepest cache" logic in fault_get_page. That seems suspect to me. I've checked and that logic has actually been there in one form or another since the very beginning of the main repository history, and more than that goes back to NewOS itself (see ​here for where it was introduced).

[waddlesplash]

Fixed in hrev58548.