Bug 8467

Created attachment 11500 [details]
Fix for a timeout issue on lockd RPC calls

Does the above patch make a difference for you?

I'll apply it next reboot.  Is the patch valid vs. 2.6.21.x also?

Yep. It should apply to all existing 2.6.21 kernels...

I applied this patch to 2.6.20.11 last night.  I'm going on vacation in a few
days and decided to stay with the older kernel for now (in case any problems
come up while I'm gone).  As soon as people started logging in to the client
workstations this morning the problem (or a very similar one) happened again. 
This time there were a large number of kernel messages like:


lockd: server jacquere not responding, timed out
lockd: couldn't create RPC handle for jacquere
lockd: server jacquere not responding, timed out
lockd: couldn't create RPC handle for jacquere
lockd: server jacquere not responding, timed out
lockd: couldn't create RPC handle for jacquere

Was this patch not meant to work with 2.6.20.x?

It was meant to work with 2.6.20, but you appear to have an additional problem
with your setup.

Could you check the output from 'rpcinfo -t jacquere nlockmgr' and
'rpcinfo -t jacquere status'?

I should note that, although all of the log messages I saw were from the client
jacquere, locking failed (i.e. kde logins froze) on all of the clients.

$ rpcinfo -t jacquere nlockmgr
program 100021 version 1 ready and waiting
rpcinfo: RPC: Program/version mismatch; low version = 1, high version = 4
program 100021 version 2 is not available
program 100021 version 3 ready and waiting
program 100021 version 4 ready and waiting
$ rpcinfo -t jacquere status
program 100024 version 1 ready and waiting

What kernel are the clients running?

They're all running vanilla 2.6.20.11.

I'm assuming that you restarted the portmapper, nfsd, lockd and statd in the
correct order on the server? Does

rpcinfo -t localhost nlockmgr

and

rpcinfo -t localhost status

when you are on the server work too?

The server was rebooted (nothing else will fix it), so I didn't restart the
nfs/rpc stuff by hand.  Also I switched it back to vanilla 2.6.20.11 since the
patch seemed to make things worse (people have to work on the workstations).  So
everything's working fine for now.  On the server (the last rpcinfo commands
were also run on the server):

$ rpcinfo -t localhost nlockmgr
program 100021 version 1 ready and waiting
rpcinfo: RPC: Program/version mismatch; low version = 1, high version = 4
program 100021 version 2 is not available
program 100021 version 3 ready and waiting
program 100021 version 4 ready and waiting
$ rpcinfo -t localhost status
program 100024 version 1 ready and waiting

Can you please provide alt-sysrq-t trace at the time of the hang.
Thanks.

Created attachment 16060 [details]
sysrq-t trace from 2.6.23.16

Happened again this morning, I'm now running 2.6.23.16.  I had to cut and paste the sysrq-t trace off the serial console in chunks, so the line breaks are a little funny but all the data should be there.

Trond, does this look like nfs or rpc problem to you?

pdflush is trying to write out dirty pages and is in congestion_wait:
pdflush       D 0000000000000002     0  7172      2
 ffff8101974b5db0 0000000000000046 ffff810006df2668 ffff810007253dd0
 ffffffff80609480 ffff81025a4e6140 ffff81025fe507a0 ffff81025a4e6358
 0000000200000003 ffff8101974b5dc0 ffff8101974b5e20 000000011be047e8
Call Trace:
 [<ffffffff80231824>] __mod_timer+0xb6/0xc4
 [<ffffffff804b0a5e>] schedule_timeout+0x8a/0xad
 [<ffffffff802315ec>] process_timeout+0x0/0x5
 [<ffffffff804b043c>] io_schedule_timeout+0x28/0x33
 [<ffffffff80254634>] congestion_wait+0x66/0x80
 [<ffffffff8023a9cc>] autoremove_wake_function+0x0/0x2e
 [<ffffffff80282737>] writeback_inodes+0xa3/0xd3
 [<ffffffff80250135>] wb_kupdate+0xba/0x111
 [<ffffffff8025042a>] pdflush+0x0/0x1ce
 [<ffffffff8025054e>] pdflush+0x124/0x1ce
 [<ffffffff8025007b>] wb_kupdate+0x0/0x111
 [<ffffffff8023a8bc>] kthread+0x47/0x73
 [<ffffffff8020c358>] child_rip+0xa/0x12
 [<ffffffff8023a875>] kthread+0x0/0x73
 [<ffffffff8020c34e>] child_rip+0x0/0x12

There is also ext3 journaling thread who's stuck trying to commit transactions:

kjournald     D 0000000000000000     0  1165      2
 ffff81025ff27d30 0000000000000046 0000000000000000 ffffffff80231824
 0000000000000287 ffff81025fe927a0 ffffffff805a43c0 ffff81025fe929b8
 000000005f74d358 ffffffff805a43c0 00000000000000ff ffffffff802f7034
Call Trace:

 [<ffffffff80231824>] __mod_timer+0xb6/0xc4
 [<ffffffff802f7034>] elv_next_request+0x139/0x149
 [<ffffffff802864d5>] sync_buffer+0x0/0x40
 [<ffffffff804b06a0>] io_schedule+0x28/0x33
 [<ffffffff80286510>] sync_buffer+0x3b/0x40
 [<ffffffff804b0bc9>] __wait_on_bit+0x40/0x6e
 [<ffffffff802864d5>] sync_buffer+0x0/0x40
 [<ffffffff804b0c63>] out_of_line_wait_on_bit+0x6c/0x78
 [<ffffffff8023a9fa>] wake_bit_function+0x0/0x23
 [<ffffffff802b40c2>] journal_commit_transaction+0x550/0xff6
 [<ffffffff802316d9>] lock_timer_base+0x26/0x4b
 [<ffffffff802b79b4>] kjournald+0xc3/0x1e6
 [<ffffffff8023a9cc>] autoremove_wake_function+0x0/0x2e
 [<ffffffff802b78f1>] kjournald+0x0/0x1e6
 [<ffffffff8023a8bc>] kthread+0x47/0x73
 [<ffffffff8020c358>] child_rip+0xa/0x12
 [<ffffffff8023a875>] kthread+0x0/0x73
 [<ffffffff8020c34e>] child_rip+0x0/0x12

You should check if system is out of memory, with /proc/meminfo and top or vmstat output.

Some tuning seems to be needed, such as pdflush tunables in /proc/sys/vm, and for ext3 journaling. Chris, correct me if i'm wrong..

...Ryan, you should also try latest kernel, 2.6.23 is really old.

(In reply to comment #14)
> You should check if system is out of memory, with /proc/meminfo and top or
> vmstat output.

Just happened again, same old kernel I'm afraid.  I'll update the kernel soon.  Here's /proc/meminfo, which looks pretty typical for this machine:

MemTotal:      8163412 kB
MemFree:         51144 kB
Buffers:       1102236 kB
Cached:        5371748 kB
SwapCached:          0 kB
Active:        1039308 kB
Inactive:      5562868 kB
SwapTotal:     3960012 kB
SwapFree:      3959972 kB
Dirty:             232 kB
Writeback:           0 kB
AnonPages:      128196 kB
Mapped:          54420 kB
Slab:          1478300 kB
SReclaimable:  1378988 kB
SUnreclaim:      99312 kB
PageTables:       5884 kB
NFS_Unstable:        0 kB
Bounce:              0 kB
CommitLimit:   8041716 kB
Committed_AS:   227260 kB
VmallocTotal: 34359738367 kB
VmallocUsed:      2932 kB
VmallocChunk: 34359735411 kB

The backtraces shows a number of processes stuck in __mod_timer()

__mod_timer calls into lock_timer_base which looks suspiciously complex.

Could you enable lockdep and run the tests again?