From: "J. R. Okajima" Subject: NFS, race in writeback? Date: Sun, 23 May 2010 02:14:08 +0900 Message-ID: <11621.1274548448@jrobl> Cc: linux-nfs@vger.kernel.org, linux-kernel@vger.kernel.org To: Trond.Myklebust@netapp.com Return-path: Sender: linux-kernel-owner@vger.kernel.org List-ID: I got "task xxx blocked for more than 120 seconds" in 2.6.34 NFS, which didn't happen in 2.6.33. The four call-traces are attached. Git bisect told me that "bad" is, commit ba8b06e67ed7a560b0e7c80091bcadda4f4727a5 Author: Trond Myklebust Date: Tue Apr 27 18:33:54 2010 -0400 NFS: Ensure that nfs_wb_page() waits for Pg_writeback to clear Neil Brown reports that he is seeing the BUG_ON(ret == 0) trigger in nfs_page_async_flush. According to the trace in https://bugzilla.novell.com/show_bug.cgi?id=599628 the problem appears to be due to nfs_wb_page() not waiting for the PG_writeback flag to clear. There is a ditto problem in nfs_wb_page_cancel() I am not sure whether this commit is the root cause or not, but it must be related at least. Was the commit insufficient? J. R. Okajima ---------------------------------------------------------------------- INFO: task flush-0:1207:24945 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. flush-0:1207 D 0000000000000000 0 24945 2 0x00000000 ffff880000b49c50 0000000000000046 0000000000000001 ffff880000b48000 ffff880000b49fd8 ffff880000b48000 ffff880000b49fd8 ffff880000b49fd8 ffff88000f163040 0000000000014d00 0000000000000000 ffff88000f163040 Call Trace: [] inode_wait+0xe/0x20 [] __wait_on_bit+0x62/0x90 [] ? inode_wait+0x0/0x20 [] inode_wait_for_writeback+0x93/0xc0 [] ? wake_bit_function+0x0/0x50 [] wb_writeback+0x191/0x200 [] wb_do_writeback+0x1db/0x1e0 [] ? wb_do_writeback+0x30/0x1e0 [] bdi_writeback_task+0x53/0xe0 [] ? bdi_start_fn+0x0/0x100 [] bdi_start_fn+0x86/0x100 [] ? bdi_start_fn+0x0/0x100 [] kthread+0x96/0xb0 [] kernel_thread_helper+0x4/0x10 [] ? restore_args+0x0/0x30 [] ? kthread+0x0/0xb0 [] ? kernel_thread_helper+0x0/0x10 no locks held by flush-0:1207/24945. INFO: task mv:4227 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. mv D 0000000000000000 0 4227 23660 0x00000000 ffff88000e899b58 0000000000000046 0000000000000001 ffff88000e898000 ffff88000e899fd8 ffff88000e898000 ffff88000e899fd8 ffff88000e899fd8 ffff88000d59f040 0000000000014d00 0000000000000000 ffff88000d59f040 Call Trace: [] inode_wait+0xe/0x20 [] __wait_on_bit+0x62/0x90 [] ? inode_wait+0x0/0x20 [] inode_wait_for_writeback+0x93/0xc0 [] ? wake_bit_function+0x0/0x50 [] writeback_single_inode+0x118/0x360 [] sync_inode+0x33/0x50 [] nfs_wb_all+0x45/0x50 [] nfs_rename+0x280/0x310 [] vfs_rename+0x3f4/0x460 [] ? tomoyo_path_rename+0x35/0x40 [] sys_renameat+0x266/0x270 [] ? handle_mm_fault+0x523/0x8b0 [] ? do_page_fault+0x319/0x600 [] ? up_read+0x23/0x40 [] ? retint_swapgs+0x13/0x1b [] ? trace_hardirqs_on_caller+0x145/0x190 [] sys_rename+0x1b/0x20 [] system_call_fastpath+0x16/0x1b 3 locks held by mv/4227: #0: (&s->s_vfs_rename_mutex){+.+.+.}, at: [] lock_rename+0x41/0xf0 #1: (&sb->s_type->i_mutex_key#12/1){+.+.+.}, at: [] lock_rename+0x6a/0xf0 #2: (&sb->s_type->i_mutex_key#12/2){+.+.+.}, at: [] lock_rename+0x7f/0xf0 INFO: task dd:4230 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. dd D 0000000000000001 0 4230 23641 0x00000000 ffff880010857b28 0000000000000046 0000000000000000 ffff880010856000 ffff880010857fd8 ffff880010856000 ffff880010857fd8 ffff880010857fd8 ffff880010507040 0000000000014d00 0000000000000001 ffff880010507040 Call Trace: [] io_schedule+0x52/0x70 [] sync_page+0x6d/0xb0 [] __wait_on_bit_lock+0x5a/0xb0 [] ? sync_page+0x0/0xb0 [] __lock_page+0x69/0x70 [] ? wake_bit_function+0x0/0x50 [] write_cache_pages+0x2c0/0x420 [] ? nfs_writepages_callback+0x0/0x80 [] nfs_writepages+0xd6/0x170 [] ? nfs_flush_one+0x0/0x100 [] do_writepages+0x24/0x40 [] writeback_single_inode+0x180/0x360 [] sync_inode+0x33/0x50 [] nfs_wb_all+0x45/0x50 [] nfs_do_fsync+0x2d/0x60 [] nfs_file_flush+0x82/0xc0 [] filp_close+0x42/0x90 [] sys_close+0xbe/0x160 [] system_call_fastpath+0x16/0x1b no locks held by dd/4230. INFO: task dd:4250 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. dd D 0000000000000000 0 4250 23590 0x00000000 ffff88001249b988 0000000000000046 0000000000000001 ffff88001249a000 ffff88001249bfd8 ffff88001249a000 ffff88001249bfd8 ffff88001249bfd8 ffff88000da7e040 0000000000014d00 0000000000000000 ffff88000da7e040 Call Trace: [] inode_wait+0xe/0x20 [] __wait_on_bit+0x62/0x90 [] ? inode_wait+0x0/0x20 [] inode_wait_for_writeback+0x93/0xc0 [] ? wake_bit_function+0x0/0x50 [] writeback_single_inode+0x118/0x360 [] sync_inode+0x33/0x50 [] nfs_wb_page+0x76/0xc0 [] nfs_flush_incompatible+0x44/0x70 [] nfs_write_begin+0xb5/0x210 [] generic_file_buffered_write+0x190/0x2e0 [] __generic_file_aio_write+0x484/0x540 [] ? generic_file_aio_write+0x64/0xd0 [] generic_file_aio_write+0x78/0xd0 [] nfs_file_write+0x10b/0x210 [] do_sync_write+0xd9/0x120 [] ? security_file_permission+0x16/0x20 [] ? rw_verify_area+0xea/0x160 [] vfs_write+0x116/0x230 [] sys_write+0x57/0xb0 [] system_call_fastpath+0x16/0x1b 1 lock held by dd/4250: #0: (&sb->s_type->i_mutex_key#12){+.+.+.}, at: [] generic_file_aio_write+0x64/0xd0