Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753489Ab3HVF7I (ORCPT ); Thu, 22 Aug 2013 01:59:08 -0400 Received: from mail-ph.de-nserver.de ([85.158.179.214]:53788 "EHLO mail-ph.de-nserver.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753160Ab3HVF7G (ORCPT ); Thu, 22 Aug 2013 01:59:06 -0400 X-Fcrdns: No Message-ID: <5215A8A8.90900@profihost.ag> Date: Thu, 22 Aug 2013 07:59:04 +0200 From: Stefan Priebe User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:17.0) Gecko/20130801 Thunderbird/17.0.8 MIME-Version: 1.0 To: Kent Overstreet CC: Jens Axboe , linux-kernel@vger.kernel.org, linux-bcache@vger.kernel.org Subject: Re: bcache: Fix a writeback performance regression References: <20130814225904.GA6427@kmo-pixel> <520C788A.1060208@profihost.ag> <520DFAB4.1050402@profihost.ag> <52114614.4070509@profihost.ag> <20130819222718.GA32104@kmo-pixel> <52132243.8050803@profihost.ag> <521323D1.1070503@profihost.ag> <20130821234715.GA4630@moria.home.lan> <5215A130.9080508@profihost.ag> <20130822054336.GA14935@kmo-pixel> In-Reply-To: <20130822054336.GA14935@kmo-pixel> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit X-User-Auth: Auth by s.priebe@profihost.ag through 85.158.179.66 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 28669 Lines: 506 >schedule_timeout() is not the same as >schedule_timeout_interruptible(). just search and replace? So i can try on my own. Stefan Am 22.08.2013 07:43, schrieb Kent Overstreet: > On Thu, Aug 22, 2013 at 07:27:12AM +0200, Stefan Priebe wrote: >> today i had this one: > > Heh, I finally tracked it down earlier today. Turned out to be a rather > embarassing bug... schedule_timeout() is not the same as > schedule_timeout_interruptible(). > > I'll get the fix out in the morning, for the moment an easy workaround > is to set writeback_percent to 0. > >> >> 2013-08-22 06:28:55 [] schedule+0x24/0x70 >> 2013-08-22 06:28:55 [] io_schedule+0x87/0xd0 >> 2013-08-22 06:28:55 [] sleep_on_page+0x9/0x10 >> 2013-08-22 06:28:55 [] __wait_on_bit+0x57/0x80 >> 2013-08-22 06:28:55 [] ? find_get_pages_tag+0xcc/0x180 >> 2013-08-22 06:28:55 [] wait_on_page_bit+0x6e/0x80 >> 2013-08-22 06:28:55 [] ? >> autoremove_wake_function+0x40/0x40 >> 2013-08-22 06:28:55 [] ? pagevec_lookup_tag+0x20/0x30 >> 2013-08-22 06:28:55 [] >> filemap_fdatawait_range+0x10f/0x1b0 >> 2013-08-22 06:28:55 [] >> filemap_write_and_wait_range+0x90/0xa0 >> 2013-08-22 06:28:55 [] xfs_file_fsync+0x63/0x1e0 >> 2013-08-22 06:28:55 [] vfs_fsync_range+0x23/0x30 >> 2013-08-22 06:28:55 [] vfs_fsync+0x17/0x20 >> 2013-08-22 06:28:55 [] do_fsync+0x3c/0x60 >> 2013-08-22 06:28:55 [] SyS_fdatasync+0xe/0x20 >> 2013-08-22 06:28:55 [] system_call_fastpath+0x16/0x1b >> 2013-08-22 06:28:54 [] schedule+0x24/0x70 >> 2013-08-22 06:28:54 [] io_schedule+0x87/0xd0 >> 2013-08-22 06:28:54 [] sleep_on_page+0x9/0x10 >> 2013-08-22 06:28:54 [] __wait_on_bit+0x57/0x80 >> 2013-08-22 06:28:54 [] ? find_get_pages_tag+0xcc/0x180 >> 2013-08-22 06:28:54 [] wait_on_page_bit+0x6e/0x80 >> 2013-08-22 06:28:54 [] ? >> autoremove_wake_function+0x40/0x40 >> 2013-08-22 06:28:54 [] ? pagevec_lookup_tag+0x20/0x30 >> 2013-08-22 06:28:54 [] >> filemap_fdatawait_range+0x10f/0x1b0 >> 2013-08-22 06:28:54 [] >> filemap_write_and_wait_range+0x90/0xa0 >> 2013-08-22 06:28:54 [] xfs_file_fsync+0x63/0x1e0 >> 2013-08-22 06:28:54 [] vfs_fsync_range+0x23/0x30 >> 2013-08-22 06:28:54 [] vfs_fsync+0x17/0x20 >> 2013-08-22 06:28:54 [] do_fsync+0x3c/0x60 >> 2013-08-22 06:28:54 [] SyS_fsync+0xb/0x10 >> 2013-08-22 06:28:54 [] system_call_fastpath+0x16/0x1b >> 2013-08-22 06:28:54 INFO: task ceph-osd:3520 blocked for more >> than 120 seconds. >> 2013-08-22 06:28:54 "echo 0 > >> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> 2013-08-22 06:28:54 ceph-osd D ffffffff8160f760 0 3520 1 0x00000004 >> 2013-08-22 06:28:54 ffff880c381d5c78 0000000000000086 >> ffff880c381d5fd8 0000000000012c80 >> 2013-08-22 06:28:54 ffff880c381d4010 0000000000012c80 >> 0000000000012c80 0000000000012c80 >> 2013-08-22 06:28:54 ffff880c381d5fd8 0000000000012c80 >> ffff880c39100000 ffff880c48dd0000 >> 2013-08-22 06:28:54 Call Trace: >> 2013-08-22 06:28:54 [] ? __lock_page+0x70/0x70 >> 2013-08-22 06:28:53 [] ? find_get_pages_tag+0xcc/0x180 >> 2013-08-22 06:28:53 [] wait_on_page_bit+0x6e/0x80 >> 2013-08-22 06:28:53 [] ? >> autoremove_wake_function+0x40/0x40 >> 2013-08-22 06:28:53 [] ? pagevec_lookup_tag+0x20/0x30 >> 2013-08-22 06:28:53 [] >> filemap_fdatawait_range+0x10f/0x1b0 >> 2013-08-22 06:28:53 [] ? schedule+0x24/0x70 >> 2013-08-22 06:28:53 [] ? schedule_timeout+0x16d/0x200 >> 2013-08-22 06:28:53 [] ? >> __queue_delayed_work+0xaa/0x1a0 >> 2013-08-22 06:28:53 [] ? >> try_to_grab_pending+0x109/0x190 >> 2013-08-22 06:28:53 [] filemap_fdatawait+0x23/0x30 >> 2013-08-22 06:28:53 [] wait_sb_inodes+0xb5/0x110 >> 2013-08-22 06:28:53 [] sync_inodes_sb+0x9c/0xd0 >> 2013-08-22 06:28:53 [] __sync_filesystem+0x16/0x50 >> 2013-08-22 06:28:53 [] sync_filesystem+0x43/0x60 >> 2013-08-22 06:28:53 [] SyS_syncfs+0x50/0x90 >> 2013-08-22 06:28:53 [] system_call_fastpath+0x16/0x1b >> 2013-08-22 06:28:53 INFO: task ceph-osd:3516 blocked for more >> than 120 seconds. >> 2013-08-22 06:28:53 "echo 0 > >> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> 2013-08-22 06:28:53 ceph-osd D ffffffff8160f760 0 3516 1 0x00000004 >> 2013-08-22 06:28:53 ffff880c383d3c78 0000000000000086 >> ffff880c383d3fd8 0000000000012c80 >> 2013-08-22 06:28:53 ffff880c383d2010 0000000000012c80 >> 0000000000012c80 0000000000012c80 >> 2013-08-22 06:28:53 ffff880c383d3fd8 0000000000012c80 >> ffff880c428018e0 ffff880c48dd0000 >> 2013-08-22 06:28:53 Call Trace: >> 2013-08-22 06:28:53 [] ? __lock_page+0x70/0x70 >> 2013-08-22 06:28:52 [] ? xfs_bmbt_get_all+0x13/0x20 >> 2013-08-22 06:28:52 [] xfs_attr_set_int+0x3a4/0x4f0 >> 2013-08-22 06:28:52 [] xfs_attr_set+0x81/0x90 >> 2013-08-22 06:28:52 [] xfs_xattr_set+0x42/0x60 >> 2013-08-22 06:28:52 [] generic_setxattr+0x9b/0xb0 >> 2013-08-22 06:28:52 [] __vfs_setxattr_noperm+0x5f/0xe0 >> 2013-08-22 06:28:52 [] vfs_setxattr+0xb4/0xc0 >> 2013-08-22 06:28:52 [] setxattr+0xbe/0x200 >> 2013-08-22 06:28:52 [] ? __sb_start_write+0x71/0x110 >> 2013-08-22 06:28:52 [] ? >> __mnt_want_write_file+0x61/0x80 >> 2013-08-22 06:28:52 [] SyS_fsetxattr+0xa6/0xc0 >> 2013-08-22 06:28:52 [] system_call_fastpath+0x16/0x1b >> 2013-08-22 06:28:52 INFO: task ceph-osd:3508 blocked for more >> than 120 seconds. >> 2013-08-22 06:28:52 "echo 0 > >> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> 2013-08-22 06:28:52 ceph-osd D ffffffff8160f760 0 3508 1 0x00000004 >> 2013-08-22 06:28:52 ffff880c2c1bfc28 0000000000000086 >> ffff880c2c1bffd8 0000000000012c80 >> 2013-08-22 06:28:52 ffff880c2c1be010 0000000000012c80 >> 0000000000012c80 0000000000012c80 >> 2013-08-22 06:28:52 ffff880c2c1bffd8 0000000000012c80 >> ffff880c43eae380 ffff880c48dd4aa0 >> 2013-08-22 06:28:52 Call Trace: >> 2013-08-22 06:28:52 [] ? __lock_page+0x70/0x70 >> 2013-08-22 06:28:52 [] schedule+0x24/0x70 >> 2013-08-22 06:28:52 [] io_schedule+0x87/0xd0 >> 2013-08-22 06:28:52 [] sleep_on_page+0x9/0x10 >> 2013-08-22 06:28:52 [] __wait_on_bit+0x57/0x80 >> 2013-08-22 06:28:51 [] system_call_fastpath+0x16/0x1b >> 2013-08-22 06:28:51 INFO: task ceph-osd:3467 blocked for more >> than 120 seconds. >> 2013-08-22 06:28:51 "echo 0 > >> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> 2013-08-22 06:28:51 ceph-osd D ffffffff8160f760 0 3467 1 0x00000004 >> 2013-08-22 06:28:51 ffff880c375657e8 0000000000000086 >> ffff880c37565fd8 0000000000012c80 >> 2013-08-22 06:28:51 ffff880c37564010 0000000000012c80 >> 0000000000012c80 0000000000012c80 >> 2013-08-22 06:28:51 ffff880c37565fd8 0000000000012c80 >> ffff880c3850caa0 ffff880c48dd4aa0 >> 2013-08-22 06:28:51 Call Trace: >> 2013-08-22 06:28:51 [] ? xlog_bdstrat+0x1e/0x60 >> 2013-08-22 06:28:51 [] schedule+0x24/0x70 >> 2013-08-22 06:28:51 [] schedule_timeout+0x16d/0x200 >> 2013-08-22 06:28:51 [] ? xlog_sync+0x2ed/0x490 >> 2013-08-22 06:28:51 [] __down+0x6a/0xa0 >> 2013-08-22 06:28:51 [] ? _xfs_buf_find+0x107/0x290 >> 2013-08-22 06:28:51 [] down+0x3c/0x50 >> 2013-08-22 06:28:51 [] xfs_buf_lock+0x40/0xe0 >> 2013-08-22 06:28:51 [] _xfs_buf_find+0x107/0x290 >> 2013-08-22 06:28:51 [] xfs_buf_get_map+0x2f/0x180 >> 2013-08-22 06:28:51 [] >> xfs_trans_get_buf_map+0xc8/0x160 >> 2013-08-22 06:28:51 [] xfs_da_get_buf+0xb3/0xe0 >> 2013-08-22 06:28:51 [] >> xfs_attr3_leaf_to_node+0xb0/0x240 >> 2013-08-22 06:28:51 [] ? >> xfs_attr3_leaf_add+0x15b/0x1c0 >> 2013-08-22 06:28:51 [] >> xfs_attr_leaf_addname+0x14c/0x380 >> 2013-08-22 06:28:51 [] ? xfs_trans_add_item+0x28/0x70 >> 2013-08-22 06:28:50 [] ? mempool_alloc_slab+0x10/0x20 >> 2013-08-22 06:28:50 [] ? down_read+0x12/0x20 >> 2013-08-22 06:28:50 [] >> request_write+0x8a/0x380 [bcache] >> 2013-08-22 06:28:50 [] >> cached_dev_make_request+0x27b/0x350 [bcache] >> 2013-08-22 06:28:50 [] generic_make_request+0xc2/0x100 >> 2013-08-22 06:28:50 [] submit_bio+0x67/0x130 >> 2013-08-22 06:28:50 [] xfs_submit_ioend_bio+0x2f/0x40 >> 2013-08-22 06:28:50 [] xfs_submit_ioend+0xc4/0x130 >> 2013-08-22 06:28:50 [] xfs_vm_writepage+0x2eb/0x590 >> 2013-08-22 06:28:50 [] __writepage+0x12/0x40 >> 2013-08-22 06:28:50 [] write_cache_pages+0x23b/0x4e0 >> 2013-08-22 06:28:50 [] ? __schedule+0x3d7/0x6d0 >> 2013-08-22 06:28:50 [] ? set_page_dirty+0x60/0x60 >> 2013-08-22 06:28:50 [] generic_writepages+0x4c/0x70 >> 2013-08-22 06:28:50 [] xfs_vm_writepages+0x4f/0x60 >> 2013-08-22 06:28:50 [] do_writepages+0x1b/0x40 >> 2013-08-22 06:28:50 [] >> __filemap_fdatawrite_range+0x51/0x60 >> 2013-08-22 06:28:50 [] ? futex_wake+0x110/0x120 >> 2013-08-22 06:28:50 [] >> filemap_write_and_wait_range+0x7a/0xa0 >> 2013-08-22 06:28:50 [] xfs_file_fsync+0x63/0x1e0 >> 2013-08-22 06:28:50 [] vfs_fsync_range+0x23/0x30 >> 2013-08-22 06:28:50 [] vfs_fsync+0x17/0x20 >> 2013-08-22 06:28:50 [] do_fsync+0x3c/0x60 >> 2013-08-22 06:28:50 [] SyS_fdatasync+0xe/0x20 >> 2013-08-22 06:28:49 [] ? set_page_dirty+0x60/0x60 >> 2013-08-22 06:28:49 [] generic_writepages+0x4c/0x70 >> 2013-08-22 06:28:49 [] ? setxattr+0xf3/0x200 >> 2013-08-22 06:28:49 [] xfs_vm_writepages+0x4f/0x60 >> 2013-08-22 06:28:49 [] do_writepages+0x1b/0x40 >> 2013-08-22 06:28:49 [] >> __filemap_fdatawrite_range+0x51/0x60 >> 2013-08-22 06:28:49 [] >> filemap_write_and_wait_range+0x7a/0xa0 >> 2013-08-22 06:28:49 [] xfs_file_fsync+0x63/0x1e0 >> 2013-08-22 06:28:49 [] vfs_fsync_range+0x23/0x30 >> 2013-08-22 06:28:49 [] vfs_fsync+0x17/0x20 >> 2013-08-22 06:28:49 [] do_fsync+0x3c/0x60 >> 2013-08-22 06:28:49 [] SyS_fsync+0xb/0x10 >> 2013-08-22 06:28:49 [] system_call_fastpath+0x16/0x1b >> 2013-08-22 06:28:49 INFO: task ceph-osd:3483 blocked for more >> than 120 seconds. >> 2013-08-22 06:28:49 "echo 0 > >> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> 2013-08-22 06:28:49 ceph-osd D ffffffff8160f760 0 3483 1 0x00000004 >> 2013-08-22 06:28:49 ffff880c2c0d1910 0000000000000086 >> ffff880c2c0d1fd8 0000000000012c80 >> 2013-08-22 06:28:49 ffff880c2c0d0010 0000000000012c80 >> 0000000000012c80 0000000000012c80 >> 2013-08-22 06:28:49 ffff880c2c0d1fd8 0000000000012c80 >> ffff880c3a14caa0 ffff880c48dd31c0 >> 2013-08-22 06:28:49 Call Trace: >> 2013-08-22 06:28:49 [] schedule+0x24/0x70 >> 2013-08-22 06:28:49 [] >> rwsem_down_read_failed+0x9d/0xe5 >> 2013-08-22 06:28:49 [] >> call_rwsem_down_read_failed+0x14/0x30 >> 2013-08-22 06:28:48 [] ? __sb_start_write+0x71/0x110 >> 2013-08-22 06:28:48 [] ? >> __mnt_want_write_file+0x61/0x80 >> 2013-08-22 06:28:48 [] SyS_fsetxattr+0xa6/0xc0 >> 2013-08-22 06:28:48 [] system_call_fastpath+0x16/0x1b >> 2013-08-22 06:28:48 INFO: task ceph-osd:3482 blocked for more >> than 120 seconds. >> 2013-08-22 06:28:48 "echo 0 > >> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> 2013-08-22 06:28:48 ceph-osd D ffffffff8160f760 0 3482 1 0x00000004 >> 2013-08-22 06:28:48 ffff880c2c0cf910 0000000000000086 >> ffff880c2c0cffd8 0000000000012c80 >> 2013-08-22 06:28:48 ffff880c2c0ce010 0000000000012c80 >> 0000000000012c80 0000000000012c80 >> 2013-08-22 06:28:48 ffff880c2c0cffd8 0000000000012c80 >> ffff880c47768000 ffff880c48dd0000 >> 2013-08-22 06:28:48 Call Trace: >> 2013-08-22 06:28:48 [] schedule+0x24/0x70 >> 2013-08-22 06:28:48 [] >> rwsem_down_read_failed+0x9d/0xe5 >> 2013-08-22 06:28:48 [] >> call_rwsem_down_read_failed+0x14/0x30 >> 2013-08-22 06:28:48 [] ? mempool_alloc_slab+0x10/0x20 >> 2013-08-22 06:28:48 [] ? down_read+0x12/0x20 >> 2013-08-22 06:28:48 [] >> request_write+0x8a/0x380 [bcache] >> 2013-08-22 06:28:48 [] >> cached_dev_make_request+0x27b/0x350 [bcache] >> 2013-08-22 06:28:48 [] generic_make_request+0xc2/0x100 >> 2013-08-22 06:28:48 [] submit_bio+0x67/0x130 >> 2013-08-22 06:28:48 [] xfs_submit_ioend_bio+0x2f/0x40 >> 2013-08-22 06:28:48 [] xfs_submit_ioend+0xee/0x130 >> 2013-08-22 06:28:48 [] xfs_vm_writepage+0x2eb/0x590 >> 2013-08-22 06:28:48 [] __writepage+0x12/0x40 >> 2013-08-22 06:28:48 [] write_cache_pages+0x23b/0x4e0 >> 2013-08-22 06:28:47 [] _xfs_log_force+0x116/0x250 >> 2013-08-22 06:28:47 [] xfs_log_force+0x2a/0x90 >> 2013-08-22 06:28:47 [] ? _xfs_buf_find+0x107/0x290 >> 2013-08-22 06:28:47 [] xfs_buf_lock+0x73/0xe0 >> 2013-08-22 06:28:47 [] _xfs_buf_find+0x107/0x290 >> 2013-08-22 06:28:47 [] xfs_buf_get_map+0x2f/0x180 >> 2013-08-22 06:28:47 [] >> xfs_trans_get_buf_map+0xc8/0x160 >> 2013-08-22 06:28:47 [] xfs_da_get_buf+0xb3/0xe0 >> 2013-08-22 06:28:47 [] >> xfs_attr3_leaf_to_node+0xb0/0x240 >> 2013-08-22 06:28:47 [] ? >> xfs_attr3_leaf_add+0x15b/0x1c0 >> 2013-08-22 06:28:47 [] >> xfs_attr_leaf_addname+0x14c/0x380 >> 2013-08-22 06:28:47 [] ? xfs_trans_add_item+0x28/0x70 >> 2013-08-22 06:28:47 [] ? xfs_bmbt_get_all+0x13/0x20 >> 2013-08-22 06:28:47 [] xfs_attr_set_int+0x3a4/0x4f0 >> 2013-08-22 06:28:47 [] xfs_attr_set+0x81/0x90 >> 2013-08-22 06:28:47 [] xfs_xattr_set+0x42/0x60 >> 2013-08-22 06:28:47 [] generic_setxattr+0x9b/0xb0 >> 2013-08-22 06:28:47 [] __vfs_setxattr_noperm+0x5f/0xe0 >> 2013-08-22 06:28:47 [] vfs_setxattr+0xb4/0xc0 >> 2013-08-22 06:28:47 [] setxattr+0xbe/0x200 >> 2013-08-22 06:28:47 [] xfs_buf_iorequest+0x4a/0xa0 >> 2013-08-22 06:28:47 [] xlog_bdstrat+0x1e/0x60 >> 2013-08-22 06:28:47 [] xlog_sync+0x2ed/0x490 >> 2013-08-22 06:28:47 [] >> xlog_state_release_iclog+0x8b/0xc0 >> 2013-08-22 06:28:46 [] SyS_syncfs+0x50/0x90 >> 2013-08-22 06:28:46 [] system_call_fastpath+0x16/0x1b >> 2013-08-22 06:28:46 INFO: task ceph-osd:3481 blocked for more >> than 120 seconds. >> 2013-08-22 06:28:46 "echo 0 > >> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> 2013-08-22 06:28:46 ceph-osd D ffffffff8160f760 0 3481 1 0x00000004 >> 2013-08-22 06:28:46 ffff880c2c0cd500 0000000000000086 >> ffff880c2c0cdfd8 0000000000012c80 >> 2013-08-22 06:28:46 ffff880c2c0cc010 0000000000012c80 >> 0000000000012c80 0000000000012c80 >> 2013-08-22 06:28:46 ffff880c2c0cdfd8 0000000000012c80 >> ffff880c4776b1c0 ffff880c48dd4aa0 >> 2013-08-22 06:28:46 Call Trace: >> 2013-08-22 06:28:46 [] ? xfs_trans_brelse+0xb6/0x100 >> 2013-08-22 06:28:46 [] schedule+0x24/0x70 >> 2013-08-22 06:28:46 [] >> rwsem_down_read_failed+0x9d/0xe5 >> 2013-08-22 06:28:46 [] >> call_rwsem_down_read_failed+0x14/0x30 >> 2013-08-22 06:28:46 [] ? mempool_alloc_slab+0x10/0x20 >> 2013-08-22 06:28:46 [] ? down_read+0x12/0x20 >> 2013-08-22 06:28:46 [] >> request_write+0x8a/0x380 [bcache] >> 2013-08-22 06:28:46 [] >> cached_dev_make_request+0x27b/0x350 [bcache] >> 2013-08-22 06:28:46 [] generic_make_request+0xc2/0x100 >> 2013-08-22 06:28:46 [] submit_bio+0x67/0x130 >> 2013-08-22 06:28:46 [] xfs_buf_ioapply_map+0x180/0x1d0 >> 2013-08-22 06:28:46 [] _xfs_buf_ioapply+0x107/0x150 >> 2013-08-22 06:28:46 [] ? xlog_bdstrat+0x1e/0x60 >> 2013-08-22 06:28:45 "echo 0 > >> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> 2013-08-22 06:28:45 ceph-osd D ffffffff8160f760 0 3462 1 0x00000004 >> 2013-08-22 06:28:45 ffff880c375cdc28 0000000000000086 >> ffff880c375cdfd8 0000000000012c80 >> 2013-08-22 06:28:45 ffff880c375cc010 0000000000012c80 >> 0000000000012c80 0000000000012c80 >> 2013-08-22 06:28:45 ffff880c375cdfd8 0000000000012c80 >> ffff880c46318000 ffff880c48dd6380 >> 2013-08-22 06:28:45 Call Trace: >> 2013-08-22 06:28:45 [] ? __lock_page+0x70/0x70 >> 2013-08-22 06:28:45 [] schedule+0x24/0x70 >> 2013-08-22 06:28:45 [] io_schedule+0x87/0xd0 >> 2013-08-22 06:28:45 [] sleep_on_page+0x9/0x10 >> 2013-08-22 06:28:45 [] __wait_on_bit+0x57/0x80 >> 2013-08-22 06:28:45 [] ? find_get_pages_tag+0xcc/0x180 >> 2013-08-22 06:28:45 [] wait_on_page_bit+0x6e/0x80 >> 2013-08-22 06:28:45 [] ? >> autoremove_wake_function+0x40/0x40 >> 2013-08-22 06:28:45 [] ? pagevec_lookup_tag+0x20/0x30 >> 2013-08-22 06:28:45 [] >> filemap_fdatawait_range+0x10f/0x1b0 >> 2013-08-22 06:28:45 [] ? schedule+0x24/0x70 >> 2013-08-22 06:28:45 [] ? schedule_timeout+0x16d/0x200 >> 2013-08-22 06:28:45 [] ? >> __queue_delayed_work+0xaa/0x1a0 >> 2013-08-22 06:28:45 [] filemap_fdatawait+0x23/0x30 >> 2013-08-22 06:28:45 [] wait_sb_inodes+0xb5/0x110 >> 2013-08-22 06:28:45 [] sync_inodes_sb+0x9c/0xd0 >> 2013-08-22 06:28:45 [] __sync_filesystem+0x16/0x50 >> 2013-08-22 06:28:45 [] sync_filesystem+0x43/0x60 >> 2013-08-22 06:28:44 [] >> cached_dev_make_request+0x27b/0x350 [bcache] >> 2013-08-22 06:28:44 [] generic_make_request+0xc2/0x100 >> 2013-08-22 06:28:44 [] submit_bio+0x67/0x130 >> 2013-08-22 06:28:44 [] xfs_submit_ioend_bio+0x2f/0x40 >> 2013-08-22 06:28:44 [] xfs_submit_ioend+0xee/0x130 >> 2013-08-22 06:28:44 [] xfs_vm_writepage+0x2eb/0x590 >> 2013-08-22 06:28:44 [] __writepage+0x12/0x40 >> 2013-08-22 06:28:44 [] write_cache_pages+0x23b/0x4e0 >> 2013-08-22 06:28:44 [] ? __schedule+0x3d7/0x6d0 >> 2013-08-22 06:28:44 [] ? set_page_dirty+0x60/0x60 >> 2013-08-22 06:28:44 [] generic_writepages+0x4c/0x70 >> 2013-08-22 06:28:44 [] xfs_vm_writepages+0x4f/0x60 >> 2013-08-22 06:28:44 [] do_writepages+0x1b/0x40 >> 2013-08-22 06:28:44 [] >> __filemap_fdatawrite_range+0x51/0x60 >> 2013-08-22 06:28:44 [] ? futex_wake+0x110/0x120 >> 2013-08-22 06:28:44 [] >> filemap_write_and_wait_range+0x7a/0xa0 >> 2013-08-22 06:28:44 [] xfs_file_fsync+0x63/0x1e0 >> 2013-08-22 06:28:44 [] vfs_fsync_range+0x23/0x30 >> 2013-08-22 06:28:44 [] vfs_fsync+0x17/0x20 >> 2013-08-22 06:28:44 [] do_fsync+0x3c/0x60 >> 2013-08-22 06:28:44 [] SyS_fdatasync+0xe/0x20 >> 2013-08-22 06:28:44 [] system_call_fastpath+0x16/0x1b >> 2013-08-22 06:28:44 INFO: task ceph-osd:3462 blocked for more >> than 120 seconds. >> 2013-08-22 06:28:43 INFO: task ceph-osd:24130 blocked for more >> than 120 seconds. >> 2013-08-22 06:28:43 "echo 0 > >> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> 2013-08-22 06:28:43 ceph-osd D ffffffff8160f760 0 24130 1 0x00000004 >> 2013-08-22 06:28:43 ffff880c27fe98d8 0000000000000082 >> ffff880c27fe9fd8 0000000000012c80 >> 2013-08-22 06:28:43 ffff880c27fe8010 0000000000012c80 >> 0000000000012c80 0000000000012c80 >> 2013-08-22 06:28:43 ffff880c27fe9fd8 0000000000012c80 >> ffff880c215e6380 ffff880c48decaa0 >> 2013-08-22 06:28:43 Call Trace: >> 2013-08-22 06:28:43 [] ? __wait_on_buffer+0x30/0x30 >> 2013-08-22 06:28:43 [] schedule+0x24/0x70 >> 2013-08-22 06:28:43 [] io_schedule+0x87/0xd0 >> 2013-08-22 06:28:43 [] sleep_on_buffer+0x9/0x10 >> 2013-08-22 06:28:43 [] __wait_on_bit+0x57/0x80 >> 2013-08-22 06:28:43 [] ? __wait_on_buffer+0x30/0x30 >> 2013-08-22 06:28:43 [] >> out_of_line_wait_on_bit+0x73/0x90 >> 2013-08-22 06:28:43 [] ? >> autoremove_wake_function+0x40/0x40 >> 2013-08-22 06:28:43 [] ? submit_bh+0xb/0x10 >> 2013-08-22 06:28:43 [] __wait_on_buffer+0x26/0x30 >> 2013-08-22 06:28:43 [] __block_write_begin+0x383/0x530 >> 2013-08-22 06:28:43 [] ? >> xfs_get_blocks_direct+0x20/0x20 >> 2013-08-22 06:28:43 [] ? >> grab_cache_page_write_begin+0x9f/0xd0 >> 2013-08-22 06:28:43 [] xfs_vm_write_begin+0x5f/0xd0 >> 2013-08-22 06:28:43 [] >> generic_perform_write+0xca/0x200 >> 2013-08-22 06:28:43 [] >> generic_file_buffered_write+0x5f/0x90 >> 2013-08-22 06:28:43 [] >> xfs_file_buffered_aio_write+0xf5/0x180 >> 2013-08-22 06:28:43 [] xfs_file_aio_write+0xce/0x150 >> 2013-08-22 06:28:43 [] ? path_put+0x1d/0x30 >> 2013-08-22 06:28:43 [] do_sync_readv_writev+0x68/0xa0 >> 2013-08-22 06:28:43 [] do_readv_writev+0xf2/0x2e0 >> 2013-08-22 06:28:43 [] ? >> xfs_file_buffered_aio_write+0x180/0x180 >> 2013-08-22 06:28:43 [] ? >> do_sync_readv_writev+0xa0/0xa0 >> 2013-08-22 06:28:43 [] vfs_writev+0x3e/0x60 >> 2013-08-22 06:28:43 [] SyS_writev+0x5a/0xc0 >> 2013-08-22 06:28:43 [] ? SyS_lseek+0x53/0x80 >> 2013-08-22 06:28:43 [] system_call_fastpath+0x16/0x1b >> 2013-08-22 06:28:43 INFO: task ceph-osd:24134 blocked for more >> than 120 seconds. >> 2013-08-22 06:28:43 "echo 0 > >> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> 2013-08-22 06:28:43 ceph-osd D ffffffff8160f760 0 24134 1 0x00000004 >> 2013-08-22 06:28:43 ffff880c23d31708 0000000000000082 >> ffff880c23d31fd8 0000000000012c80 >> 2013-08-22 06:28:43 ffff880c23d30010 0000000000012c80 >> 0000000000012c80 0000000000012c80 >> 2013-08-22 06:28:43 ffff880c23d31fd8 0000000000012c80 >> ffff880c361e0000 ffff880c48dd4aa0 >> 2013-08-22 06:28:43 Call Trace: >> 2013-08-22 06:28:43 [] schedule+0x24/0x70 >> 2013-08-22 06:28:43 [] >> schedule_preempt_disabled+0x9/0x10 >> 2013-08-22 06:28:43 [] >> __mutex_lock_slowpath+0x194/0x240 >> 2013-08-22 06:28:43 [] mutex_lock+0x1e/0x40 >> 2013-08-22 06:28:43 [] >> bch_bucket_alloc_set+0x3b/0x80 [bcache] >> 2013-08-22 06:28:43 [] >> bch_alloc_sectors+0x12c/0x4e0 [bcache] >> 2013-08-22 06:28:43 [] ? >> bch_generic_make_request_hack+0x25/0xc0 [bcache] >> 2013-08-22 06:28:43 [] ? >> __bch_submit_bbio+0x73/0x80 [bcache] >> 2013-08-22 06:28:43 [] >> bch_insert_data_loop+0xf8/0x610 [bcache] >> 2013-08-22 06:28:43 [] ? >> bch_get_congested+0x25/0x70 [bcache] >> 2013-08-22 06:28:43 [] >> bch_insert_data+0x1d/0x20 [bcache] >> 2013-08-22 06:28:43 [] closure_queue+0x43/0x60 >> [bcache] >> 2013-08-22 06:28:43 [] >> request_write+0x19e/0x380 [bcache] >> >> Am 22.08.2013 01:47, schrieb Kent Overstreet: >>> On Tue, Aug 20, 2013 at 10:07:45AM +0200, Stefan Priebe - Profihost AG wrote: >>>> Am 20.08.2013 10:01, schrieb Stefan Priebe - Profihost AG: >>>>> Am 20.08.2013 00:27, schrieb Kent Overstreet: >>>>>> On Mon, Aug 19, 2013 at 12:09:24AM +0200, Stefan Priebe wrote: >>>>>>> >>>>>>> Vanilla 3.10.7 + bcache: Fix a writeback performance regression >>>>>>> >>>>>>> http://pastebin.com/raw.php?i=LXZk4cMH >>>>>> >>>>>> Whoops, at first I thought this was the same bug as one I'd already been >>>>>> chasing down that had been a harmless bug - turns out I didn't look >>>>>> closely enough at the backtrace. >>>>>> >>>>>> What happened is background writeback is deadlocking, because for some >>>>>> reason the workqueue it's running out of is a singlethreaded workqueue, >>>>>> so as soon as it decides to queue enough writeback bios that it has to >>>>>> sleep on that semaphore (which often won't happen due to the PD >>>>>> controller based ratelimiting) - boom, deadlock. >>>>>> >>>>>> Here's the fixup patch I just tested and am applying: >>>> >>>> Oh i'm now seeing very high CPU spikes of kworker... i don't see if i >>>> remove bcache: Fix a writeback performance regression. >>> >>> Are you able to reproduce it? I'm not having any luck reproducing it... >>> -- >>> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in >>> the body of a message to majordomo@vger.kernel.org >>> More majordomo info at http://vger.kernel.org/majordomo-info.html >>> > -- > To unsubscribe from this list: send the line "unsubscribe linux-bcache" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html > -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/