From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mout.gmx.net ([212.227.15.19]:64272 "EHLO mout.gmx.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752953Ab3LaLqJ (ORCPT ); Tue, 31 Dec 2013 06:46:09 -0500 Received: from [192.168.0.2] ([93.82.95.55]) by mail.gmx.com (mrgmx103) with ESMTPSA (Nemesis) id 0MDi9C-1WDsav42YQ-00H4D9 for ; Tue, 31 Dec 2013 12:46:08 +0100 Message-ID: <52C2AE7C.5020601@gmx.at> Date: Tue, 31 Dec 2013 12:46:04 +0100 From: Sulla MIME-Version: 1.0 To: linux-btrfs@vger.kernel.org Subject: btrfs-transaction blocked for more than 120 seconds Content-Type: text/plain; charset=ISO-8859-1 Sender: linux-btrfs-owner@vger.kernel.org List-ID: Dear all! On my Ubuntu Server 13.10 I use a RAID5 blockdevice consisting of 3 WD20EARS drives. On this I built a LVM and in this LVM I use quite normal partitions /, /home, SWAP (/boot resides on a RAID1.) and also a custom /data partition. Everything (except boot and swap) is on btrfs. sometimes my system hangs for quite some time (top is showing a high wait percentage), then runs on normally. I get kernel messages into /var/log/sylsog, see below. I am unable to make any sense of the kernel messages, there is no reference to the filesystem or drive affected (at least I can not find one). Question: What is happening here? * Is a HDD failing (smart looks good, however) * Is something wrong with my btrfs-filesystem? with which one? * How can I find the cause? thanks, Wolfgang Dec 31 12:27:49 freedom kernel: [ 4681.264112] INFO: task btrfs-transacti:529 blocked for more than 120 seconds. Dec 31 12:27:49 freedom kernel: [ 4681.264239] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Dec 31 12:27:49 freedom kernel: [ 4681.264367] btrfs-transacti D ffff88013fc14580 0 529 2 0x00000000 Dec 31 12:27:49 freedom kernel: [ 4681.264377] ffff880138345e10 0000000000000046 ffff880138345fd8 0000000000014580 Dec 31 12:27:49 freedom kernel: [ 4681.264386] ffff880138345fd8 0000000000014580 ffff880135615dc0 ffff880132fb6a00 Dec 31 12:27:49 freedom kernel: [ 4681.264393] ffff880133f45800 ffff880138345e30 ffff880137ee2000 ffff880137ee2070 Dec 31 12:27:49 freedom kernel: [ 4681.264402] Call Trace: Dec 31 12:27:49 freedom kernel: [ 4681.264418] [] schedule+0x29/0x70 Dec 31 12:27:49 freedom kernel: [ 4681.264477] [] btrfs_commit_transaction+0x34d/0x980 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.264487] [] ? wake_up_atomic_t+0x30/0x30 Dec 31 12:27:49 freedom kernel: [ 4681.264517] [] transaction_kthread+0x1a5/0x240 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.264548] [] ? verify_parent_transid+0x150/0x150 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.264557] [] kthread+0xc0/0xd0 Dec 31 12:27:49 freedom kernel: [ 4681.264565] [] ? kthread_create_on_node+0x120/0x120 Dec 31 12:27:49 freedom kernel: [ 4681.264573] [] ret_from_fork+0x7c/0xb0 Dec 31 12:27:49 freedom kernel: [ 4681.264580] [] ? kthread_create_on_node+0x120/0x120 Dec 31 12:27:49 freedom kernel: [ 4681.264610] INFO: task kworker/u4:0:9975 blocked for more than 120 seconds. Dec 31 12:27:49 freedom kernel: [ 4681.264722] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Dec 31 12:27:49 freedom kernel: [ 4681.264847] kworker/u4:0 D ffff88013fd14580 0 9975 2 0x00000000 Dec 31 12:27:49 freedom kernel: [ 4681.264861] Workqueue: writeback bdi_writeback_workfn (flush-btrfs-4) Dec 31 12:27:49 freedom kernel: [ 4681.264865] ffff8800a8739538 0000000000000046 ffff8800a8739fd8 0000000000014580 Dec 31 12:27:49 freedom kernel: [ 4681.264873] ffff8800a8739fd8 0000000000014580 ffff8801351e5dc0 ffff8801351e5dc0 Dec 31 12:27:49 freedom kernel: [ 4681.264880] ffff880134c5e6a8 ffff880134c5e6b0 ffffffff00000000 ffff880134c5e6b8 Dec 31 12:27:49 freedom kernel: [ 4681.264887] Call Trace: Dec 31 12:27:49 freedom kernel: [ 4681.264895] [] schedule+0x29/0x70 Dec 31 12:27:49 freedom kernel: [ 4681.264902] [] rwsem_down_write_failed+0x105/0x1e0 Dec 31 12:27:49 freedom kernel: [ 4681.264911] [] ? __rwsem_do_wake+0xdd/0x160 Dec 31 12:27:49 freedom kernel: [ 4681.264918] [] call_rwsem_down_write_failed+0x13/0x20 Dec 31 12:27:49 freedom kernel: [ 4681.264927] [] ? down_write+0x2d/0x30 Dec 31 12:27:49 freedom kernel: [ 4681.264956] [] cache_block_group+0x290/0x3b0 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.264963] [] ? wake_up_atomic_t+0x30/0x30 Dec 31 12:27:49 freedom kernel: [ 4681.264991] [] find_free_extent+0xa38/0xac0 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265022] [] btrfs_reserve_extent+0xa2/0x1c0 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265056] [] __cow_file_range+0x15d/0x4a0 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265090] [] cow_file_range+0x8a/0xd0 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265122] [] run_delalloc_range+0x350/0x390 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265158] [] ? find_lock_delalloc_range.constprop.42+0x1d1/0x1f0 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265194] [] __extent_writepage+0x304/0x750 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265202] [] ? set_next_entity+0x95/0xb0 Dec 31 12:27:49 freedom kernel: [ 4681.265212] [] ? __switch_to+0x126/0x4b0 Dec 31 12:27:49 freedom kernel: [ 4681.265221] [] ? default_spin_lock_flags+0x9/0x10 Dec 31 12:27:49 freedom kernel: [ 4681.265229] [] ? find_get_pages_tag+0xd1/0x180 Dec 31 12:27:49 freedom kernel: [ 4681.265266] [] extent_write_cache_pages.isra.31.constprop.46+0x282/0x3e0 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265303] [] extent_writepages+0x4d/0x70 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265336] [] ? btrfs_real_readdir+0x5c0/0x5c0 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265369] [] btrfs_writepages+0x28/0x30 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265378] [] do_writepages+0x1e/0x40 Dec 31 12:27:49 freedom kernel: [ 4681.265387] [] __writeback_single_inode+0x40/0x220 Dec 31 12:27:49 freedom kernel: [ 4681.265395] [] writeback_sb_inodes+0x19b/0x3b0 Dec 31 12:27:49 freedom kernel: [ 4681.265403] [] __writeback_inodes_wb+0x9f/0xd0 Dec 31 12:27:49 freedom kernel: [ 4681.265411] [] wb_writeback+0x243/0x2c0 Dec 31 12:27:49 freedom kernel: [ 4681.265418] [] bdi_writeback_workfn+0x1b9/0x3d0 Dec 31 12:27:49 freedom kernel: [ 4681.265426] [] process_one_work+0x17c/0x430 Dec 31 12:27:49 freedom kernel: [ 4681.265432] [] worker_thread+0x11c/0x3c0 Dec 31 12:27:49 freedom kernel: [ 4681.265439] [] ? manage_workers.isra.24+0x2a0/0x2a0 Dec 31 12:27:49 freedom kernel: [ 4681.265447] [] kthread+0xc0/0xd0 Dec 31 12:27:49 freedom kernel: [ 4681.265454] [] ? kthread_create_on_node+0x120/0x120 Dec 31 12:27:49 freedom kernel: [ 4681.265461] [] ret_from_fork+0x7c/0xb0 Dec 31 12:27:49 freedom kernel: [ 4681.265469] [] ? kthread_create_on_node+0x120/0x120 Dec 31 12:27:49 freedom kernel: [ 4681.265476] INFO: task smbd:10275 blocked for more than 120 seconds. Dec 31 12:27:49 freedom kernel: [ 4681.265579] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Dec 31 12:27:49 freedom kernel: [ 4681.265704] smbd D ffff88013fc14580 0 10275 723 0x00000004 Dec 31 12:27:49 freedom kernel: [ 4681.265711] ffff8800a5abbbc0 0000000000000046 ffff8800a5abbfd8 0000000000014580 Dec 31 12:27:49 freedom kernel: [ 4681.265718] ffff8800a5abbfd8 0000000000014580 ffff880133d5aee0 ffff880137ee2000 Dec 31 12:27:49 freedom kernel: [ 4681.265726] ffff880133db79e8 ffff880133db79e8 0000000000000001 ffff880132d2dc80 Dec 31 12:27:49 freedom kernel: [ 4681.265733] Call Trace: Dec 31 12:27:49 freedom kernel: [ 4681.265739] [] schedule+0x29/0x70 Dec 31 12:27:49 freedom kernel: [ 4681.265772] [] wait_current_trans.isra.18+0xbf/0x120 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265778] [] ? wake_up_atomic_t+0x30/0x30 Dec 31 12:27:49 freedom kernel: [ 4681.265810] [] start_transaction+0x356/0x520 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265843] [] btrfs_start_transaction+0x1b/0x20 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265876] [] btrfs_cont_expand+0x1c7/0x460 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265911] [] btrfs_file_aio_write+0x346/0x520 [btrfs] Dec 31 12:27:49 freedom kernel: [ 4681.265919] [] ? poll_select_copy_remaining+0x130/0x130 Dec 31 12:27:49 freedom kernel: [ 4681.265928] [] do_sync_write+0x80/0xb0 Dec 31 12:27:49 freedom kernel: [ 4681.265936] [] vfs_write+0xbd/0x1e0 Dec 31 12:27:49 freedom kernel: [ 4681.265942] [] SyS_pwrite64+0x72/0xb0 Dec 31 12:27:49 freedom kernel: [ 4681.265949] [] system_call_fastpath+0x1a/0x1f -- For a successful technology, reality must take precedence over public relations, for Nature cannot be fooled. Richard P. Feynman