On Thu, 2010-05-06 at 18:40 +0300, Timo Aaltonen wrote: > Reviving the old thread, since it's still happening. Maybe I should file a > proper bug about this? Please do. Can you see if you can get a trace of the recovery thread? Also, please check your dmesg log for any 'unhandled error' messages. If there is nothing there, then we may have to get a 'wireshark' trace too... Cheers Trond > On Fri, 12 Feb 2010, Trond Myklebust wrote: > > > On Fri, 2010-02-12 at 11:13 -0500, Jeff Layton wrote: > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] 130.233.227.1 D 00000000ffffffff 0 29902 2 0x00000080 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] ffff8800c158dc50 0000000000000046 0000000000015ac0 0000000000015ac0 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] ffff880116251ab0 ffff8800c158dfd8 0000000000015ac0 ffff8801162516f0 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] 0000000000015ac0 ffff8800c158dfd8 0000000000015ac0 ffff880116251ab0 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] Call Trace: > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa09fec20>] ? rpc_wait_bit_killable+0x0/0x40 [sunrpc] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa09fec44>] rpc_wait_bit_killable+0x24/0x40 [sunrpc] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffff8155f05f>] __wait_on_bit+0x5f/0x90 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa09fec20>] ? rpc_wait_bit_killable+0x0/0x40 [sunrpc] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffff8155f108>] out_of_line_wait_on_bit+0x78/0x90 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffff81083640>] ? wake_bit_function+0x0/0x40 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa09ff555>] __rpc_execute+0x105/0x220 [sunrpc] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa09ff696>] rpc_execute+0x26/0x30 [sunrpc] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa09f7b8a>] rpc_run_task+0x3a/0x90 [sunrpc] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa09f7ce2>] rpc_call_sync+0x42/0x70 [sunrpc] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffff81055080>] ? finish_task_switch+0x50/0xd0 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa0baa0ed>] nfs4_proc_renew+0x4d/0xa0 [nfs] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa0bb61fc>] nfs4_check_lease+0x8c/0xc0 [nfs] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa0bb6fa0>] ? nfs4_run_state_manager+0x0/0x40 [nfs] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa0bb6e98>] nfs4_state_manager+0xf8/0x200 [nfs] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffff810672ed>] ? allow_signal+0x9d/0xb0 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffffa0bb6fc3>] nfs4_run_state_manager+0x23/0x40 [nfs] > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffff81083286>] kthread+0x96/0xa0 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffff8101422a>] child_rip+0xa/0x20 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffff810831f0>] ? kthread+0x0/0xa0 > >> Feb 12 16:11:38 nexus6 kernel: [10629.733513] [<ffffffff81014220>] ? child_rip+0x0/0x20 > >> > >> Here, the mount appears to be attempting to renew the state. > >> > >> <wild ass speculation> > >> Another thread (not shown in the sysrq-t) is attempting to do writeback > >> (maybe the bdev flush thread?) and that's in turn blocked by the state > >> recovery code? > >> </wild ass speculation> > >> > >> Looking back over the capture that you sent originally, I see that the > >> client is attempting a WRITE, getting a NFS4ERR_BAD_STATEID back from > >> the server, issuing a RENEW which succeeds and then reattempting the > >> WRITE. > >> > >> Trond, shouldn't it be trying to recover the state before reissuing the > >> write? > >> > > > > Yes. Both nfs4_read_done() and nfs4_write_done() will call > > nfs4_async_handle_error(), which again should call > > nfs4_state_mark_reclaim_nograce() on the stateid. The state manager > > should then end up recovering that stateid before the write is > > reattempted. > > > > We did previously have an issue if the server were to return > > NFS4ERR_STALE_STATEID, followed by NFS4ERR_OK to our RENEW probe > > (==seriously buggy server), but 2.6.33-rc7 has a fix for that. > > The offending app seems to be the new "indicator-applet" on the Ubuntu > GNOME desktop, so maybe that's why others haven't seen this bug yet? > Here's the trace from dmesg: > > [482400.730245] INFO: task indicator-apple:28782 blocked for more than 120 seconds. > [482400.730247] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [482400.730249] indicator-app D 0000000000000000 0 28782 1 0x00000080 > [482400.730253] ffff880010579ac8 0000000000000082 0000000000015bc0 0000000000015bc0 > [482400.730257] ffff880109bb1ab0 ffff880010579fd8 0000000000015bc0 ffff880109bb16f0 > [482400.730261] 0000000000015bc0 ffff880010579fd8 0000000000015bc0 ffff880109bb1ab0 > [482400.730265] Call Trace: > [482400.730275] [<ffffffffa0b6b2b0>] ? nfs_wait_bit_uninterruptible+0x0/0x20 [nfs] > [482400.730279] [<ffffffff8153eb57>] io_schedule+0x47/0x70 > [482400.730288] [<ffffffffa0b6b2be>] nfs_wait_bit_uninterruptible+0xe/0x20 [nfs] > [482400.730292] [<ffffffff8153f3af>] __wait_on_bit+0x5f/0x90 > [482400.730302] [<ffffffffa0b6b2b0>] ? nfs_wait_bit_uninterruptible+0x0/0x20 [nfs] > [482400.730305] [<ffffffff8153f458>] out_of_line_wait_on_bit+0x78/0x90 > [482400.730309] [<ffffffff81085360>] ? wake_bit_function+0x0/0x40 > [482400.730318] [<ffffffffa0b6b29f>] nfs_wait_on_request+0x2f/0x40 [nfs] > [482400.730329] [<ffffffffa0b6f6af>] nfs_wait_on_requests_locked+0x7f/0xd0 [nfs] > [482400.730340] [<ffffffffa0b70aee>] nfs_sync_mapping_wait+0x9e/0x1a0 [nfs] > [482400.730350] [<ffffffffa0b70ed9>] nfs_write_mapping+0x79/0xb0 [nfs] > [482400.730361] [<ffffffffa0b70f47>] nfs_wb_all+0x17/0x20 [nfs] > [482400.730369] [<ffffffffa0b5feba>] nfs_do_fsync+0x2a/0x60 [nfs] > [482400.730378] [<ffffffffa0b608b6>] nfs_file_write+0x106/0x1e0 [nfs] > [482400.730381] [<ffffffff8114270a>] do_sync_write+0xfa/0x140 > [482400.730385] [<ffffffff81085320>] ? autoremove_wake_function+0x0/0x40 > [482400.730389] [<ffffffff81250b96>] ? security_file_permission+0x16/0x20 > [482400.730392] [<ffffffff81142a08>] vfs_write+0xb8/0x1a0 > [482400.730396] [<ffffffff810c03e2>] ? audit_syscall_entry+0x242/0x270 > [482400.730399] [<ffffffff811432a1>] sys_write+0x51/0x80 > [482400.730403] [<ffffffff810131b2>] system_call_fastpath+0x16/0x1b > > I haven't tried the 2.6.34-series yet.. > -- To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
