4.13: "error in btrfs_run_delayed_refs:3009: errno=-28 No space left" with 1.3TB unallocated / 737G free?

[Vladimir Panteleev <thecybershadow@gmail.com>]

Hi,

I'm experiencing some issues with a btrfs filesystem - mounting and 
other operations taking forever, a balance that takes hours to start and 
never completes (due to the error in the subject line), and I've also 
seen the NULL pointer dereference in free_reloc_roots which Naohiro Aota 
fixed in 4.13.5 (I was on 4.13.4 at the time).

The output of the relevant commands:

# uname -a
Linux home.thecybershadow.net 4.13.6-1-ARCH #1 SMP PREEMPT Thu Oct 12 
12:42:27 CEST 2017 x86_64 GNU/Linux

# btrfs --version
btrfs-progs v4.13

# df -h /mnt/a
Filesystem      Size  Used Avail Use% Mounted on
/dev/sdi1       5.5T  4.8T  737G  87% /mnt/a

# btrfs filesystem show /mnt/a
Label: none  uuid: f4162b8e-930d-49fa-bbea-56ea3bb544fa
	Total devices 4 FS bytes used 4.74TiB
	devid    2 size 2.73TiB used 2.73TiB path /dev/sdi1
	devid    3 size 2.73TiB used 2.73TiB path /dev/sdb1
	devid    4 size 2.73TiB used 2.73TiB path /dev/sda1
	devid    7 size 2.73TiB used 2.73TiB path /dev/sde1

# btrfs filesystem df /mnt/a
Data, RAID10: total=5.34TiB, used=4.62TiB
System, RAID1: total=8.00MiB, used=608.00KiB
Metadata, RAID1: total=122.03GiB, used=121.37GiB
GlobalReserve, single: total=512.00MiB, used=149.00MiB

# btrfs filesystem usage /mnt/a
Overall:
     Device size:		  10.92TiB
     Device allocated:		  10.91TiB
     Device unallocated:		   2.00GiB
     Device missing:		     0.00B
     Used:			   9.47TiB
     Free (estimated):		 737.75GiB	(min: 737.75GiB)
     Data ratio:			      2.00
     Metadata ratio:		      2.00
     Global reserve:		 512.00MiB	(used: 149.00MiB)

Data,RAID10: Size:5.34TiB, Used:4.62TiB
    /dev/sda1	   1.33TiB
    /dev/sdb1	   1.33TiB
    /dev/sde1	   1.33TiB
    /dev/sdi1	   1.33TiB

Metadata,RAID1: Size:122.03GiB, Used:121.37GiB
    /dev/sda1	  59.51GiB
    /dev/sdb1	  61.51GiB
    /dev/sde1	  61.52GiB
    /dev/sdi1	  61.52GiB

System,RAID1: Size:8.00MiB, Used:608.00KiB
    /dev/sda1	   8.00MiB
    /dev/sdb1	   8.00MiB

Unallocated:
    /dev/sda1	   1.34TiB
    /dev/sdb1	   1.33TiB
    /dev/sde1	   1.33TiB
    /dev/sdi1	   1.33TiB

# btrfs device usage /mnt/a
/dev/sda1, ID: 4
    Device size:             2.73TiB
    Device slack:            3.50KiB
    Data,RAID10:             1.33TiB
    Metadata,RAID1:         59.51GiB
    System,RAID1:            8.00MiB
    Unallocated:             1.34TiB

/dev/sdb1, ID: 3
    Device size:             2.73TiB
    Device slack:            3.50KiB
    Data,RAID10:             1.33TiB
    Metadata,RAID1:         61.51GiB
    System,RAID1:            8.00MiB
    Unallocated:             1.33TiB

/dev/sde1, ID: 7
    Device size:             2.73TiB
    Device slack:              0.00B
    Data,RAID10:             1.33TiB
    Metadata,RAID1:         61.52GiB
    Unallocated:             1.33TiB

/dev/sdi1, ID: 2
    Device size:             2.73TiB
    Device slack:            3.50KiB
    Data,RAID10:             1.33TiB
    Metadata,RAID1:         61.52GiB
    Unallocated:             1.33TiB

I admit I'm somewhat confused by some of these figures. If I'm reading 
this correctly, the metadata blocks are almost full, however that 
shouldn't be an issue because there seems to be plenty of unallocated 
space - or is there? The "Unallocated" figure in the "Overall:" section 
(2.00GiB) doesn't seem to match that in the "Unallocated:" section 
(1.33TiB), and my gut estimate is that the actual amount of data on the 
disks roughly matches df's output. In any case, I've tried deleting some 
200GiB worth of files (which has not helped the situation in any way 
that I've noticed) and running a balance with -dusage=0 and -dusage=10 
(which never completes due to the errors below).

Here's the timeline (with dmesg excerpts) of trying to mount the 
filesystem. The previous unmount was unclean due to the NULL pointer 
dereference, and it seems to attempt to resume the balance started a few 
mounts ago right after mounting.

(running mount command)

[  128.514335] BTRFS info (device sdb1): disk space caching is enabled
[  128.514340] BTRFS info (device sdb1): has skinny extents
[  128.827147] BTRFS info (device sdb1): bdev /dev/sdb1 errs: wr 61870, 
rd 18726, flush 1320, corrupt 0, gen 275
[  128.827154] BTRFS info (device sdb1): bdev /dev/sde1 errs: wr 0, rd 
36, flush 0, corrupt 0, gen 0
[  128.827161] BTRFS info (device sdb1): bdev /dev/sda1 errs: wr 0, rd 
457, flush 0, corrupt 0, gen 0
[  184.666715] BTRFS warning (device sdb1): block group 2378367500288 
has wrong amount of free space
[  184.666717] BTRFS warning (device sdb1): failed to load free space 
cache for block group 2378367500288, rebuilding it now
[  184.732017] BTRFS warning (device sdb1): block group 7880254160896 
has wrong amount of free space
[  184.732018] BTRFS warning (device sdb1): failed to load free space 
cache for block group 7880254160896, rebuilding it now
[  184.790792] BTRFS warning (device sdb1): block group 8582481313792 
has wrong amount of free space
[  184.790794] BTRFS warning (device sdb1): failed to load free space 
cache for block group 8582481313792, rebuilding it now
(...a few more of these...)
[  326.714923] BTRFS warning (device sdb1): block group 15167773474816 
has wrong amount of free space
[  326.714926] BTRFS warning (device sdb1): failed to load free space 
cache for block group 15167773474816, rebuilding it now
[  361.777631] BTRFS warning (device sdb1): block group 9985861877760 
has wrong amount of free space
[  361.777635] BTRFS warning (device sdb1): failed to load free space 
cache for block group 9985861877760, rebuilding it now
[ 1579.535116] BTRFS info (device sdb1): checking UUID tree
[ 1579.535118] BTRFS info (device sdb1): continuing balance
[ 1592.162452] BTRFS info (device sdb1): relocating block group 
15527562706944 flags metadata|raid1

(mount command exits here)

[12624.021210] BTRFS info (device sdb1): relocating block group 
15527562706944 flags metadata|raid1
[13748.745807] perf: interrupt took too long (3143 > 3130), lowering 
kernel.perf_event_max_sample_rate to 63600

(here it seems to be trying to resume the balance, but gets stuck in 
btrfs_shrink_device for a very long time - sysrq-w follows)

[14510.837275] sysrq: SysRq : Show Blocked State
[14510.837277]   task                        PC stack   pid father
[14510.837486] btrfs-transacti D    0  2245      2 0x00000000
[14510.837488] Call Trace:
[14510.837493]  __schedule+0x239/0x890
[14510.837495]  schedule+0x3d/0x90
[14510.837497]  io_schedule+0x16/0x40
[14510.837499]  get_request+0x283/0x800
[14510.837501]  ? ioc_lookup_icq+0x50/0x70
[14510.837503]  ? wait_woken+0x80/0x80
[14510.837505]  blk_queue_bio+0x118/0x410
[14510.837507]  generic_make_request+0x125/0x320
[14510.837508]  ? bio_alloc_bioset+0xcc/0x1e0
[14510.837509]  submit_bio+0x73/0x150
[14510.837510]  ? __bio_clone_fast+0x5f/0x70
[14510.837511]  ? submit_bio+0x73/0x150
[14510.837512]  ? bio_clone_fast+0x31/0x70
[14510.837526]  btrfs_map_bio+0x100/0x300 [btrfs]
[14510.837533]  btree_submit_bio_hook+0x5d/0xd0 [btrfs]
[14510.837541]  ? write_one_eb+0xff/0x260 [btrfs]
[14510.837549]  submit_one_bio+0x67/0x90 [btrfs]
[14510.837556]  flush_epd_write_bio+0x35/0x50 [btrfs]
[14510.837562]  flush_write_bio+0xe/0x10 [btrfs]
[14510.837569]  btree_write_cache_pages+0x3cd/0x420 [btrfs]
[14510.837577]  btree_writepages+0x5d/0x70 [btrfs]
[14510.837579]  do_writepages+0x48/0xd0
[14510.837585]  ? merge_state.part.44+0x44/0x130 [btrfs]
[14510.837587]  ? kmem_cache_alloc+0x165/0x1c0
[14510.837589]  __filemap_fdatawrite_range+0xc1/0x100
[14510.837590]  ? __filemap_fdatawrite_range+0xc1/0x100
[14510.837592]  filemap_fdatawrite_range+0x13/0x20
[14510.837599]  btrfs_write_marked_extents+0x5a/0x120 [btrfs]
[14510.837605] 
btrfs_write_and_wait_marked_extents.constprop.20+0x4f/0x90 [btrfs]
[14510.837612]  btrfs_commit_transaction+0x5b1/0x8e0 [btrfs]
[14510.837618]  ? btrfs_commit_transaction+0x5b1/0x8e0 [btrfs]
[14510.837624]  transaction_kthread+0x193/0x1c0 [btrfs]
[14510.837626]  kthread+0x125/0x140
[14510.837632]  ? btrfs_cleanup_transaction+0x510/0x510 [btrfs]
[14510.837633]  ? kthread_create_on_node+0x70/0x70
[14510.837635]  ret_from_fork+0x25/0x30
[14510.837637] btrfs-balance   D    0  5474      2 0x00000000
[14510.837638] Call Trace:
[14510.837640]  __schedule+0x239/0x890
[14510.837641]  schedule+0x3d/0x90
[14510.837646]  wait_current_trans+0xc4/0xf0 [btrfs]
[14510.837648]  ? wait_woken+0x80/0x80
[14510.837653]  start_transaction+0x33a/0x420 [btrfs]
[14510.837659]  btrfs_start_transaction+0x1e/0x20 [btrfs]
[14510.837667]  relocate_block_group+0x145/0x620 [btrfs]
[14510.837674]  btrfs_relocate_block_group+0x184/0x230 [btrfs]
[14510.837682]  btrfs_relocate_chunk+0x38/0xd0 [btrfs]
[14510.837689]  btrfs_shrink_device+0x1d1/0x4d0 [btrfs]
[14510.837696]  btrfs_balance+0x3ee/0x13d0 [btrfs]
[14510.837698]  ? vprintk_func+0x27/0x60
[14510.837699]  ? printk+0x52/0x6e
[14510.837704]  ? btrfs_printk+0x150/0x160 [btrfs]
[14510.837705]  ? __schedule+0x241/0x890
[14510.837711]  balance_kthread+0x5b/0x80 [btrfs]
[14510.837713]  kthread+0x125/0x140
[14510.837719]  ? btrfs_balance+0x13d0/0x13d0 [btrfs]
[14510.837720]  ? kthread_create_on_node+0x70/0x70
[14510.837722]  ret_from_fork+0x25/0x30

[23590.145036] BTRFS info (device sdb1): relocating block group 
13896429600768 flags data|raid10
[23693.855884] BTRFS info (device sdb1): found 1457 extents

(finally gets out of btrfs_shrink_device after 4 hours:)

[28240.779051] sysrq: SysRq : Show Blocked State
[28240.779054]   task                        PC stack   pid father
[28240.779263] btrfs-balance   D    0  5474      2 0x00000000
[28240.779265] Call Trace:
[28240.779270]  __schedule+0x239/0x890
[28240.779272]  schedule+0x3d/0x90
[28240.779274]  io_schedule+0x16/0x40
[28240.779277]  get_request+0x283/0x800
[28240.779279]  ? wait_woken+0x80/0x80
[28240.779281]  blk_queue_bio+0x118/0x410
[28240.779283]  generic_make_request+0x125/0x320
[28240.779284]  ? bio_alloc_bioset+0xcc/0x1e0
[28240.779285]  submit_bio+0x73/0x150
[28240.779286]  ? __bio_clone_fast+0x5f/0x70
[28240.779287]  ? submit_bio+0x73/0x150
[28240.779288]  ? bio_clone_fast+0x31/0x70
[28240.779302]  btrfs_map_bio+0x100/0x300 [btrfs]
[28240.779309]  btree_submit_bio_hook+0x5d/0xd0 [btrfs]
[28240.779317]  ? write_one_eb+0xff/0x260 [btrfs]
[28240.779324]  submit_one_bio+0x67/0x90 [btrfs]
[28240.779331]  flush_epd_write_bio+0x35/0x50 [btrfs]
[28240.779337]  flush_write_bio+0xe/0x10 [btrfs]
[28240.779344]  btree_write_cache_pages+0x3cd/0x420 [btrfs]
[28240.779351]  ? free_extent_state+0x3e/0xa0 [btrfs]
[28240.779358]  btree_writepages+0x5d/0x70 [btrfs]
[28240.779360]  do_writepages+0x48/0xd0
[28240.779366]  ? merge_state.part.44+0x44/0x130 [btrfs]
[28240.779368]  ? kmem_cache_alloc+0x165/0x1c0
[28240.779370]  __filemap_fdatawrite_range+0xc1/0x100
[28240.779371]  ? __filemap_fdatawrite_range+0xc1/0x100
[28240.779373]  filemap_fdatawrite_range+0x13/0x20
[28240.779380]  btrfs_write_marked_extents+0x5a/0x120 [btrfs]
[28240.779386] 
btrfs_write_and_wait_marked_extents.constprop.20+0x4f/0x90 [btrfs]
[28240.779392]  btrfs_commit_transaction+0x5b1/0x8e0 [btrfs]
[28240.779398]  ? btrfs_commit_transaction+0x5b1/0x8e0 [btrfs]
[28240.779404]  ? btrfs_block_rsv_check+0x5c/0x70 [btrfs]
[28240.779410]  __btrfs_end_transaction+0x2bc/0x2e0 [btrfs]
[28240.779416]  btrfs_end_transaction_throttle+0x13/0x20 [btrfs]
[28240.779422]  btrfs_drop_snapshot+0x4aa/0x890 [btrfs]
[28240.779430]  merge_reloc_roots+0xe0/0x240 [btrfs]
[28240.779437]  relocate_block_group+0x24c/0x620 [btrfs]
[28240.779444]  btrfs_relocate_block_group+0x184/0x230 [btrfs]
[28240.779451]  btrfs_relocate_chunk+0x38/0xd0 [btrfs]
[28240.779458]  btrfs_balance+0xc10/0x13d0 [btrfs]
[28240.779460]  ? vprintk_func+0x27/0x60
[28240.779467]  balance_kthread+0x5b/0x80 [btrfs]
[28240.779468]  kthread+0x125/0x140
[28240.779474]  ? btrfs_balance+0x13d0/0x13d0 [btrfs]
[28240.779476]  ? kthread_create_on_node+0x70/0x70
[28240.779478]  ret_from_fork+0x25/0x30
[32045.071810] BTRFS info (device sdb1): relocating block group 
13892134633472 flags data|raid10
[32327.848335] BTRFS info (device sdb1): found 5445 extents

(and here's the -28 error:)

[32378.507277] BTRFS: Transaction aborted (error -28)
[32378.507309] ------------[ cut here ]------------
[32378.507322] WARNING: CPU: 10 PID: 31101 at 
fs/btrfs/extent-tree.c:3009 btrfs_run_delayed_refs+0x23d/0x250 [btrfs]
[32378.507322] Modules linked in: fuse nls_utf8 cifs ccm dns_resolver 
fscache xt_nat vhost_net vhost tap xt_CHECKSUM iptable_mangle 
xt_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp ebtable_filter ebtables 
ip6table_filter ip6_tables iptable_filter devlink tun uinput it87 
hwmon_vid ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat 
nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack 
libcrc32c crc32c_generic sit tunnel4 ip_tunnel snd_hda_codec_hdmi 8021q 
mrp snd_hda_codec_realtek snd_hda_codec_generic nls_iso8859_1 nls_cp437 
vfat fat iTCO_wdt iTCO_vendor_support intel_rapl mxm_wmi 
x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass 
crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc aesni_intel 
aes_x86_64 crypto_simd glue_helper cryptd intel_cstate nvidia_drm(PO) 
intel_rapl_perf
[32378.507343]  nvidia_modeset(PO) i2c_i801 arc4 ath3k uvcvideo btusb 
videobuf2_vmalloc btrtl videobuf2_memops btbcm btintel videobuf2_v4l2 
nvidia(PO) snd_usb_audio videobuf2_core bluetooth ath9k snd_usbmidi_lib 
videodev snd_rawmidi pl2303 evdev mousedev input_leds ath9k_common 
joydev ecdh_generic crc16 usbserial media snd_seq_device mac_hid cdc_acm 
ath9k_hw ath mac80211 snd_hda_intel drm_kms_helper snd_hda_codec 
snd_hda_core snd_hwdep drm cfg80211 snd_pcm r8169 snd_timer e1000e 
mei_me agpgart lpc_ich snd mii syscopyarea sysfillrect mei rfkill 
sysimgblt fb_sys_fops led_class soundcore ioatdma ptp pps_core dca 
shpchp wmi bridge tpm_infineon tpm_tis tpm_tis_core tpm stp llc button 
sch_fq_codel sg ip_tables x_tables btrfs xor raid6_pq sd_mod sr_mod 
cdrom hid_generic hid_dr ff_memless usbhid hid crc32c_intel
[32378.507368]  xhci_pci isci ehci_pci xhci_hcd libsas ehci_hcd ahci 
scsi_transport_sas libahci usbcore usb_common libata scsi_mod serio
[32378.507374] CPU: 10 PID: 31101 Comm: kworker/u24:11 Tainted: P 
    O    4.13.6-1-ARCH #1
[32378.507375] Hardware name: Gigabyte Technology Co., Ltd. To be filled 
by O.E.M./X79S-UP5, BIOS F5f 03/19/2014
[32378.507380] Workqueue: events_unbound 
btrfs_async_reclaim_metadata_space [btrfs]
[32378.507381] task: ffff9301b7cc5a00 task.stack: ffffaa284e1cc000
[32378.507386] RIP: 0010:btrfs_run_delayed_refs+0x23d/0x250 [btrfs]
[32378.507387] RSP: 0018:ffffaa284e1cfc50 EFLAGS: 00010282
[32378.507388] RAX: 0000000000000026 RBX: ffff9301af40f618 RCX: 
0000000000000000
[32378.507388] RDX: 0000000000000000 RSI: ffff9301bf48dc78 RDI: 
ffff9301bf48dc78
[32378.507389] RBP: ffffaa284e1cfca8 R08: 00000000000007b4 R09: 
0000000000000004
[32378.507389] R10: ffffaa284e1cfb40 R11: 0000000000000001 R12: 
00000000ffffffe4
[32378.507390] R13: ffff9301561f0000 R14: ffff92f98fddd800 R15: 
0000000000006090
[32378.507391] FS:  0000000000000000(0000) GS:ffff9301bf480000(0000) 
knlGS:0000000000000000
[32378.507391] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[32378.507392] CR2: 00007fe0611e3000 CR3: 0000000f7fa09000 CR4: 
00000000001426e0
[32378.507392] Call Trace:
[32378.507401]  btrfs_commit_transaction+0x9b/0x8e0 [btrfs]
[32378.507407]  ? start_transaction+0x99/0x420 [btrfs]
[32378.507412]  flush_space+0xab/0x570 [btrfs]
[32378.507415]  ? dequeue_entity+0xed/0x4d0
[32378.507417]  ? pick_next_task_fair+0x162/0x560
[32378.507420]  ? __switch_to+0x1fc/0x4d0
[32378.507425]  btrfs_async_reclaim_metadata_space+0xd0/0x490 [btrfs]
[32378.507426]  process_one_work+0x1de/0x430
[32378.507428]  worker_thread+0x47/0x3f0
[32378.507429]  kthread+0x125/0x140
[32378.507430]  ? process_one_work+0x430/0x430
[32378.507432]  ? kthread_create_on_node+0x70/0x70
[32378.507434]  ret_from_fork+0x25/0x30
[32378.507435] Code: 44 89 e1 ba c1 0b 00 00 48 c7 c6 60 78 44 c0 48 89 
df e8 7d a7 09 00 e9 ac fe ff ff 44 89 e6 48 c7 c7 40 e6 44 c0 e8 e4 6e 
d3 d5 <0f> ff eb d1 e8 f7 a8 09 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f
[32378.507451] ---[ end trace 148d3f8f75efeefd ]---
[32378.507453] BTRFS: error (device sdb1) in 
btrfs_run_delayed_refs:3009: errno=-28 No space left
[32378.507456] BTRFS info (device sdb1): forced readonly
[32378.508112] BTRFS info (device sdb1): 1 enospc errors during balance

The above seems to repeat every time I mount it no matter the number of 
tries, so whatever work it's doing for the hours leading to the error, 
it seems to want to redo them all again on every mount.

I noticed that this situation looks similar to the one described by 
Tomasz Chmielewski in his thread "4.13: No space left with plenty of 
free space (/home/kernel/COD/linux/fs/btrfs/extent-tree.c:6989 
__btrfs_free_extent.isra.62+0xc2c/0xdb0)". There, Josef Bacik suggests 
trying a branch with some fixes. Would it make sense to try these for 
this situation?

Thanks!