kernel btrfs file system wedged -- is it toast?

kernel btrfs file system wedged -- is it toast?

[Paul Jackson]

This may be a repeat, in a slightly variant form, of the problem that
Marc MERLIN reports in:

  https://www.spinics.net/lists/linux-btrfs/msg67393.html
  20170716160658.r4uxuqlfe24hgi5n@merlins.org
  BTRFS: error (device dm-2) in btrfs_run_delayed_refs:2960: errno=-17 Object already exists (since 3.4 / 2012)

I would have replied to the above thread, but just signed up for the
linux-btrfs email list a few minutes ago, and don't know how to
reply to older email on the list.

I am running Linux kernel 4.11.10-1-MANJARO on an Intel Sandy Bridge CPU.

I was running both a "btrfs balance" and a "btrfs receive" into the same file system.

Then I noticed that the disk light (on an 8TB helium filled 5400 RPM drive) stopped blinking
(it should have been blinking for many more hours, just on the btrfs balance command.)

My dmesg output shows (including the last few successful balance entries):

======================
[50583.100966] BTRFS info (device sde1): relocating block group 5980234448896 flags data
[50607.655851] BTRFS info (device sde1): found 5076 extents
[50650.791868] BTRFS info (device sde1): found 5076 extents
[50651.561918] BTRFS info (device sde1): relocating block group 5979160707072 flags data
[50671.583960] BTRFS info (device sde1): found 5326 extents
[50715.786757] BTRFS info (device sde1): found 5326 extents
[50716.365571] BTRFS info (device sde1): relocating block group 5978086965248 flags data
[50738.280469] BTRFS info (device sde1): found 5539 extents
[50779.009891] BTRFS info (device sde1): found 5539 extents
[50781.939661] BTRFS info (device sde1): relocating block group 5977013223424 flags data
[50805.881194] BTRFS info (device sde1): found 10658 extents
[50994.082530] INFO: task btrfs-cleaner:9958 blocked for more than 120 seconds.
[50994.082532]       Tainted: G           O    4.11.10-1-MANJARO #1
[50994.082533] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[50994.082534] btrfs-cleaner   D    0  9958      2 0x00000000
[50994.082536] Call Trace:
[50994.082542]  __schedule+0x22e/0x8e0
[50994.082543]  schedule+0x3d/0x90
[50994.082545]  schedule_preempt_disabled+0x15/0x20
[50994.082547]  __mutex_lock.isra.0+0x2ac/0x530
[50994.082549]  __mutex_lock_slowpath+0x13/0x20
[50994.082550]  ? __mutex_lock_slowpath+0x13/0x20
[50994.082551]  mutex_lock+0x25/0x30
[50994.082564]  btrfs_delete_unused_bgs+0xc2/0x3b0 [btrfs]
[50994.082566]  ? iput+0x1ae/0x240
[50994.082575]  cleaner_kthread+0x15e/0x170 [btrfs]
[50994.082577]  kthread+0x125/0x140
[50994.082585]  ? btrfs_destroy_pinned_extent+0xd0/0xd0 [btrfs]
[50994.082586]  ? kthread_create_on_node+0x70/0x70
[50994.082588]  ret_from_fork+0x25/0x30
[51239.838954] INFO: task btrfs-cleaner:9958 blocked for more than 120 seconds.
[51239.838956]       Tainted: G           O    4.11.10-1-MANJARO #1
[51239.838956] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[51239.838957] btrfs-cleaner   D    0  9958      2 0x00000000
[51239.838959] Call Trace:
[51239.838964]  __schedule+0x22e/0x8e0
[51239.838965]  schedule+0x3d/0x90
[51239.838966]  schedule_preempt_disabled+0x15/0x20
[51239.838967]  __mutex_lock.isra.0+0x2ac/0x530
[51239.838969]  __mutex_lock_slowpath+0x13/0x20
[51239.838970]  ? __mutex_lock_slowpath+0x13/0x20
[51239.838970]  mutex_lock+0x25/0x30
[51239.838980]  btrfs_delete_unused_bgs+0xc2/0x3b0 [btrfs]
[51239.838981]  ? iput+0x1ae/0x240
[51239.838987]  cleaner_kthread+0x15e/0x170 [btrfs]
[51239.838988]  kthread+0x125/0x140
[51239.838993]  ? btrfs_destroy_pinned_extent+0xd0/0xd0 [btrfs]
[51239.838994]  ? kthread_create_on_node+0x70/0x70
[51239.838995]  ret_from_fork+0x25/0x30
[51239.838997] INFO: task btrfs:23561 blocked for more than 120 seconds.
[51239.838997]       Tainted: G           O    4.11.10-1-MANJARO #1
[51239.838997] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[51239.838998] btrfs           D    0 23561   5610 0x00000000
[51239.838999] Call Trace:
[51239.839000]  __schedule+0x22e/0x8e0
[51239.839001]  schedule+0x3d/0x90
[51239.839002]  schedule_timeout+0x224/0x3c0
[51239.839004]  ? wake_up_process+0x15/0x20
[51239.839005]  wait_for_common+0xb9/0x180
[51239.839005]  ? wait_for_common+0xb9/0x180
[51239.839006]  ? wake_up_q+0x80/0x80
[51239.839007]  wait_for_completion+0x1d/0x20
[51239.839012]  btrfs_async_run_delayed_refs+0x119/0x140 [btrfs]
[51239.839017]  __btrfs_end_transaction+0x1fa/0x300 [btrfs]
[51239.839022]  btrfs_end_transaction_throttle+0x13/0x20 [btrfs]
[51239.839028]  relocate_block_group+0x3f2/0x620 [btrfs]
[51239.839034]  btrfs_relocate_block_group+0x18c/0x270 [btrfs]
[51239.839040]  btrfs_relocate_chunk+0x38/0xd0 [btrfs]
[51239.839045]  btrfs_balance+0xbdc/0x1340 [btrfs]
[51239.839046]  ? ttwu_do_wakeup.isra.16+0x1e/0x170
[51239.839053]  btrfs_ioctl_balance+0x316/0x380 [btrfs]
[51239.839058]  btrfs_ioctl+0x1177/0x24a0 [btrfs]
[51239.839060]  ? tty_flip_buffer_push+0x2b/0x30
[51239.839061]  ? remove_wait_queue+0x4d/0x60
[51239.839062]  ? __wake_up+0x44/0x50
[51239.839064]  do_vfs_ioctl+0xa5/0x600
[51239.839065]  ? do_vfs_ioctl+0xa5/0x600
[51239.839066]  ? vfs_write+0x168/0x1a0
[51239.839067]  SyS_ioctl+0x79/0x90
[51239.839069]  entry_SYSCALL_64_fastpath+0x1a/0xa9
[51239.839069] RIP: 0033:0x7fb06bfe6c47
[51239.839070] RSP: 002b:00007ffdc77cd118 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
[51239.839071] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007fb06bfe6c47
[51239.839071] RDX: 00007ffdc77cd1b0 RSI: 00000000c4009420 RDI: 0000000000000003
[51239.839072] RBP: 0000000000000003 R08: 00007fb06cf2f8c0 R09: 00007fb06cf2f8c0
[51239.839072] R10: 0000000000000545 R11: 0000000000000206 R12: 00007ffdc77cd1b0
[51239.839073] R13: 0000000000480525 R14: 0000000000000000 R15: 00007ffdc77cf591
[51239.839076] INFO: task btrfs:29186 blocked for more than 120 seconds.
[51239.839077]       Tainted: G           O    4.11.10-1-MANJARO #1
[51239.839077] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[51239.839078] btrfs           D    0 29186  27726 0x00000000
[51239.839079] Call Trace:
[51239.839080]  __schedule+0x22e/0x8e0
[51239.839081]  schedule+0x3d/0x90
[51239.839082]  schedule_timeout+0x224/0x3c0
[51239.839086]  ? btrfs_leaf_free_space+0x54/0xa0 [btrfs]
[51239.839087]  ? wake_up_process+0x15/0x20
[51239.839088]  wait_for_common+0xb9/0x180
[51239.839089]  ? wait_for_common+0xb9/0x180
[51239.839089]  ? wake_up_q+0x80/0x80
[51239.839090]  wait_for_completion+0x1d/0x20
[51239.839095]  btrfs_async_run_delayed_refs+0x119/0x140 [btrfs]
[51239.839100]  __btrfs_end_transaction+0x1fa/0x300 [btrfs]
[51239.839105]  btrfs_end_transaction+0x10/0x20 [btrfs]
[51239.839110]  btrfs_setattr+0x129/0x3b0 [btrfs]
[51239.839111]  notify_change+0x2c7/0x430
[51239.839112]  do_truncate+0x73/0xc0
[51239.839113]  vfs_truncate+0x14e/0x190
[51239.839114]  ? user_path_at_empty+0x36/0x40
[51239.839115]  do_sys_truncate.part.0+0x8a/0xa0
[51239.839116]  SyS_truncate+0x13/0x20
[51239.839117]  entry_SYSCALL_64_fastpath+0x1a/0xa9
[51239.839118] RIP: 0033:0x7f325f704ce7
[51239.839118] RSP: 002b:00007ffda084a908 EFLAGS: 00000297 ORIG_RAX: 000000000000004c
[51239.839119] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f325f704ce7
[51239.839119] RDX: 0000000000000000 RSI: 000000001124aa3b RDI: 00007ffda084a910
[51239.839120] RBP: 00007ffda084ba20 R08: 0000000000000057 R09: 0000000001e56170
[51239.839120] R10: 0000000001e561c0 R11: 0000000000000297 R12: 000000000000000f
[51239.839121] R13: 000000000000c06b R14: 00000000e37b700a R15: 00007ffda084ba24
[51362.717193] INFO: task btrfs:29898 blocked for more than 120 seconds.
[51362.717195]       Tainted: G           O    4.11.10-1-MANJARO #1
[51362.717195] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[51362.717196] btrfs           D    0 29898  23640 0x00000004
[51362.717198] Call Trace:
[51362.717203]  __schedule+0x22e/0x8e0
[51362.717205]  schedule+0x3d/0x90
[51362.717218]  btrfs_pause_balance+0xc7/0x110 [btrfs]
[51362.717220]  ? wake_bit_function+0x60/0x60
[51362.717228]  btrfs_ioctl+0x1adb/0x24a0 [btrfs]
[51362.717230]  ? lru_cache_add_active_or_unevictable+0x36/0xb0
[51362.717231]  ? __handle_mm_fault+0xa5b/0x12a0
[51362.717233]  ? _copy_to_user+0x51/0x60
[51362.717235]  do_vfs_ioctl+0xa5/0x600
[51362.717236]  ? do_vfs_ioctl+0xa5/0x600
[51362.717237]  ? handle_mm_fault+0xde/0x240
[51362.717239]  ? __do_page_fault+0x2b9/0x520
[51362.717240]  SyS_ioctl+0x79/0x90
[51362.717242]  entry_SYSCALL_64_fastpath+0x1a/0xa9
[51362.717243] RIP: 0033:0x7f60efce0c47
[51362.717244] RSP: 002b:00007ffd965895a8 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[51362.717245] RAX: ffffffffffffffda RBX: 0000000000008041 RCX: 00007f60efce0c47
[51362.717246] RDX: 0000000000000001 RSI: 0000000040049421 RDI: 0000000000000003
[51362.717246] RBP: 00007f60eff9bae0 R08: 0000000000000003 R09: 000000000000007c
[51362.717247] R10: 0000000000000545 R11: 0000000000000202 R12: 0000000000000000
[51362.717248] R13: 00007f60eff9bb38 R14: 0000000000008060 R15: 0000000000000000
[51485.595419] INFO: task btrfs:29898 blocked for more than 120 seconds.
[51485.595421]       Tainted: G           O    4.11.10-1-MANJARO #1
[51485.595422] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[51485.595423] btrfs           D    0 29898  23640 0x00000004
[51485.595426] Call Trace:
[51485.595431]  __schedule+0x22e/0x8e0
[51485.595434]  schedule+0x3d/0x90
[51485.595447]  btrfs_pause_balance+0xc7/0x110 [btrfs]
[51485.595449]  ? wake_bit_function+0x60/0x60
[51485.595455]  btrfs_ioctl+0x1adb/0x24a0 [btrfs]
[51485.595457]  ? lru_cache_add_active_or_unevictable+0x36/0xb0
[51485.595459]  ? __handle_mm_fault+0xa5b/0x12a0
[51485.595460]  ? _copy_to_user+0x51/0x60
[51485.595462]  do_vfs_ioctl+0xa5/0x600
[51485.595462]  ? do_vfs_ioctl+0xa5/0x600
[51485.595463]  ? handle_mm_fault+0xde/0x240
[51485.595465]  ? __do_page_fault+0x2b9/0x520
[51485.595466]  SyS_ioctl+0x79/0x90
[51485.595467]  entry_SYSCALL_64_fastpath+0x1a/0xa9
[51485.595469] RIP: 0033:0x7f60efce0c47
[51485.595469] RSP: 002b:00007ffd965895a8 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[51485.595470] RAX: ffffffffffffffda RBX: 0000000000008041 RCX: 00007f60efce0c47
[51485.595471] RDX: 0000000000000001 RSI: 0000000040049421 RDI: 0000000000000003
[51485.595471] RBP: 00007f60eff9bae0 R08: 0000000000000003 R09: 000000000000007c
[51485.595472] R10: 0000000000000545 R11: 0000000000000202 R12: 0000000000000000
[51485.595472] R13: 00007f60eff9bb38 R14: 0000000000008060 R15: 0000000000000000
[51608.473644] INFO: task btrfs:29898 blocked for more than 120 seconds.
[51608.473646]       Tainted: G           O    4.11.10-1-MANJARO #1
[51608.473647] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[51608.473648] btrfs           D    0 29898  23640 0x00000004
[51608.473650] Call Trace:
[51608.473655]  __schedule+0x22e/0x8e0
[51608.473657]  schedule+0x3d/0x90
[51608.473671]  btrfs_pause_balance+0xc7/0x110 [btrfs]
[51608.473673]  ? wake_bit_function+0x60/0x60
[51608.473683]  btrfs_ioctl+0x1adb/0x24a0 [btrfs]
[51608.473685]  ? lru_cache_add_active_or_unevictable+0x36/0xb0
[51608.473687]  ? __handle_mm_fault+0xa5b/0x12a0
[51608.473689]  ? _copy_to_user+0x51/0x60
[51608.473691]  do_vfs_ioctl+0xa5/0x600
[51608.473692]  ? do_vfs_ioctl+0xa5/0x600
[51608.473694]  ? handle_mm_fault+0xde/0x240
[51608.473696]  ? __do_page_fault+0x2b9/0x520
[51608.473697]  SyS_ioctl+0x79/0x90
[51608.473699]  entry_SYSCALL_64_fastpath+0x1a/0xa9
[51608.473701] RIP: 0033:0x7f60efce0c47
[51608.473701] RSP: 002b:00007ffd965895a8 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[51608.473703] RAX: ffffffffffffffda RBX: 0000000000008041 RCX: 00007f60efce0c47
[51608.473704] RDX: 0000000000000001 RSI: 0000000040049421 RDI: 0000000000000003
[51608.473704] RBP: 00007f60eff9bae0 R08: 0000000000000003 R09: 000000000000007c
[51608.473705] R10: 0000000000000545 R11: 0000000000000202 R12: 0000000000000000
[51608.473706] R13: 00007f60eff9bb38 R14: 0000000000008060 R15: 0000000000000000
[51731.351862] INFO: task btrfs-cleaner:9958 blocked for more than 120 seconds.
[51731.351864]       Tainted: G           O    4.11.10-1-MANJARO #1
[51731.351864] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[51731.351865] btrfs-cleaner   D    0  9958      2 0x00000000
[51731.351867] Call Trace:
[51731.351873]  __schedule+0x22e/0x8e0
[51731.351874]  schedule+0x3d/0x90
[51731.351876]  schedule_preempt_disabled+0x15/0x20
[51731.351877]  __mutex_lock.isra.0+0x2ac/0x530
[51731.351879]  __mutex_lock_slowpath+0x13/0x20
[51731.351880]  ? __mutex_lock_slowpath+0x13/0x20
[51731.351881]  mutex_lock+0x25/0x30
[51731.351894]  btrfs_delete_unused_bgs+0xc2/0x3b0 [btrfs]
[51731.351895]  ? iput+0x1ae/0x240
[51731.351904]  cleaner_kthread+0x15e/0x170 [btrfs]
[51731.351906]  kthread+0x125/0x140
[51731.351914]  ? btrfs_destroy_pinned_extent+0xd0/0xd0 [btrfs]
[51731.351915]  ? kthread_create_on_node+0x70/0x70
[51731.351917]  ret_from_fork+0x25/0x30
[51731.351919] INFO: task btrfs:23561 blocked for more than 120 seconds.
[51731.351920]       Tainted: G           O    4.11.10-1-MANJARO #1
[51731.351920] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[51731.351921] btrfs           D    0 23561   5610 0x00000000
[51731.351922] Call Trace:
[51731.351924]  __schedule+0x22e/0x8e0
[51731.351925]  schedule+0x3d/0x90
[51731.351927]  schedule_timeout+0x224/0x3c0
[51731.351929]  ? wake_up_process+0x15/0x20
[51731.351930]  wait_for_common+0xb9/0x180
[51731.351931]  ? wait_for_common+0xb9/0x180
[51731.351932]  ? wake_up_q+0x80/0x80
[51731.351934]  wait_for_completion+0x1d/0x20
[51731.351941]  btrfs_async_run_delayed_refs+0x119/0x140 [btrfs]
[51731.351950]  __btrfs_end_transaction+0x1fa/0x300 [btrfs]
[51731.351959]  btrfs_end_transaction_throttle+0x13/0x20 [btrfs]
[51731.351968]  relocate_block_group+0x3f2/0x620 [btrfs]
[51731.351977]  btrfs_relocate_block_group+0x18c/0x270 [btrfs]
[51731.351987]  btrfs_relocate_chunk+0x38/0xd0 [btrfs]
[51731.351996]  btrfs_balance+0xbdc/0x1340 [btrfs]
[51731.351997]  ? ttwu_do_wakeup.isra.16+0x1e/0x170
[51731.352007]  btrfs_ioctl_balance+0x316/0x380 [btrfs]
[51731.352016]  btrfs_ioctl+0x1177/0x24a0 [btrfs]
[51731.352018]  ? tty_flip_buffer_push+0x2b/0x30
[51731.352020]  ? remove_wait_queue+0x4d/0x60
[51731.352021]  ? __wake_up+0x44/0x50
[51731.352023]  do_vfs_ioctl+0xa5/0x600
[51731.352024]  ? do_vfs_ioctl+0xa5/0x600
[51731.352026]  ? vfs_write+0x168/0x1a0
[51731.352027]  SyS_ioctl+0x79/0x90
[51731.352029]  entry_SYSCALL_64_fastpath+0x1a/0xa9
[51731.352030] RIP: 0033:0x7fb06bfe6c47
[51731.352031] RSP: 002b:00007ffdc77cd118 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
[51731.352032] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007fb06bfe6c47
[51731.352033] RDX: 00007ffdc77cd1b0 RSI: 00000000c4009420 RDI: 0000000000000003
[51731.352034] RBP: 0000000000000003 R08: 00007fb06cf2f8c0 R09: 00007fb06cf2f8c0
[51731.352034] R10: 0000000000000545 R11: 0000000000000206 R12: 00007ffdc77cd1b0
[51731.352035] R13: 0000000000480525 R14: 0000000000000000 R15: 00007ffdc77cf591
[51731.352040] INFO: task btrfs:29186 blocked for more than 120 seconds.
[51731.352041]       Tainted: G           O    4.11.10-1-MANJARO #1
[51731.352041] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[51731.352042] btrfs           D    0 29186  27726 0x00000000
[51731.352043] Call Trace:
[51731.352045]  __schedule+0x22e/0x8e0
[51731.352046]  schedule+0x3d/0x90
[51731.352048]  schedule_timeout+0x224/0x3c0
[51731.352049]  ? wake_up_process+0x15/0x20
[51731.352051]  wait_for_common+0xb9/0x180
[51731.352052]  ? wait_for_common+0xb9/0x180
[51731.352053]  ? wake_up_q+0x80/0x80
[51731.352055]  wait_for_completion+0x1d/0x20
[51731.352063]  btrfs_async_run_delayed_refs+0x119/0x140 [btrfs]
[51731.352072]  __btrfs_end_transaction+0x1fa/0x300 [btrfs]
[51731.352080]  btrfs_end_transaction+0x10/0x20 [btrfs]
[51731.352088]  btrfs_alloc_data_chunk_ondemand+0xfa/0x370 [btrfs]
[51731.352096]  btrfs_check_data_free_space+0x53/0xa0 [btrfs]
[51731.352106]  __btrfs_buffered_write.isra.4+0x185/0x6e0 [btrfs]
[51731.352115]  btrfs_file_write_iter+0x186/0x4e0 [btrfs]
[51731.352117]  new_sync_write+0xc3/0x110
[51731.352119]  __vfs_write+0x26/0x40
[51731.352120]  vfs_write+0xb5/0x1a0
[51731.352121]  SyS_pwrite64+0x95/0xb0
[51731.352123]  ? exit_to_usermode_loop+0x72/0xb0
[51731.352125]  entry_SYSCALL_64_fastpath+0x1a/0xa9
[51731.352125] RIP: 0033:0x7f325f9d4053
[51731.352126] RSP: 002b:00007ffda084a8e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000012
[51731.352127] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f325f9d4053
[51731.352128] RDX: 000000000000c000 RSI: 00007ffda084ba8e RDI: 0000000000000006
[51731.352129] RBP: 00007ffda084ba20 R08: 0000ffff00000000 R09: 0000000001e56170
[51731.352129] R10: 000000000264c000 R11: 0000000000000246 R12: 000000000000000f
[51731.352130] R13: 000000000000c060 R14: 00000000ee954cf5 R15: 00007ffda084ba24

======================

I also have issued a "btrfs balance pause" command, which is now in an unkillable
wait in the kernel.

I will reboot after sending this present email and see what I can see.

But based on Marc's thread mentioned above, I am quite concerned
that I should NEVER trust this particular btrfs file system again, and
that I should reformat that 8 TB disk partition and rebuild the file
store on that disk from scratch.

If so, I must conclude that I should NEVER trust btrfs again.

======================

Questions:

Is there anyway to recover this receiving btrfs file system?

Is there anyway to know, with confidence, that this receiving btrfs  file
system is healthy?

If not is there any reliable way to avoid hitting this disaster again?

===

If not that either, then know that I will necessarily throw out the
last couple of months work I've spent, developing a backup system
for my particular purposes that relies heavily on btrfs snapshots,
sent and received to create off-site and off-line backups from multiple
locations.

Just rebuilding the file system I was sending to would take me days
of work.  This target file system contains backups of a half dozen
other btrfs file systems.

As Marc said:
> If so, this blows, and I'm not really wanting to recreate a clean 12TB
> filesystem "just because", especially since this could just happen
> again after I've rebuilt it.

(Unlike Marc's disk, this target disk was only 8 TB, but it's a slow 8 TB ...)

I have coped with and worked through a variety of ways of messing
up btrfs snapshots and copies over the last two months ... but I can NOT
accept bugs that wipe out whole file systems.

Fortunately, my primary file systems are still EXT ... so it's just my
backup file systems, spanning about 40 TB of disks, and a couple
months of work, that are at risk.

P.S. -- About 50 minutes after issuing the above "btrfs balance pause",
just before I was about to hit send on this email, I noticed:

1.  my disk light flashing again
2.  that pause command returnedto the shell prompt (pause command exited),
3. the in progress balance command also exited, stating "balance paused by user"), and
4. the sequence of "btrfs receives" into that file system resumed progress.

Is that good news, bad news, or impossible to say news?

-- 
                Paul Jackson
                pj@usa.net

Re: kernel btrfs file system wedged -- is it toast?

[Hans van Kranenburg]

Hi,

On 07/20/2017 08:47 PM, Paul Jackson wrote:
> 
> This may be a repeat, in a slightly variant form, of the problem that
> Marc MERLIN reports in:
> 
>   https://www.spinics.net/lists/linux-btrfs/msg67393.html
>   20170716160658.r4uxuqlfe24hgi5n@merlins.org
>   BTRFS: error (device dm-2) in btrfs_run_delayed_refs:2960: errno=-17 Object already exists (since 3.4 / 2012)

No, it's not the same. You don't have an 'errno=-17 Object already
exists' error in btrfs_run_delayed_refs.

> [...]
> I was running both a "btrfs balance" and a "btrfs receive" into the same file system.

Just curious, what was the reason for using balance?

> Then I noticed that the disk light (on an 8TB helium filled 5400 RPM drive) stopped blinking
> (it should have been blinking for many more hours, just on the btrfs balance command.)
> 
> My dmesg output shows (including the last few successful balance entries):
> 
> ======================
> [50583.100966] BTRFS info (device sde1): relocating block group 5980234448896 flags data
> [50607.655851] BTRFS info (device sde1): found 5076 extents
> [50650.791868] BTRFS info (device sde1): found 5076 extents
> [50651.561918] BTRFS info (device sde1): relocating block group 5979160707072 flags data
> [50671.583960] BTRFS info (device sde1): found 5326 extents
> [50715.786757] BTRFS info (device sde1): found 5326 extents
> [50716.365571] BTRFS info (device sde1): relocating block group 5978086965248 flags data
> [50738.280469] BTRFS info (device sde1): found 5539 extents
> [50779.009891] BTRFS info (device sde1): found 5539 extents
> [50781.939661] BTRFS info (device sde1): relocating block group 5977013223424 flags data
> [50805.881194] BTRFS info (device sde1): found 10658 extents
> [...]

Here's the first one, the cleaner thread, which is apparently looking
around if it can delete block groups that are completely empty to return
them as unallocated space. It's waiting for another thread which is
keeping a lock, it seems.

> [51239.838954] INFO: task btrfs-cleaner:9958 blocked for more than 120 seconds.
> [51239.838956]       Tainted: G           O    4.11.10-1-MANJARO #1
> [51239.838956] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [51239.838957] btrfs-cleaner   D    0  9958      2 0x00000000
> [51239.838959] Call Trace:
> [51239.838964]  __schedule+0x22e/0x8e0
> [51239.838965]  schedule+0x3d/0x90
> [51239.838966]  schedule_preempt_disabled+0x15/0x20
> [51239.838967]  __mutex_lock.isra.0+0x2ac/0x530
> [51239.838969]  __mutex_lock_slowpath+0x13/0x20
> [51239.838970]  ? __mutex_lock_slowpath+0x13/0x20
> [51239.838970]  mutex_lock+0x25/0x30
> [51239.838980]  btrfs_delete_unused_bgs+0xc2/0x3b0 [btrfs]
> [51239.838981]  ? iput+0x1ae/0x240
> [51239.838987]  cleaner_kthread+0x15e/0x170 [btrfs]
> [51239.838988]  kthread+0x125/0x140
> [51239.838993]  ? btrfs_destroy_pinned_extent+0xd0/0xd0 [btrfs]
> [51239.838994]  ? kthread_create_on_node+0x70/0x70
> [51239.838995]  ret_from_fork+0x25/0x30

Second one is the btrfs balance, which is relocating a block group, and
wants to complete a transaction, and waits for that to happen:

> [51239.838997] INFO: task btrfs:23561 blocked for more than 120 seconds.
> [51239.838997]       Tainted: G           O    4.11.10-1-MANJARO #1
> [51239.838997] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [51239.838998] btrfs           D    0 23561   5610 0x00000000
> [51239.838999] Call Trace:
> [51239.839000]  __schedule+0x22e/0x8e0
> [51239.839001]  schedule+0x3d/0x90
> [51239.839002]  schedule_timeout+0x224/0x3c0
> [51239.839004]  ? wake_up_process+0x15/0x20
> [51239.839005]  wait_for_common+0xb9/0x180
> [51239.839005]  ? wait_for_common+0xb9/0x180
> [51239.839006]  ? wake_up_q+0x80/0x80
> [51239.839007]  wait_for_completion+0x1d/0x20
> [51239.839012]  btrfs_async_run_delayed_refs+0x119/0x140 [btrfs]
> [51239.839017]  __btrfs_end_transaction+0x1fa/0x300 [btrfs]
> [51239.839022]  btrfs_end_transaction_throttle+0x13/0x20 [btrfs]
> [51239.839028]  relocate_block_group+0x3f2/0x620 [btrfs]
> [51239.839034]  btrfs_relocate_block_group+0x18c/0x270 [btrfs]
> [51239.839040]  btrfs_relocate_chunk+0x38/0xd0 [btrfs]
> [51239.839045]  btrfs_balance+0xbdc/0x1340 [btrfs]
> [51239.839046]  ? ttwu_do_wakeup.isra.16+0x1e/0x170
> [51239.839053]  btrfs_ioctl_balance+0x316/0x380 [btrfs]
> [51239.839058]  btrfs_ioctl+0x1177/0x24a0 [btrfs]
> [51239.839060]  ? tty_flip_buffer_push+0x2b/0x30
> [51239.839061]  ? remove_wait_queue+0x4d/0x60
> [51239.839062]  ? __wake_up+0x44/0x50
> [51239.839064]  do_vfs_ioctl+0xa5/0x600
> [51239.839065]  ? do_vfs_ioctl+0xa5/0x600
> [51239.839066]  ? vfs_write+0x168/0x1a0
> [51239.839067]  SyS_ioctl+0x79/0x90
> [51239.839069]  entry_SYSCALL_64_fastpath+0x1a/0xa9
> [51239.839069] RIP: 0033:0x7fb06bfe6c47
> [51239.839070] RSP: 002b:00007ffdc77cd118 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
> [51239.839071] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007fb06bfe6c47
> [51239.839071] RDX: 00007ffdc77cd1b0 RSI: 00000000c4009420 RDI: 0000000000000003
> [51239.839072] RBP: 0000000000000003 R08: 00007fb06cf2f8c0 R09: 00007fb06cf2f8c0
> [51239.839072] R10: 0000000000000545 R11: 0000000000000206 R12: 00007ffdc77cd1b0
> [51239.839073] R13: 0000000000480525 R14: 0000000000000000 R15: 00007ffdc77cf591

Third one is probably btrfs receive, which is also waiting for the
transaction:

> [51239.839076] INFO: task btrfs:29186 blocked for more than 120 seconds.
> [51239.839077]       Tainted: G           O    4.11.10-1-MANJARO #1
> [51239.839077] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [51239.839078] btrfs           D    0 29186  27726 0x00000000
> [51239.839079] Call Trace:
> [51239.839080]  __schedule+0x22e/0x8e0
> [51239.839081]  schedule+0x3d/0x90
> [51239.839082]  schedule_timeout+0x224/0x3c0
> [51239.839086]  ? btrfs_leaf_free_space+0x54/0xa0 [btrfs]
> [51239.839087]  ? wake_up_process+0x15/0x20
> [51239.839088]  wait_for_common+0xb9/0x180
> [51239.839089]  ? wait_for_common+0xb9/0x180
> [51239.839089]  ? wake_up_q+0x80/0x80
> [51239.839090]  wait_for_completion+0x1d/0x20
> [51239.839095]  btrfs_async_run_delayed_refs+0x119/0x140 [btrfs]
> [51239.839100]  __btrfs_end_transaction+0x1fa/0x300 [btrfs]
> [51239.839105]  btrfs_end_transaction+0x10/0x20 [btrfs]
> [51239.839110]  btrfs_setattr+0x129/0x3b0 [btrfs]
> [51239.839111]  notify_change+0x2c7/0x430
> [51239.839112]  do_truncate+0x73/0xc0
> [51239.839113]  vfs_truncate+0x14e/0x190
> [51239.839114]  ? user_path_at_empty+0x36/0x40
> [51239.839115]  do_sys_truncate.part.0+0x8a/0xa0
> [51239.839116]  SyS_truncate+0x13/0x20
> [51239.839117]  entry_SYSCALL_64_fastpath+0x1a/0xa9
> [51239.839118] RIP: 0033:0x7f325f704ce7
> [51239.839118] RSP: 002b:00007ffda084a908 EFLAGS: 00000297 ORIG_RAX: 000000000000004c
> [51239.839119] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f325f704ce7
> [51239.839119] RDX: 0000000000000000 RSI: 000000001124aa3b RDI: 00007ffda084a910
> [51239.839120] RBP: 00007ffda084ba20 R08: 0000000000000057 R09: 0000000001e56170
> [51239.839120] R10: 0000000001e561c0 R11: 0000000000000297 R12: 000000000000000f
> [51239.839121] R13: 000000000000c06b R14: 00000000e37b700a R15: 00007ffda084ba24
> [...]

There's probably another process, I suspect it being the
btrfs-transaction kernel thread, that is actually active at the same
time, taking long to get its work done, letting the other processes
wait, and maybe also even holding the lock which the cleaner is waiting for.

> ======================
> 
> I also have issued a "btrfs balance pause" command, which is now in an unkillable
> wait in the kernel.

Yes, that just waits for the balance to finish the block group it's
currently busy with, and then makes sure it doesn't start working on a
new one. So it's just joining the queue with blocked processes.

> I will reboot after sending this present email and see what I can see.

Rebooting while all those things are still busy is possible, but I think
it means you'll probably lose whatever was part of this transaction that
was being finished.

> But based on Marc's thread mentioned above, I am quite concerned
> that I should NEVER trust this particular btrfs file system again, and
> that I should reformat that 8 TB disk partition and rebuild the file
> store on that disk from scratch.
> 
> If so, I must conclude that I should NEVER trust btrfs again.

Don't panic. There's no big error anywhere yet.

Find out which process is the actually running process (all the other
ones reported in the log are waiting for that one), and see what it's
doing. 100% cpu? or a lot of disk reads and writes?

> ======================
> 
> Questions:
> 
> Is there anyway to recover this receiving btrfs file system?

Wait a bit until the busy process completes, and in the meantime try to
figure out what it's doing. Maybe the people on IRC can help a bit.

> Is there anyway to know, with confidence, that this receiving btrfs  file
> system is healthy?

I think there are no really big unhealty things happening yet, although
it's a bit inconvenient.

> If not is there any reliable way to avoid hitting this disaster again?

Doing 'big things' at the same time can lead to situations in which
similar things as seen above happen. Just avoid them. Don't remove 100
subvolumes at the same time as doing a receive and doing balance and
also doing another send somewhere. Or pointing balance at metadata and
then remove subvolumes (last time I saw that explode was in a 4.5 kernel).

The only really problematic combination I know is using send and balance
at the same time. Last two times I (accidentally) tried that I ended up
with one filesystem that ended up being broken in memory, crashed, and
was fine after a reboot again because it couldn't write its broken state
to disk. The other one crashed its send process in the kernel, and was
also fine again after a reboot.

> ===
> 
> If not that either, then know that I will necessarily throw out the
> last couple of months work I've spent, developing a backup system
> for my particular purposes that relies heavily on btrfs snapshots,
> sent and received to create off-site and off-line backups from multiple
> locations.
> 
> Just rebuilding the file system I was sending to would take me days
> of work.  This target file system contains backups of a half dozen
> other btrfs file systems.

Yeah, well... Btrfs is great, especially for things like backup servers
with snapshots (I'm doing that myself too), but you have to be very careful.

As I already said above, don't fire up too many fancy things at once. It
might go well, or they're already disallowed to do dangerous things at
the same time (leading to one being able to work, and the others hang
and wait), or it can trigger bugs which are lurking around in the
multithreaded code.

Also, choose your kernel versions wisely. Right now, the 4.9 LTS kernel
is a good bet. New kernels have fixes, new features but also new bugs.
In the case of btrfs, the LTS kernel sadly usually doesn't get most of
the bugfixes that fix "inconveniences" which are not causing actual data
corruption, but at least you can find out what the known issues are.
Data corruption bugs have a high chance of showing up in the latest LTS
though.

And if it all suddenly falls apart on a sunday night at 4AM and eats all
your data... then you're left with the pieces.

> [...]
> 
> P.S. -- About 50 minutes after issuing the above "btrfs balance pause",
> just before I was about to hit send on this email, I noticed:
> 
> 1.  my disk light flashing again
> 2.  that pause command returnedto the shell prompt (pause command exited),
> 3. the in progress balance command also exited, stating "balance paused by user"), and
> 4. the sequence of "btrfs receives" into that file system resumed progress.
> 
> Is that good news, bad news, or impossible to say news?

Well, there it is. :-) Whatever the busy thread was doing finished and
allowed the other ones to also continue again.

-- 
Hans van Kranenburg

Re: kernel btrfs file system wedged -- is it toast?

[Paul Jackson]

Thanks for you thoughtful answer, Hans.

>> what was the reason for using balance?

I had filled up that 8TB btrfs file system a couple of days ago,
which made me worry about it,  and do what things I thought
might ensure it was healthy again (after I removed a bunch
of stuff.)    I am not using RAID or any of the obvious reasons
to rebalance, but was guessing that the removals had left
lots of "blocks" (whatever  btrfs calls its chunks of data) half
full, so the rebalance was one of the operations I superstitiously
included in my "spring housecleaning"

>>  100% cpu? or a lot of disk reads and writes?

The disk light was off ...which is what I first noticed.  So I don't
think it was disk bound during that 50 minutes.

I did not look at CPU usage during that 50 minutes, and was
not doing anything else that needed much CPU, so would not
have known if one or two CPU cores were busy, or not.  I had
been assuming, without checking, that these kernel threads
were deadlocked, and would be so until reboot.  Apparently
that wasn't so, and one of them was busy doing something.

I already systematically use user level locking to
keep myself or my cron jobs from doing multiple things
at once to any given btrfs file system.  Looks like I need
to apply that locking to my balance/scrub/... jobs as well.

===

Two more, perhaps the last two, questions:

What could possibly take 50 minutes of kernel thread blocking
CPU time (since this wasn't disk bound, as best I know) in this
workload?

What are the "good things to do" to a btrfs file system that
has been filled up, after removing some stuff, of course?

Thanks!

-- 
                Paul Jackson
                pj@usa.net

Re: kernel btrfs file system wedged -- is it toast?

[Paul Jackson]

Regarding CPU vs disk hanging ... fifteen minutes ago, after
doing a "mount -oclear_cache", then a "mount -ospace_cache",
to clear some space cache errors reported by btrfs check,
I changed a shell's working directory into the top directory
of the freshly remounted btrfs file system, and then entered
"cd dir\t", where that tab was the completion character for
my shell.

That shell is still hung in the kernel, on a "disk sleep" fifteen
minutes later, and one of my CPU cores is pegged at 100%,
and the disk activity light is not coming on at all.

Apparently the way that btrfs gets all those nice features is
by placing a lower priority on fast, reliable, responsive,
robust, multi-tasking and on rock solid data integrity under
all manner of simultaneous operations.

What in god green's earth can kernel file system code be
doing that takes fifteen minutes (so far, in this case) or
fifty minutes (in the case I first reported on this thread?

This is not disk bound activity ... it's kernel code bound.

That's insane ... and sad.

-- 
                Paul Jackson
                pj@usa.net

Re: kernel btrfs file system wedged -- is it toast?

[David Goodwin]

....
> That shell is still hung in the kernel, on a "disk sleep" fifteen
> minutes later, and one of my CPU cores is pegged at 100%,
> and the disk activity light is not coming on at all.
>
> ......
> This is not disk bound activity ... it's kernel code bound.
>
> That's insane ... and sad.
>
'perf top' is my first thought.... it might at least highlight the area 
gobbling up cpu time.

I regularly see a limited balance (btrfs balance -musage=30 -dusage=30 
or something like that) take 3-4 days on a m3.medium (1 core) or 
m3.large (2 core?) EC2 VM with a 1Tb filesystem.

I see plenty of the 'hung kernel timeout' messages within dmesg (like 
your first post) but it eventually recovers and behaves.

About once every 6-9 months the filesystem will break on one of the 
single core VMs, and I'll end up wiping / starting again..... on a dual 
core VM it's run without issue and behaved much better.

(It's an 'offsite backup-backup server'. I tend to use one of the latest 
stable kernels - e.g. 4.9 at the moment).

David

Re: kernel btrfs file system wedged -- is it toast?

[Paul Jackson]

My btrfs file system, after doing a "mount -oclear_cache", followed
by a "mount -ospace_cache", eleven hours ago now, is still hung.

David Goodwin suggested:
>> 'perf top' is my first thought.... it might at least highlight the area 
>> gobbling up cpu time.

Thanks for suggesting that. It has been a long time since I've done
any kernel work, and I didn't know of (or had forgotten about)
perf-tools.   I just now installed these perf tools, and perf-top shows
this btrfs activity on the system stil trying to handle the above
"mount -ospace_cache":

+   78.00%    78.00%  [btrfs]                      [k] btrfs_merge_delayed_refs
+   38.56%     0.00%  [btrfs]                      [k] transaction_kthread
+   38.56%     0.00%  [btrfs]                      [k] btrfs_commit_transaction
+   38.56%     0.00%  [btrfs]                      [k] btrfs_start_dirty_block_groups
+   38.56%     0.00%  [btrfs]                      [k] btrfs_run_delayed_refs
+   38.56%     0.00%  [btrfs]                      [k] __btrfs_run_delayed_refs

Regarding the time to balance - yes I too have many  snapshots,
perhaps 100's to over a 1000 snapshots on each of a half dozen
subvolumes, with major sharing within the subvolumes.

Graham Cobb wrote:
>>  If I understand correctly, this is because btrfs does not have
>> an efficient structure to help find all the references 

Yeah this feels like  an Order n^2 or n^3 algorithm, or worse,  in
the wrong place(s).

If this conclusion  is anywhere close to acccurate, then I would
STRONGLY encourage the key developers of btrfs to announce
loudly and clearly to any potential users, in multiple places
(perhaps a key announcement in a few places and links to that
announcement from many places, such as prominent WARNING's
in man pages, at the top of Wiki pages, and in posts on prominent
forums and Youtube with "click-bait" titles):

... Do NOT create more  than a few btrfs snapshots  in file systems
... that cannot tolerate being unexpectedly locked in uninterruptible
... kernel code, for minutes, hours, even days, depending on the
... operations being performed on them.  DO expect to first have to
... learn, the hard way, of whatever special mitigations might apply
... in ones particular circumstances, before considering deploying
... btrfs into a production environment where this, or other (what
... other?) surprising limitations of btrfs may apply.

(The above suggested warning text may be technically inaccurate.
 I'm just  guessing.)

The btrfs developers should have known this, and announced this,
a long time ago, in various prominent ways that it would be difficult
for potential new users to miss.  All the prominent places that
respond to the question of whether btrfs is ready for production
use (spanning several years now) should if possible display this
warning.

Would you buy a car with an "unusual" engine that, whenever
it happened to be driven in a certain way (a unique and wonderful
way that no other car could do), would sometimes  recommend
a certain strange button on the dash board be pushed, which
then caused the car to freeze, in place, without notice, for hours
or days?  No ... and if you had such a car, you'd be looking to
replace it, no matter how unique and useful some of its features
 were. ... and if you had not been prominently warned of this
unusual behavior ahead of time, you'd likely avoid ever buying
another car from that company ever again.

I will now reboot this PC, as that btrfs file system  is still hung after
 that  "mount -oclear_cache",  "mount -ospace_cache" sequence.
This may mean that I lose the eleven hours I've spent so far
trying to get that file system remounted and operational.  I have
no way of knowing, that I know of.  (P.S. -- Update -- Once again,
the time I've taken to compose a diatribe was time well spent.
That  "mount -ospace_cache"  has completed successfully,
in under 12 hours.)

Whether or not the key developers of btrfs know of this or not ...
either way it is sad.  They should have known, and they should
have quite public about it, for many years now.

Back in my day, such a performance bug would have made the
software containing it unreleasable, _especially_ in software such
as a major file system that is expected to provide reliable service,
where "reliable" means both preserving data integrity and 
doing so within an order of magnitude of a reasonably
expected  time.

P.S. -- Hopefully my above diatribe represents an embarrassing
lack of understanding on my part, rather than an embrarrassing
lack of integrity on the part of key btrfs developers.

-- 
                Paul Jackson
                pj@usa.net

Re: kernel btrfs file system wedged -- is it toast?

[Chris Murphy]

On Fri, Jul 21, 2017 at 12:53 PM, Paul Jackson <pj@usa.net> wrote:
>
> My btrfs file system, after doing a "mount -oclear_cache", followed
> by a "mount -ospace_cache", eleven hours ago now, is still hung.
>
> David Goodwin suggested:
>>> 'perf top' is my first thought.... it might at least highlight the area
>>> gobbling up cpu time.
>
> Thanks for suggesting that. It has been a long time since I've done
> any kernel work, and I didn't know of (or had forgotten about)
> perf-tools.   I just now installed these perf tools, and perf-top shows
> this btrfs activity on the system stil trying to handle the above
> "mount -ospace_cache":
>
> +   78.00%    78.00%  [btrfs]                      [k] btrfs_merge_delayed_refs
> +   38.56%     0.00%  [btrfs]                      [k] transaction_kthread
> +   38.56%     0.00%  [btrfs]                      [k] btrfs_commit_transaction
> +   38.56%     0.00%  [btrfs]                      [k] btrfs_start_dirty_block_groups
> +   38.56%     0.00%  [btrfs]                      [k] btrfs_run_delayed_refs
> +   38.56%     0.00%  [btrfs]                      [k] __btrfs_run_delayed_refs
>
> Regarding the time to balance - yes I too have many  snapshots,
> perhaps 100's to over a 1000 snapshots on each of a half dozen
> subvolumes, with major sharing within the subvolumes.
>
> Graham Cobb wrote:
>>>  If I understand correctly, this is because btrfs does not have
>>> an efficient structure to help find all the references
>
> Yeah this feels like  an Order n^2 or n^3 algorithm, or worse,  in
> the wrong place(s).

No need to feel, the code is published.

[chris@f26s ~]$ grep -nR btrfs_merge_delayed_refs
/srv/scratch/gits.20170719/linux//fs/btrfs/
/srv/scratch/gits.20170719/linux//fs/btrfs/delayed-ref.c:269:void
btrfs_merge_delayed_refs(struct btrfs_trans_handle *trans,
/srv/scratch/gits.20170719/linux//fs/btrfs/delayed-ref.h:262:void
btrfs_merge_delayed_refs(struct btrfs_trans_handle *trans,
/srv/scratch/gits.20170719/linux//fs/btrfs/extent-tree.c:2566:
btrfs_merge_delayed_refs(trans, fs_info, delayed_refs,

>
> If this conclusion  is anywhere close to acccurate, then I would
> STRONGLY encourage the key developers of btrfs to announce
> loudly and clearly to any potential users, in multiple places
> (perhaps a key announcement in a few places and links to that
> announcement from many places, such as prominent WARNING's
> in man pages, at the top of Wiki pages, and in posts on prominent
> forums and Youtube with "click-bait" titles):
>
> ... Do NOT create more  than a few btrfs snapshots  in file systems
> ... that cannot tolerate being unexpectedly locked in uninterruptible
> ... kernel code, for minutes, hours, even days, depending on the
> ... operations being performed on them.  DO expect to first have to
> ... learn, the hard way, of whatever special mitigations might apply
> ... in ones particular circumstances, before considering deploying
> ... btrfs into a production environment where this, or other (what
> ... other?) surprising limitations of btrfs may apply.
>
> (The above suggested warning text may be technically inaccurate.
>  I'm just  guessing.)
>
> The btrfs developers should have known this, and announced this,
> a long time ago, in various prominent ways that it would be difficult
> for potential new users to miss.  All the prominent places that
> respond to the question of whether btrfs is ready for production
> use (spanning several years now) should if possible display this
> warning.
>
> Would you buy a car with an "unusual" engine that, whenever


If you've bought Btrfs, you have an SLA with a company like SUSE and
you can bring your complaint and reproducible problem to them, and
they'll probably provide some work arounds or advice until such time
as code improvements are available.

But if you're coming on the development list for advice on your own,
the usual way this works is you're expected to evaluate a file system
with your workload and basically just ask questions and state what
behavior you're experiencing, and see if it happens to catch a
developer's interest.

For hangs and performance related problems, often a developer will
like to see sysrq + t output. Depending on your kernel you'll need to
enable it, and then issue it - since my keyboards don't have a literal
sysrq key, I use Terminal and echo the value as described here:

https://www.kernel.org/doc/html/v4.11/admin-guide/sysrq.html

It's best to attached the output, if it's small enough, so MUAs don't
hose the formatting and make it insanely difficult to read; if it's
too big to attach (decently likely) then it needs to go up on pastebin
or as an uploaded file to the cloud and post the URL.


> Back in my day, such a performance bug would have made the
> software containing it unreleasable, _especially_ in software such
> as a major file system that is expected to provide reliable service,
> where "reliable" means both preserving data integrity and
> doing so within an order of magnitude of a reasonably
> expected  time.

OK? What contract or normative behavior makes this relevant and
applicable in this context?


>
> P.S. -- Hopefully my above diatribe represents an embarrassing
> lack of understanding on my part, rather than an embrarrassing
> lack of integrity on the part of key btrfs developers.

I think the former is certain, so consider your wish granted.

-- 
Chris Murphy

Re: kernel btrfs file system wedged -- is it toast?

[Hans van Kranenburg]

Hey,

On 07/21/2017 08:53 PM, Paul Jackson wrote:
> 
> My btrfs file system, after doing a "mount -oclear_cache", followed
> by a "mount -ospace_cache", eleven hours ago now, is still hung.
> 
> David Goodwin suggested:
>>> 'perf top' is my first thought.... it might at least highlight the area 
>>> gobbling up cpu time.
> 
> Thanks for suggesting that. It has been a long time since I've done
> any kernel work, and I didn't know of (or had forgotten about)
> perf-tools.   I just now installed these perf tools, and perf-top shows
> this btrfs activity on the system stil trying to handle the above
> "mount -ospace_cache":
> 
> +   78.00%    78.00%  [btrfs]                      [k] btrfs_merge_delayed_refs
> +   38.56%     0.00%  [btrfs]                      [k] transaction_kthread
> +   38.56%     0.00%  [btrfs]                      [k] btrfs_commit_transaction
> +   38.56%     0.00%  [btrfs]                      [k] btrfs_start_dirty_block_groups
> +   38.56%     0.00%  [btrfs]                      [k] btrfs_run_delayed_refs
> +   38.56%     0.00%  [btrfs]                      [k] __btrfs_run_delayed_refs
> 
> Regarding the time to balance - yes I too have many  snapshots,
> perhaps 100's to over a 1000 snapshots on each of a half dozen
> subvolumes, with major sharing within the subvolumes.
> 
> Graham Cobb wrote:
>>>  If I understand correctly, this is because btrfs does not have
>>> an efficient structure to help find all the references 
> 
> Yeah this feels like  an Order n^2 or n^3 algorithm, or worse,  in
> the wrong place(s).
> 
> If this conclusion  is anywhere close to acccurate, then I would
> STRONGLY encourage the key developers of btrfs to announce [...]

Well, there it is:

https://btrfs.wiki.kernel.org/index.php/Gotchas#Having_many_subvolumes_can_be_very_slow

It says that having "subvolumes with more than a dozen snapshots" (a
dozen is 12) starts bringing you into areas where some things might not
be optimized yet. So your "100's to over a 1000 snapshots" falls well
outside of the recommended documented limits.

> Would you buy a car with an "unusual" engine that, whenever
> it [...rant...]

Be aware that the attitude displayed in your ramblings is not helping
the situation. Reading them does not likely encourage other people to
spend their spare time to start explaining more things to you and
helping you to overcome issues. Things are not going to improve by
shouting at them. Other people are scared away instead.

What you got (the btrfs program code) is something other people have
been working on for hours, days or years, and they provide it to you
with the possibility to use it for free. But, it also comes with a big
disclaimer, which says, quoting the GPL-2... that what you get is "THE
PROGRAM "AS IS" WITHOUT WARRANTY OF ANY KIND" and it even says that
there is no guarantee at all that it has any "FITNESS FOR A PARTICULAR
PURPOSE".

So the analogy, when you are at the car dealer is more like: "Yes, you
can buy this car, it has security certifications, bla bla tested bla bla
guarantee, but, you can also get this other model for free. If you take
the free model, we cannot give you any guarantee that it will work, set
itself on fire while locking all doors, kill you and your family within
a day or do anything else you wouldn't suspect. And if it does, you
cannot sue us."

Have fun,

-- 
Hans van Kranenburg

Re: kernel btrfs file system wedged -- is it toast?

[Paul Jackson]

Hans wrote:
>> Be aware that the attitude displayed in your ramblings is not helping
>> the situation.

Yes - this is true.  I agree that my last post was burning some bridges.

You were quite helpful in your earlier reply - thank-you.

I stand by my protest. 

-- 
                Paul Jackson
                pj@usa.net

Re: kernel btrfs file system wedged -- is it toast?

[Peter Grandi]

> [ ... ] announce loudly and clearly to any potential users, in
> multiple places (perhaps a key announcement in a few places
> and links to that announcement from many places,

https://btrfs.wiki.kernel.org/index.php/Gotchas#Having_many_subvolumes_can_be_very_slow

> ... DO expect to first have to learn, the hard way, of
> ... whatever special mitigations might apply in ones
> ... particular circumstances, before considering deploying
> ... btrfs into a production environment where this, or other
> ... (what other?) surprising limitations of btrfs may apply.

In computer jargon that is called "being a system engineer".

> All the prominent places that respond to the question of
> whether btrfs is ready for production use (spanning several
> years now) should if possible display this warning.

https://btrfs.wiki.kernel.org/index.php/Status
  "The table below aims to serve as an overview for the stability
  status of the features BTRFS supports. While a feature may be
  functionally safe and reliable, it does not necessarily mean
  that its useful, for example in meeting your performance
  expectations for your specific workload."

> [ ... ] Back in my day, such a performance bug would have made
> the software containing it unreleasable, _especially_ in
> software such as a major file system that is expected to
> provide reliable service, where "reliable" means both
> preserving data integrity and doing so within an order of
> magnitude of a reasonably expected time.

For the past several decades, since perhaps the Manchester MARK I
(or the ZUSE probably), it has been known to "system engineers"
and "programmers" that most features of "hardware" and "software"
have very anisotropic performance envelopes, both as to speed and
usability and reliability, and not all potentially syntactically
valid combinations of features are equally robust and excellent
under every possible workload, and indeed very few are, and it is
part of "being a system engineer" or "being a programmer" to
develop insight and experience, leading to knowledge ideally, as
to what combinations work well and which work badly.

Considering somewhat imprecise car analogies, jet engines on cars
tend not to be wholly desirable, even if syntactically valid, and
using cars to plow fields does not necessarily yield the highest
productivity, even if also syntactically valid.

General introduction about anisotropy and performance:

  http://www.sabi.co.uk/blog/15-two.html?151023#151023

In storage system and filesystems "system engineers" often have
to confront a large number of pathological cases of anisotropy,
some examples I can find quickly in my links:

  http://www.sabi.co.uk/blog/1005May.html?100520#100520
  http://www.sabi.co.uk/blog/16-one.html?160322#160322
  http://www.sabi.co.uk/blog/15-one.html?150203#150203
  http://www.sabi.co.uk/blog/12-fou.html?121218#121218
  http://www.sabi.co.uk/blog/0802feb.html?080210#080210
  http://www.sabi.co.uk/blog/0802feb.html?080216#080216

I try to keep lists of "known pathologies" of various types here:

  http://www.sabi.co.uk/Notes/linuxStor.html
  http://www.sabi.co.uk/Notes/linuxFS.html#fsHints

Even "legendary" 'ext3' has/had pathological (and common) cases:

  https://lwn.net/Articles/328370/
  https://lwn.net/Articles/328363/
  https://bugzilla.kernel.org/show_bug.cgi?id=12309
  https://news.ycombinator.com/item?id=7376750
  https://news.ycombinator.com/item?id=7377315

  https://lkml.org/lkml/2009/4/6/331
    the difference between the occasional 5+ second pause and the
    occasional 10+ second pause wasn't really all that
    interesting. They were both unusuable, and both made me kill
    the background writer almost immediately

Wisely L Torvalds writes:

  https://lkml.org/lkml/2010/11/10/233
    ext3 [f]sync sucks. We know. All filesystems suck.
    They just tend to do it in different dimensions.

Re: kernel btrfs file system wedged -- is it toast?

[Marat Khalili]

> The btrfs developers should have known this, and announced this,
a long time ago, in various prominent ways that it would be difficult
for potential new users to miss. 

I'm also a user like you, and I felt like this too when I came here (BTW there are several traps in BTRFS, and other are causing partial or whole filesystem loss, so you're lucky). There's truth in your words that some warning is needed, but in this open-source business it is not clear who should give it to whom. Developers in the list are actually spending their time on adding such warnings to kernel and command-line tools, but e.g. people using GUI and not reading dmesg over breakfast won't see them anyways. All situation is unfortunate because hardware and OS vendors keep hyping BTRFS and making it default in their products when it is clearly not ready, but you're now talking to and blaming the wrong people.

Personally for me coming to this list was the most helpful thing in understanding BTRFS current state and limitations. I'm still using it, although in a very careful and controlled manner. But browsing the list every day sadly takes time. If you can't afford it or are running something absolutely critical, better look to other, more mature filesystems. After all, as adage says: "legacy is what we run in production".
-- 

With Best Regards,
Marat Khalili

Re: kernel btrfs file system wedged -- is it toast?

[Graham Cobb]

On 21/07/17 07:06, Paul Jackson wrote:
> What in god green's earth can kernel file system code be
> doing that takes fifteen minutes (so far, in this case) or
> fifty minutes (in the case I first reported on this thread?

I find that just doing a balance on a disk with lots of snapshots can
cause this sort of effect.  If I understand correctly, this is because
btrfs does not have an efficient structure to help find all the
references in different subvolumes to an extent which is being
manipulated and many trees have to be searched. My understanding may be
wrong but, in any case, the effect is that many operations can take
massive amounts of processing time if there are lots of shared extents.

This caused my early experiments with using btrfs snapshots on my main
data disk (full of mail files, etc) to make the system lock up for many
**hours** at a time (preventing mail processing, etc).

I took the advice on this list to significantly decrease the number of
snapshots I kept on the disk (I keep more on a separate backup disk,
which has no day-to-day transactions happening, and can also better
tolerate any issues).

I also created a very hacky script to try to limit the impact of the
balances which I do weekly. See
https://github.com/GrahamCobb/btrfs-balance-slowly if you are
interested. Between these things, the serious disruption is now gone.

Note: despite all the hangs, I never saw any disk corruption.

Graham