From mboxrd@z Thu Jan 1 00:00:00 1970 From: Roman Mamedov Subject: btrfs lock-up on copying files Date: Thu, 30 Jun 2011 12:37:38 +0600 Message-ID: <20110630123738.6042e563@natsu> Mime-Version: 1.0 Content-Type: multipart/signed; micalg=PGP-SHA1; boundary="Sig_/t9_BcqNHKspdO+RNP3nEC=0"; protocol="application/pgp-signature" To: linux-btrfs Return-path: List-ID: --Sig_/t9_BcqNHKspdO+RNP3nEC=0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: quoted-printable Hello, I was copying a set of files to a btrfs filesystem, and the copy process lo= cked-up with the following messages in dmesg. The kernel version is 2.6.39.1; the filesystem was recently resized from 3 = to 4TB (if that matters). It is mounted remotely via AoE but the remote host is up and no errors rega= rding block devices are registered on it. The network is fine and the AoE device with btrfs continues to be accessibl= e normally on the client. ---------------------------------------------------------------------------= --------------------------- [2054595.220707] device fsid df4e3e1ef28f59c2-60011bb47a1f19ab devid 1 tran= sid 120743 /dev/etherd/e1.1 [2054595.221402] btrfs: use zlib compression [2054595.221405] btrfs: force clearing of disk cache [2054595.291517] btrfs: disk space caching is enabled [2055480.556022] INFO: task kthreadd:2 blocked for more than 120 seconds. [2055480.556026] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable= s this message. [2055480.556028] kthreadd D ffff8800bfd13cc0 0 2 0 0x00= 000000 [2055480.556032] ffff8800bc2786c0 0000000000000046 ffff8800bfd16eb8 000000= 0000000000 [2055480.556036] ffff880095d3e540 0000000000013cc0 ffff8800bc277fd8 000000= 0000013cc0 [2055480.556039] ffff8800bc276000 ffff8800bc277fd8 0000000000013cc0 ffff88= 00bc2786c0 [2055480.556043] Call Trace: [2055480.556050] [] ? __lock_page+0x70/0x70 [2055480.556054] [] ? io_schedule+0x84/0xd0 [2055480.556057] [] ? sleep_on_page+0x9/0x10 [2055480.556059] [] ? __wait_on_bit_lock+0x4a/0xb0 [2055480.556062] [] ? __lock_page+0x5e/0x70 [2055480.556066] [] ? autoremove_wake_function+0x30/0x30 [2055480.556069] [] ? _cond_resched+0x2f/0x40 [2055480.556073] [] ? move_to_new_page+0x23b/0x240 [2055480.556076] [] ? migrate_pages+0x3f3/0x490 [2055480.556078] [] ? perf_trace_mm_compaction_migratepa= ges+0xf0/0xf0 [2055480.556081] [] ? compact_zone+0x591/0x880 [2055480.556084] [] ? compact_zone_order+0xa9/0xf0 [2055480.556087] [] ? delayacct_end+0x82/0xa0 [2055480.556090] [] ? try_to_compact_pages+0xf0/0x120 [2055480.556093] [] ? __alloc_pages_direct_compact+0xde/= 0x1b0 [2055480.556096] [] ? __alloc_pages_nodemask+0x4d7/0x920 [2055480.556100] [] ? copy_process+0x148/0x1230 [2055480.556103] [] ? do_fork+0x71/0x380 [2055480.556106] [] ? native_sched_clock+0x11/0x60 [2055480.556110] [] ? update_curr+0xea/0x1f0 [2055480.556113] [] ? kernel_thread+0x7c/0x90 [2055480.556116] [] ? kthread_worker_fn+0x1a0/0x1a0 [2055480.556119] [] ? gs_change+0x13/0x13 [2055480.556121] [] ? kthreadd+0x106/0x140 [2055480.556124] [] ? kernel_thread_helper+0x4/0x10 [2055480.556127] [] ? tsk_fork_get_node+0x20/0x20 [2055480.556129] [] ? gs_change+0x13/0x13 [2055480.556166] INFO: task btrfs-transacti:24692 blocked for more than 120= seconds. [2055480.556167] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable= s this message. [2055480.556169] btrfs-transacti D ffff8800bfd13cc0 0 24692 2 0x00= 000000 [2055480.556173] ffff8800871d4380 0000000000000046 0000000000000ec2 ffff88= 0000000000 [2055480.556176] ffff8800bc27ca40 0000000000013cc0 ffff88008a643fd8 000000= 0000013cc0 [2055480.556179] ffff88008a642000 ffff88008a643fd8 0000000000013cc0 ffff88= 00871d4380 [2055480.556182] Call Trace: [2055480.556185] [] ? schedule_timeout+0x22d/0x310 [2055480.556219] [] ? btrfs_run_delayed_refs+0xc7/0x210 = [btrfs] [2055480.556222] [] ? mutex_lock+0x16/0x50 [2055480.556233] [] ? btrfs_run_ordered_operations+0x1cd= /0x1f0 [btrfs] [2055480.556245] [] ? btrfs_commit_transaction+0x26d/0x7= a0 [btrfs] [2055480.556248] [] ? wake_up_bit+0x40/0x40 [2055480.556258] [] ? transaction_kthread+0x273/0x290 [b= trfs] [2055480.556268] [] ? btrfs_congested_fn+0x90/0x90 [btrf= s] [2055480.556278] [] ? btrfs_congested_fn+0x90/0x90 [btrf= s] [2055480.556281] [] ? kthread+0x96/0xa0 [2055480.556284] [] ? kernel_thread_helper+0x4/0x10 [2055480.556287] [] ? kthread_worker_fn+0x1a0/0x1a0 [2055480.556289] [] ? gs_change+0x13/0x13 [2055480.556291] INFO: task mirrordir:24715 blocked for more than 120 secon= ds. [2055480.556293] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable= s this message. [2055480.556295] mirrordir D ffff8800bfd13cc0 0 24715 24660 0x00= 000000 [2055480.556298] ffff880087278d80 0000000000000082 0000000000000003 ffff88= 000d8b1910 [2055480.556301] ffff880095d3e540 0000000000013cc0 ffff88000d8b1fd8 000000= 0000013cc0 [2055480.556304] ffff88000d8b0000 ffff88000d8b1fd8 0000000000013cc0 ffff88= 0087278d80 [2055480.556307] Call Trace: [2055480.556317] [] ? __extent_writepage+0x386/0x760 [bt= rfs] [2055480.556320] [] ? __lock_page+0x70/0x70 [2055480.556323] [] ? io_schedule+0x84/0xd0 [2055480.556326] [] ? sleep_on_page+0x9/0x10 [2055480.556328] [] ? __wait_on_bit_lock+0x4a/0xb0 [2055480.556331] [] ? __lock_page+0x5e/0x70 [2055480.556334] [] ? autoremove_wake_function+0x30/0x30 [2055480.556345] [] ? extent_write_cache_pages.clone.18.= clone.25+0x1b3/0x2e0 [btrfs] [2055480.556356] [] ? extent_writepages+0x40/0x60 [btrfs] [2055480.556367] [] ? btrfs_writepage_fixup_worker+0x150= /0x150 [btrfs] [2055480.556371] [] ? writeback_single_inode+0x104/0x250 [2055480.556373] [] ? writeback_sb_inodes+0xf6/0x1a0 [2055480.556376] [] ? writeback_inodes_wb+0x8d/0x1a0 [2055480.556379] [] ? balance_dirty_pages_ratelimited_nr= +0x3bb/0x4b0 [2055480.556391] [] ? __btrfs_buffered_write.clone.13+0x= 22c/0x2f0 [btrfs] [2055480.556394] [] ? current_fs_time+0xd/0x50 [2055480.556405] [] ? btrfs_file_aio_write+0x22d/0x4a0 [= btrfs] [2055480.556416] [] ? btrfs_file_aio_write+0x2/0x4a0 [bt= rfs] [2055480.556420] [] ? do_sync_write+0xbf/0x100 [2055480.556424] [] ? security_file_permission+0x24/0xc0 [2055480.556427] [] ? vfs_write+0xc6/0x180 [2055480.556430] [] ? sys_write+0x4e/0x90 [2055480.556433] [] ? system_call_fastpath+0x16/0x1b [2055480.556436] INFO: task btrfs-delalloc-:24754 blocked for more than 120= seconds. [2055480.556437] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable= s this message. [2055480.556439] btrfs-delalloc- D ffff8800bfd13cc0 0 24754 2 0x00= 000000 [2055480.556442] ffff880095d39b00 0000000000000046 ffff8800bffe7c08 000000= 0200000001 [2055480.556446] ffff8800af69d7c0 0000000000013cc0 ffff8800060c3fd8 000000= 0000013cc0 [2055480.556449] ffff8800060c2000 ffff8800060c3fd8 0000000000013cc0 ffff88= 0095d39b00 [2055480.556452] Call Trace: [2055480.556455] [] ? schedule_timeout+0x22d/0x310 [2055480.556458] [] ? select_task_rq_fair+0x2f3/0x750 [2055480.556461] [] ? wait_for_common+0xe1/0x1a0 [2055480.556464] [] ? try_to_wake_up+0x320/0x320 [2055480.556466] [] ? try_to_wake_up+0xbc/0x320 [2055480.556471] [] ? kthread_create_on_node+0x8f/0x110 [2055480.556480] [] ? btrfs_put_block_group+0x70/0x70 [b= trfs] [2055480.556484] [] ? rwsem_wake+0x4a/0x60 [2055480.556487] [] ? call_rwsem_wake+0x17/0x30 [2055480.556498] [] ? cache_block_group+0x1ba/0x2a0 [btr= fs] [2055480.556508] [] ? find_free_extent.clone.64+0x400/0x= aa0 [btrfs] [2055480.556518] [] ? btrfs_reserve_extent+0xea/0x1b0 [b= trfs] [2055480.556529] [] ? cow_file_range+0x16b/0x370 [btrfs] [2055480.556540] [] ? submit_compressed_extents+0x228/0x= 440 [btrfs] [2055480.556544] [] ? try_to_del_timer_sync+0x7a/0xd0 [2055480.556554] [] ? run_ordered_completions+0x63/0xc0 = [btrfs] [2055480.556564] [] ? worker_loop+0xb1/0x510 [btrfs] [2055480.556574] [] ? btrfs_queue_worker+0x2f0/0x2f0 [bt= rfs] [2055480.556583] [] ? btrfs_queue_worker+0x2f0/0x2f0 [bt= rfs] [2055480.556587] [] ? kthread+0x96/0xa0 [2055480.556589] [] ? kernel_thread_helper+0x4/0x10 [2055480.556593] [] ? kthread_worker_fn+0x1a0/0x1a0 [2055480.556595] [] ? gs_change+0x13/0x13 [2055600.556049] INFO: task btrfs-transacti:24692 blocked for more than 120= seconds. [2055600.556052] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable= s this message. [2055600.556055] btrfs-transacti D ffff8800bfd13cc0 0 24692 2 0x00= 000000 [2055600.556059] ffff8800871d4380 0000000000000046 0000000000000ec2 ffff88= 0000000000 [2055600.556063] ffff8800bc27ca40 0000000000013cc0 ffff88008a643fd8 000000= 0000013cc0 [2055600.556066] ffff88008a642000 ffff88008a643fd8 0000000000013cc0 ffff88= 00871d4380 [2055600.556069] Call Trace: [2055600.556077] [] ? schedule_timeout+0x22d/0x310 [2055600.556110] [] ? btrfs_run_delayed_refs+0xc7/0x210 = [btrfs] [2055600.556113] [] ? mutex_lock+0x16/0x50 [2055600.556125] [] ? btrfs_run_ordered_operations+0x1cd= /0x1f0 [btrfs] [2055600.556136] [] ? btrfs_commit_transaction+0x26d/0x7= a0 [btrfs] [2055600.556141] [] ? wake_up_bit+0x40/0x40 [2055600.556151] [] ? transaction_kthread+0x273/0x290 [b= trfs] [2055600.556161] [] ? btrfs_congested_fn+0x90/0x90 [btrf= s] [2055600.556171] [] ? btrfs_congested_fn+0x90/0x90 [btrf= s] [2055600.556174] [] ? kthread+0x96/0xa0 [2055600.556178] [] ? kernel_thread_helper+0x4/0x10 [2055600.556181] [] ? kthread_worker_fn+0x1a0/0x1a0 [2055600.556183] [] ? gs_change+0x13/0x13 [2055600.556186] INFO: task mirrordir:24715 blocked for more than 120 secon= ds. [2055600.556187] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable= s this message. [2055600.556189] mirrordir D ffff8800bfd13cc0 0 24715 24660 0x00= 000000 [2055600.556193] ffff880087278d80 0000000000000082 0000000000000003 ffff88= 000d8b1910 [2055600.556196] ffff880095d3e540 0000000000013cc0 ffff88000d8b1fd8 000000= 0000013cc0 [2055600.556199] ffff88000d8b0000 ffff88000d8b1fd8 0000000000013cc0 ffff88= 0087278d80 [2055600.556203] Call Trace: [2055600.556214] [] ? __extent_writepage+0x386/0x760 [bt= rfs] [2055600.556217] [] ? __lock_page+0x70/0x70 [2055600.556220] [] ? io_schedule+0x84/0xd0 [2055600.556223] [] ? sleep_on_page+0x9/0x10 [2055600.556226] [] ? __wait_on_bit_lock+0x4a/0xb0 [2055600.556228] [] ? __lock_page+0x5e/0x70 [2055600.556231] [] ? autoremove_wake_function+0x30/0x30 [2055600.556242] [] ? extent_write_cache_pages.clone.18.= clone.25+0x1b3/0x2e0 [btrfs] [2055600.556253] [] ? extent_writepages+0x40/0x60 [btrfs] [2055600.556264] [] ? btrfs_writepage_fixup_worker+0x150= /0x150 [btrfs] [2055600.556268] [] ? writeback_single_inode+0x104/0x250 [2055600.556271] [] ? writeback_sb_inodes+0xf6/0x1a0 [2055600.556274] [] ? writeback_inodes_wb+0x8d/0x1a0 [2055600.556277] [] ? balance_dirty_pages_ratelimited_nr= +0x3bb/0x4b0 [2055600.556288] [] ? __btrfs_buffered_write.clone.13+0x= 22c/0x2f0 [btrfs] [2055600.556292] [] ? current_fs_time+0xd/0x50 [2055600.556303] [] ? btrfs_file_aio_write+0x22d/0x4a0 [= btrfs] [2055600.556314] [] ? btrfs_file_aio_write+0x2/0x4a0 [bt= rfs] [2055600.556318] [] ? do_sync_write+0xbf/0x100 [2055600.556323] [] ? security_file_permission+0x24/0xc0 [2055600.556325] [] ? vfs_write+0xc6/0x180 [2055600.556328] [] ? sys_write+0x4e/0x90 [2055600.556331] [] ? system_call_fastpath+0x16/0x1b [2055600.556334] INFO: task btrfs-delalloc-:24754 blocked for more than 120= seconds. [2055600.556336] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable= s this message. [2055600.556337] btrfs-delalloc- D ffff8800bfd13cc0 0 24754 2 0x00= 000000 [2055600.556341] ffff880095d39b00 0000000000000046 ffff8800bffe7c08 000000= 0200000001 [2055600.556344] ffff8800af69d7c0 0000000000013cc0 ffff8800060c3fd8 000000= 0000013cc0 [2055600.556347] ffff8800060c2000 ffff8800060c3fd8 0000000000013cc0 ffff88= 0095d39b00 [2055600.556350] Call Trace: [2055600.556353] [] ? schedule_timeout+0x22d/0x310 [2055600.556356] [] ? select_task_rq_fair+0x2f3/0x750 [2055600.556359] [] ? wait_for_common+0xe1/0x1a0 [2055600.556363] [] ? try_to_wake_up+0x320/0x320 [2055600.556365] [] ? try_to_wake_up+0xbc/0x320 [2055600.556370] [] ? kthread_create_on_node+0x8f/0x110 [2055600.556379] [] ? btrfs_put_block_group+0x70/0x70 [b= trfs] [2055600.556383] [] ? rwsem_wake+0x4a/0x60 [2055600.556386] [] ? call_rwsem_wake+0x17/0x30 [2055600.556397] [] ? cache_block_group+0x1ba/0x2a0 [btr= fs] [2055600.556406] [] ? find_free_extent.clone.64+0x400/0x= aa0 [btrfs] [2055600.556417] [] ? btrfs_reserve_extent+0xea/0x1b0 [b= trfs] [2055600.556428] [] ? cow_file_range+0x16b/0x370 [btrfs] [2055600.556439] [] ? submit_compressed_extents+0x228/0x= 440 [btrfs] [2055600.556443] [] ? try_to_del_timer_sync+0x7a/0xd0 [2055600.556453] [] ? run_ordered_completions+0x63/0xc0 = [btrfs] [2055600.556463] [] ? worker_loop+0xb1/0x510 [btrfs] [2055600.556473] [] ? btrfs_queue_worker+0x2f0/0x2f0 [bt= rfs] [2055600.556483] [] ? btrfs_queue_worker+0x2f0/0x2f0 [bt= rfs] [2055600.556486] [] ? kthread+0x96/0xa0 [2055600.556488] [] ? kernel_thread_helper+0x4/0x10 [2055600.556492] [] ? kthread_worker_fn+0x1a0/0x1a0 [2055600.556494] [] ? gs_change+0x13/0x13 [2055720.556041] INFO: task kthreadd:2 blocked for more than 120 seconds. [2055720.556044] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable= s this message. [2055720.556047] kthreadd D ffff8800bfc13cc0 0 2 0 0x00= 000000 [2055720.556051] ffff8800bc2786c0 0000000000000046 ffff8800bfd16eb8 000000= 0000000000 [2055720.556055] ffffffff8180b020 0000000000013cc0 ffff8800bc277fd8 000000= 0000013cc0 [2055720.556058] ffff8800bc276000 ffff8800bc277fd8 0000000000013cc0 ffff88= 00bc2786c0 [2055720.556061] Call Trace: [2055720.556069] [] ? __lock_page+0x70/0x70 [2055720.556073] [] ? io_schedule+0x84/0xd0 [2055720.556076] [] ? sleep_on_page+0x9/0x10 [2055720.556079] [] ? __wait_on_bit_lock+0x4a/0xb0 [2055720.556082] [] ? __lock_page+0x5e/0x70 [2055720.556086] [] ? autoremove_wake_function+0x30/0x30 [2055720.556089] [] ? _cond_resched+0x2f/0x40 [2055720.556093] [] ? move_to_new_page+0x23b/0x240 [2055720.556096] [] ? migrate_pages+0x3f3/0x490 [2055720.556099] [] ? perf_trace_mm_compaction_migratepa= ges+0xf0/0xf0 [2055720.556101] [] ? compact_zone+0x591/0x880 [2055720.556104] [] ? compact_zone_order+0xa9/0xf0 [2055720.556107] [] ? delayacct_end+0x82/0xa0 [2055720.556110] [] ? try_to_compact_pages+0xf0/0x120 [2055720.556114] [] ? __alloc_pages_direct_compact+0xde/= 0x1b0 [2055720.556117] [] ? __alloc_pages_nodemask+0x4d7/0x920 [2055720.556121] [] ? copy_process+0x148/0x1230 [2055720.556124] [] ? do_fork+0x71/0x380 [2055720.556127] [] ? native_sched_clock+0x11/0x60 [2055720.556131] [] ? update_curr+0xea/0x1f0 [2055720.556133] [] ? kernel_thread+0x7c/0x90 [2055720.556137] [] ? kthread_worker_fn+0x1a0/0x1a0 [2055720.556139] [] ? gs_change+0x13/0x13 [2055720.556142] [] ? kthreadd+0x106/0x140 [2055720.556145] [] ? kernel_thread_helper+0x4/0x10 [2055720.556148] [] ? tsk_fork_get_node+0x20/0x20 [2055720.556150] [] ? gs_change+0x13/0x13 [2055720.556184] INFO: task kworker/1:3:24047 blocked for more than 120 sec= onds. [2055720.556186] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable= s this message. [2055720.556188] kworker/1:3 D ffff8800bfd13cc0 0 24047 2 0x00= 000000 [2055720.556191] ffff88008718de80 0000000000000046 0000000000013cc0 000000= 0000000000 [2055720.556194] ffff8800bc27ca40 0000000000013cc0 ffff8800b9e5ffd8 000000= 0000013cc0 [2055720.556198] ffff8800b9e5e000 ffff8800b9e5ffd8 0000000000013cc0 ffff88= 008718de80 [2055720.556201] Call Trace: [2055720.556204] [] ? schedule_timeout+0x22d/0x310 [2055720.556207] [] ? native_sched_clock+0x11/0x60 [2055720.556210] [] ? wait_for_common+0xe1/0x1a0 [2055720.556213] [] ? try_to_wake_up+0x320/0x320 [2055720.556217] [] ? kthread_create_on_node+0x8f/0x110 [2055720.556220] [] ? manage_workers.clone.21+0x230/0x230 [2055720.556223] [] ? kmem_cache_alloc_trace+0xd7/0x130 [2055720.556226] [] ? create_worker+0x13e/0x1c0 [2055720.556229] [] ? manage_workers.clone.21+0x11d/0x230 [2055720.556232] [] ? worker_thread+0x28f/0x340 [2055720.556235] [] ? manage_workers.clone.21+0x230/0x230 [2055720.556237] [] ? manage_workers.clone.21+0x230/0x230 [2055720.556240] [] ? kthread+0x96/0xa0 [2055720.556243] [] ? kernel_thread_helper+0x4/0x10 [2055720.556246] [] ? kthread_worker_fn+0x1a0/0x1a0 [2055720.556248] [] ? gs_change+0x13/0x13 [2055720.556253] INFO: task btrfs-transacti:24692 blocked for more than 120= seconds. [2055720.556254] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable= s this message. [2055720.556256] btrfs-transacti D ffff8800bfd13cc0 0 24692 2 0x00= 000000 [2055720.556259] ffff8800871d4380 0000000000000046 0000000000000ec2 ffff88= 0000000000 [2055720.556262] ffff8800bc27ca40 0000000000013cc0 ffff88008a643fd8 000000= 0000013cc0 [2055720.556265] ffff88008a642000 ffff88008a643fd8 0000000000013cc0 ffff88= 00871d4380 [2055720.556268] Call Trace: [2055720.556271] [] ? schedule_timeout+0x22d/0x310 [2055720.556303] [] ? btrfs_run_delayed_refs+0xc7/0x210 = [btrfs] [2055720.556306] [] ? mutex_lock+0x16/0x50 [2055720.556318] [] ? btrfs_run_ordered_operations+0x1cd= /0x1f0 [btrfs] [2055720.556330] [] ? btrfs_commit_transaction+0x26d/0x7= a0 [btrfs] [2055720.556333] [] ? wake_up_bit+0x40/0x40 [2055720.556343] [] ? transaction_kthread+0x273/0x290 [b= trfs] [2055720.556353] [] ? btrfs_congested_fn+0x90/0x90 [btrf= s] [2055720.556363] [] ? btrfs_congested_fn+0x90/0x90 [btrf= s] [2055720.556366] [] ? kthread+0x96/0xa0 [2055720.556369] [] ? kernel_thread_helper+0x4/0x10 [2055720.556372] [] ? kthread_worker_fn+0x1a0/0x1a0 [2055720.556374] [] ? gs_change+0x13/0x13 --=20 With respect, Roman --Sig_/t9_BcqNHKspdO+RNP3nEC=0 Content-Type: application/pgp-signature; name=signature.asc Content-Disposition: attachment; filename=signature.asc -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux) iEUEARECAAYFAk4MGbIACgkQTLKSvz+PZwiDmgCUDY1gXRt0rYM8nkqNQSkCknZS QwCgjj6dhibssc0dXkvmo/EGM7+ZQh4= =+OGE -----END PGP SIGNATURE----- --Sig_/t9_BcqNHKspdO+RNP3nEC=0--