linux-kernel - inconsistent lock state message on 2.6.36.4 stable release

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Date:	Wed, 2 Mar 2011 13:19:48 -0700
From:	"Nadolski, Edmund" <edmund.nadolski@...el.com>
To:	"linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>
CC:	"Williams, Dan J" <dan.j.williams@...el.com>,
	"mel@....ul.ie" <mel@....ul.ie>, "gregkh@...e.de" <gregkh@...e.de>
Subject: inconsistent lock state message on 2.6.36.4 stable release

With v2.6.36.4 stable release and CONFIG_PROVE_LOCKING set, I notice the below message during boot (full dmesg attached):

...
[    7.201343] =================================
[    7.201344] [ INFO: inconsistent lock state ]
[    7.201345] 2.6.36.4 #2
[    7.201346] ---------------------------------
[    7.201347] inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage.
[    7.201349] kswapd1/94 [HC0[0]:SC0[0]:HE1:SE1] takes:
[    7.201350]  (cpu_hotplug.lock){+.+.?.}, at: [<ffffffff81061f4e>] get_online_cpus+0x2e/0x50
[    7.201356] {RECLAIM_FS-ON-W} state was registered at:
[    7.201357]   [<ffffffff81097b8c>] mark_held_locks+0x6c/0xa0
[    7.201361]   [<ffffffff81097c61>] lockdep_trace_alloc+0xa1/0xe0
[    7.201363]   [<ffffffff811433f1>] kmem_cache_alloc+0x41/0x180
[    7.201366]   [<ffffffff812c0b60>] idr_pre_get+0x60/0x90
[    7.201369]   [<ffffffff812c0bb3>] ida_pre_get+0x23/0xe0
[    7.201371]   [<ffffffff8107d435>] create_worker+0x55/0x190
[    7.201374]   [<ffffffff8156972a>] workqueue_cpu_callback+0xb9/0x232
[    7.201377]   [<ffffffff81582b46>] notifier_call_chain+0x56/0x80
[    7.201381]   [<ffffffff8108828e>] __raw_notifier_call_chain+0xe/0x10
[    7.201384]   [<ffffffff81061dc0>] __cpu_notify+0x20/0x40
[    7.201385]   [<ffffffff815787f3>] _cpu_up+0x73/0x113
[    7.201388]   [<ffffffff815788e4>] cpu_up+0x51/0x61
[    7.201389]   [<ffffffff81acf6d7>] kernel_init+0xc9/0x1e8
[    7.201393]   [<ffffffff8100bf24>] kernel_thread_helper+0x4/0x10
[    7.201396] irq event stamp: 33
[    7.201396] hardirqs last  enabled at (33): [<ffffffff8157e9d0>] _raw_spin_unlock_irqrestore+0x40/0x70
[    7.201400] hardirqs last disabled at (32): [<ffffffff8157e2ce>] _raw_spin_lock_irqsave+0x2e/0x70
[    7.201402] softirqs last  enabled at (0): [<ffffffff8105e4f3>] copy_process+0x5c3/0x1310
[    7.201404] softirqs last disabled at (0): [<(null)>] (null)
[    7.201405] 
[    7.201405] other info that might help us debug this:
[    7.201406] no locks held by kswapd1/94.
[    7.201407] 
[    7.201407] stack backtrace:
[    7.201409] Pid: 94, comm: kswapd1 Not tainted 2.6.36.4 #2
[    7.201410] Call Trace:
[    7.201412]  [<ffffffff81096c2a>] print_usage_bug+0x18a/0x190
[    7.201415]  [<ffffffff81018b0f>] ? save_stack_trace+0x2f/0x50
[    7.201417]  [<ffffffff81096f90>] ? check_usage_forwards+0x0/0x100
[    7.201419]  [<ffffffff81097a54>] mark_lock+0x344/0x410
[    7.201421]  [<ffffffff810985e1>] __lock_acquire+0x431/0x14c0
[    7.201424]  [<ffffffff8106f67c>] ? lock_timer_base+0x3c/0x70
[    7.201427]  [<ffffffff812cf884>] ? do_raw_spin_lock+0x54/0x150
[    7.201429]  [<ffffffff81099710>] lock_acquire+0xa0/0x150
[    7.201430]  [<ffffffff81061f4e>] ? get_online_cpus+0x2e/0x50
[    7.201432]  [<ffffffff8157c8d7>] __mutex_lock_common+0x47/0x3d0
[    7.201434]  [<ffffffff81061f4e>] ? get_online_cpus+0x2e/0x50
[    7.201436]  [<ffffffff81061f4e>] ? get_online_cpus+0x2e/0x50
[    7.201438]  [<ffffffff8108290a>] ? prepare_to_wait+0x2a/0x90
[    7.201440]  [<ffffffff812cf884>] ? do_raw_spin_lock+0x54/0x150
[    7.201442]  [<ffffffff812cf884>] ? do_raw_spin_lock+0x54/0x150
[    7.201444]  [<ffffffff8157e9d0>] ? _raw_spin_unlock_irqrestore+0x40/0x70
[    7.201445]  [<ffffffff8157cd15>] mutex_lock_nested+0x35/0x40
[    7.201447]  [<ffffffff81061f4e>] get_online_cpus+0x2e/0x50
[    7.201450]  [<ffffffff81118d8e>] restore_pgdat_percpu_threshold+0x1e/0x110
[    7.201453]  [<ffffffff8111051f>] kswapd+0x34f/0x410
[    7.201455]  [<ffffffff81082690>] ? autoremove_wake_function+0x0/0x40
[    7.201456]  [<ffffffff811101d0>] ? kswapd+0x0/0x410
[    7.201458]  [<ffffffff81082126>] kthread+0xa6/0xb0
[    7.201460]  [<ffffffff8100bf24>] kernel_thread_helper+0x4/0x10
[    7.201462]  [<ffffffff8157eed0>] ? restore_args+0x0/0x30
[    7.201464]  [<ffffffff81082080>] ? kthread+0x0/0xb0
[    7.201465]  [<ffffffff8100bf20>] ? kernel_thread_helper+0x0/0x10
[    7.582914] pcieport 0000:00:1c.5: setting latency timer to 64
[    7.589538]   alloc irq_desc for 69 on node -1
[    7.594577]   alloc kstat_irqs on node -1
[    7.599139] pcieport 0000:00:1c.5: irq 69 for MSI/MSI-X
...


Per git bisect, it seems to have originated with this commit:

$ git bisect good
c04eb9683fbb6374275309b859fcbf02e1db2c78 is the first bad commit
commit c04eb9683fbb6374275309b859fcbf02e1db2c78
Author: Mel Gorman <mel@....ul.ie>
Date:   Thu Jan 13 15:45:41 2011 -0800

    mm: page allocator: adjust the per-cpu counter threshold when memory is low

    commit 88f5acf88ae6a9778f6d25d0d5d7ec2d57764a97 upstream.

The message goes away after I do a git revert on this commit. I've also seen this message on 2.6.37.2, but not on 2.6.38-rc7.

Regards,
Ed Nadolski
edmund.nadolski@...el.com







Download attachment "dmesg.2.6.36.4" of type "application/octet-stream" (79408 bytes)