Return-Path: <linux-nfs-owner@vger.kernel.org>
Received: from vms173001pub.verizon.net ([206.46.173.1]:37269 "EHLO
	vms173001pub.verizon.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
	with ESMTP id S1753086Ab0EUVbs (ORCPT
	<rfc822;linux-nfs@vger.kernel.org>); Fri, 21 May 2010 17:31:48 -0400
Received: from backoffice.bplinux.com ([unknown] [98.118.141.73])
 by vms173001.mailsrvcs.net
 (Sun Java(tm) System Messaging Server 7u2-7.02 32bit (built Apr 16 2009))
 with ESMTPA id <0L2S007AZH482MD5@vms173001.mailsrvcs.net> for
 linux-nfs@vger.kernel.org; Fri, 21 May 2010 16:31:25 -0500 (CDT)
Date: Fri, 21 May 2010 17:24:50 -0400 (EDT)
From: Christopher Hawkins <chawkins@bplinux.com>
To: "J. Bruce Fields" <bfields@fieldses.org>
Cc: linux-nfs@vger.kernel.org
Message-id: <29552358.871274477090274.JavaMail.javamailuser@localhost>
In-reply-to: <23795442.851274476971674.JavaMail.javamailuser@localhost>
Subject: Re: nfs4 hang
Content-type: text/plain; charset=utf-8
Sender: linux-nfs-owner@vger.kernel.org
List-ID: <linux-nfs.vger.kernel.org>
MIME-Version: 1.0

I managed to make it go a little further and now the nodes will finish booting, though they hang when I start other nodes and start using files. And this was captured in the syslog from one of the nodes where nfs4 goes unresponsive. Not familiar enough with nfs4 to read it, however. Does this point to a culprit?

It's as if the nodes are writing all over each others connections, like maybe I have a shared directory where each node must have its own private directory. They each have their own /var/lib and /var/lib/nfs/rpc_pipefs mounted. Anything else that nfs clients write to (aside from proc and dev)?

May 21 17:13:45 192.168.1.243 kernel: INFO: task rpciod/0:1297 blocked for more than 120 seconds.
May 21 17:13:45 192.168.1.243 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 21 17:13:45 192.168.1.243 kernel: rpciod/0      D 00000097  2580  1297      7          1306   340 (L-TLB)
May 21 17:13:45 192.168.1.243 kernel:        de89de40 00000046 1dfa3ac0 00000097 de8ca3b4 c1984c78 00000001 0000000a
May 21 17:13:45 192.168.1.243 kernel:        de8ce000 1dfa3ac0 00000097 00000000 00000000 de8ce10c c1787100 f54ebac0
May 21 17:13:45 192.168.1.243 kernel:        c041ebcc 00000000 00000000 00000003 00000296 c1984b00 c17875bc de89de68
May 21 17:13:45 192.168.1.243 kernel: Call Trace:
May 21 17:13:45 192.168.1.243 kernel:  [<c041ebcc>] __wake_up+0x2a/0x3d
May 21 17:13:45 192.168.1.243 kernel:  [<f8916155>] rpc_queue_upcall+0x92/0x99 [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<f8992b04>] nfs_idmap_id+0x18b/0x1f6 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<c041f7a7>] default_wake_function+0x0/0xc
May 21 17:13:45 192.168.1.243 kernel:  [<f8992ba9>] nfs_map_name_to_uid+0x1b/0x1f [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f898d719>] decode_getfattr+0x611/0xbbd [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f898c0bd>] decode_open+0xf3/0x25e [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f898e47c>] decode_getfh+0x61/0xa3 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f898e4be>] nfs4_xdr_dec_open+0x0/0xa2 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f898e533>] nfs4_xdr_dec_open+0x75/0xa2 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f890e755>] rpcauth_unwrap_resp+0x5b/0x60 [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<f89097e9>] call_decode+0x437/0x47d [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<f898e4be>] nfs4_xdr_dec_open+0x0/0xa2 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f890df54>] __rpc_execute+0x7a/0x1f8 [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<c0433276>] run_workqueue+0x78/0xb5
May 21 17:13:45 192.168.1.243 kernel:  [<f890e0d2>] rpc_async_schedule+0x0/0x5 [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<c0433b2a>] worker_thread+0xd9/0x10b
May 21 17:13:45 192.168.1.243 kernel:  [<c041f7a7>] default_wake_function+0x0/0xc
May 21 17:13:45 192.168.1.243 kernel:  [<c0433a51>] worker_thread+0x0/0x10b
May 21 17:13:45 192.168.1.243 kernel:  [<c0435f43>] kthread+0xc0/0xed
May 21 17:13:45 192.168.1.243 kernel:  [<c0435e83>] kthread+0x0/0xed
May 21 17:13:45 192.168.1.243 kernel:  [<c0405c53>] kernel_thread_helper+0x7/0x10
May 21 17:13:45 192.168.1.243 kernel:  =======================
May 21 17:13:45 192.168.1.243 kernel: INFO: task java:13420 blocked for more than 120 seconds.
May 21 17:13:45 192.168.1.243 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 21 17:13:45 192.168.1.243 kernel: java          D 00000098  2068 13420      1         13421 13386 (NOTLB)
May 21 17:13:45 192.168.1.243 kernel:        f6bbfab0 00000086 ada06900 00000098 00000000 c06ba340 dfc6d280 0000000a
May 21 17:13:45 192.168.1.243 kernel:        f5781000 ada06900 00000098 00000000 00000000 f578110c c1787100 f649d3c0
May 21 17:13:45 192.168.1.243 kernel:        00000098 00000000 de7c6804 c1787100 de7c6800 f6bbfb1c c04ec500 ffffffff
May 21 17:13:45 192.168.1.243 kernel: Call Trace:
May 21 17:13:45 192.168.1.243 kernel:  [<c04ec500>] __next_cpu+0x12/0x21
May 21 17:13:45 192.168.1.243 kernel:  [<c061cf25>] __mutex_lock_slowpath+0x4d/0x7c
May 21 17:13:45 192.168.1.243 kernel:  [<c061cf63>] .text.lock.mutex+0xf/0x14
May 21 17:13:45 192.168.1.243 kernel:  [<f89929f2>] nfs_idmap_id+0x79/0x1f6 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<c041f7a7>] default_wake_function+0x0/0xc
May 21 17:13:45 192.168.1.243 kernel:  [<f8992ba9>] nfs_map_name_to_uid+0x1b/0x1f [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f898d719>] decode_getfattr+0x611/0xbbd [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<c042d5f5>] lock_timer_base+0x15/0x2f
May 21 17:13:45 192.168.1.243 kernel:  [<f898e025>] nfs4_xdr_dec_getattr+0x0/0x45 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f898e063>] nfs4_xdr_dec_getattr+0x3e/0x45 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f890e755>] rpcauth_unwrap_resp+0x5b/0x60 [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<f89097e9>] call_decode+0x437/0x47d [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<f898e025>] nfs4_xdr_dec_getattr+0x0/0x45 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f890df54>] __rpc_execute+0x7a/0x1f8 [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<f8909951>] rpc_call_sync+0x6b/0x91 [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<f89879f9>] nfs4_proc_getattr+0x6f/0x8b [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f897a157>] __nfs_revalidate_inode+0x120/0x249 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<c061c526>] schedule+0xa22/0xa55
May 21 17:13:45 192.168.1.243 kernel:  [<f8975dbe>] nfs_lookup_revalidate+0x1e8/0x3d7 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<c042d5f5>] lock_timer_base+0x15/0x2f
May 21 17:13:45 192.168.1.243 kernel:  [<f898baea>] decode_compound_hdr+0x35/0x72 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f898b9da>] decode_op_hdr+0xd/0x58 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f898bf3c>] nfs4_xdr_dec_access+0x54/0x8d [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<c042d5f5>] lock_timer_base+0x15/0x2f
May 21 17:13:45 192.168.1.243 kernel:  [<c042d769>] __mod_timer+0xda/0xe4
May 21 17:13:45 192.168.1.243 kernel:  [<f890e4f8>] rpc_wake_up_next+0x11f/0x126 [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<c042e0d2>] recalc_sigpending+0xe/0x20
May 21 17:13:45 192.168.1.243 kernel:  [<c042e194>] sigprocmask+0xb0/0xce
May 21 17:13:45 192.168.1.243 kernel:  [<f890996f>] rpc_call_sync+0x89/0x91 [sunrpc]
May 21 17:13:45 192.168.1.243 kernel:  [<f8986c9d>] _nfs4_proc_access+0xa7/0xdb [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<f8976912>] nfs_access_add_cache+0xad/0x135 [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<c048b233>] dput+0x22/0xed
May 21 17:13:45 192.168.1.243 kernel:  [<f897816c>] nfs_open_revalidate+0x186/0x1da [nfs]
May 21 17:13:45 192.168.1.243 kernel:  [<c0481e46>] do_lookup+0x135/0x174
May 21 17:13:45 192.168.1.243 kernel:  [<c0483652>] __link_path_walk+0x314/0xd33
May 21 17:13:45 192.168.1.243 kernel:  [<c04840a9>] link_path_walk+0x38/0x95
May 21 17:13:45 192.168.1.243 kernel:  [<c048446a>] do_path_lookup+0x219/0x27f
May 21 17:13:45 192.168.1.243 kernel:  [<c0483652>] __link_path_walk+0x314/0xd33
May 21 17:13:45 192.168.1.243 kernel:  [<c04840a9>] link_path_walk+0x38/0x95
May 21 17:13:45 192.168.1.243 kernel:  [<c048446a>] do_path_lookup+0x219/0x27f
May 21 17:13:45 192.168.1.243 kernel:  [<c0484bc4>] __user_walk_fd+0x29/0x3a
May 21 17:13:45 192.168.1.243 kernel:  [<c047e380>] vfs_stat_fd+0x15/0x3c
May 21 17:13:45 192.168.1.243 kernel:  [<c041f7a7>] default_wake_function+0x0/0xc
May 21 17:13:45 192.168.1.243 kernel:  [<c047e434>] sys_stat64+0xf/0x23
May 21 17:13:45 192.168.1.243 kernel:  [<c042c7a5>] getnstimeofday+0x30/0xb6
May 21 17:13:45 192.168.1.243 kernel:  [<c04f0b41>] copy_to_user+0x31/0x48
May 21 17:13:45 192.168.1.243 kernel:  [<c04356e7>] sys_clock_gettime+0x58/0x7e
May 21 17:13:45 192.168.1.243 kernel:  [<c0404f17>] syscall_call+0x7/0xb
May 21 17:13:45 192.168.1.243 kernel:  =======================


Christopher Hawkins

Cell: 315-882-2551
Fax:   716-662-0788

----- "J. Bruce Fields" <bfields@fieldses.org> wrote:

> On Thu, May 20, 2010 at 03:54:28PM -0400, Christopher Hawkins wrote:
> > Hello, 
> > 
> > I have a bash script that sets up a root filesystem over NFS. The
> method works fine over NFS3 but hangs when using NFS4 as a transport.
> Hoping someone can help me figure out why?
> > 
> > In a nutshell:
> > 
> > 1. The node boots into a ramdisk that has a few thousand files in it
> already
> > 2. connects to an NFS server exporting / and mounts that in a tmp
> dir
> > 3. bash (on the booting node) loops through the local and remote
> filesystem and creates a local symlink to anything in the nfs root
> that it doesn't already have.
> 
> Wild.
> 
> > Export options are: /
> 192.168.1.0/24(rw,no_root_squash,no_subtree_check,fsid=0)
> > Mount options are: rw,sync,noatime,rsize=1024,wsize=1024
> > 
> > rpcidmapd, portmap, statd are running on server and client, and
> rpc_pipefs is mounted on both as well. The script currently makes
> about 6200 links, total. Nfs4 hangs about 90% of the way through. I
> removed the directory it was hanging on (a simple, empty dir) and then
> it just hung on the next one.
> 
> Is it possible there's some idmap deadlock?  (If say an upcall to
> idmapd
> is hanging because the mapping requires access to some file that
> isn't
> there yet?)
> 
> A sysrq-T trace might help.
> 
> --b.
> 
> > Really appreciate any help or pointers on where to look for more
> info. Thanks!
> > 
> > Chris
> > 
> > 
> >    
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-nfs"
> in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html