2013-04-30 21:21:50

by Dave Jones

[permalink] [raw]
Subject: clockevents_program_event WARN_ON preventing boot.

I have a machine that crashes instantly on boot up on Linus'
post-3.9 tree. (8c55f1463c1fd318d5e785f02b80bcc32176d342)

By booting with boot_delay=100, I was able to take a photo
and capture the top of the trace. (For some reason, larger boot
delay parameters seem to make it take forever before printing
even a single character, which made this a pain to debug).

The WARN_ON it prints right before locking up is this in clockevents_program_event

208 if (unlikely(expires.tv64 < 0)) {
209 WARN_ON_ONCE(1);
210 return -ETIME;
211 }

booting with maxcpus=1 avoids the problem.

I'm still trying to get a complete stack trace, though it's painful
due to the above reason.

Dave


2013-04-30 21:37:31

by Dave Jones

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Tue, Apr 30, 2013 at 05:20:07PM -0400, Dave Jones wrote:
> I have a machine that crashes instantly on boot up on Linus'
> post-3.9 tree. (8c55f1463c1fd318d5e785f02b80bcc32176d342)
>
> By booting with boot_delay=100, I was able to take a photo
> and capture the top of the trace. (For some reason, larger boot
> delay parameters seem to make it take forever before printing
> even a single character, which made this a pain to debug).
>
> The WARN_ON it prints right before locking up is this in clockevents_program_event
>
> 208 if (unlikely(expires.tv64 < 0)) {
> 209 WARN_ON_ONCE(1);
> 210 return -ETIME;
> 211 }
>
> booting with maxcpus=1 avoids the problem.
>
> I'm still trying to get a complete stack trace, though it's painful
> due to the above reason.

On a second machine, I'm seeing an oops even earlier. As soon as I
exit grub, I get a blinking cursor. If I boot with earlyprintk=vga
I can see..

Call Trace:
<IRQ>
tick_check_oneshot_broadcast
tick_check_idle
irq_enter
do_IRQ
common_interrupt
<EOI>
x86_64_start_reservations
x86_64_start_kernel
RIP: clockevents_set_mode+0x18

Matching up the Code: line of the trace with the disassembly I see..

if (dev->mode != mode) {
4c8: 39 77 38 cmp %esi,0x38(%rdi)


the comment above that code is telling..

/*
* Must be called with interrupts disabled !
*/

So how did we get an IRQ ?

2013-05-02 10:37:30

by Thomas Gleixner

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Tue, 30 Apr 2013, Dave Jones wrote:
> On Tue, Apr 30, 2013 at 05:20:07PM -0400, Dave Jones wrote:
> > I have a machine that crashes instantly on boot up on Linus'
> > post-3.9 tree. (8c55f1463c1fd318d5e785f02b80bcc32176d342)
> >
> > By booting with boot_delay=100, I was able to take a photo
> > and capture the top of the trace. (For some reason, larger boot
> > delay parameters seem to make it take forever before printing
> > even a single character, which made this a pain to debug).
> >
> > The WARN_ON it prints right before locking up is this in clockevents_program_event
> >
> > 208 if (unlikely(expires.tv64 < 0)) {
> > 209 WARN_ON_ONCE(1);
> > 210 return -ETIME;
> > 211 }
> >
> > booting with maxcpus=1 avoids the problem.
> >
> > I'm still trying to get a complete stack trace, though it's painful
> > due to the above reason.
>
> On a second machine, I'm seeing an oops even earlier. As soon as I
> exit grub, I get a blinking cursor. If I boot with earlyprintk=vga
> I can see..
>
> Call Trace:
> <IRQ>
> tick_check_oneshot_broadcast
> tick_check_idle
> irq_enter
> do_IRQ
> common_interrupt
> <EOI>
> x86_64_start_reservations
> x86_64_start_kernel
> RIP: clockevents_set_mode+0x18
>
> Matching up the Code: line of the trace with the disassembly I see..
>
> if (dev->mode != mode) {
> 4c8: 39 77 38 cmp %esi,0x38(%rdi)
>
>
> the comment above that code is telling..
>
> /*
> * Must be called with interrupts disabled !
> */
>
> So how did we get an IRQ ?

Well, we are inside an IRQ and the code is called with interrupts
disabled from there. Fix below.

Thanks,

tglx

diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index 61d00a8..db9da73 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -475,7 +475,8 @@ void tick_check_oneshot_broadcast(int cpu)
if (cpumask_test_cpu(cpu, tick_broadcast_oneshot_mask)) {
struct tick_device *td = &per_cpu(tick_cpu_device, cpu);

- clockevents_set_mode(td->evtdev, CLOCK_EVT_MODE_ONESHOT);
+ if (td)
+ clockevents_set_mode(td->evtdev, CLOCK_EVT_MODE_ONESHOT);
}
}

2013-05-02 15:46:31

by Dave Jones

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Thu, May 02, 2013 at 12:37:26PM +0200, Thomas Gleixner wrote:

> > On a second machine, I'm seeing an oops even earlier. As soon as I
> > exit grub, I get a blinking cursor. If I boot with earlyprintk=vga
> > I can see..
> >
> > Call Trace:
> > <IRQ>
> > tick_check_oneshot_broadcast
> > tick_check_idle
> > irq_enter
> > do_IRQ
> > common_interrupt
> > <EOI>
> > x86_64_start_reservations
> > x86_64_start_kernel
> > RIP: clockevents_set_mode+0x18
> >
> > Matching up the Code: line of the trace with the disassembly I see..
> >
> > if (dev->mode != mode) {
> > 4c8: 39 77 38 cmp %esi,0x38(%rdi)
> >
> >
>
> diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
> index 61d00a8..db9da73 100644
> --- a/kernel/time/tick-broadcast.c
> +++ b/kernel/time/tick-broadcast.c
> @@ -475,7 +475,8 @@ void tick_check_oneshot_broadcast(int cpu)
> if (cpumask_test_cpu(cpu, tick_broadcast_oneshot_mask)) {
> struct tick_device *td = &per_cpu(tick_cpu_device, cpu);
>
> - clockevents_set_mode(td->evtdev, CLOCK_EVT_MODE_ONESHOT);
> + if (td)
> + clockevents_set_mode(td->evtdev, CLOCK_EVT_MODE_ONESHOT);
> }
> }
>

td must be non-null, because this doesn't change anything.

a clue: If I disable CONFIG_SLUB_DEBUG, or even boot with slub_debug=- then it boots fine.

I'll bisect.

Dave

2013-05-02 17:56:51

by Yinghai Lu

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Thu, May 2, 2013 at 8:46 AM, Dave Jones <[email protected]> wrote:
> On Thu, May 02, 2013 at 12:37:26PM +0200, Thomas Gleixner wrote:
>
> > > On a second machine, I'm seeing an oops even earlier. As soon as I
> > > exit grub, I get a blinking cursor. If I boot with earlyprintk=vga
> > > I can see..
> > >
> > > Call Trace:
> > > <IRQ>
> > > tick_check_oneshot_broadcast
> > > tick_check_idle
> > > irq_enter
> > > do_IRQ
> > > common_interrupt
> > > <EOI>
> > > x86_64_start_reservations
> > > x86_64_start_kernel
> > > RIP: clockevents_set_mode+0x18
> > >

trace:
[ 3.394328] ------------[ cut here ]------------
[ 3.394346] WARNING: at kernel/time/clockevents.c:209
clockevents_program_event+0x3b/0x100()
[ 3.394349] Modules linked in:
[ 3.394355] CPU: 10 PID: 0 Comm: swapper/10 Not tainted
3.9.0-yh-07884-g14d850d-dirty #1534
[ 3.394357] Hardware name: Oracle Corporation unknown /
, BIOS 11016600 05/17/2011
[ 3.394373] 0000000000000009 ffff88203e203ed8 ffffffff82091492
ffff88203e203f18
[ 3.394381] ffffffff81088990 ffff88203e203f08 80000000003d08ff
80000000003d08ff
[ 3.394389] 000000000000000a ffff8810275e7fd8 0000000000000000
ffff88203e203f28
[ 3.394390] Call Trace:
[ 3.394405] <IRQ> [<ffffffff82091492>] dump_stack+0x19/0x1b
[ 3.394415] [<ffffffff81088990>] warn_slowpath_common+0x70/0xa0
[ 3.394419] [<ffffffff810889da>] warn_slowpath_null+0x1a/0x20
[ 3.394422] [<ffffffff810e312b>] clockevents_program_event+0x3b/0x100
[ 3.394427] [<ffffffff810e35ec>] tick_handle_periodic+0x4c/0x80
[ 3.394434] [<ffffffff820aed4d>] smp_apic_timer_interrupt+0x8d/0xa3
[ 3.394444] [<ffffffff820ae06f>] apic_timer_interrupt+0x6f/0x80
[ 3.394453] <EOI> [<ffffffff810527f7>] ? default_idle+0x57/0xd0
[ 3.394457] [<ffffffff810527f5>] ? default_idle+0x55/0xd0
[ 3.394461] [<ffffffff81053078>] arch_cpu_idle+0x18/0x20
[ 3.394465] [<ffffffff810dbec5>] cpu_startup_entry+0x165/0x210
[ 3.394473] [<ffffffff8207f81d>] start_secondary+0x1df/0x1e6
[ 3.394497] ---[ end trace d8b8ac23062f0bee ]---
[ 3.660026] Initializing CPU#11
[ 3.660229] CPU 11/26: logical apicid:00020040 in cluster 0002

then panic with cpu 64.


[ 10.253249] smpboot: CPU64: Intel(R) Xeon(R) CPU X7560 @
2.27GHz (fam: 06, model: 2e, stepping: 06)
[ 10.269640] checking TSC synchronization [CPU#0 -> CPU#64]: passed.
[ 10.272017] BUG: unable to handle kernel NULL pointer dereference
at 0000000000000048
[ 10.289803] IP: [<ffffffff810e3c46>] tick_do_broadcast+0x86/0xa0
[ 10.309535] PGD 0
[ 10.309683] Oops: 0000 [#1] SMP
[ 10.309885] Modules linked in:
[ 10.310069] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G W
3.9.0-yh-07884-g14d850d-dirty #1534
[ 10.340098] Hardware name: Oracle Corporation unknown /
, BIOS 11016600 05/17/2011
[ 10.359764] task: ffff8810274f0000 ti: ffff8810274ee000 task.ti:
ffff8810274ee000
[ 10.379412] RIP: 0010:[<ffffffff810e3c46>] [<ffffffff810e3c46>]
tick_do_broadcast+0x86/0xa0
[ 10.379871] RSP: 0000:ffff88103de03e68 EFLAGS: 00010002
[ 10.399560] RAX: 0000000000000000 RBX: ffff88103d848000 RCX: 0000000000000002
[ 10.399918] RDX: 0000000000000000 RSI: 0000000000000080 RDI: ffff88103d848000
[ 10.419810] RBP: ffff88103de03e78 R08: 0000000000000040 R09: 0000000000000002
[ 10.439551] R10: 0000000000000000 R11: 0000000000000000 R12: 000000000000d880
[ 10.439918] R13: ffffffff82a20680 R14: 0000000000000000 R15: 0000000000000001
[ 10.459717] FS: 0000000000000000(0000) GS:ffff88103de00000(0000)
knlGS:0000000000000000
[ 10.479545] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 10.479853] CR2: 0000000000000048 CR3: 000000807ea14000 CR4: 00000000000007f0
[ 10.499624] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 10.519441] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 10.519839] Stack:
[ 10.519953] ffffffff82a20680 ffffffff82a2d6c0 ffff88103de03e88
ffffffff810e3e41
[ 10.539793] ffff88103de03ea8 ffffffff810e3e64 ffffffff82a20680
0000000000000000
[ 10.559593] ffff88103de03eb8 ffffffff8104cc55 ffff88103de03f08
ffffffff81111b82
[ 10.560012] Call Trace:
[ 10.579490] <IRQ>
[ 10.579588] [<ffffffff810e3e41>] tick_do_periodic_broadcast+0x41/0x50
[ 10.579976] [<ffffffff810e3e64>] tick_handle_periodic_broadcast+0x14/0x60
[ 10.599726] [<ffffffff8104cc55>] timer_interrupt+0x15/0x20
[ 10.619453] [<ffffffff81111b82>] handle_irq_event_percpu+0x62/0x1e0
[ 10.619787] [<ffffffff81111d48>] handle_irq_event+0x48/0x70
[ 10.639517] [<ffffffff811147de>] ? handle_edge_irq+0x1e/0x130
[ 10.639830] [<ffffffff811148b8>] handle_edge_irq+0xf8/0x130
[ 10.659531] [<ffffffff8104c4c2>] handle_irq+0x22/0x40
[ 10.659802] [<ffffffff820aec4a>] do_IRQ+0x5a/0xd0
[ 10.679485] [<ffffffff820a4eaf>] common_interrupt+0x6f/0x6f
[ 10.679769] <EOI>
[ 10.679882] [<ffffffff810eb086>] ? mark_held_locks+0x136/0x150
[ 10.699615] [<ffffffff8207fe7f>] ? native_cpu_up+0x5ad/0x62d
[ 10.699958] [<ffffffff82081179>] _cpu_up+0xc0/0x133
[ 10.719594] [<ffffffff820812c5>] cpu_up+0xd9/0xec
[ 10.719860] [<ffffffff82db4239>] smp_init+0x76/0xa6
[ 10.739553] [<ffffffff82d9423d>] kernel_init_freeable+0xcd/0x251
[ 10.739879] [<ffffffff82074850>] ? rest_init+0xd0/0xd0
[ 10.759555] [<ffffffff8207485e>] kernel_init+0xe/0xf0
[ 10.759833] [<ffffffff820ad29c>] ret_from_fork+0x7c/0xb0
[ 10.779528] [<ffffffff82074850>] ? rest_init+0xd0/0xd0
[ 10.779779] Code: 85 c0 75 2a 48 63 35 5e f8 ac 01 48 89 df 49 c7
c4 80 d8 00 00 e8 cb 50 41 00 89 c0 48 89 df 48 8b 04 c5 e0 74 ba 82
4a 8b 04 20 <ff> 50 48 48 8b 5d f0 4c 8b 65 f8 c9 c3 66 66 66 66 2e 0f
1f 84
[ 10.819807] RIP [<ffffffff810e3c46>] tick_do_broadcast+0x86/0xa0
[ 10.820147] RSP <ffff88103de03e68>
[ 10.839550] CR2: 0000000000000048
[ 10.839723] ---[ end trace d8b8ac23062f0bef ]---
[ 10.839952] Kernel panic - not syncing: Fatal exception in interrupt
[ 11.907579] Shutting down cpus with NMI

2013-05-02 19:58:07

by Thomas Gleixner

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Thu, 2 May 2013, Dave Jones wrote:
> On Thu, May 02, 2013 at 12:37:26PM +0200, Thomas Gleixner wrote:
>
> > > On a second machine, I'm seeing an oops even earlier. As soon as I
> > > exit grub, I get a blinking cursor. If I boot with earlyprintk=vga
> > > I can see..
> > >
> > > Call Trace:
> > > <IRQ>
> > > tick_check_oneshot_broadcast
> > > tick_check_idle
> > > irq_enter
> > > do_IRQ
> > > common_interrupt
> > > <EOI>
> > > x86_64_start_reservations
> > > x86_64_start_kernel
> > > RIP: clockevents_set_mode+0x18
> > >
> > > Matching up the Code: line of the trace with the disassembly I see..
> > >
> > > if (dev->mode != mode) {
> > > 4c8: 39 77 38 cmp %esi,0x38(%rdi)
> > >
> > >
> >
> > diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
> > index 61d00a8..db9da73 100644
> > --- a/kernel/time/tick-broadcast.c
> > +++ b/kernel/time/tick-broadcast.c
> > @@ -475,7 +475,8 @@ void tick_check_oneshot_broadcast(int cpu)
> > if (cpumask_test_cpu(cpu, tick_broadcast_oneshot_mask)) {
> > struct tick_device *td = &per_cpu(tick_cpu_device, cpu);
> >
> > - clockevents_set_mode(td->evtdev, CLOCK_EVT_MODE_ONESHOT);
> > + if (td)
> > + clockevents_set_mode(td->evtdev, CLOCK_EVT_MODE_ONESHOT);
> > }
> > }
> >
>
> td must be non-null, because this doesn't change anything.

Bah, I'm a moron. td is always non-null.

The check should be:

if (td->evtdev && tick_device_is_functional(td->evtdev))

> a clue: If I disable CONFIG_SLUB_DEBUG, or even boot with slub_debug=- then it boots fine.

Huch? That does not make any sense.

Thanks,

tglx

2013-05-02 20:54:19

by Yinghai Lu

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Thu, May 2, 2013 at 12:58 PM, Thomas Gleixner <[email protected]> wrote:

>
> The check should be:
>
> if (td->evtdev && tick_device_is_functional(td->evtdev))

still happens.

[ 3.457866] checking TSC synchronization [CPU#0 -> CPU#10]: passed.
[ 3.460806] SMP alternatives: lockdep: fixing up alternatives
[ 3.464282] ------------[ cut here ]------------
[ 3.464297] WARNING: at kernel/time/clockevents.c:209
clockevents_program_event+0x3b/0x100()
[ 3.464300] Modules linked in:
[ 3.464306] CPU: 10 PID: 0 Comm: swapper/10 Not tainted
3.9.0-yh-08066-g1252014-dirty #1537
[ 3.464308] Hardware name: Oracle Corporation unknown /
, BIOS 11016600 05/17/2011
[ 3.464327] 0000000000000009 ffff88203e203ed8 ffffffff82091022
ffff88203e203f18
[ 3.464343] ffffffff81088990 ffff88203e203f08 80000000003d08ff
80000000003d08ff
[ 3.464359] 000000000000000a ffff881027557fd8 0000000000000000
ffff88203e203f28
[ 3.464361] Call Trace:
[ 3.464379] <IRQ> [<ffffffff82091022>] dump_stack+0x19/0x1b
[ 3.464392] [<ffffffff81088990>] warn_slowpath_common+0x70/0xa0
[ 3.464395] [<ffffffff810889da>] warn_slowpath_null+0x1a/0x20
[ 3.464399] [<ffffffff810e312b>] clockevents_program_event+0x3b/0x100
[ 3.464403] [<ffffffff810e35ec>] tick_handle_periodic+0x4c/0x80
[ 3.464409] [<ffffffff820ae8cd>] smp_apic_timer_interrupt+0x8d/0xa3
[ 3.464418] [<ffffffff820adbef>] apic_timer_interrupt+0x6f/0x80
[ 3.464426] <EOI> [<ffffffff810527f7>] ? default_idle+0x57/0xd0
[ 3.464430] [<ffffffff810527f5>] ? default_idle+0x55/0xd0
[ 3.464434] [<ffffffff81053078>] arch_cpu_idle+0x18/0x20
[ 3.464438] [<ffffffff810dbec5>] cpu_startup_entry+0x165/0x210
[ 3.464446] [<ffffffff8207f3ad>] start_secondary+0x1df/0x1e6
[ 3.464469] ---[ end trace 89673eac7a3370c6 ]---
[ 3.717988] smpboot: Booting processor 11 APIC 0x26 ip 0x90000


>
>> a clue: If I disable CONFIG_SLUB_DEBUG, or even boot with slub_debug=- then it boots fine.
>
> Huch? That does not make any sense.

I don't have that CONFIG_SLUB_DEBUG in .config

Yinghai

2013-05-02 21:19:09

by Thomas Gleixner

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Thu, 2 May 2013, Yinghai Lu wrote:
> On Thu, May 2, 2013 at 12:58 PM, Thomas Gleixner <[email protected]> wrote:
>
> >
> > The check should be:
> >
> > if (td->evtdev && tick_device_is_functional(td->evtdev))
>
> still happens.
>
> [ 3.457866] checking TSC synchronization [CPU#0 -> CPU#10]: passed.
> [ 3.460806] SMP alternatives: lockdep: fixing up alternatives
> [ 3.464282] ------------[ cut here ]------------
> [ 3.464297] WARNING: at kernel/time/clockevents.c:209
> clockevents_program_event+0x3b/0x100()

I didn't expect it to fix the warning, I just wanted to prevent the
crash which Dave decoded. Though the warning and the crash have
probably the same root cause...

> [ 3.464300] Modules linked in:
> [ 3.464306] CPU: 10 PID: 0 Comm: swapper/10 Not tainted
> 3.9.0-yh-08066-g1252014-dirty #1537
> [ 3.464308] Hardware name: Oracle Corporation unknown /
> , BIOS 11016600 05/17/2011
> [ 3.464327] 0000000000000009 ffff88203e203ed8 ffffffff82091022
> ffff88203e203f18
> [ 3.464343] ffffffff81088990 ffff88203e203f08 80000000003d08ff
> 80000000003d08ff
> [ 3.464359] 000000000000000a ffff881027557fd8 0000000000000000
> ffff88203e203f28
> [ 3.464361] Call Trace:
> [ 3.464379] <IRQ> [<ffffffff82091022>] dump_stack+0x19/0x1b
> [ 3.464392] [<ffffffff81088990>] warn_slowpath_common+0x70/0xa0
> [ 3.464395] [<ffffffff810889da>] warn_slowpath_null+0x1a/0x20
> [ 3.464399] [<ffffffff810e312b>] clockevents_program_event+0x3b/0x100
> [ 3.464403] [<ffffffff810e35ec>] tick_handle_periodic+0x4c/0x80

Now, that's really odd.

next = ktime_add(dev->next_event, tick_period);

clockevents_program_event(dev, next, false);

and next.tv64 is < 0 !?!

Can you please apply the following debug patch and provide the output?

Thanks,

tglx

diff --git a/kernel/time/clockevents.c b/kernel/time/clockevents.c
index c6d6400..b4d9622 100644
--- a/kernel/time/clockevents.c
+++ b/kernel/time/clockevents.c
@@ -207,6 +207,8 @@ int clockevents_program_event(struct clock_event_device *dev, ktime_t expires,

if (unlikely(expires.tv64 < 0)) {
WARN_ON_ONCE(1);
+ printk_once(KERN_INFO "expires %llx, dev->next %llx\n",
+ expires.tv64, dev->next_event.tv64);
return -ETIME;
}

2013-05-02 21:36:16

by Yinghai Lu

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Thu, May 2, 2013 at 2:19 PM, Thomas Gleixner <[email protected]> wrote:
> Can you please apply the following debug patch and provide the output?
>
> diff --git a/kernel/time/clockevents.c b/kernel/time/clockevents.c
> index c6d6400..b4d9622 100644
> --- a/kernel/time/clockevents.c
> +++ b/kernel/time/clockevents.c
> @@ -207,6 +207,8 @@ int clockevents_program_event(struct clock_event_device *dev, ktime_t expires,
>
> if (unlikely(expires.tv64 < 0)) {
> WARN_ON_ONCE(1);
> + printk_once(KERN_INFO "expires %llx, dev->next %llx\n",
> + expires.tv64, dev->next_event.tv64);
> return -ETIME;
> }
>

[ 3.450968] SMP alternatives: lockdep: fixing up alternatives
[ 3.454454] ------------[ cut here ]------------
[ 3.454470] WARNING: at kernel/time/clockevents.c:209
clockevents_program_event+0x3e/0x120()
[ 3.454473] Modules linked in:
[ 3.454479] CPU: 10 PID: 0 Comm: swapper/10 Not tainted
3.9.0-yh-08066-g1252014-dirty #1538
[ 3.454481] Hardware name: Oracle Corporation unknown /
, BIOS 11016600 05/17/2011
[ 3.454500] 0000000000000009 ffff88203e203ed8 ffffffff82091042
ffff88203e203f18
[ 3.454518] ffffffff81088990 ffff88203e203f08 ffff88203e20d000
80000000003d08ff
[ 3.454526] 000000000000000a ffff881027557fd8 0000000000000000
ffff88203e203f28
[ 3.454527] Call Trace:
[ 3.454540] <IRQ> [<ffffffff82091042>] dump_stack+0x19/0x1b
[ 3.454548] [<ffffffff81088990>] warn_slowpath_common+0x70/0xa0
[ 3.454552] [<ffffffff810889da>] warn_slowpath_null+0x1a/0x20
[ 3.454556] [<ffffffff810e312e>] clockevents_program_event+0x3e/0x120
[ 3.454560] [<ffffffff810e360c>] tick_handle_periodic+0x4c/0x80
[ 3.454566] [<ffffffff820ae8cd>] smp_apic_timer_interrupt+0x8d/0xa3
[ 3.454575] [<ffffffff820adbef>] apic_timer_interrupt+0x6f/0x80
[ 3.454583] <EOI> [<ffffffff810527f7>] ? default_idle+0x57/0xd0
[ 3.454587] [<ffffffff810527f5>] ? default_idle+0x55/0xd0
[ 3.454591] [<ffffffff81053078>] arch_cpu_idle+0x18/0x20
[ 3.454595] [<ffffffff810dbec5>] cpu_startup_entry+0x165/0x210
[ 3.454603] [<ffffffff8207f3cd>] start_secondary+0x1df/0x1e6
[ 3.454626] ---[ end trace 2f2f1a2adee9c881 ]---
[ 3.454628] expires 80000000003d08ff, dev->next 7fffffffffffffff

2013-05-02 22:49:28

by Thomas Gleixner

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Thu, 2 May 2013, Yinghai Lu wrote:
> On Thu, May 2, 2013 at 2:19 PM, Thomas Gleixner <[email protected]> wrote:
> > Can you please apply the following debug patch and provide the output?
> >
> > diff --git a/kernel/time/clockevents.c b/kernel/time/clockevents.c
> > index c6d6400..b4d9622 100644
> > --- a/kernel/time/clockevents.c
> > +++ b/kernel/time/clockevents.c
> > @@ -207,6 +207,8 @@ int clockevents_program_event(struct clock_event_device *dev, ktime_t expires,
> >
> > if (unlikely(expires.tv64 < 0)) {
> > WARN_ON_ONCE(1);
> > + printk_once(KERN_INFO "expires %llx, dev->next %llx\n",
> > + expires.tv64, dev->next_event.tv64);

> [ 3.454628] expires 80000000003d08ff, dev->next 7fffffffffffffff

So dev->next_event == KTIME_MAX. That means that the device has been
shut down, at least I can't see any other reason at that point - we
are not in highres/nohz mode yet. And it still got an interrupt served
for whatever reason. What's even more confusing is that in
tick_handle_periodic() we check for:

if (dev->mode != CLOCK_EVT_MODE_ONESHOT)
return;

So if the device is shutdown for real the mode would be
CLOCK_EVT_MODE_SHUTDOWN and we'd never reach that code.

Shut down at that point only happens in context of the broadcast
crap. Your crash:

[ 10.272017] BUG: unable to handle kernel NULL pointer dereference
at 0000000000000048
[ 10.289803] IP: [<ffffffff810e3c46>] tick_do_broadcast+0x86/0xa0

points to the broadcast stuff as well. 0x48 is the offset of the
broadcast function. So your machine died at:

td->evtdev->broadcast(mask);

That means, that the cpu was set in the broadcast mask, but the per
cpu event device was not yet registered !?!

That does not make any sense, as we explicitely prevent the broadcast
activation for cpus which have no per cpu tick device registered yet.

I'm fundamentally confused and Daves observation about slub debug does
not make it less confusing.

It'd be nice if you could add some more instrumentation or bisect the
issue.

Thanks,

tglx

2013-05-03 14:49:25

by Dave Jones

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Fri, May 03, 2013 at 12:49:20AM +0200, Thomas Gleixner wrote:

> I'm fundamentally confused and Daves observation about slub debug does
> not make it less confusing.
>
> It'd be nice if you could add some more instrumentation or bisect the
> issue.

Here's what I ended up with..

git bisect start
# good: [8cf90797fc2d7172480343cda0ff5898b92afc94] Merge branch 'master' of /home/davej/src/kernel/git-trees/linux
git bisect good 8cf90797fc2d7172480343cda0ff5898b92afc94
# bad: [a9754f91ed5255a992dc4c230f8b4b6ee57c399a] Merge branch 'master' of /home/davej/src/kernel/git-trees/linux
git bisect bad a9754f91ed5255a992dc4c230f8b4b6ee57c399a
# good: [ec25e246b94a3233ab064994ef05a170bdba0e7c] Merge tag 'usb-3.10-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb
git bisect good ec25e246b94a3233ab064994ef05a170bdba0e7c
# good: [8700c95adb033843fc163d112b9d21d4fda78018] Merge branch 'smp-hotplug-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good 8700c95adb033843fc163d112b9d21d4fda78018
# good: [a6f5635e63ffa02c30a22ea4af21f3daa1e98cdf] [media] exynos4-is: Improve the ISP chain parameter count calculation
git bisect good a6f5635e63ffa02c30a22ea4af21f3daa1e98cdf
# good: [df90e2258950fd631cdbf322c1ee1f22068391aa] Merge branch 'devel-for-v3.10' into v4l_for_linus
git bisect good df90e2258950fd631cdbf322c1ee1f22068391aa
# bad: [19b344efa35dbc253e2d10403dafe6aafda73c56] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/jikos/hid
git bisect bad 19b344efa35dbc253e2d10403dafe6aafda73c56
# bad: [74c7d2f5200a340ae6655e9adcf990381e387937] Merge branch 'x86-platform-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect bad 74c7d2f5200a340ae6655e9adcf990381e387937
# bad: [77c675ba18836802f6b73d2d773481d06ebc0f04] timekeeping: Update tk->cycle_last in resume
git bisect bad 77c675ba18836802f6b73d2d773481d06ebc0f04
# bad: [0ed2aef9b3bffe598045b62a31a50d912eee92d8] Merge branch 'fortglx/3.10/time' of git://git.linaro.org/people/jstultz/linux into timers/core
git bisect bad 0ed2aef9b3bffe598045b62a31a50d912eee92d8
# good: [dd5d70e869f960bde6376f4447fff59f16186cf5] timekeeping: __timekeeping_set_tai_offset can be static
git bisect good dd5d70e869f960bde6376f4447fff59f16186cf5
# bad: [989dcb645ca715129c5a2b39102c8334a20d9615] tick: Handle broadcast wakeup of multiple cpus
git bisect bad 989dcb645ca715129c5a2b39102c8334a20d9615
# bad: [f9ae39d04ccdec8d8ecf532191b7056c279a22c0] tick: Pass broadcast device to tick_broadcast_set_event()
git bisect bad f9ae39d04ccdec8d8ecf532191b7056c279a22c0
# bad: [b352bc1cbc29134a356b5c16ee2281807a7b984e] tick: Convert broadcast cpu bitmaps to cpumask_var_t
git bisect bad b352bc1cbc29134a356b5c16ee2281807a7b984e
# good: [ad2b13536ace08dfcca4cf86b75a5d06efe06373] tick: Call tick_init late
git bisect good ad2b13536ace08dfcca4cf86b75a5d06efe06373

b352bc1cbc29134a356b5c16ee2281807a7b984e is the first bad commit
commit b352bc1cbc29134a356b5c16ee2281807a7b984e
Author: Thomas Gleixner <[email protected]>
Date: Tue Mar 5 14:25:32 2013 +0100

tick: Convert broadcast cpu bitmaps to cpumask_var_t

Signed-off-by: Thomas Gleixner <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Cc: Rusty Russell <[email protected]>

:040000 040000 689609c27a2c8da0b09f8136f4552ab8814a0094 9e59b78318177ec8267e1fabfdede034c3fb6b4f M kernel


2013-05-03 18:33:08

by Thomas Gleixner

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Fri, 3 May 2013, Dave Jones wrote:
> On Fri, May 03, 2013 at 12:49:20AM +0200, Thomas Gleixner wrote:
>
> > I'm fundamentally confused and Daves observation about slub debug does
> > not make it less confusing.
> >
> > It'd be nice if you could add some more instrumentation or bisect the
> > issue.
>
> Here's what I ended up with..
> b352bc1cbc29134a356b5c16ee2281807a7b984e is the first bad commit
> commit b352bc1cbc29134a356b5c16ee2281807a7b984e
> Author: Thomas Gleixner <[email protected]>
> Date: Tue Mar 5 14:25:32 2013 +0100
>
> tick: Convert broadcast cpu bitmaps to cpumask_var_t
>
> Signed-off-by: Thomas Gleixner <[email protected]>
> Link: http://lkml.kernel.org/r/[email protected]
> Cc: Rusty Russell <[email protected]>
>

I bet you have CONFIG_CPUMASK_OFFSTACK enabled.

/me is a moron and rumages for a brown paperbag.

Patch below.

Thanks,

tglx

------------>

Subject: tick: Use zalloc_cpumask_var for allocating offstack cpumasks
From: Thomas Gleixner <[email protected]>
Date: Fri, 03 May 2013 20:22:36 +0200

commit b352bc1cbc (tick: Convert broadcast cpu bitmaps to
cpumask_var_t) broke CONFIG_CPUMASK_OFFSTACK in a very subtle way.

Instead of allocating the cpumasks with zalloc_cpumask_var it uses
alloc_cpumask_var, so we can get random data there, which of course
confuses the logic completely and causes random failures.

Reported-by: Dave Jones <[email protected]>
Reported-by: Yinghai Lu <[email protected]>
Signed-off-by: Thomas Gleixner <[email protected]>
---
kernel/time/tick-broadcast.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)

Index: linux-2.6/kernel/time/tick-broadcast.c
===================================================================
--- linux-2.6.orig/kernel/time/tick-broadcast.c
+++ linux-2.6/kernel/time/tick-broadcast.c
@@ -785,11 +785,11 @@ bool tick_broadcast_oneshot_available(vo

void __init tick_broadcast_init(void)
{
- alloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tmpmask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tmpmask, GFP_NOWAIT);
#ifdef CONFIG_TICK_ONESHOT
- alloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
#endif
}


2013-05-03 20:10:52

by Dave Jones

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Fri, May 03, 2013 at 08:32:58PM +0200, Thomas Gleixner wrote:
> On Fri, 3 May 2013, Dave Jones wrote:
> > On Fri, May 03, 2013 at 12:49:20AM +0200, Thomas Gleixner wrote:
> >
> > > I'm fundamentally confused and Daves observation about slub debug does
> > > not make it less confusing.
> > >
> > > It'd be nice if you could add some more instrumentation or bisect the
> > > issue.
> >
> > Here's what I ended up with..
> > b352bc1cbc29134a356b5c16ee2281807a7b984e is the first bad commit
> > commit b352bc1cbc29134a356b5c16ee2281807a7b984e
> > Author: Thomas Gleixner <[email protected]>
> > Date: Tue Mar 5 14:25:32 2013 +0100
> >
> > tick: Convert broadcast cpu bitmaps to cpumask_var_t
> >
> > Signed-off-by: Thomas Gleixner <[email protected]>
> > Link: http://lkml.kernel.org/r/[email protected]
> > Cc: Rusty Russell <[email protected]>
> >
>
> I bet you have CONFIG_CPUMASK_OFFSTACK enabled.
>
> /me is a moron and rumages for a brown paperbag.
>
> Patch below.

Works for me.

Tested-by: Dave Jones <[email protected]>

2013-05-04 05:03:13

by Yinghai Lu

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Fri, May 3, 2013 at 11:32 AM, Thomas Gleixner <[email protected]> wrote:
> Subject: tick: Use zalloc_cpumask_var for allocating offstack cpumasks
> From: Thomas Gleixner <[email protected]>
> Date: Fri, 03 May 2013 20:22:36 +0200
>
> commit b352bc1cbc (tick: Convert broadcast cpu bitmaps to
> cpumask_var_t) broke CONFIG_CPUMASK_OFFSTACK in a very subtle way.
>
> Instead of allocating the cpumasks with zalloc_cpumask_var it uses
> alloc_cpumask_var, so we can get random data there, which of course
> confuses the logic completely and causes random failures.
>
> Reported-by: Dave Jones <[email protected]>
> Reported-by: Yinghai Lu <[email protected]>
> Signed-off-by: Thomas Gleixner <[email protected]>
> ---
> kernel/time/tick-broadcast.c | 10 +++++-----
> 1 file changed, 5 insertions(+), 5 deletions(-)
>
> Index: linux-2.6/kernel/time/tick-broadcast.c
> ===================================================================
> --- linux-2.6.orig/kernel/time/tick-broadcast.c
> +++ linux-2.6/kernel/time/tick-broadcast.c
> @@ -785,11 +785,11 @@ bool tick_broadcast_oneshot_available(vo
>
> void __init tick_broadcast_init(void)
> {
> - alloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
> - alloc_cpumask_var(&tmpmask, GFP_NOWAIT);
> + zalloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
> + zalloc_cpumask_var(&tmpmask, GFP_NOWAIT);
> #ifdef CONFIG_TICK_ONESHOT
> - alloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
> - alloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
> - alloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
> + zalloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
> + zalloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
> + zalloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
> #endif
> }

Yes, it works on Nehalem-EX 8 socket system now.

Tested-by: Yinghai Lu <[email protected]>

Subject: [tip:timers/urgent] tick: Use zalloc_cpumask_var for allocating offstack cpumasks

Commit-ID: de9de4f5f11d8c89ad3e4fad49e2ebb36630a09a
Gitweb: http://git.kernel.org/tip/de9de4f5f11d8c89ad3e4fad49e2ebb36630a09a
Author: Thomas Gleixner <[email protected]>
AuthorDate: Fri, 3 May 2013 20:22:36 +0200
Committer: Thomas Gleixner <[email protected]>
CommitDate: Sun, 5 May 2013 08:15:11 +0200

tick: Use zalloc_cpumask_var for allocating offstack cpumasks

commit b352bc1cbc (tick: Convert broadcast cpu bitmaps to
cpumask_var_t) broke CONFIG_CPUMASK_OFFSTACK in a very subtle way.

Instead of allocating the cpumasks with zalloc_cpumask_var it uses
alloc_cpumask_var, so we can get random data there, which of course
confuses the logic completely and causes random failures.

Reported-and-tested-by: Dave Jones <[email protected]>
Reported-and-tested-by: Yinghai Lu <[email protected]>
Link: http://lkml.kernel.org/r/alpine.LFD.2.02.1305032015060.2990@ionos
Signed-off-by: Thomas Gleixner <[email protected]>
---
kernel/time/tick-broadcast.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index 61d00a8..d70cdc4 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -785,11 +785,11 @@ bool tick_broadcast_oneshot_available(void)

void __init tick_broadcast_init(void)
{
- alloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tmpmask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tmpmask, GFP_NOWAIT);
#ifdef CONFIG_TICK_ONESHOT
- alloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
#endif
}

Subject: [tip:timers/urgent] tick: Use zalloc_cpumask_var for allocating offstack cpumasks

Commit-ID: fbd44a607a1a5019bc32c3615cead8c5ee8f89c9
Gitweb: http://git.kernel.org/tip/fbd44a607a1a5019bc32c3615cead8c5ee8f89c9
Author: Thomas Gleixner <[email protected]>
AuthorDate: Fri, 3 May 2013 20:22:36 +0200
Committer: Ingo Molnar <[email protected]>
CommitDate: Sun, 5 May 2013 11:12:19 +0200

tick: Use zalloc_cpumask_var for allocating offstack cpumasks

commit b352bc1cbc (tick: Convert broadcast cpu bitmaps to
cpumask_var_t) broke CONFIG_CPUMASK_OFFSTACK in a very subtle way.

Instead of allocating the cpumasks with zalloc_cpumask_var it uses
alloc_cpumask_var, so we can get random data there, which of course
confuses the logic completely and causes random failures.

Reported-and-tested-by: Dave Jones <[email protected]>
Reported-and-tested-by: Yinghai Lu <[email protected]>
Link: http://lkml.kernel.org/r/alpine.LFD.2.02.1305032015060.2990@ionos
Signed-off-by: Thomas Gleixner <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
---
kernel/time/tick-broadcast.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index 61d00a8..d70cdc4 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -785,11 +785,11 @@ bool tick_broadcast_oneshot_available(void)

void __init tick_broadcast_init(void)
{
- alloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tmpmask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tmpmask, GFP_NOWAIT);
#ifdef CONFIG_TICK_ONESHOT
- alloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
#endif
}

Subject: [tip:timers/urgent] tick: Use zalloc_cpumask_var for allocating offstack cpumasks

Commit-ID: 9978ec69635548d00f7dabec95cf0412b3c313c4
Gitweb: http://git.kernel.org/tip/9978ec69635548d00f7dabec95cf0412b3c313c4
Author: Thomas Gleixner <[email protected]>
AuthorDate: Fri, 3 May 2013 20:22:36 +0200
Committer: Thomas Gleixner <[email protected]>
CommitDate: Sun, 5 May 2013 14:44:08 +0200

tick: Use zalloc_cpumask_var for allocating offstack cpumasks

commit b352bc1cbc (tick: Convert broadcast cpu bitmaps to
cpumask_var_t) broke CONFIG_CPUMASK_OFFSTACK in a very subtle way.

Instead of allocating the cpumasks with zalloc_cpumask_var it uses
alloc_cpumask_var, so we can get random data there, which of course
confuses the logic completely and causes random failures.

Reported-and-tested-by: Dave Jones <[email protected]>
Reported-and-tested-by: Yinghai Lu <[email protected]>
Link: http://lkml.kernel.org/r/alpine.LFD.2.02.1305032015060.2990@ionos
Signed-off-by: Thomas Gleixner <[email protected]>
---
kernel/time/tick-broadcast.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index 61d00a8..d70cdc4 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -785,11 +785,11 @@ bool tick_broadcast_oneshot_available(void)

void __init tick_broadcast_init(void)
{
- alloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tmpmask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tmpmask, GFP_NOWAIT);
#ifdef CONFIG_TICK_ONESHOT
- alloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
#endif
}

Subject: [tip:timers/urgent] tick: Use zalloc_cpumask_var for allocating offstack cpumasks

Commit-ID: 642fb0f86fa38efefc0cf0e46ac20fa03e7f7f01
Gitweb: http://git.kernel.org/tip/642fb0f86fa38efefc0cf0e46ac20fa03e7f7f01
Author: Thomas Gleixner <[email protected]>
AuthorDate: Fri, 3 May 2013 20:22:36 +0200
Committer: Thomas Gleixner <[email protected]>
CommitDate: Sun, 5 May 2013 16:06:35 +0200

tick: Use zalloc_cpumask_var for allocating offstack cpumasks

commit b352bc1cbc (tick: Convert broadcast cpu bitmaps to
cpumask_var_t) broke CONFIG_CPUMASK_OFFSTACK in a very subtle way.

Instead of allocating the cpumasks with zalloc_cpumask_var it uses
alloc_cpumask_var, so we can get random data there, which of course
confuses the logic completely and causes random failures.

Reported-and-tested-by: Dave Jones <[email protected]>
Reported-and-tested-by: Yinghai Lu <[email protected]>
Link: http://lkml.kernel.org/r/alpine.LFD.2.02.1305032015060.2990@ionos
Signed-off-by: Thomas Gleixner <[email protected]>
---
kernel/time/tick-broadcast.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index 61d00a8..d70cdc4 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -785,11 +785,11 @@ bool tick_broadcast_oneshot_available(void)

void __init tick_broadcast_init(void)
{
- alloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tmpmask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tmpmask, GFP_NOWAIT);
#ifdef CONFIG_TICK_ONESHOT
- alloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
- alloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
+ zalloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
#endif
}

2013-05-10 13:24:42

by Josh Boyer

[permalink] [raw]
Subject: Re: clockevents_program_event WARN_ON preventing boot.

On Fri, May 3, 2013 at 2:32 PM, Thomas Gleixner <[email protected]> wrote:
> On Fri, 3 May 2013, Dave Jones wrote:
>> On Fri, May 03, 2013 at 12:49:20AM +0200, Thomas Gleixner wrote:
>>
>> > I'm fundamentally confused and Daves observation about slub debug does
>> > not make it less confusing.
>> >
>> > It'd be nice if you could add some more instrumentation or bisect the
>> > issue.
>>
>> Here's what I ended up with..
>> b352bc1cbc29134a356b5c16ee2281807a7b984e is the first bad commit
>> commit b352bc1cbc29134a356b5c16ee2281807a7b984e
>> Author: Thomas Gleixner <[email protected]>
>> Date: Tue Mar 5 14:25:32 2013 +0100
>>
>> tick: Convert broadcast cpu bitmaps to cpumask_var_t
>>
>> Signed-off-by: Thomas Gleixner <[email protected]>
>> Link: http://lkml.kernel.org/r/[email protected]
>> Cc: Rusty Russell <[email protected]>
>>
>
> I bet you have CONFIG_CPUMASK_OFFSTACK enabled.
>
> /me is a moron and rumages for a brown paperbag.
>
> Patch below.
>
> Thanks,
>
> tglx
>
> ------------>
>
> Subject: tick: Use zalloc_cpumask_var for allocating offstack cpumasks
> From: Thomas Gleixner <[email protected]>
> Date: Fri, 03 May 2013 20:22:36 +0200
>
> commit b352bc1cbc (tick: Convert broadcast cpu bitmaps to
> cpumask_var_t) broke CONFIG_CPUMASK_OFFSTACK in a very subtle way.
>
> Instead of allocating the cpumasks with zalloc_cpumask_var it uses
> alloc_cpumask_var, so we can get random data there, which of course
> confuses the logic completely and causes random failures.
>
> Reported-by: Dave Jones <[email protected]>
> Reported-by: Yinghai Lu <[email protected]>
> Signed-off-by: Thomas Gleixner <[email protected]>

This still isn't in Linus' tree and it fixes boot issues on a number
of different machine types. Is it queued up anywhere? Hoping it gets
into 3.10-rc1.

josh

> ---
> kernel/time/tick-broadcast.c | 10 +++++-----
> 1 file changed, 5 insertions(+), 5 deletions(-)
>
> Index: linux-2.6/kernel/time/tick-broadcast.c
> ===================================================================
> --- linux-2.6.orig/kernel/time/tick-broadcast.c
> +++ linux-2.6/kernel/time/tick-broadcast.c
> @@ -785,11 +785,11 @@ bool tick_broadcast_oneshot_available(vo
>
> void __init tick_broadcast_init(void)
> {
> - alloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
> - alloc_cpumask_var(&tmpmask, GFP_NOWAIT);
> + zalloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
> + zalloc_cpumask_var(&tmpmask, GFP_NOWAIT);
> #ifdef CONFIG_TICK_ONESHOT
> - alloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
> - alloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
> - alloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
> + zalloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
> + zalloc_cpumask_var(&tick_broadcast_pending_mask, GFP_NOWAIT);
> + zalloc_cpumask_var(&tick_broadcast_force_mask, GFP_NOWAIT);
> #endif
> }