From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S937224AbXG0O6V (ORCPT ); Fri, 27 Jul 2007 10:58:21 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S933110AbXG0O6L (ORCPT ); Fri, 27 Jul 2007 10:58:11 -0400 Received: from nz-out-0506.google.com ([64.233.162.230]:5897 "EHLO nz-out-0506.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1759460AbXG0O6K (ORCPT ); Fri, 27 Jul 2007 10:58:10 -0400 DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=beta; h=received:message-id:date:from:to:subject:cc:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; b=EZSkQsFuCSuXhl8d4u+Z3azxv2cJ9xRhltYt77vu1XiLDa9VKWt/fm++Q8BsALz/62ZzJRYHNHiKJKt3yR68JLa9hEV9ADN8OMvIyK2oBn84r5BCihF7kmYexHFnc3eIsvk1DxAXX9L7GCBpOemgnuv/k9FTQbRan8f0RgCtA0o= Message-ID: Date: Fri, 27 Jul 2007 20:28:08 +0530 From: "Satyam Sharma" To: "Marc Dietrich" Subject: Re: NFSv4 poops itself Cc: "Jeff Garzik" , "kernel list" , "Trond Myklebust" , "Andrew Morton" , "Michal Piotrowski" In-Reply-To: <200707271537.00647.marc.dietrich@ap.physik.uni-giessen.de> MIME-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-Disposition: inline References: <46A9EAB0.3090306@garzik.org> <200707271537.00647.marc.dietrich@ap.physik.uni-giessen.de> Sender: linux-kernel-owner@vger.kernel.org X-Mailing-List: linux-kernel@vger.kernel.org On 7/27/07, Marc Dietrich wrote: > > Hi, > > Am Friday 27 July 2007 14:53 schrieben Sie: > > Background: > > > > Server: x86-64 dual core Intel, kernel 2.6.23-rc1 (my home fileserver) > > Exporting NFS/NFSv4 mounts. Client count: 1 Uptime: 4 days > > > > Client: x86-64 dual core Intel, kernel 2.6.23-rc1 (my main workstation) > > NFS mount setup: > > pretzel:/ on /g type nfs4 (rw,noatime,proto=tcp,addr=10.10.10.1) > > Uptime: 4 days > > > > Home directory mounted via NFSv4. > > > > Problem: > > > > My workstation has been happily talking to my file server for several > > days without incident. An hour ago, my numeric keypad stopping working > > (unrelated problem... USB or X bug?). The solution to the keypad > > problem is usually to log out of X and log back in, or worse case, reboot. > > > > So, I log out, and log back in. At first, a few shell windows open and > > successfully initialize themselves (read bash profile over NFS, etc.) > > Then, as more shell windows open, things start hanging. I can easily > > switch to console and ssh to the fileserver, so it is clear this is an > > NFS hang. > > > > No adverse messages at all on the client. > > > > On the server, I see NFSv4 spamming dmesg with hundreds of thousands of > > messages: > > > > Jul 27 08:20:53 pretzel kernel: NFSD: preprocess_seqid_op: old stateid! > > Jul 27 08:21:24 pretzel last message repeated 167966 times > > Jul 27 08:21:55 pretzel last message repeated 173628 times > > Jul 27 08:21:55 pretzel kernel: NFSD: preprocess_seqid_op: old stateid! > > Jul 27 08:22:26 pretzel last message repeated 171286 times > > Jul 27 08:23:27 pretzel last message repeated 344461 times > > Jul 27 08:23:30 pretzel last message repeated 18656 times > > > > I rebooted the client, the problem disappeared, and everything is happy > > again... but clearly NFSv4 shat itself. And now I am worried this will > > happen again. > > > > In all my quite-heavy use of NFSv4 I've never seen this behavior before, > > so I would call this a regression. > > > > I always run vanilla linux-2.6.git self-built kernels on both client and > > server. > > me too, my server has 2.6.18-? (openSUSE 10.2). On the client > (2.6.23-rc1-mm1), I also see (shortly before the hang) > > Jul 26 13:09:19 fb07-iapwap2 kernel: ================================= > Jul 26 13:09:19 fb07-iapwap2 kernel: [ INFO: inconsistent lock state ] > Jul 26 13:09:19 fb07-iapwap2 kernel: 2.6.23-rc1-mm1 #1 > Jul 26 13:09:19 fb07-iapwap2 kernel: --------------------------------- > Jul 26 13:09:19 fb07-iapwap2 kernel: inconsistent {softirq-on-W} -> > {in-softirq-W} usage. > Jul 26 13:09:19 fb07-iapwap2 kernel: hald/3873 [HC0[0]:SC1[1]:HE1:SE0] takes: > Jul 26 13:09:19 fb07-iapwap2 kernel: (rpc_credcache_lock){-+..}, at: > [] _atomic_dec_and_lock+0x16/0x60 > Jul 26 13:09:19 fb07-iapwap2 kernel: {softirq-on-W} state was registered at: > Jul 26 13:09:19 fb07-iapwap2 kernel: [] mark_lock+0x77/0x630 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] add_lock_to_list+0x44/0xc0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > __lock_acquire+0x65f/0x1020 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] mark_held_locks+0x5e/0x80 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] local_bh_enable+0x7d/0x130 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] lock_acquire+0x5f/0x80 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > _atomic_dec_and_lock+0x16/0x60 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] _spin_lock+0x2a/0x40 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > _atomic_dec_and_lock+0x16/0x60 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > _atomic_dec_and_lock+0x16/0x60 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] _spin_lock+0x2a/0x40 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] put_rpccred+0x60/0x110 > [sunrpc] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > rpcauth_unbindcred+0x20/0x60 [sunrpc] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] rpc_put_task+0x44/0xb0 > [sunrpc] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] rpc_call_sync+0x2d/0x40 > [sunrpc] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] rpcb_register+0x10d/0x1c0 > [sunrpc] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] svc_register+0x8f/0x160 > [sunrpc] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > trace_hardirqs_on+0xc5/0x170 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] __svc_create+0x1d5/0x200 > [sunrpc] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] svc_create+0x10/0x20 > [sunrpc] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] nfs_callback_up+0x82/0x120 > [nfs] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] nfs_get_client+0x17d/0x390 > [nfs] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] kmem_cache_alloc+0x79/0xd0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > trace_hardirqs_on+0xc5/0x170 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] nfs4_set_client+0x34/0x1a0 > [nfs] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > nfs4_create_server+0x61/0x3c0 [nfs] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] __kmalloc+0xdf/0x120 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > trace_hardirqs_on+0xc5/0x170 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > __lock_acquire+0x737/0x1020 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] copy_from_user+0x3d/0x80 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] strndup_user+0x62/0x80 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] nfs4_get_sb+0x3c7/0x610 > [nfs] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > __lock_acquire+0x737/0x1020 > Jul 26Jul 26 13:09:19 fb07-iapwap2 kernel: [] > get_page_from_freelist+0x316/0x460 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > trace_hardirqs_on+0xc5/0x170 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] __alloc_pages+0x4e/0x370 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] vfs_kern_mount+0xa0/0x120 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] do_mount+0x21d/0x840 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > handle_mm_fault+0x4a7/0x690 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] _spin_unlock+0x14/0x20 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > handle_mm_fault+0x453/0x690 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] up_read+0x14/0x30 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] do_page_fault+0x1ed/0x6e0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > copy_mount_options+0xb7/0x150 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] sys_mount+0x72/0xb0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] syscall_call+0x7/0xb > Jul 26 13:09:19 fb07-iapwap2 kernel: [] 0xffffffff > Jul 26 13:09:19 fb07-iapwap2 kernel: irq event stamp: 240896 > Jul 26 13:09:19 fb07-iapwap2 kernel: hardirqs last enabled at (240896): > [] kmem_cache_free+0x7e/0xb0 > Jul 26 13:09:19 fb07-iapwap2 kernel: hardirqs last disabled at (240895): > [] kmem_cache_free+0x4c/0xb0 > Jul 26 13:09:19 fb07-iapwap2 kernel: softirqs last enabled at (240446): > [] do_softirq+0x45/0x50 > Jul 26 13:09:19 fb07-iapwap2 kernel: softirqs last disabled at (240887): > [] do_softirq+0x45/0x50 > Jul 26 13:09:19 fb07-iapwap2 kernel: > Jul 26 13:09:19 fb07-iapwap2 kernel: other info that might help us debug this: > Jul 26 13:09:19 fb07-iapwap2 kernel: no locks held by hald/3873. > Jul 26 13:09:19 fb07-iapwap2 kernel: > Jul 26 13:09:19 fb07-iapwap2 kernel: stack backtrace: > Jul 26 13:09:19 fb07-iapwap2 kernel: [] print_usage_bug+0x15c/0x170 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] mark_lock+0x45a/0x630 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] __lock_acquire+0x607/0x1020 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] __lock_acquire+0x737/0x1020 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] lock_acquire+0x5f/0x80 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > _atomic_dec_and_lock+0x16/0x60 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] _spin_lock+0x2a/0x40 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > _atomic_dec_and_lock+0x16/0x60 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > _atomic_dec_and_lock+0x16/0x60 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] put_rpccred+0x60/0x110 > [sunrpc] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > nfs_free_delegation_callback+0x10/0x20 [nfs] > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > __rcu_process_callbacks+0x67/0x1c0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > rcu_process_callbacks+0xf/0x20 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] tasklet_action+0x33/0x70 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] __do_softirq+0x55/0xb0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] do_softirq+0x45/0x50 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > smp_apic_timer_interrupt+0x40/0x80 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > apic_timer_interrupt+0x29/0x38 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > apic_timer_interrupt+0x33/0x38 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] _spin_unlock_irq+0x22/0x30 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > __sched_text_start+0x1c4/0x390 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > __sched_text_start+0x139/0x390 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] __mod_timer+0x8b/0xa0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] schedule_timeout+0x4a/0xc0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] process_timeout+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] do_sys_poll+0x237/0x320 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] __pollwait+0x0/0xf0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > default_wake_function+0x0/0x10 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] _read_unlock+0x14/0x20 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > unix_stream_sendmsg+0x1a5/0x350 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] sock_aio_write+0x117/0x140 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] __lock_acquire+0x737/0x1020 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] do_readv_writev+0x144/0x1c0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] sock_aio_write+0x0/0x140 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] do_gettimeofday+0x31/0xf0 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] restore_nocheck+0x12/0x15 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] > trace_hardirqs_on+0xc5/0x170 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] copy_to_user+0x3f/0x70 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] sys_poll+0x28/0x40 > Jul 26 13:09:19 fb07-iapwap2 kernel: [] syscall_call+0x7/0xb > Jul 26 13:09:19 fb07-iapwap2 kernel: ======================= Doesn't appear related ... could you rebuild with CONFIG_FRAME_POINTER and test + resend the above log? The trace up there looks quite ugly. [ Unrelated, but I just realized from lib/Kconfig.debug that stuff in there "select"s LOCKDEP, which itself "selects" frame pointers (on some archs). But I thought "select" didn't chain properly like that? There's whole lots of depending and selecting and non-user-visible options out there in that file -- and I'm not sure all those selects and depends are really even required to successfully build (?) ] Satyam