Fix smp_idle() stack resetting bug
authorBarret Rhoden <brho@cs.berkeley.edu>
Thu, 2 Jun 2016 16:17:18 +0000 (12:17 -0400)
committerBarret Rhoden <brho@cs.berkeley.edu>
Thu, 16 Jun 2016 15:48:39 +0000 (11:48 -0400)
commit1da910a2cd962faa233ca53f4589e9cc59b7e9e5
treea35ccf9cf1babad1ce0157f3e93bae04c5ae0e56
parentbd4856b7d7e7d78b8667d998e87c74b7a22fa07d
Fix smp_idle() stack resetting bug

This started as a page fault in the backtracer while the system was under
heavy PMU interrupt load (every 100 or 1000 cycles).  For those curious,
here's how I sorted it out:

HW TRAP frame at 0xffff80081f7c5ce0 on core 0
  rax  0x0000000000000002
  rbx  0x0000000000000001
  rcx  0x000000000000000f
  rdx  0xffff80081f7c5de8
  rbp  0xffff80081f7c5da0
  rsi  0x00000000006f6770
  rdi  0xffffffffc2052b10
  r8   0x0000000000000000
  r9   0x0000000000000000
  r10  0xffff80082f9c6540
  r11  0x0000000000000202
  r12  0x0000000200000000
  r13  0xffff80082cf5e440
  r14  0xffff80081f7c5f40
  r15  0xffff80082fabb528
  trap 0x0000000e Page Fault
  gsbs 0xffffffffc76e50c0
  fsbs 0x0000000000000000
  err  0x--------00000000
  rip  0xffffffffc211afee
  cs   0x------------0008
  flag 0x0000000000010002
  rsp  0xffff80081f7c5da0
  ss   0x------------0010

Backtrace of kernel context on Core 0:
 #01 [<0xffffffffc211afee>] in backtrace_list
 #02 [<0xffffffffc204a0f9>] in profiler_add_kernel_backtrace
 #03 [<0xffffffffc211f4ba>] in perfmon_interrupt
 #04 [<0xffffffffc2123472>] in irq_dispatch
 #05 [<0xffffffffc2123e2f>] in handle_irq
kernel panic at kern/arch/x86/trap.c:270, from core 0: Proc-less Page Fault in the Kernel at 0x00000000006f6778!
Entering Nanwan's Dungeon on Core 0 (Ints off):

backtrace_list() thought we had a kernel FP == 0x6f67700 (rsi).

What were we BTing?  At that addr (from looking at the asm), rdi is the PC
we had just written, and rdx looks like the pc array.

ROS(Core 0)> kfunc hexdump 0xffff80081f7c5de8 100
ffff80081f7c5de8: 5e 77 05 c2 ff ff ff ff 10 2b 05 c2 ff ff ff ff

There's rdi, which is:

0xffffffffc2052b10 process.c:1150
proc_yield(), scp !being_nice case, around save_context_s

And the first one:

0xffffffffc205775e arch/trap.h:303
set frame pointer, being called from smp_idle (which is clear
from the asm).

The most recent thing written (yield) should be the older on the stack
trace.  Yield does call smp_idle, though not from that exact location.
Probably close enough.

More importantly, we should not be able to backtrace back through an
smp_idle!  We set the frame pointer to 0 in there.

looking more closely:

ffffffffc205775e:   48 89 c5                mov    %rax,%rbp

If we got interrupted here from the PMU and didn't actually run that
instruction, then we didn't reset rbp yet...

Are IRQs disabled during smp_idle?  Looks like no from looking at the code
(which is the bug this commit fixes).  Yet we did reset the stack pointer!
although the FP is still the old one, we jumped ourselves to the top of the
stack, and once we get interrupted, we are actively using it!  That's the
same stack that we're walking back and looking at for the backtrace.
Whoops!  That will clearly trash our backtrace.  (the backtrace should be
looking at parts of the stack below the initial RSP from when we took the
IRQ).

To confirm, let's poke around and see what we can see.

The rsp of the faulting context was 0xffff80081f7c5da0, but that was the
rsp of the running context - not the one that was interrupted.  But if the
theory is right, then that stack should be the same as the one that just
smp_idled.

Let's look at the whole stack:

Try kfunc hexdump 0xffff80081f7c5000 0x1000  (remember kfunc takes hex!)

ffff80081f7c5000: ef be ad de 00 00 00 00 00 00 00 00 00 00 00 00
...

There's the canary at the bottom of the stack.

rdx is 0xffff80081f7c5de8, which is on that page.  (That's a stack-local
array of PCs).  That should be no surprise.  What we'd like to see is that
it's the same stack (although clobbered!) as the original context we were
backtracing.  We'd likely need to look below the backtracer's rsp to see
any evidence.

Here's a chunk below the backtracer's SP.  We'll want to look from the
bottom and work our way up, since this stack has been reused a lot.

ffff80081f7c5cf0: 02 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 ................
ffff80081f7c5d00: 0f 00 00 00 00 00 00 00 e8 5d 7c 1f 08 80 ff ff .........]|.....
ffff80081f7c5d10: a0 5d 7c 1f 08 80 ff ff 70 67 6f 00 00 00 00 00 .]|.....pgo.....
ffff80081f7c5d20: 10 2b 05 c2 ff ff ff ff 00 00 00 00 00 00 00 00 .+..............
ffff80081f7c5d30: 00 00 00 00 00 00 00 00 40 65 9c 2f 08 80 ff ff ........@e./....
ffff80081f7c5d40: 02 02 00 00 00 00 00 00 00 00 00 00 02 00 00 00 ................
ffff80081f7c5d50: 40 e4 f5 2c 08 80 ff ff 40 5f 7c 1f 08 80 ff ff @..,....@_|.....
ffff80081f7c5d60: 28 b5 ab 2f 08 80 ff ff 0e 00 00 00 00 00 00 00 (../............
ffff80081f7c5d70: 00 00 00 00 00 00 00 00 ee af 11 c2 ff ff ff ff ................
ffff80081f7c5d80: 08 00 00 00 00 00 00 00 02 00 01 00 00 00 00 00 ................
ffff80081f7c5d90: a0 5d 7c 1f 08 80 ff ff 10 00 00 00 00 00 00 00 .]|.............
ffff80081f7c5da0:

There are a few code pointers on there.  Ones at higher addrs (lower in the
output) were called first, if they were ever actually called.  Sometimes
there's just stuff on the stack.

0xffffffffc211afee kern/arch/x86/kdebug.c:343

0xffffffffc2052b10 kern/src/process.c:1150
Sound familiar?  That's the one from our BT earlier!

Even weirder, kdebug.c 343 is the faulting address of our current context!
I doubt that proc_yield called backtrace like that - more likely it's
leftover from a previous run.  We are hammering the system with backtrace
calls, btw.  The fact that I found the address of a function in the
backtrace on the stack right below where the stack was clobbered is enough
for me to think this was likely the problem.

So the scenario was that we got deep in a syscall (yield), far enough to
make it down the stack that we can see traces of it later.  Then we
smp_idled and got interrupted after setting the stack pointer, but before
setting the frame pointer.  FP was still pointing into the old location,
down the stack, which we are using in the IRQ handler.  Eventually the IRQ
handler clobbers the stack enough that the BT goes wild and PFs.

Signed-off-by: Barret Rhoden <brho@cs.berkeley.edu>
kern/src/smp.c