BUG: unable to handle kernel paging request at virtual address 6b6b6b6f

DISCUSSION Frank van Maarseveen 2 participants 5 messages Jul 3, 2007 – Jul 16, 2007

Subsystems (2)

NFS client NFS server

lore

Share & tools

lore

Frank van Maarseveen

author

2007-07-03 07:17 UTC #0 lore raw

I've reported this earlier but now I figured out how to reproduce it:
start nfsd with 50 instances and then try to stop it.

Jul  3 09:10:39 kernel: BUG: unable to handle kernel paging request at virtual address 6b6b6b6f
Jul  3 09:10:39 kernel:  printing eip:
Jul  3 09:10:39 kernel: c053f594
Jul  3 09:10:39 kernel: *pde = 00000000
Jul  3 09:10:39 kernel: Oops: 0000 [#1]
Jul  3 09:10:39 kernel: SMP
Jul  3 09:10:39 kernel: Modules linked in: vmthrottle
Jul  3 09:10:39 kernel: CPU:    1
Jul  3 09:10:39 kernel: EIP:    0060:[<c053f594>]    Not tainted VLI
Jul  3 09:10:39 kernel: EFLAGS: 00010202   (2.6.21.5-x160 #1)
Jul  3 09:10:39 kernel: EIP is at cache_clean+0x124/0x1e0
Jul  3 09:10:39 kernel: eax: 00000000   ebx: 6b6b6b6b   ecx: c06dffa0   edx: c0a1f380
Jul  3 09:10:39 kernel: esi: f672d800   edi: 00000000   ebp: f5a11f40   esp: f5a11f34
Jul  3 09:10:39 kernel: ds: 007b   es: 007b   fs: 00d8  gs: 0000  ss: 0068
Jul  3 09:10:39 kernel: Process nfsd (pid: 4420, ti=f5a10000 task=f596c070 task.ti=f5a10000)
Jul  3 09:10:39 kernel: Stack: c06dffa0 f6a3c268 f6a3c234 f5a11f48 c053f69f f5a11f54 c053f6da f6a3c260
Jul  3 09:10:39 kernel:        f5a11f5c c020ef47 f5a11f70 c0205632 c06597c8 f6a3c268 f6a3c7ac f5a11f94
Jul  3 09:10:39 kernel:        c0537b23 f59b2000 f5a11f94 00000286 f6a3c270 f59b2000 f6a3c7ac f6a3c234
Jul  3 09:10:39 kernel: Call Trace:
Jul  3 09:10:39 kernel:  [<c01054a9>] show_trace_log_lvl+0x19/0x30
Jul  3 09:10:39 kernel:  [<c010556b>] show_stack_log_lvl+0x8b/0xb0
Jul  3 09:10:39 kernel:  [<c01057c6>] show_registers+0x1e6/0x310
Jul  3 09:10:39 kernel:  [<c0105a4f>] die+0x10f/0x240
Jul  3 09:10:39 kernel:  [<c0115f82>] do_page_fault+0x342/0x610
Jul  3 09:10:39 kernel:  [<c054d1ac>] error_code+0x7c/0x90
Jul  3 09:10:39 kernel:  [<c053f69f>] cache_flush+0xf/0x30
Jul  3 09:10:39 kernel:  [<c053f6da>] cache_purge+0x1a/0x30
Jul  3 09:10:39 kernel:  [<c020ef47>] nfsd_export_flush+0x17/0x30
Jul  3 09:10:39 kernel:  [<c0205632>] nfsd_last_thread+0x72/0x80
Jul  3 09:10:39 kernel:  [<c0537b23>] svc_destroy+0x103/0x140
Jul  3 09:10:39 kernel:  [<c0537fca>] svc_exit_thread+0x8a/0x90
Jul  3 09:10:39 kernel:  [<c0205ceb>] nfsd+0x24b/0x2a0
Jul  3 09:10:39 kernel:  [<c0105317>] kernel_thread_helper+0x7/0x10
Jul  3 09:10:39 kernel:  =======================
Jul  3 09:10:39 kernel: Code: c0 8b 51 08 8d 34 82 8b 1e 85 db 75 1e eb 64 8b 0d 88 a6 a4 c0 8b 41 50 39 43 08 7c 25 89 de 8b 1b 85 db 74 4e 8b 0d 88 a6 a4 c0 <8b> 43 04 39 41 5c 7e 07 40 89 41 5c 8b 43 04 3b 05 00 4e 7f c0
Jul  3 09:10:39 kernel: EIP: [<c053f594>] cache_clean+0x124/0x1e0 SS:ESP 0068:f5a11f34
Jul  3 09:10:48 kernel: BUG: soft lockup detected on CPU#1!
Jul  3 09:10:48 kernel:  [<c01054a9>] show_trace_log_lvl+0x19/0x30
Jul  3 09:10:48 kernel:  [<c01054d2>] show_trace+0x12/0x20
Jul  3 09:10:48 kernel:  [<c01055d4>] dump_stack+0x14/0x20
Jul  3 09:10:48 kernel:  [<c014a8e2>] softlockup_tick+0xa2/0xc0
Jul  3 09:10:48 kernel:  [<c012bf02>] run_local_timers+0x12/0x20
Jul  3 09:10:48 kernel:  [<c012bd1d>] update_process_times+0x5d/0x90
Jul  3 09:10:48 kernel:  [<c013da4c>] tick_sched_timer+0x5c/0xd0
Jul  3 09:10:48 kernel:  [<c01393f7>] hrtimer_interrupt+0x177/0x1e0
Jul  3 09:10:48 kernel:  [<c010fb07>] local_apic_timer_interrupt+0x57/0x60
Jul  3 09:10:48 kernel:  [<c010fb33>] smp_apic_timer_interrupt+0x23/0x40
Jul  3 09:10:48 kernel:  [<c0105158>] apic_timer_interrupt+0x28/0x30
Jul  3 09:10:48 kernel:  [<c02944e9>] __delay+0x9/0x10
Jul  3 09:10:48 kernel:  [<c0296315>] __spin_lock_debug+0x55/0xd0
Jul  3 09:10:48 kernel:  [<c02963e5>] _raw_spin_lock+0x55/0x80
Jul  3 09:10:48 kernel:  [<c054cce2>] _spin_lock+0x32/0x40
Jul  3 09:10:48 kernel:  [<c053f482>] cache_clean+0x12/0x1e0
Jul  3 09:10:48 kernel:  [<c053f69f>] cache_flush+0xf/0x30
Jul  3 09:10:48 kernel:  [<c0540925>] write_flush+0x95/0xb0
Jul  3 09:10:48 kernel:  [<c016e836>] vfs_write+0x86/0x130
Jul  3 09:10:48 kernel:  [<c016e98d>] sys_write+0x3d/0x70
Jul  3 09:10:48 kernel:  [<c0104120>] syscall_call+0x7/0xb
Jul  3 09:10:48 kernel:  =======================

Signature · 10 lines

Frank

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist  -  [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

J. Bruce Fields

2007-07-03 19:39 UTC #1 lore raw

Quoted 2 lines · Frank van Maarseveen

I've reported this earlier but now I figured out how to reproduce it:
start nfsd with 50 instances and then try to stop it.

So, all it takes is this?:

	rpc.nfsd 50
	rpc.nfsd 0

Quoted 8 lines

Jul  3 09:10:39 kernel: BUG: unable to handle kernel paging request at virtual address 6b6b6b6f
Jul  3 09:10:39 kernel:  printing eip:
Jul  3 09:10:39 kernel: c053f594
Jul  3 09:10:39 kernel: *pde = 00000000
Jul  3 09:10:39 kernel: Oops: 0000 [#1]
Jul  3 09:10:39 kernel: SMP
Jul  3 09:10:39 kernel: Modules linked in: vmthrottle

What's vmthrottle, by the way?

Quoted 13 lines

Jul  3 09:10:39 kernel: CPU:    1
Jul  3 09:10:39 kernel: EIP:    0060:[<c053f594>]    Not tainted VLI
Jul  3 09:10:39 kernel: EFLAGS: 00010202   (2.6.21.5-x160 #1)
Jul  3 09:10:39 kernel: EIP is at cache_clean+0x124/0x1e0
Jul  3 09:10:39 kernel: eax: 00000000   ebx: 6b6b6b6b   ecx: c06dffa0   edx: c0a1f380
Jul  3 09:10:39 kernel: esi: f672d800   edi: 00000000   ebp: f5a11f40   esp: f5a11f34
Jul  3 09:10:39 kernel: ds: 007b   es: 007b   fs: 00d8  gs: 0000  ss: 0068
Jul  3 09:10:39 kernel: Process nfsd (pid: 4420, ti=f5a10000 task=f596c070 task.ti=f5a10000)
Jul  3 09:10:39 kernel: Stack: c06dffa0 f6a3c268 f6a3c234 f5a11f48 c053f69f f5a11f54 c053f6da f6a3c260
Jul  3 09:10:39 kernel:        f5a11f5c c020ef47 f5a11f70 c0205632 c06597c8 f6a3c268 f6a3c7ac f5a11f94
Jul  3 09:10:39 kernel:        c0537b23 f59b2000 f5a11f94 00000286 f6a3c270 f59b2000 f6a3c7ac f6a3c234
Jul  3 09:10:39 kernel: Call Trace:
Jul  3 09:10:39 kernel:  [<c01054a9>] show_trace_log_lvl+0x19/0x30

Quoted 8 lines

Jul  3 09:10:39 kernel:  [<c010556b>] show_stack_log_lvl+0x8b/0xb0
Jul  3 09:10:39 kernel:  [<c01057c6>] show_registers+0x1e6/0x310
Jul  3 09:10:39 kernel:  [<c0105a4f>] die+0x10f/0x240
Jul  3 09:10:39 kernel:  [<c0115f82>] do_page_fault+0x342/0x610
Jul  3 09:10:39 kernel:  [<c054d1ac>] error_code+0x7c/0x90
Jul  3 09:10:39 kernel:  [<c053f69f>] cache_flush+0xf/0x30
Jul  3 09:10:39 kernel:  [<c053f6da>] cache_purge+0x1a/0x30
Jul  3 09:10:39 kernel:  [<c020ef47>] nfsd_export_flush+0x17/0x30

So I guess the nfsd export cache is corrupted somehow.

Perhaps turning on more debugging options in the kernel config would help catch the problem earlier. I'm not having any luck reproducing this now.

--b.

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Frank van Maarseveen

author

2007-07-03 20:22 UTC #2 lore raw

Quoted 8 lines · J. Bruce Fields

Quoted 2 lines · Frank van Maarseveen
I've reported this earlier but now I figured out how to reproduce it:
start nfsd with 50 instances and then try to stop it.
So, all it takes is this?:
	rpc.nfsd 50
	rpc.nfsd 0

I guess so: On debian etch I adapted /etc/defaults/nfs-kernel-server (IIRC) to start 50 daemons and after a reboot it sufficed to type /etc/init.d/nfs-kernel-server stop to make it say BUG. Very reproducable here (5 machines).

Quoted 11 lines

Quoted 9 lines


Jul  3 09:10:39 kernel: BUG: unable to handle kernel paging request at virtual address 6b6b6b6f
Jul  3 09:10:39 kernel:  printing eip:
Jul  3 09:10:39 kernel: c053f594
Jul  3 09:10:39 kernel: *pde = 00000000
Jul  3 09:10:39 kernel: Oops: 0000 [#1]
Jul  3 09:10:39 kernel: SMP
Jul  3 09:10:39 kernel: Modules linked in: vmthrottle

What's vmthrottle, by the way?

That's a custom module to kill memory hungry processes when the uid doesn't match the one running the X server (basically). That way 40-50 workstations for software development can also participate in distributed compiler testing without interfering too much. An unpatched and moduleless kernel still crashes.

Quoted 23 lines

Quoted 14 lines

Jul  3 09:10:39 kernel: CPU:    1
Jul  3 09:10:39 kernel: EIP:    0060:[<c053f594>]    Not tainted VLI
Jul  3 09:10:39 kernel: EFLAGS: 00010202   (2.6.21.5-x160 #1)
Jul  3 09:10:39 kernel: EIP is at cache_clean+0x124/0x1e0
Jul  3 09:10:39 kernel: eax: 00000000   ebx: 6b6b6b6b   ecx: c06dffa0   edx: c0a1f380
Jul  3 09:10:39 kernel: esi: f672d800   edi: 00000000   ebp: f5a11f40   esp: f5a11f34
Jul  3 09:10:39 kernel: ds: 007b   es: 007b   fs: 00d8  gs: 0000  ss: 0068
Jul  3 09:10:39 kernel: Process nfsd (pid: 4420, ti=f5a10000 task=f596c070 task.ti=f5a10000)
Jul  3 09:10:39 kernel: Stack: c06dffa0 f6a3c268 f6a3c234 f5a11f48 c053f69f f5a11f54 c053f6da f6a3c260
Jul  3 09:10:39 kernel:        f5a11f5c c020ef47 f5a11f70 c0205632 c06597c8 f6a3c268 f6a3c7ac f5a11f94
Jul  3 09:10:39 kernel:        c0537b23 f59b2000 f5a11f94 00000286 f6a3c270 f59b2000 f6a3c7ac f6a3c234
Jul  3 09:10:39 kernel: Call Trace:
Jul  3 09:10:39 kernel:  [<c01054a9>] show_trace_log_lvl+0x19/0x30

Quoted 8 lines

Jul  3 09:10:39 kernel:  [<c010556b>] show_stack_log_lvl+0x8b/0xb0
Jul  3 09:10:39 kernel:  [<c01057c6>] show_registers+0x1e6/0x310
Jul  3 09:10:39 kernel:  [<c0105a4f>] die+0x10f/0x240
Jul  3 09:10:39 kernel:  [<c0115f82>] do_page_fault+0x342/0x610
Jul  3 09:10:39 kernel:  [<c054d1ac>] error_code+0x7c/0x90
Jul  3 09:10:39 kernel:  [<c053f69f>] cache_flush+0xf/0x30
Jul  3 09:10:39 kernel:  [<c053f6da>] cache_purge+0x1a/0x30
Jul  3 09:10:39 kernel:  [<c020ef47>] nfsd_export_flush+0x17/0x30

Quoted 5 lines

So I guess the nfsd export cache is corrupted somehow.
Perhaps turning on more debugging options in the kernel config would help catch the problem earlier. I'm not having any luck reproducing this now.

Hmm, 6b6b6b6b looks like a poison to me and I have some debugging options on:

CONFIG_DEBUG_KERNEL=y
CONFIG_SLAB=y
CONFIG_DEBUG_SLAB=y
CONFIG_DETECT_SOFTLOCKUP=y
CONFIG_DEBUG_SPINLOCK=y
CONFIG_DEBUG_MUTEXES=y
CONFIG_DEBUG_LOCK_ALLOC=y
CONFIG_DEBUG_SPINLOCK_SLEEP=y
CONFIG_DEBUG_BUGVERBOSE=y
CONFIG_DEBUG_STACKOVERFLOW=y

Full config: http://www.frankvm.com/tmp/dot-config-cachebug

Signature · 10 lines

Frank

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist  -  [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

J. Bruce Fields

2007-07-14 03:07 UTC #3 lore raw

Quoted 7 lines · Frank van Maarseveen

Quoted 6 lines · J. Bruce Fields
Quoted 2 lines · Frank van Maarseveen
I've reported this earlier but now I figured out how to reproduce it:
start nfsd with 50 instances and then try to stop it.
So, all it takes is this?:

Quoted 7 lines

Quoted 2 lines
	rpc.nfsd 50
	rpc.nfsd 0
I guess so: On debian etch I adapted /etc/defaults/nfs-kernel-server (IIRC) to start 50 daemons and after a reboot it sufficed to type /etc/init.d/nfs-kernel-server stop to make it say BUG. Very reproducable here (5 machines).

Could you try this?

--b.

Quoted 1 line

From b941e6b14f6cf53c6dea17cfb80c5619304afe99 Mon Sep 17 00:00:00 2001

From: J. Bruce Fields <[email protected]>
Date: Thu, 12 Jul 2007 22:17:34 -0400
Subject: [PATCH] nfsd: fix possible read-ahead cache and export table corruption

The value of nperbucket calculated here is too small--we should be rounding up instead of down--with the result that the index j in the following loop can overflow the raparm_hash array. At least in my case, the next thing in memory turns out to be export_table, so the symptoms I see are crashes caused by the appearance of four zeroed-out export entries in the first bucket of the hash table of exports (which were actually entries in the readahead cache, a pointer to which had been written to the export table in this initialization code).

It looks like the bug was probably introduced with commit fce1456a19f5c08b688c29f00ef90fdfa074c79b ("knfsd: make the readahead params cache SMP-friendly").

Cc Greg Banks <[email protected]>

Signed-off-by "J. Bruce Fields" <[email protected]>

---
 fs/nfsd/vfs.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

fs/nfsd/vfs.c +1 -1

index 7e50da0..dd3604e 100644
@@ -1885,7 +1885,7 @@ nfsd_racache_init(int cache_size)
 		raparm_hash[i].pb_head = NULL;
 		spin_lock_init(&raparm_hash[i].pb_lock);
 	}
-	nperbucket = cache_size >> RAPARM_HASH_BITS;
+	nperbucket = DIV_ROUND_UP(cache_size, RAPARM_HASH_SIZE);
 	for (i = 0; i < cache_size - 1; i++) {
 		if (i % nperbucket == 0)
 			raparm_hash[j++].pb_head = raparml + i;

Signature · 11 lines

1.5.3.rc0.63.gc956


-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist  -  [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Frank van Maarseveen

author

2007-07-16 12:19 UTC #4 lore raw

Quoted 59 lines · J. Bruce Fields

Quoted 7 lines · Frank van Maarseveen
Quoted 6 lines · J. Bruce Fields
Quoted 2 lines · Frank van Maarseveen
I've reported this earlier but now I figured out how to reproduce it:
start nfsd with 50 instances and then try to stop it.
So, all it takes is this?:
Quoted 7 lines
Quoted 2 lines
	rpc.nfsd 50
	rpc.nfsd 0
I guess so: On debian etch I adapted /etc/defaults/nfs-kernel-server (IIRC) to start 50 daemons and after a reboot it sufficed to type /etc/init.d/nfs-kernel-server stop to make it say BUG. Very reproducable here (5 machines).
Could you try this?
--b.
Quoted 1 line
From b941e6b14f6cf53c6dea17cfb80c5619304afe99 Mon Sep 17 00:00:00 2001
From: J. Bruce Fields <[email protected]>
Date: Thu, 12 Jul 2007 22:17:34 -0400
Subject: [PATCH] nfsd: fix possible read-ahead cache and export table corruption
The value of nperbucket calculated here is too small--we should be rounding up instead of down--with the result that the index j in the following loop can overflow the raparm_hash array. At least in my case, the next thing in memory turns out to be export_table, so the symptoms I see are crashes caused by the appearance of four zeroed-out export entries in the first bucket of the hash table of exports (which were actually entries in the readahead cache, a pointer to which had been written to the export table in this initialization code).
It looks like the bug was probably introduced with commit fce1456a19f5c08b688c29f00ef90fdfa074c79b ("knfsd: make the readahead params cache SMP-friendly").
Cc Greg Banks <[email protected]>
Signed-off-by "J. Bruce Fields" <[email protected]>
---
 fs/nfsd/vfs.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)
fs/nfsd/vfs.c +1 -1
index 7e50da0..dd3604e 100644
@@ -1885,7 +1885,7 @@ nfsd_racache_init(int cache_size)
 		raparm_hash[i].pb_head = NULL;
 		spin_lock_init(&raparm_hash[i].pb_lock);
 	}
-	nperbucket = cache_size >> RAPARM_HASH_BITS;
+	nperbucket = DIV_ROUND_UP(cache_size, RAPARM_HASH_SIZE);
 	for (i = 0; i < cache_size - 1; i++) {
 		if (i % nperbucket == 0)
 			raparm_hash[j++].pb_head = raparml + i;
Signature · 1 line
1.5.3.rc0.63.gc956

Yes, that fixes it for me. I chose 50 daemons just because the server has about 50 clients and for one time I wanted to think instead of picking a random power of two. I should have known better ;-)

Signature · 10 lines

Frank

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist  -  [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs