Re: linux-next: Tree for December 11

["Alexey Zaytsev" <alexey.zaytsev@gmail.com>]

On Sun, Dec 14, 2008 at 17:34, Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:
> On Thu, Dec 11, 2008 at 15:40, Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:
>> On Thu, Dec 11, 2008 at 12:04, Stephen Rothwell <sfr@canb.auug.org.au> wrote:
>>> Hi all,
>>>
>>>
>>> ----------------------------------------------------------------------------
>>
>> Hi.

Almost a month later, the warning is still there, and now also in Linus' git.
Am I the only one who sees it?

[    0.004000] Intel machine check reporting enabled on CPU#0.
[    0.004000] using mwait in idle threads.
[    0.004000] Checking 'hlt' instruction... <4>------------[ cut here
]------------
[    0.004150] WARNING: at kernel/sched.c:4435 sub_preempt_count+0xae/0xc0()
[    0.004247] Hardware name: HP Compaq nx7300 (GB848ES#ACB)
[    0.004342] Modules linked in:
[    0.004477] Pid: 0, comm: swapper Not tainted 2.6.28-06859-gede6f5a #179
[    0.004575] Call Trace:
[    0.004672]  [<c012fbe6>] warn_slowpath+0x86/0xa0
[    0.004770]  [<c014e99b>] ? tick_check_oneshot_change+0x4b/0x100
[    0.004868]  [<c046dc00>] ? _spin_unlock_irq+0x10/0x30
[    0.004963]  [<c047045e>] sub_preempt_count+0xae/0xc0
[    0.005060]  [<c0134787>] _local_bh_enable+0x27/0xa0
[    0.005155]  [<c0134ac7>] __do_softirq+0xf7/0x150
[    0.005250]  [<c01349d0>] ? __do_softirq+0x0/0x150
[    0.005345]  <IRQ>  [<c014ec2e>] ? tick_nohz_update_jiffies+0xe/0x50
[    0.005488]  [<c013494f>] ? irq_exit+0x7f/0x90
[    0.005584]  [<c0104f23>] ? do_IRQ+0xa3/0x120
[    0.005678]  [<c01038a7>] ? common_interrupt+0x27/0x2c
[    0.005773]  [<c013007b>] ? try_acquire_console_sem+0x1b/0x30
[    0.005872]  [<c05f7378>] ? check_bugs+0xb8/0xe0
[    0.005967]  [<c05ef98a>] ? start_kernel+0x25a/0x2f0
[    0.006062]  [<c05ef270>] ? unknown_bootoption+0x0/0x210
[    0.006159]  [<c05ef07c>] ? __init_begin+0x7c/0xb0
[    0.006260] ---[ end trace 4eaa2a86a8e2da22 ]---
[    0.016003] OK.
[    0.016538] ACPI: Core revision 20080926

>>
>> I'm seeing this warning early in boot logs. It does not appear on 2.6.28-rc7.
>> Not sure how long it's been around. Haven't built -next for some time.
>>
>> [    0.004000] Intel machine check reporting enabled on CPU#0.
>> [    0.004000] using mwait in idle threads.
>> [    0.004000] Checking 'hlt' instruction... <4>------------[ cut here
>> ]------------
>> [    0.004167] WARNING: at kernel/sched.c:4364 sub_preempt_count+0xae/0xc0()
>> [    0.004266] Hardware name: HP Compaq nx7300 (GB848ES#ACB)
>> [    0.004361] Modules linked in:
>> [    0.004497] Pid: 0, comm: swapper Not tainted 2.6.28-rc8-next-20081211 #117
>> [    0.004595] Call Trace:
>> [    0.004689]  [<c01324d6>] warn_slowpath+0x86/0xa0
>> [    0.004789]  [<c0155d00>] ? check_usage_forwards+0x10/0xb0
>> [    0.004886]  [<c015394a>] ? save_trace+0x3a/0xa0
>> [    0.004981]  [<c015742d>] ? mark_lock+0x37d/0xe00
>> [    0.005076]  [<c01580f9>] ? __lock_acquire+0x249/0x610
>> [    0.005175]  [<c04a3a02>] ? _spin_unlock_irq+0x22/0x50
>> [    0.005272]  [<c0158e50>] ? trace_hardirqs_on_caller+0x70/0x1a0
>> [    0.005369]  [<c04a3a0d>] ? _spin_unlock_irq+0x2d/0x50
>> [    0.005465]  [<c0124bfe>] sub_preempt_count+0xae/0xc0
>> [    0.005564]  [<c0137012>] _local_bh_enable+0x52/0xc0
>> [    0.005661]  [<c013725f>] __do_softirq+0x11f/0x170
>> [    0.005756]  [<c0137140>] ? __do_softirq+0x0/0x170
>> [    0.005851]  <IRQ>  [<c0137729>] ? irq_exit+0x89/0xa0
>> [    0.005993]  [<c01059ed>] ? do_IRQ+0xad/0x120
>> [    0.006088]  [<c0103aac>] ? common_interrupt+0x2c/0x34
>> [    0.006184]  [<c013007b>] ? mmput+0x2b/0xc0
>> [    0.006281]  [<c06735a8>] ? check_bugs+0xb8/0xe0
>> [    0.006379]  [<c066b7ea>] ? start_kernel+0x26a/0x310
>> [    0.006475]  [<c066b270>] ? unknown_bootoption+0x0/0x210
>> [    0.006572]  [<c066b077>] ? __init_begin+0x77/0xb0
>> [    0.006674] ---[ end trace 4eaa2a86a8e2da22 ]---
>> [    0.016004] OK.
>> [    0.016560] ACPI: Core revision 20081031
>> [    0.044495] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
>>
>> Config and full dmesg attached.
>>
>
> The warning can also be reproduced in qemu, so it was easy to bisect.
>
> commit 7317d7b87edb41a9135e30be1ec3f7ef817c53dd
> Author: Nick Piggin <nickpiggin@yahoo.com.au>
> Date:   Tue Sep 30 20:50:27 2008 +1000
>
>    sched: improve preempt debugging
>
>    This patch helped me out with a problem I recently had....
>
>    Basically, when the kernel lock is held, then preempt_count
> underflow does not
>    get detected until it is released which may be a long time (and arbitrarily,
>    eg at different points it may be rescheduled). If the bkl is released at
>    schedule, the resulting output is actually fairly cryptic...
>
>    With any other lock that elevates preempt_count, it is illegal to schedule
>    under it (which would get found pretty quickly). bkl allows scheduling with
>    preempt_count elevated, which makes underflows hard to debug.
>
>    Signed-off-by: Ingo Molnar <mingo@elte.hu>
>
> I understand that not this particular commit is buggy, but at least
> I've got someone to add to the CC. ;)