On 12/1/06, Mike Mattie <[email protected]> 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/
On Fri, Dec 01, 2006 at 02:34:42PM -0800, Stephen Pollei wrote:
> On 12/1/06, Mike Mattie <[email protected]> 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.
IIRC, lockdep doesn't understand the xfs inode locks yet. We've
got a patch to fix most of this, but I don't think it's been merged.
Cheers,
Dave
--
Dave Chinner
Principal Engineer
SGI Australian Software Group