From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754831Ab2ATS4v (ORCPT ); Fri, 20 Jan 2012 13:56:51 -0500 Received: from mx1.redhat.com ([209.132.183.28]:7221 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753877Ab2ATS4u (ORCPT ); Fri, 20 Jan 2012 13:56:50 -0500 Date: Fri, 20 Jan 2012 13:56:46 -0500 From: Jeff Layton To: linux-kernel@vger.kernel.org Cc: bfields@redhat.com, sgruszka@redhat.com Subject: WARNING: at lib/debugobjects.c:262 debug_print_object+0x8c/0xb0() Message-ID: <20120120135646.2fc4fa61@tlielax.poochiereds.net> Mime-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Help! I'm working on some patches that overhaul the client state tracking on stable storage for knfsd. With this patchset, when I start nfsd it does an upcall to userspace to get some info. That upcall is done via rpc_pipefs. What I'm finding though is that if I stop and start nfsd multiple times, then I eventually get a warning like this on start: [ 5157.128514] WARNING: at lib/debugobjects.c:262 debug_print_object+0x8c/0xb0() [ 5157.128742] Hardware name: Bochs [ 5157.128742] ODEBUG: activate not available (active state 0) object type: timer_list hint: stub_timer+0x0/0x20 [ 5157.128742] Modules linked in: nfsd(O) nfs_acl auth_rpcgss lockd sunrpc floppy virtio_net i2c_piix4 i2c_core virtio_balloon joydev pcspkr virtio_blk [last unloaded: nfsd] [ 5157.128742] Pid: 1312, comm: rpc.nfsd Tainted: G W O 3.3.0-rc1+ #1 [ 5157.128742] Call Trace: [ 5157.128742] [] warn_slowpath_common+0x7f/0xc0 [ 5157.128742] [] warn_slowpath_fmt+0x46/0x50 [ 5157.128742] [] debug_print_object+0x8c/0xb0 [ 5157.128742] [] ? timer_debug_hint+0x10/0x10 [ 5157.128742] [] debug_object_activate+0xfb/0x190 [ 5157.128742] [] ? lock_timer_base.isra.24+0x38/0x70 [ 5157.128742] [] mod_timer+0xf6/0x450 [ 5157.128742] [] add_timer+0x18/0x20 [ 5157.128742] [] queue_delayed_work_on+0xbe/0x140 [ 5157.128742] [] queue_delayed_work+0x21/0x40 [ 5157.128742] [] rpc_queue_upcall+0xe8/0x100 [sunrpc] [ 5157.128742] [] __cld_pipe_upcall+0x61/0xc0 [nfsd] [ 5157.128742] [] nfsd4_cld_init+0x48/0x140 [nfsd] [ 5157.128742] [] nfsd4_client_tracking_init+0x2a/0xc0 [nfsd] [ 5157.128742] [] ? mutex_unlock+0xe/0x10 [ 5157.128742] [] nfs4_state_start+0x1a/0x100 [nfsd] [ 5157.128742] [] nfsd_svc+0x135/0x200 [nfsd] [ 5157.128742] [] ? write_maxblksize+0x130/0x130 [nfsd] [ 5157.128742] [] write_threads+0x7d/0xd0 [nfsd] [ 5157.128742] [] ? simple_transaction_get+0xca/0xe0 [ 5157.128742] [] nfsctl_transaction_write+0x57/0x90 [nfsd] [ 5157.128742] [] vfs_write+0xaf/0x190 [ 5157.128742] [] sys_write+0x4d/0x90 [ 5157.128742] [] system_call_fastpath+0x16/0x1b ...or this on stop: [ 5200.804410] WARNING: at lib/debugobjects.c:262 debug_print_object+0x8c/0xb0() [ 5200.808205] Hardware name: Bochs [ 5200.810121] ODEBUG: assert_init not available (active state 0) object type: timer_list hint: stub_timer+0x0/0x20 [ 5200.812734] Modules linked in: nfsd(O) nfs_acl auth_rpcgss lockd sunrpc floppy virtio_net i2c_piix4 i2c_core virtio_balloon joydev pcspkr virtio_blk [last unloaded: nfsd] [ 5200.821596] Pid: 1394, comm: nfsd Tainted: G W O 3.3.0-rc1+ #1 [ 5200.822409] Call Trace: [ 5200.822726] [] warn_slowpath_common+0x7f/0xc0 [ 5200.823509] [] warn_slowpath_fmt+0x46/0x50 [ 5200.824243] [] debug_print_object+0x8c/0xb0 [ 5200.824935] [] ? timer_debug_hint+0x10/0x10 [ 5200.825665] [] debug_object_assert_init+0xe3/0x120 [ 5200.826474] [] del_timer+0x24/0x1b0 [ 5200.827129] [] __cancel_work_timer+0x34/0x140 [ 5200.827829] [] cancel_delayed_work_sync+0x12/0x20 [ 5200.832905] [] rpc_unlink+0x1e0/0x230 [sunrpc] [ 5200.833716] [] nfsd4_remove_cld_pipe+0x15/0x40 [nfsd] [ 5200.834558] [] nfsd4_client_tracking_exit+0x20/0x30 [nfsd] [ 5200.835434] [] nfs4_state_shutdown+0x1a4/0x1c0 [nfsd] [ 5200.836271] [] nfsd_last_thread+0x2a/0x60 [nfsd] [ 5200.837045] [] svc_destroy+0x5c/0x140 [sunrpc] [ 5200.837778] [] svc_exit_thread+0xa6/0xb0 [sunrpc] [ 5200.838545] [] nfsd+0x123/0x170 [nfsd] [ 5200.839221] [] ? 0xffffffffa0101fff [ 5200.839820] [] kthread+0xb7/0xc0 [ 5200.840431] [] kernel_thread_helper+0x4/0x10 [ 5200.850883] [] ? retint_restore_args+0x13/0x13 [ 5200.851654] [] ? kthread_worker_fn+0x1a0/0x1a0 [ 5200.852418] [] ? gs_change+0x13/0x13 The problem is that even after staring at this code for a while, I'm still clueless as to what this is telling me. It doesn't happen every time either, so maybe there's a race of some sort involved. It's possible that my patch is broken and doing something wrong, but I'm starting not to think so. I'm not really using timers directly -- I'm using rpc_pipefs, which queues a delayed job to a workqueue, and that is manipulating the timer. The delayed_work (and hence the timer) are part of an rpc_inode. Can anyone shed a little light on what this is complaining about? -- Jeff Layton