Re: "BUG: held lock freed!" lock validator tripped by kswapd & xfs

From: Stephen Pollei
Date: Fri Dec 01 2006 - 17:35:15 EST


On 12/1/06, Mike Mattie <codermattie@xxxxxxxxx> wrote:

In an attempt to debug another kernel issue I turned on the lock validator and
managed to generate this report.

As a side note the first attempt to boot with the lock validator failed with
a message indicating I had exceeded MAX_LOCK_DEPTH. To get this trace
I patched sched.h: MAX_LOCK_DEPTH to 60.

Dec 1 08:35:41 reforged [ 3052.513931] =========================
Dec 1 08:35:41 reforged [ 3052.513937] [ BUG: held lock freed! ]
Dec 1 08:35:41 reforged [ 3052.513939] -------------------------
Dec 1 08:35:41 reforged [ 3052.513943] kswapd0/183 is freeing memory
c3458000-c3458fff, with a lock still held there! Dec 1 08:35:41
reforged [ 3052.513947] (&(&ip->i_iolock)->mr_lock){....}, at:
[<c0222289>] xfs_ilock+0x20/0x75 Dec 1 08:35:41 reforged
[ 3052.513959] 28 locks held by kswapd0/183: Dec 1 08:35:41 reforged
[ 3052.513961] #0: (&(&ip->i_iolock)->mr_lock){....}, at:
[<c0222289>] xfs_ilock+0x20/0x75 Dec 1 08:35:41 reforged
[ 3052.513968] #1: (&(&ip->i_lock)->mr_lock){....}, at: [<c02222bb>]
xfs_ilock+0x52/0x75 Dec 1 08:35:41 reforged [ 3052.513975]

seems to alternate between same two locks. But both c0222289 and
c02222bb are not between the page(oxfff=4095 or about 4k) which kswapd
is trying to get rid of.
I think this trace is on crack somehow.

[ 3052.514136] stack backtrace: Dec 1 08:35:41 reforged
[ 3052.514139] [<c0103cb9>] show_trace+0x16/0x19 Dec 1 08:35:41
reforged [ 3052.514146] [<c01040f7>] dump_stack+0x1a/0x1f Dec 1
08:35:41 reforged [ 3052.514150] [<c012be74>]
debug_check_no_locks_freed+0xe0/0xff Dec 1 08:35:41 reforged
[ 3052.514159] [<c014122d>] free_hot_cold_page+0x96/0x109 Dec 1
08:35:41 reforged [ 3052.514166] [<c01412bc>] __pagevec_free+0x1c/0x27
Dec 1 08:35:41 reforged [ 3052.514170] [<c01435dc>]
__pagevec_release_nonlru+0x65/0x71 Dec 1 08:35:41 reforged
[ 3052.514176] [<c0144702>] shrink_inactive_list+0x4b1/0x722 Dec 1
08:35:41 reforged [ 3052.514181] [<c0144a2d>] shrink_zone+0xba/0xd9
Dec 1 08:35:41 reforged [ 3052.514185] [<c0144e9e>]
kswapd+0x26a/0x361 Dec 1 08:35:41 reforged [ 3052.514189]
[<c012742b>] kthread+0xb0/0xe1 Dec 1 08:35:41 reforged [ 3052.514192]
[<c0101005>] kernel_thread_helper+0x5/0xb reforged log #


Linux reforged 2.6.18.3 #4 PREEMPT Fri Dec 1 06:15:05 PST 2006 i686 AMD Athlon(tm) XP 3000+ AuthenticAMD GNU/Linux

I know you are running preempt on up machine. I'd try running 2.6.18.4
with a small patch like this and see if you can't cause it to recrash
for you. print_freed_lock_bug uses printk which in theory might be
causing a preempt .

diff -urp linux-2.6.18.4/include/linux/sched.h linux-debug/include/linux/sched.h
--- linux-2.6.18.4/include/linux/sched.h 2006-11-29
11:28:40.000000000 -0800
+++ linux-debug/include/linux/sched.h 2006-12-01 13:25:23.000000000 -0800
@@ -936,7 +936,7 @@ struct task_struct {
int softirq_context;
#endif
#ifdef CONFIG_LOCKDEP
-# define MAX_LOCK_DEPTH 30UL
+# define MAX_LOCK_DEPTH (60UL)
u64 curr_chain_key;
int lockdep_depth;
struct held_lock held_locks[MAX_LOCK_DEPTH];
diff -urp linux-2.6.18.4/kernel/lockdep.c linux-debug/kernel/lockdep.c
--- linux-2.6.18.4/kernel/lockdep.c 2006-11-29 11:28:40.000000000 -0800
+++ linux-debug/kernel/lockdep.c 2006-12-01 14:22:14.000000000 -0800
@@ -2608,6 +2608,7 @@ void debug_check_no_locks_freed(const vo
return;

local_irq_save(flags);
+ preempt_disable();
for (i = 0; i < curr->lockdep_depth; i++) {
hlock = curr->held_locks + i;

@@ -2621,6 +2622,7 @@ void debug_check_no_locks_freed(const vo
print_freed_lock_bug(curr, mem_from, mem_to, hlock);
break;
}
+ preempt_enable();
local_irq_restore(flags);
}


--
http://dmoz.org/profiles/pollei.html
http://sourceforge.net/users/stephen_pollei/
http://www.orkut.com/Profile.aspx?uid=2455954990164098214
http://stephen_pollei.home.comcast.net/
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/