System hangs in btrfs-transaction

Benjamin King benjaminking at web.de
Tue Dec 19 08:46:51 UTC 2017


Hi,

I'm running some test using rr on a btrfs file system. The system sometimes
hangs with top reporting 100% in btrfs-transaction for minutes.

Are there any known issues specific to rr regarding this? Or should I ask in
the btrfs mailing list instead?

This is what the kernel stack trace looked like:

--- snip ---
ws-bki:~ $ pgrep rr
19004
ws-bki:~ $ cat /proc/19004/stack
[<ffffffffc03b9093>] wait_current_trans.isra.21+0xd3/0x120 [btrfs]
[<ffffffffc03ba9b5>] start_transaction+0x2c5/0x4b0 [btrfs]
[<ffffffffc03babb8>] btrfs_start_transaction+0x18/0x20 [btrfs]
[<ffffffffc03c973a>] btrfs_create+0x4a/0x210 [btrfs]
[<ffffffff8121bba7>] vfs_create+0x127/0x190
[<ffffffff8121ee3c>] path_openat+0x120c/0x1330
[<ffffffff81220151>] do_filp_open+0x91/0x100
[<ffffffff8120e508>] do_sys_open+0x138/0x2a0
[<ffffffff8120e68e>] SyS_open+0x1e/0x20
[<ffffffff818431f2>] entry_SYSCALL_64_fastpath+0x16/0x71
[<ffffffffffffffff>] 0xffffffffffffffff
--- snip ---

To put this in context, I have attached some interesting info from dmesg.

Cheers,
  Benjamin
-------------- next part --------------
[492214.984179] INFO: task kworker/u16:23:10082 blocked for more than 120 seconds.
[492214.984183]       Tainted: P           O    4.4.0-93-generic #116-Ubuntu
[492214.984184] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[492214.984185] kworker/u16:23  D ffff8801401c7c40     0 10082      2 0x00000000
[492214.984204] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
[492214.984205]  ffff8801401c7c40 ffff88013c037188 ffff8807f9f4aa00 ffff8807d09c0000
[492214.984207]  ffff8801401c8000 ffff8803e577a9f0 ffff8803e577a800 ffff8803e577a9f0
[492214.984208]  0000000000000001 ffff8801401c7c58 ffffffff8183f0d5 ffff88071fe8bb10
[492214.984209] Call Trace:
[492214.984213]  [<ffffffff8183f0d5>] schedule+0x35/0x80
[492214.984225]  [<ffffffffc03b9093>] wait_current_trans.isra.21+0xd3/0x120 [btrfs]
[492214.984228]  [<ffffffff810c4430>] ? wake_atomic_t_function+0x60/0x60
[492214.984237]  [<ffffffffc03ba965>] start_transaction+0x275/0x4b0 [btrfs]
[492214.984246]  [<ffffffffc03babf7>] btrfs_join_transaction+0x17/0x20 [btrfs]
[492214.984254]  [<ffffffffc03c3355>] btrfs_finish_ordered_io+0x435/0x650 [btrfs]
[492214.984262]  [<ffffffffc03c3855>] finish_ordered_fn+0x15/0x20 [btrfs]
[492214.984272]  [<ffffffffc03ec05a>] btrfs_scrubparity_helper+0xca/0x2f0 [btrfs]
[492214.984281]  [<ffffffffc03ec30e>] btrfs_endio_write_helper+0xe/0x10 [btrfs]
[492214.984283]  [<ffffffff8109a615>] process_one_work+0x165/0x480
[492214.984285]  [<ffffffff8109a97b>] worker_thread+0x4b/0x4c0
[492214.984286]  [<ffffffff8109a930>] ? process_one_work+0x480/0x480
[492214.984287]  [<ffffffff810a0c95>] kthread+0xe5/0x100
[492214.984289]  [<ffffffff810a0bb0>] ? kthread_create_on_node+0x1e0/0x1e0
[492214.984291]  [<ffffffff8184358f>] ret_from_fork+0x3f/0x70
[492214.984292]  [<ffffffff810a0bb0>] ? kthread_create_on_node+0x1e0/0x1e0
[492214.984301] INFO: task kworker/u16:2:15172 blocked for more than 120 seconds.
[492214.984302]       Tainted: P           O    4.4.0-93-generic #116-Ubuntu
[492214.984302] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[492214.984303] kworker/u16:2   D ffff880481e3fc40     0 15172      2 0x00000000
[492214.984313] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
[492214.984314]  ffff880481e3fc40 ffff88013c037570 ffff8807f9f4aa00 ffff8801018c4600
[492214.984316]  ffff880481e40000 ffff8803e577a9f0 ffff8803e577a800 ffff8803e577a9f0
[492214.984317]  0000000000000001 ffff880481e3fc58 ffffffff8183f0d5 ffff88071fe8bb10
[492214.984318] Call Trace:
[492214.984320]  [<ffffffff8183f0d5>] schedule+0x35/0x80
[492214.984328]  [<ffffffffc03b9093>] wait_current_trans.isra.21+0xd3/0x120 [btrfs]
[492214.984331]  [<ffffffff810c4430>] ? wake_atomic_t_function+0x60/0x60
[492214.984339]  [<ffffffffc03ba965>] start_transaction+0x275/0x4b0 [btrfs]
[492214.984346]  [<ffffffffc03babf7>] btrfs_join_transaction+0x17/0x20 [btrfs]
[492214.984354]  [<ffffffffc03c3355>] btrfs_finish_ordered_io+0x435/0x650 [btrfs]
[492214.984362]  [<ffffffffc03c3855>] finish_ordered_fn+0x15/0x20 [btrfs]
[492214.984370]  [<ffffffffc03ec05a>] btrfs_scrubparity_helper+0xca/0x2f0 [btrfs]
[492214.984378]  [<ffffffffc03ec30e>] btrfs_endio_write_helper+0xe/0x10 [btrfs]
[492214.984380]  [<ffffffff8109a615>] process_one_work+0x165/0x480
[492214.984381]  [<ffffffff8109a97b>] worker_thread+0x4b/0x4c0
[492214.984382]  [<ffffffff8109a930>] ? process_one_work+0x480/0x480
[492214.984384]  [<ffffffff810a0c95>] kthread+0xe5/0x100
[492214.984385]  [<ffffffff810a0bb0>] ? kthread_create_on_node+0x1e0/0x1e0
[492214.984386]  [<ffffffff8184358f>] ret_from_fork+0x3f/0x70
[492214.984388]  [<ffffffff810a0bb0>] ? kthread_create_on_node+0x1e0/0x1e0
[492214.984389] INFO: task kworker/u16:7:15765 blocked for more than 120 seconds.
[492214.984390]       Tainted: P           O    4.4.0-93-generic #116-Ubuntu
[492214.984390] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[492214.984391] kworker/u16:7   D ffff8801327eb600     0 15765      2 0x00000000
[492214.984394] Workqueue: writeback wb_workfn (flush-btrfs-1)
[492214.984395]  ffff8801327eb600 ffff8801327eb608 ffff8807f9f4aa00 ffff8807e313d400
[492214.984396]  ffff8801327ec000 ffff8803e577a9f0 ffff8803e577a800 ffff8803e577a9f0
[492214.984397]  0000000000000001 ffff8801327eb618 ffffffff8183f0d5 ffff88071fe8bb10
[492214.984398] Call Trace:
[492214.984400]  [<ffffffff8183f0d5>] schedule+0x35/0x80
[492214.984409]  [<ffffffffc03b9093>] wait_current_trans.isra.21+0xd3/0x120 [btrfs]
[492214.984410]  [<ffffffff810c4430>] ? wake_atomic_t_function+0x60/0x60
[492214.984418]  [<ffffffffc03ba965>] start_transaction+0x275/0x4b0 [btrfs]
[492214.984425]  [<ffffffffc03babf7>] btrfs_join_transaction+0x17/0x20 [btrfs]
[492214.984432]  [<ffffffffc03c04d0>] cow_file_range_inline+0x100/0x680 [btrfs]
[492214.984441]  [<ffffffffc03d7f5f>] ? __set_extent_bit+0x45f/0x5a0 [btrfs]
[492214.984443]  [<ffffffff81191eee>] ? mempool_alloc+0x6e/0x170
[492214.984451]  [<ffffffffc03c0dc1>] cow_file_range+0x371/0x480 [btrfs]
[492214.984460]  [<ffffffffc03d9a68>] ? test_range_bit+0x48/0x130 [btrfs]
[492214.984467]  [<ffffffffc03c1da3>] run_delalloc_range+0x393/0x3d0 [btrfs]
[492214.984476]  [<ffffffffc03d9e55>] writepage_delalloc.isra.35+0x105/0x170 [btrfs]
[492214.984484]  [<ffffffffc03dbb6a>] __extent_writepage+0xca/0x330 [btrfs]
[492214.984486]  [<ffffffff811cd410>] ? page_referenced_one+0x1a0/0x1a0
[492214.984494]  [<ffffffffc03dc0b1>] extent_write_cache_pages.isra.31.constprop.51+0x2e1/0x3d0 [btrfs]
[492214.984501]  [<ffffffffc03bbf43>] ? btrfs_submit_bio_hook+0xa3/0x1b0 [btrfs]
[492214.984509]  [<ffffffffc03bcef0>] ? btrfs_set_bit_hook+0x240/0x240 [btrfs]
[492214.984516]  [<ffffffffc03bc050>] ? btrfs_submit_bio_hook+0x1b0/0x1b0 [btrfs]
[492214.984524]  [<ffffffffc03dd36c>] extent_writepages+0x5c/0x90 [btrfs]
[492214.984531]  [<ffffffffc03be770>] ? btrfs_real_readdir+0x5d0/0x5d0 [btrfs]
[492214.984538]  [<ffffffffc03bc428>] btrfs_writepages+0x28/0x30 [btrfs]
[492214.984540]  [<ffffffff8119db0e>] do_writepages+0x1e/0x30
[492214.984542]  [<ffffffff8123e5a5>] __writeback_single_inode+0x45/0x340
[492214.984544]  [<ffffffff8123edb2>] writeback_sb_inodes+0x262/0x600
[492214.984545]  [<ffffffff8123f1dc>] __writeback_inodes_wb+0x8c/0xc0
[492214.984547]  [<ffffffff8123f533>] wb_writeback+0x253/0x310
[492214.984548]  [<ffffffff8123fdaa>] wb_workfn+0x2ea/0x400
[492214.984550]  [<ffffffff8109a615>] process_one_work+0x165/0x480
[492214.984551]  [<ffffffff8109a97b>] worker_thread+0x4b/0x4c0
[492214.984552]  [<ffffffff8109a930>] ? process_one_work+0x480/0x480
[492214.984554]  [<ffffffff810a0c95>] kthread+0xe5/0x100
[492214.984555]  [<ffffffff810a0bb0>] ? kthread_create_on_node+0x1e0/0x1e0
[492214.984556]  [<ffffffff8184358f>] ret_from_fork+0x3f/0x70
[492214.984557]  [<ffffffff810a0bb0>] ? kthread_create_on_node+0x1e0/0x1e0
[492214.984559] INFO: task kworker/u16:3:18051 blocked for more than 120 seconds.
[492214.984559]       Tainted: P           O    4.4.0-93-generic #116-Ubuntu
[492214.984560] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[492214.984561] kworker/u16:3   D ffff8802018dbc40     0 18051      2 0x00000000
[492214.984570] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
[492214.984571]  ffff8802018dbc40 ffff88013c037958 ffff8807f9f4aa00 ffff8807e3088e00
[492214.984572]  ffff8802018dc000 ffff8803e577a9f0 ffff8803e577a800 ffff8803e577a9f0
[492214.984573]  0000000000000001 ffff8802018dbc58 ffffffff8183f0d5 ffff88071fe8bb10
[492214.984574] Call Trace:
[492214.984576]  [<ffffffff8183f0d5>] schedule+0x35/0x80
[492214.984583]  [<ffffffffc03b9093>] wait_current_trans.isra.21+0xd3/0x120 [btrfs]
[492214.984585]  [<ffffffff810c4430>] ? wake_atomic_t_function+0x60/0x60
[492214.984592]  [<ffffffffc03ba965>] start_transaction+0x275/0x4b0 [btrfs]
[492214.984599]  [<ffffffffc03babf7>] btrfs_join_transaction+0x17/0x20 [btrfs]
[492214.984606]  [<ffffffffc03c3355>] btrfs_finish_ordered_io+0x435/0x650 [btrfs]
[492214.984614]  [<ffffffffc03c3855>] finish_ordered_fn+0x15/0x20 [btrfs]
[492214.984622]  [<ffffffffc03ec05a>] btrfs_scrubparity_helper+0xca/0x2f0 [btrfs]
[492214.984629]  [<ffffffffc03ec30e>] btrfs_endio_write_helper+0xe/0x10 [btrfs]
[492214.984631]  [<ffffffff8109a615>] process_one_work+0x165/0x480
[492214.984632]  [<ffffffff8109a97b>] worker_thread+0x4b/0x4c0
[492214.984633]  [<ffffffff8109a930>] ? process_one_work+0x480/0x480
[492214.984634]  [<ffffffff810a0c95>] kthread+0xe5/0x100
[492214.984636]  [<ffffffff810a0bb0>] ? kthread_create_on_node+0x1e0/0x1e0
[492214.984637]  [<ffffffff8184358f>] ret_from_fork+0x3f/0x70
[492214.984638]  [<ffffffff810a0bb0>] ? kthread_create_on_node+0x1e0/0x1e0
[492214.984640] INFO: task rr:19004 blocked for more than 120 seconds.
[492214.984641]       Tainted: P           O    4.4.0-93-generic #116-Ubuntu
[492214.984641] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[492214.984642] rr              D ffff8802018ebb80     0 19004  10995 0x00000004
[492214.984643]  ffff8802018ebb80 0001880200000001 ffff8807f9f4e200 ffff8807f7118000
[492214.984645]  ffff8802018ec000 ffff8803e577a9f0 ffff8803e577a800 ffff8803e577a9f0
[492214.984646]  0000000000000001 ffff8802018ebb98 ffffffff8183f0d5 ffff88071fe8bb10
[492214.984647] Call Trace:
[492214.984648]  [<ffffffff8183f0d5>] schedule+0x35/0x80
[492214.984656]  [<ffffffffc03b9093>] wait_current_trans.isra.21+0xd3/0x120 [btrfs]
[492214.984657]  [<ffffffff810c4430>] ? wake_atomic_t_function+0x60/0x60
[492214.984664]  [<ffffffffc03ba9b5>] start_transaction+0x2c5/0x4b0 [btrfs]
[492214.984671]  [<ffffffffc03babb8>] btrfs_start_transaction+0x18/0x20 [btrfs]
[492214.984679]  [<ffffffffc03c973a>] btrfs_create+0x4a/0x210 [btrfs]
[492214.984681]  [<ffffffff8121bba7>] vfs_create+0x127/0x190
[492214.984683]  [<ffffffff8121ee3c>] path_openat+0x120c/0x1330
[492214.984684]  [<ffffffff81220151>] do_filp_open+0x91/0x100
[492214.984686]  [<ffffffff8122db86>] ? __alloc_fd+0x46/0x190
[492214.984687]  [<ffffffff8120e508>] do_sys_open+0x138/0x2a0
[492214.984689]  [<ffffffff8120e68e>] SyS_open+0x1e/0x20
[492214.984691]  [<ffffffff818431f2>] entry_SYSCALL_64_fastpath+0x16/0x71


More information about the rr-dev mailing list