* WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
@ 2016-12-10 16:17 Borislav Petkov
2016-12-10 17:04 ` Josh Poimboeuf
0 siblings, 1 reply; 15+ messages in thread
From: Borislav Petkov @ 2016-12-10 16:17 UTC (permalink / raw)
To: Josh Poimboeuf; +Cc: x86-ml, lkml
Hey,
I see the line in $Subject on rc8+tip/master.
Fixed already?
--
Regards/Gruss,
Boris.
Good mailing practices for 400: avoid top-posting and trim the reply.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-10 16:17 WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null) Borislav Petkov
@ 2016-12-10 17:04 ` Josh Poimboeuf
2016-12-10 17:28 ` Borislav Petkov
0 siblings, 1 reply; 15+ messages in thread
From: Josh Poimboeuf @ 2016-12-10 17:04 UTC (permalink / raw)
To: Borislav Petkov; +Cc: x86-ml, lkml
On Sat, Dec 10, 2016 at 05:17:49PM +0100, Borislav Petkov wrote:
> Hey,
>
> I see the line in $Subject on rc8+tip/master.
>
> Fixed already?
That's a new one. Was there anything else printed? Were you doing
anything special when it happened? Do you see it reliably? I should
probably figure out a way to dump more data for that warning.
--
Josh
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-10 17:04 ` Josh Poimboeuf
@ 2016-12-10 17:28 ` Borislav Petkov
2016-12-12 15:45 ` Josh Poimboeuf
0 siblings, 1 reply; 15+ messages in thread
From: Borislav Petkov @ 2016-12-10 17:28 UTC (permalink / raw)
To: Josh Poimboeuf; +Cc: x86-ml, lkml
On Sat, Dec 10, 2016 at 11:04:44AM -0600, Josh Poimboeuf wrote:
> That's a new one. Was there anything else printed?
It is the first line that appears in dmesg when I boot:
[ 0.000000] WARNING: kernel stack frame pointer at ffffffffb5e03f40 in swapper:0 has bad value (null)
[ 0.000000] Linux version 4.9.0-rc8+ (boris@gondor) (gcc version 6.2.0 20161109 (Debian 6.2.0-13) ) #1 SMP PREEMPT Sat Dec 10 13:25:29 CET 2016
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.9.0-rc8+ root=/dev/sda7 ro earlyprintk=ttyS0,115200 console=ttyS0,115200 console=tty0 root=/dev/sda7 log_buf_len=10M resume=/dev/sda5 no_console_suspend ignore_loglevel
[ 0.000000] KERNEL supported cpus:
[ 0.000000] Intel GenuineIntel
[ 0.000000] AMD AuthenticAMD
[ 0.000000] Centaur CentaurHauls
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
...
> Were you doing anything special when it happened?
Not really - just booting ;-)
> Do you see it reliably?
2 of 2 boots.
> I should probably figure out a way to dump more data for that warning.
Sure, I can test patches.
Thanks.
--
Regards/Gruss,
Boris.
Good mailing practices for 400: avoid top-posting and trim the reply.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-10 17:28 ` Borislav Petkov
@ 2016-12-12 15:45 ` Josh Poimboeuf
2016-12-12 17:50 ` Borislav Petkov
0 siblings, 1 reply; 15+ messages in thread
From: Josh Poimboeuf @ 2016-12-12 15:45 UTC (permalink / raw)
To: Borislav Petkov; +Cc: x86-ml, lkml
On Sat, Dec 10, 2016 at 06:28:02PM +0100, Borislav Petkov wrote:
> On Sat, Dec 10, 2016 at 11:04:44AM -0600, Josh Poimboeuf wrote:
> > That's a new one. Was there anything else printed?
>
> It is the first line that appears in dmesg when I boot:
>
> [ 0.000000] WARNING: kernel stack frame pointer at ffffffffb5e03f40 in swapper:0 has bad value (null)
> [ 0.000000] Linux version 4.9.0-rc8+ (boris@gondor) (gcc version 6.2.0 20161109 (Debian 6.2.0-13) ) #1 SMP PREEMPT Sat Dec 10 13:25:29 CET 2016
> [ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.9.0-rc8+ root=/dev/sda7 ro earlyprintk=ttyS0,115200 console=ttyS0,115200 console=tty0 root=/dev/sda7 log_buf_len=10M resume=/dev/sda5 no_console_suspend ignore_loglevel
> [ 0.000000] KERNEL supported cpus:
> [ 0.000000] Intel GenuineIntel
> [ 0.000000] AMD AuthenticAMD
> [ 0.000000] Centaur CentaurHauls
> [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
> ...
>
> > Were you doing anything special when it happened?
>
> Not really - just booting ;-)
>
> > Do you see it reliably?
>
> 2 of 2 boots.
>
> > I should probably figure out a way to dump more data for that warning.
>
> Sure, I can test patches.
Can you try with this?
diff --git a/arch/x86/include/asm/unwind.h b/arch/x86/include/asm/unwind.h
index c5a7f3a..6fa75b1 100644
--- a/arch/x86/include/asm/unwind.h
+++ b/arch/x86/include/asm/unwind.h
@@ -12,7 +12,7 @@ struct unwind_state {
struct task_struct *task;
int graph_idx;
#ifdef CONFIG_FRAME_POINTER
- unsigned long *bp;
+ unsigned long *bp, *orig_sp;
struct pt_regs *regs;
#else
unsigned long *sp;
diff --git a/arch/x86/kernel/unwind_frame.c b/arch/x86/kernel/unwind_frame.c
index ea7b7f9..1c93984 100644
--- a/arch/x86/kernel/unwind_frame.c
+++ b/arch/x86/kernel/unwind_frame.c
@@ -6,6 +6,36 @@
#define FRAME_HEADER_SIZE (sizeof(long) * 2)
+static void unwind_dump(struct unwind_state *state, unsigned long *sp)
+{
+ static bool dumped_before = false;
+ bool prev_zero, zero = false;
+ unsigned long word;
+
+ if (dumped_before)
+ return;
+
+ dumped_before = true;
+
+ printk_deferred("unwind stack type:%d next_sp:%p mask:%lx graph_idx:%d\n",
+ state->stack_info.type, state->stack_info.next_sp,
+ state->stack_mask, state->graph_idx);
+
+ for (sp = state->orig_sp; sp < state->stack_info.end; sp++) {
+ prev_zero = zero;
+ word = READ_ONCE_NOCHECK(*sp);
+ zero = word == 0;
+
+ if (zero) {
+ if (!prev_zero)
+ printk_deferred("%p: %016x ...\n", sp, 0);
+ continue;
+ }
+
+ printk_deferred("%p: %016lx (%pB)\n", sp, word, (void *)word);
+ }
+}
+
unsigned long unwind_get_return_address(struct unwind_state *state)
{
unsigned long addr;
@@ -25,6 +55,7 @@ unsigned long unwind_get_return_address(struct unwind_state *state)
"WARNING: unrecognized kernel stack return address %p at %p in %s:%d\n",
(void *)addr, addr_p, state->task->comm,
state->task->pid);
+ unwind_dump(state, addr_p);
return 0;
}
@@ -67,6 +98,7 @@ static bool update_stack_state(struct unwind_state *state, void *addr,
size_t len)
{
struct stack_info *info = &state->stack_info;
+ enum stack_type orig_type = info->type;
/*
* If addr isn't on the current stack, switch to the next one.
@@ -80,6 +112,9 @@ static bool update_stack_state(struct unwind_state *state, void *addr,
&state->stack_mask))
return false;
+ if (!state->orig_sp || info->type != orig_type)
+ state->orig_sp = addr;
+
return true;
}
@@ -178,11 +213,13 @@ bool unwind_next_frame(struct unwind_state *state)
"WARNING: kernel stack regs at %p in %s:%d has bad 'bp' value %p\n",
state->regs, state->task->comm,
state->task->pid, next_frame);
+ unwind_dump(state, (unsigned long *)state->regs);
} else {
printk_deferred_once(KERN_WARNING
"WARNING: kernel stack frame pointer at %p in %s:%d has bad value %p\n",
state->bp, state->task->comm,
state->task->pid, next_frame);
+ unwind_dump(state, state->bp);
}
the_end:
state->stack_info.type = STACK_TYPE_UNKNOWN;
^ permalink raw reply related [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-12 15:45 ` Josh Poimboeuf
@ 2016-12-12 17:50 ` Borislav Petkov
2016-12-12 18:10 ` Josh Poimboeuf
0 siblings, 1 reply; 15+ messages in thread
From: Borislav Petkov @ 2016-12-12 17:50 UTC (permalink / raw)
To: Josh Poimboeuf; +Cc: x86-ml, lkml
On Mon, Dec 12, 2016 at 09:45:42AM -0600, Josh Poimboeuf wrote:
> Can you try with this?
That's alot of stack:
---
[ 0.000000] WARNING: kernel stack frame pointer at ffffffffbce03f40 in swapper:0 has bad value (null)
[ 0.000000] unwind stack type:0 next_sp: (null) mask:2 graph_idx:0
[ 0.000000] ffffffffbce03bc0: ffffffffbce03c40 (init_thread_union+0x3c40/0x4000)
[ 0.000000] ffffffffbce03bc8: ffffffffbc027643 (__save_stack_trace+0x73/0xd0)
[ 0.000000] ffffffffbce03bd0: 0000000000000000 ...
[ 0.000000] ffffffffbce03bd8: ffffffffbce00000 (__end_rodata+0x59000/0x59000)
[ 0.000000] ffffffffbce03be0: ffffffffbce04000 (init_thread_union+0x4000/0x4000)
[ 0.000000] ffffffffbce03be8: 0000000000000000 ...
[ 0.000000] ffffffffbce03bf0: 0000000000000002 (0x2)
[ 0.000000] ffffffffbce03bf8: ffffffffbce0e540 (root_mountflags+0x40/0x40)
[ 0.000000] ffffffffbce03c00: 0000000000000000 ...
[ 0.000000] ffffffffbce03c08: ffffffffbce03f40 (init_thread_union+0x3f40/0x4000)
[ 0.000000] ffffffffbce03c10: ffffffffbce03bc0 (init_thread_union+0x3bc0/0x4000)
[ 0.000000] ffffffffbce03c18: 0000000000000000 ...
[ 0.000000] ffffffffbce03c20: ffffffffbd7b4278 (lock_classes+0x158/0x35fe60)
[ 0.000000] ffffffffbce03c28: ffffffffbce0e540 (root_mountflags+0x40/0x40)
[ 0.000000] ffffffffbce03c30: ffffffffbcec9080 (primary_crng+0x60/0x80)
[ 0.000000] ffffffffbce03c38: 000000000000000c (0xc)
[ 0.000000] ffffffffbce03c40: ffffffffbce03c50 (init_thread_union+0x3c50/0x4000)
[ 0.000000] ffffffffbce03c48: ffffffffbc0276bb (save_stack_trace+0x1b/0x20)
[ 0.000000] ffffffffbce03c50: ffffffffbce03c68 (init_thread_union+0x3c68/0x4000)
[ 0.000000] ffffffffbce03c58: ffffffffbc0bf60b (save_trace+0x3b/0xc0)
[ 0.000000] ffffffffbce03c60: 000000000000000c (0xc)
[ 0.000000] ffffffffbce03c68: ffffffffbce03cb0 (init_thread_union+0x3cb0/0x4000)
[ 0.000000] ffffffffbce03c70: ffffffffbc0c1d78 (mark_lock+0x188/0x610)
[ 0.000000] ffffffffbce03c78: 0000000000000000 ...
[ 0.000000] ffffffffbce03c80: ffffffffbcec9080 (primary_crng+0x60/0x80)
[ 0.000000] ffffffffbce03c88: ffffffffbce0ed08 (init_task+0x7c8/0x2340)
[ 0.000000] ffffffffbce03c90: 0000000000000000 ...
[ 0.000000] ffffffffbce03c98: ffffffffbcec9080 (primary_crng+0x60/0x80)
[ 0.000000] ffffffffbce03ca0: ffffffffbce0e540 (root_mountflags+0x40/0x40)
[ 0.000000] ffffffffbce03ca8: 0000000000000001 (0x1)
[ 0.000000] ffffffffbce03cb0: ffffffffbce03d68 (init_thread_union+0x3d68/0x4000)
[ 0.000000] ffffffffbce03cb8: ffffffffbc0c2a6f (__lock_acquire+0x2ff/0x1760)
[ 0.000000] ffffffffbce03cc0: 0000000000000000 ...
[ 0.000000] ffffffffbce03cd0: 000000000000002d (0x2d)
[ 0.000000] ffffffffbce03cd8: ffffffff00000001 (0xffffffff00000001)
[ 0.000000] ffffffffbce03ce0: ffffffffbd7b4120 (classhash_table+0x8000/0x8000)
[ 0.000000] ffffffffbce03ce8: 0000000000000000 ...
[ 0.000000] ffffffffbce03cf0: ffffffffbce0ed08 (init_task+0x7c8/0x2340)
[ 0.000000] ffffffffbce03cf8: 0000000000000000 ...
[ 0.000000] ffffffffbce03d10: ffffffffbce03e0c (init_thread_union+0x3e0c/0x4000)
[ 0.000000] ffffffffbce03d18: ffffffffffffffff (0xffffffffffffffff)
[ 0.000000] ffffffffbce03d20: 00000000431fc205 (0x431fc205)
[ 0.000000] ffffffffbce03d28: ffffffffbcc881f4 (.LC9+0x10e9/0x1606)
[ 0.000000] ffffffffbce03d30: ffffffffbcc881f0 (.LC9+0x10e5/0x1606)
[ 0.000000] ffffffffbce03d38: ffffffffbce03d90 (init_thread_union+0x3d90/0x4000)
[ 0.000000] ffffffffbce03d40: 0000000000000096 (0x96)
[ 0.000000] ffffffffbce03d48: 0000000000000000 ...
[ 0.000000] ffffffffbce03d58: 0000000000000001 (0x1)
[ 0.000000] ffffffffbce03d60: 0000000000000000 ...
[ 0.000000] ffffffffbce03d68: ffffffffbce03dd8 (init_thread_union+0x3dd8/0x4000)
[ 0.000000] ffffffffbce03d70: ffffffffbc0c4537 (lock_acquire+0x107/0x210)
[ 0.000000] ffffffffbce03d78: 0000000000000000 ...
[ 0.000000] ffffffffbce03d80: ffffffffbc498ac0 (_extract_crng+0x40/0xb0)
[ 0.000000] ffffffffbce03d88: 0000000000000000 ...
[ 0.000000] ffffffffbce03d90: ffffffff00000000 (0xffffffff00000000)
[ 0.000000] ffffffffbce03d98: 0000000000000096 (0x96)
[ 0.000000] ffffffffbce03da0: 00000000bc3c8673 (0xbc3c8673)
[ 0.000000] ffffffffbce03da8: ffffffffbcec9080 (primary_crng+0x60/0x80)
[ 0.000000] ffffffffbce03db0: ffffffffbcec9068 (primary_crng+0x48/0x80)
[ 0.000000] ffffffffbce03db8: 0000000000000096 (0x96)
[ 0.000000] ffffffffbce03dc0: 0000000000000008 (0x8)
[ 0.000000] ffffffffbce03dc8: ffffffffbce03e50 (init_thread_union+0x3e50/0x4000)
[ 0.000000] ffffffffbce03dd0: ffffffff0000ffff (0xffffffff0000ffff)
[ 0.000000] ffffffffbce03dd8: ffffffffbce03e00 (init_thread_union+0x3e00/0x4000)
[ 0.000000] ffffffffbce03de0: ffffffffbc873466 (_raw_spin_lock_irqsave+0x46/0x60)
[ 0.000000] ffffffffbce03de8: ffffffffbc498ac0 (_extract_crng+0x40/0xb0)
[ 0.000000] ffffffffbce03df0: ffffffffbcec9020 (input_pool+0xc0/0xc0)
[ 0.000000] ffffffffbce03df8: ffffffffbcec9068 (primary_crng+0x48/0x80)
[ 0.000000] ffffffffbce03e00: ffffffffbce03e30 (init_thread_union+0x3e30/0x4000)
[ 0.000000] ffffffffbce03e08: ffffffffbc498ac0 (_extract_crng+0x40/0xb0)
[ 0.000000] ffffffffbce03e10: ffffffffbce03ec8 (init_thread_union+0x3ec8/0x4000)
[ 0.000000] ffffffffbce03e18: ffffffffbce03e50 (init_thread_union+0x3e50/0x4000)
[ 0.000000] ffffffffbce03e20: 0000000000000008 (0x8)
[ 0.000000] ffffffffbce03e28: ffffffffbcf67b66 (start_kernel+0x2b/0x3d9)
[ 0.000000] ffffffffbce03e30: ffffffffbce03e40 (init_thread_union+0x3e40/0x4000)
[ 0.000000] ffffffffbce03e38: ffffffffbc498b6f (extract_crng+0x3f/0x50)
[ 0.000000] ffffffffbce03e40: ffffffffbce03eb8 (init_thread_union+0x3eb8/0x4000)
[ 0.000000] ffffffffbce03e48: ffffffffbc49a6f5 (get_random_bytes+0x95/0x260)
[ 0.000000] ffffffffbce03e50: ffffffffbcf67155 (early_idt_handler_common+0x35/0x4c)
[ 0.000000] ffffffffbce03e58: ffffffff0000ffff (0xffffffff0000ffff)
[ 0.000000] ffffffffbce03e60: fffffff8ffffffff (0xfffffff8ffffffff)
[ 0.000000] ffffffffbce03e68: 0000000000055000 (0x55000)
[ 0.000000] ffffffffbce03e70: bcf68e0000107117 (0xbcf68e0000107117)
[ 0.000000] ffffffffbce03e78: ffffffffbce03f00 (init_thread_union+0x3f00/0x4000)
[ 0.000000] ffffffffbce03e80: ffffffffbcb00ef0 (_fw_end+0x4000/0x4000)
[ 0.000000] ffffffffbce03e88: 0000000000004400 (0x4400)
[ 0.000000] ffffffffbce03e90: 0000000000000000 ...
[ 0.000000] ffffffffbce03e98: bcf68e0000107117 (0xbcf68e0000107117)
[ 0.000000] ffffffffbce03ea0: bcf68e0000107117 (0xbcf68e0000107117)
[ 0.000000] ffffffffbce03ea8: 0000000000055000 (0x55000)
[ 0.000000] ffffffffbce03eb0: fffffff8ffffffff (0xfffffff8ffffffff)
[ 0.000000] ffffffffbce03eb8: ffffffffbce03ef0 (init_thread_union+0x3ef0/0x4000)
[ 0.000000] ffffffffbce03ec0: ffffffffbcf67b66 (start_kernel+0x2b/0x3d9)
[ 0.000000] ffffffffbce03ec8: 0000000000000000 ...
[ 0.000000] ffffffffbce03ed0: bcf68e0000107117 (0xbcf68e0000107117)
[ 0.000000] ffffffffbce03ed8: bcf68e0000107117 (0xbcf68e0000107117)
[ 0.000000] ffffffffbce03ee0: 0000000000055000 (0x55000)
[ 0.000000] ffffffffbce03ee8: fffffff8ffffffff (0xfffffff8ffffffff)
[ 0.000000] ffffffffbce03ef0: ffffffffbce03f00 (init_thread_union+0x3f00/0x4000)
[ 0.000000] ffffffffbce03ef8: ffffffffbcf67286 (x86_64_start_reservations+0x24/0x26)
[ 0.000000] ffffffffbce03f00: ffffffffbce03f40 (init_thread_union+0x3f40/0x4000)
[ 0.000000] ffffffffbce03f08: ffffffffbcf6740a (x86_64_start_kernel+0x182/0x193)
[ 0.000000] ffffffffbce03f10: 0000000000000000 ...
[ 0.000000] ffffffffbce03f18: ffffffffbce03f58 (init_thread_union+0x3f58/0x4000)
[ 0.000000] ffffffffbce03f20: 00000000000000f0 (0xf0)
[ 0.000000] ffffffffbce03f28: 00000000ac41fb60 (0xac41fb60)
[ 0.000000] ffffffffbce03f30: 00000000ac6c8364 (0xac6c8364)
[ 0.000000] ffffffffbce03f38: 00000000ac767740 (0xac767740)
[ 0.000000] ffffffffbce03f40: 0000000000000000 ...
[ 0.000000] ffffffffbce03f48: ffffffffbc0001b5 (start_cpu+0x5/0x14)
[ 0.000000] ffffffffbce03f50: ffffffffbc0001b5 (start_cpu+0x5/0x14)
[ 0.000000] ffffffffbce03f58: 0000000000000000 ...
[ 0.000000] Linux version 4.9.0-rc8+ (root@gondor) (gcc version 6.2.0 20161109 (Debian 6.2.0-13) ) #2 SMP PREEMPT Mon Dec 12 18:36:48 CET 2016
...
--
Regards/Gruss,
Boris.
Good mailing practices for 400: avoid top-posting and trim the reply.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-12 17:50 ` Borislav Petkov
@ 2016-12-12 18:10 ` Josh Poimboeuf
2016-12-12 21:16 ` Josh Poimboeuf
0 siblings, 1 reply; 15+ messages in thread
From: Josh Poimboeuf @ 2016-12-12 18:10 UTC (permalink / raw)
To: Borislav Petkov; +Cc: x86-ml, lkml
On Mon, Dec 12, 2016 at 06:50:23PM +0100, Borislav Petkov wrote:
> [ 0.000000] ffffffffbce03f40: 0000000000000000 ...
> [ 0.000000] ffffffffbce03f48: ffffffffbc0001b5 (start_cpu+0x5/0x14)
> [ 0.000000] ffffffffbce03f50: ffffffffbc0001b5 (start_cpu+0x5/0x14)
> [ 0.000000] ffffffffbce03f58: 0000000000000000 ...
> [ 0.000000] Linux version 4.9.0-rc8+ (root@gondor) (gcc version 6.2.0 20161109 (Debian 6.2.0-13) ) #2 SMP PREEMPT Mon Dec 12 18:36:48 CET 2016
Something funky is going on in the head code. It looks like start_cpu
is getting executed twice somehow. Need to do some more head
scratching...
--
Josh
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-12 18:10 ` Josh Poimboeuf
@ 2016-12-12 21:16 ` Josh Poimboeuf
2016-12-12 21:34 ` Borislav Petkov
0 siblings, 1 reply; 15+ messages in thread
From: Josh Poimboeuf @ 2016-12-12 21:16 UTC (permalink / raw)
To: Borislav Petkov; +Cc: x86-ml, lkml, Andy Lutomirski
On Mon, Dec 12, 2016 at 12:10:25PM -0600, Josh Poimboeuf wrote:
> On Mon, Dec 12, 2016 at 06:50:23PM +0100, Borislav Petkov wrote:
> > [ 0.000000] ffffffffbce03f40: 0000000000000000 ...
> > [ 0.000000] ffffffffbce03f48: ffffffffbc0001b5 (start_cpu+0x5/0x14)
> > [ 0.000000] ffffffffbce03f50: ffffffffbc0001b5 (start_cpu+0x5/0x14)
> > [ 0.000000] ffffffffbce03f58: 0000000000000000 ...
> > [ 0.000000] Linux version 4.9.0-rc8+ (root@gondor) (gcc version 6.2.0 20161109 (Debian 6.2.0-13) ) #2 SMP PREEMPT Mon Dec 12 18:36:48 CET 2016
>
> Something funky is going on in the head code. It looks like start_cpu
> is getting executed twice somehow. Need to do some more head
> scratching...
I still can't figure out what could cause this, nor can I recreate it.
Andy, any idea? I'm trying to figure out why a stack trace of the
initial task, early in start_kernel(), would show start_cpu() on the
stack *twice*. The start_cpu() entry on the stack at ffffffffbce03f50
is right where it's supposed to be. But then there's another
start_cpu() entry at 0xffffffffbce03f48 which is pointed to by the frame
pointer chain. I can't figure out where that one came from and why the
stack is offset by a word, compared to all the other idle task stacks
I've seen.
Boris, what kind of CPU is it?
--
Josh
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-12 21:16 ` Josh Poimboeuf
@ 2016-12-12 21:34 ` Borislav Petkov
2016-12-12 22:11 ` Josh Poimboeuf
0 siblings, 1 reply; 15+ messages in thread
From: Borislav Petkov @ 2016-12-12 21:34 UTC (permalink / raw)
To: Josh Poimboeuf; +Cc: x86-ml, lkml, Andy Lutomirski
On Mon, Dec 12, 2016 at 03:16:27PM -0600, Josh Poimboeuf wrote:
> I still can't figure out what could cause this, nor can I recreate it.
Want my .config?
> Andy, any idea? I'm trying to figure out why a stack trace of the
> initial task, early in start_kernel(), would show start_cpu() on the
> stack *twice*. The start_cpu() entry on the stack at ffffffffbce03f50
> is right where it's supposed to be. But then there's another
> start_cpu() entry at 0xffffffffbce03f48 which is pointed to by the frame
> pointer chain. I can't figure out where that one came from and why the
> stack is offset by a word, compared to all the other idle task stacks
> I've seen.
Btw, why do you have:
call 1f # put return address on stack for unwinder
there in start_cpu() instead of
push $start_cpu
or so? That CALL looks strange there. If you want to put the return
address, just push start_cpu's address and that's it.
Or am I missing something?
> Boris, what kind of CPU is it?
[ 0.169371] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-1620 0 @ 3.60GHz (family: 0x6, model: 0x2d, stepping: 0x7)
Sandybridge. The model 0x2d corresponds to that INTEL_FAM6_SANDYBRIDGE_X
define in intel-family.h.
--
Regards/Gruss,
Boris.
Good mailing practices for 400: avoid top-posting and trim the reply.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-12 21:34 ` Borislav Petkov
@ 2016-12-12 22:11 ` Josh Poimboeuf
2016-12-12 22:33 ` Borislav Petkov
0 siblings, 1 reply; 15+ messages in thread
From: Josh Poimboeuf @ 2016-12-12 22:11 UTC (permalink / raw)
To: Borislav Petkov; +Cc: x86-ml, lkml, Andy Lutomirski
On Mon, Dec 12, 2016 at 10:34:46PM +0100, Borislav Petkov wrote:
> On Mon, Dec 12, 2016 at 03:16:27PM -0600, Josh Poimboeuf wrote:
> > I still can't figure out what could cause this, nor can I recreate it.
>
> Want my .config?
Yes, please.
> > Andy, any idea? I'm trying to figure out why a stack trace of the
> > initial task, early in start_kernel(), would show start_cpu() on the
> > stack *twice*. The start_cpu() entry on the stack at ffffffffbce03f50
> > is right where it's supposed to be. But then there's another
> > start_cpu() entry at 0xffffffffbce03f48 which is pointed to by the frame
> > pointer chain. I can't figure out where that one came from and why the
> > stack is offset by a word, compared to all the other idle task stacks
> > I've seen.
>
> Btw, why do you have:
>
> call 1f # put return address on stack for unwinder
>
> there in start_cpu() instead of
>
> push $start_cpu
>
> or so? That CALL looks strange there. If you want to put the return
> address, just push start_cpu's address and that's it.
>
> Or am I missing something?
Yeah, it's kind of obtuse.
The problem with "push $start_cpu" is that it will show up on the stack
trace as:
secondary_startup_64+0x90/0x90
instead of what you would expect:
start_cpu+0x0/0x14
That's because the printk '%pB' modifier is smart enough to know that
the beginning of a function isn't a valid function call return address.
The only way such an address could end up on the stack would be if the
previous function made a tail call. So it shows the end of the previous
function instead.
That said, the code could probably be made a little clearer by changing
"call 1f" to "push $1f" and then move the '1' label to after the lretq
instruction, like:
pushq $1f # put return address on stack for unwinder
xorq %rbp, %rbp # clear frame pointer
movq initial_code(%rip), %rax
pushq $__KERNEL_CS # set correct cs
pushq %rax # target address in negative space
lretq
1:
ENDPROC(start_cpu)
That shows:
start_cpu+0x14/0x14
Which is more accurate anyway. I'll make a patch.
--
Josh
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-12 22:11 ` Josh Poimboeuf
@ 2016-12-12 22:33 ` Borislav Petkov
2016-12-12 23:05 ` Josh Poimboeuf
0 siblings, 1 reply; 15+ messages in thread
From: Borislav Petkov @ 2016-12-12 22:33 UTC (permalink / raw)
To: Josh Poimboeuf; +Cc: x86-ml, lkml, Andy Lutomirski
[-- Attachment #1: Type: text/plain, Size: 855 bytes --]
On Mon, Dec 12, 2016 at 04:11:47PM -0600, Josh Poimboeuf wrote:
> Yes, please.
Attached.
> That said, the code could probably be made a little clearer by changing
> "call 1f" to "push $1f" and then move the '1' label to after the lretq
> instruction, like:
>
> pushq $1f # put return address on stack for unwinder
> xorq %rbp, %rbp # clear frame pointer
> movq initial_code(%rip), %rax
> pushq $__KERNEL_CS # set correct cs
> pushq %rax # target address in negative space
> lretq
> 1:
> ENDPROC(start_cpu)
>
> That shows:
>
> start_cpu+0x14/0x14
>
> Which is more accurate anyway. I'll make a patch.
Yap, makes more sense. I'll run it tomorrow.
FWIW, I tried
pushq $1f
before without moving the 1: label but the thing still fired.
--
Regards/Gruss,
Boris.
Good mailing practices for 400: avoid top-posting and trim the reply.
[-- Attachment #2: config.gz --]
[-- Type: application/gzip, Size: 26012 bytes --]
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-12 22:33 ` Borislav Petkov
@ 2016-12-12 23:05 ` Josh Poimboeuf
2016-12-13 14:34 ` Josh Poimboeuf
0 siblings, 1 reply; 15+ messages in thread
From: Josh Poimboeuf @ 2016-12-12 23:05 UTC (permalink / raw)
To: Borislav Petkov; +Cc: x86-ml, lkml, Andy Lutomirski
On Mon, Dec 12, 2016 at 11:33:54PM +0100, Borislav Petkov wrote:
> On Mon, Dec 12, 2016 at 04:11:47PM -0600, Josh Poimboeuf wrote:
> > Yes, please.
>
> Attached.
Thanks, I was able to recreate. Will take a look tomorrow.
--
Josh
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-12 23:05 ` Josh Poimboeuf
@ 2016-12-13 14:34 ` Josh Poimboeuf
2016-12-13 16:55 ` Andy Lutomirski
0 siblings, 1 reply; 15+ messages in thread
From: Josh Poimboeuf @ 2016-12-13 14:34 UTC (permalink / raw)
To: Borislav Petkov; +Cc: x86-ml, lkml, Andy Lutomirski
On Mon, Dec 12, 2016 at 05:05:11PM -0600, Josh Poimboeuf wrote:
> On Mon, Dec 12, 2016 at 11:33:54PM +0100, Borislav Petkov wrote:
> > On Mon, Dec 12, 2016 at 04:11:47PM -0600, Josh Poimboeuf wrote:
> > > Yes, please.
> >
> > Attached.
>
> Thanks, I was able to recreate. Will take a look tomorrow.
Figured it out. Your config has CONFIG_PARAVIRT=n, which convinces gcc
to create the following preamble for x86_64_start_kernel():
0000000000000124 <x86_64_start_kernel>:
124: 4c 8d 54 24 08 lea 0x8(%rsp),%r10
129: 48 83 e4 f0 and $0xfffffffffffffff0,%rsp
12d: 41 ff 72 f8 pushq -0x8(%r10)
131: 55 push %rbp
132: 48 89 e5 mov %rsp,%rbp
It's an unusual pattern which aligns rsp (though in this case it's
already aligned) and saves the start_cpu() return address again on the
stack before storing the frame pointer.
The unwinder assumes the last stack frame header is at a certain offset,
but the above code breaks that assumption. I still need to think about
the best way to fix it.
--
Josh
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-13 14:34 ` Josh Poimboeuf
@ 2016-12-13 16:55 ` Andy Lutomirski
2016-12-13 17:26 ` Josh Poimboeuf
2016-12-13 17:51 ` Borislav Petkov
0 siblings, 2 replies; 15+ messages in thread
From: Andy Lutomirski @ 2016-12-13 16:55 UTC (permalink / raw)
To: Josh Poimboeuf; +Cc: Borislav Petkov, x86-ml, lkml, Andy Lutomirski
On Tue, Dec 13, 2016 at 6:34 AM, Josh Poimboeuf <jpoimboe@redhat.com> wrote:
> On Mon, Dec 12, 2016 at 05:05:11PM -0600, Josh Poimboeuf wrote:
>> On Mon, Dec 12, 2016 at 11:33:54PM +0100, Borislav Petkov wrote:
>> > On Mon, Dec 12, 2016 at 04:11:47PM -0600, Josh Poimboeuf wrote:
>> > > Yes, please.
>> >
>> > Attached.
>>
>> Thanks, I was able to recreate. Will take a look tomorrow.
>
> Figured it out. Your config has CONFIG_PARAVIRT=n, which convinces gcc
> to create the following preamble for x86_64_start_kernel():
>
> 0000000000000124 <x86_64_start_kernel>:
> 124: 4c 8d 54 24 08 lea 0x8(%rsp),%r10
> 129: 48 83 e4 f0 and $0xfffffffffffffff0,%rsp
> 12d: 41 ff 72 f8 pushq -0x8(%r10)
> 131: 55 push %rbp
> 132: 48 89 e5 mov %rsp,%rbp
>
> It's an unusual pattern which aligns rsp (though in this case it's
> already aligned) and saves the start_cpu() return address again on the
> stack before storing the frame pointer.
Um, what? I can reproduce it -- I get:
0000000000000124 <x86_64_start_kernel>:
124: 4c 8d 54 24 08 lea 0x8(%rsp),%r10
129: 48 83 e4 f0 and $0xfffffffffffffff0,%rsp
12d: 41 ff 72 f8 pushq -0x8(%r10)
131: 55 push %rbp
132: 48 89 e5 mov %rsp,%rbp
135: 41 57 push %r15
137: 41 56 push %r14
139: 41 55 push %r13
13b: 41 54 push %r12
13d: 41 52 push %r10
13f: 53 push %rbx
140: 48 83 ec 10 sub $0x10,%rsp
...
and the epilog looks like:
29c: 58 pop %rax
29d: 5a pop %rdx
29e: 5b pop %rbx
29f: 41 5a pop %r10
2a1: 41 5c pop %r12
2a3: 41 5d pop %r13
2a5: 41 5e pop %r14
2a7: 41 5f pop %r15
2a9: 5d pop %rbp
2aa: 49 8d 62 f8 lea -0x8(%r10),%rsp
2ae: c3 retq
This is, I think, *terrible* code. It makes it entirely impossible
for the CPU to look through the retq until the instruction right
before it finishes because there's no way the CPU can tell what rsp is
until the instruction right before the retq. And it's saving and
restoring an entire extra register (r10) instead of just using rbp for
this purpose. *And* the extra copy of the return address seems
totally useless except for unwinding.
This does indeed depend on CONFIG_PARAVIRT, but I'm not seeing what
changes. Presumably something related to what happens in the
function?
I want to file a GCC bug, though. This code sucks.
>
> The unwinder assumes the last stack frame header is at a certain offset,
> but the above code breaks that assumption. I still need to think about
> the best way to fix it.
Have a dummy written-in-asm top-of-the-stack function? Or recognize
the end by the final saved RBP?
--Andy
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-13 16:55 ` Andy Lutomirski
@ 2016-12-13 17:26 ` Josh Poimboeuf
2016-12-13 17:51 ` Borislav Petkov
1 sibling, 0 replies; 15+ messages in thread
From: Josh Poimboeuf @ 2016-12-13 17:26 UTC (permalink / raw)
To: Andy Lutomirski; +Cc: Borislav Petkov, x86-ml, lkml, Andy Lutomirski
On Tue, Dec 13, 2016 at 08:55:53AM -0800, Andy Lutomirski wrote:
> On Tue, Dec 13, 2016 at 6:34 AM, Josh Poimboeuf <jpoimboe@redhat.com> wrote:
> > On Mon, Dec 12, 2016 at 05:05:11PM -0600, Josh Poimboeuf wrote:
> >> On Mon, Dec 12, 2016 at 11:33:54PM +0100, Borislav Petkov wrote:
> >> > On Mon, Dec 12, 2016 at 04:11:47PM -0600, Josh Poimboeuf wrote:
> >> > > Yes, please.
> >> >
> >> > Attached.
> >>
> >> Thanks, I was able to recreate. Will take a look tomorrow.
> >
> > Figured it out. Your config has CONFIG_PARAVIRT=n, which convinces gcc
> > to create the following preamble for x86_64_start_kernel():
> >
> > 0000000000000124 <x86_64_start_kernel>:
> > 124: 4c 8d 54 24 08 lea 0x8(%rsp),%r10
> > 129: 48 83 e4 f0 and $0xfffffffffffffff0,%rsp
> > 12d: 41 ff 72 f8 pushq -0x8(%r10)
> > 131: 55 push %rbp
> > 132: 48 89 e5 mov %rsp,%rbp
> >
> > It's an unusual pattern which aligns rsp (though in this case it's
> > already aligned) and saves the start_cpu() return address again on the
> > stack before storing the frame pointer.
>
> Um, what? I can reproduce it -- I get:
>
> 0000000000000124 <x86_64_start_kernel>:
> 124: 4c 8d 54 24 08 lea 0x8(%rsp),%r10
> 129: 48 83 e4 f0 and $0xfffffffffffffff0,%rsp
> 12d: 41 ff 72 f8 pushq -0x8(%r10)
> 131: 55 push %rbp
> 132: 48 89 e5 mov %rsp,%rbp
> 135: 41 57 push %r15
> 137: 41 56 push %r14
> 139: 41 55 push %r13
> 13b: 41 54 push %r12
> 13d: 41 52 push %r10
> 13f: 53 push %rbx
> 140: 48 83 ec 10 sub $0x10,%rsp
>
> ...
>
> and the epilog looks like:
>
> 29c: 58 pop %rax
> 29d: 5a pop %rdx
> 29e: 5b pop %rbx
> 29f: 41 5a pop %r10
> 2a1: 41 5c pop %r12
> 2a3: 41 5d pop %r13
> 2a5: 41 5e pop %r14
> 2a7: 41 5f pop %r15
> 2a9: 5d pop %rbp
> 2aa: 49 8d 62 f8 lea -0x8(%r10),%rsp
> 2ae: c3 retq
>
> This is, I think, *terrible* code. It makes it entirely impossible
> for the CPU to look through the retq until the instruction right
> before it finishes because there's no way the CPU can tell what rsp is
> until the instruction right before the retq. And it's saving and
> restoring an entire extra register (r10) instead of just using rbp for
> this purpose. *And* the extra copy of the return address seems
> totally useless except for unwinding.
>
> This does indeed depend on CONFIG_PARAVIRT, but I'm not seeing what
> changes. Presumably something related to what happens in the
> function?
>
> I want to file a GCC bug, though. This code sucks.
Yeah, I can't figure out why it's doing that. I've seen it align the
stack before, but it was always *after* setting up the frame pointer and
pushing the registers on the stack. I have no idea what triggered it to
do it this way, but it would interesting to know if we can turn it off
somehow.
> > The unwinder assumes the last stack frame header is at a certain offset,
> > but the above code breaks that assumption. I still need to think about
> > the best way to fix it.
>
> Have a dummy written-in-asm top-of-the-stack function? Or recognize
> the end by the final saved RBP?
Assuming this issue could theoretically show up in *any* function called
by entry or head code, I think the least pervasive change would be to
just adjust the "last frame" check in the unwinder, aka
is_last_task_frame()), to check at the "aligned" off-by-one-word offset
in addition to the normal offset.
--
Josh
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null)
2016-12-13 16:55 ` Andy Lutomirski
2016-12-13 17:26 ` Josh Poimboeuf
@ 2016-12-13 17:51 ` Borislav Petkov
1 sibling, 0 replies; 15+ messages in thread
From: Borislav Petkov @ 2016-12-13 17:51 UTC (permalink / raw)
To: Andy Lutomirski; +Cc: Josh Poimboeuf, x86-ml, lkml, Andy Lutomirski
On Tue, Dec 13, 2016 at 08:55:53AM -0800, Andy Lutomirski wrote:
> I want to file a GCC bug, though. This code sucks.
Looks like it started doing that with gcc-5. gcc-4.9 output looks fine here:
.globl x86_64_start_kernel
.type x86_64_start_kernel, @function
x86_64_start_kernel:
.LFB2013:
.loc 1 134 0
.cfi_startproc
pushq %rbp #
.cfi_def_cfa_offset 16
.cfi_offset 6, -16
movq %rsp, %rbp #,
.cfi_def_cfa_register 6
pushq %rbx #
.cfi_offset 3, -24
.loc 1 134 0
movq %rdi, %rbx # real_mode_data, real_mode_data
.LBB157:
.LBB158:
.LBB159:
.LBB160:
.LBB161:
.loc 3 69 0
#APP
# 69 "./arch/x86/include/asm/special_insns.h" 1
mov %cr4,%rax # val
--
Regards/Gruss,
Boris.
Good mailing practices for 400: avoid top-posting and trim the reply.
^ permalink raw reply [flat|nested] 15+ messages in thread
end of thread, other threads:[~2016-12-13 17:27 UTC | newest]
Thread overview: 15+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-12-10 16:17 WARNING: kernel stack frame pointer at ffffffff82e03f40 in swapper:0 has bad value (null) Borislav Petkov
2016-12-10 17:04 ` Josh Poimboeuf
2016-12-10 17:28 ` Borislav Petkov
2016-12-12 15:45 ` Josh Poimboeuf
2016-12-12 17:50 ` Borislav Petkov
2016-12-12 18:10 ` Josh Poimboeuf
2016-12-12 21:16 ` Josh Poimboeuf
2016-12-12 21:34 ` Borislav Petkov
2016-12-12 22:11 ` Josh Poimboeuf
2016-12-12 22:33 ` Borislav Petkov
2016-12-12 23:05 ` Josh Poimboeuf
2016-12-13 14:34 ` Josh Poimboeuf
2016-12-13 16:55 ` Andy Lutomirski
2016-12-13 17:26 ` Josh Poimboeuf
2016-12-13 17:51 ` Borislav Petkov
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).