Transaction aborted error -28 clone_finish_inode_update

Transaction aborted error -28 clone_finish_inode_update

[David Goodwin]

While trying to run/use bedup ( https://github.com/g2p/bedup ) .... I 
hit this :


[Thu Oct  4 15:34:51 2018] ------------[ cut here ]------------
[Thu Oct  4 15:34:51 2018] BTRFS: Transaction aborted (error -28)
[Thu Oct  4 15:34:51 2018] WARNING: CPU: 0 PID: 28832 at 
fs/btrfs/ioctl.c:3671 clone_finish_inode_update+0xf3/0x140
[Thu Oct  4 15:34:51 2018] Modules linked in: ipt_REJECT nf_reject_ipv4 
dm_mod dax xt_multiport iptable_filter ip_tables x_tables intel_rapl 
crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel pcbc 
evdev aesni_intel snd_pcsp aes_x86_64 crypto_simd snd_pcm snd_timer 
cryptd snd glue_helper soundcore xen_netfront xen_blkfront
[Thu Oct  4 15:34:51 2018] CPU: 0 PID: 28832 Comm: bedup Not tainted 
4.18.10-psi-dg1 #1
[Thu Oct  4 15:34:51 2018] RIP: e030:clone_finish_inode_update+0xf3/0x140
[Thu Oct  4 15:34:51 2018] Code: c7 e9 67 ff ff ff 49 8b 44 24 50 f0 48 
0f ba a8 08 17 00 00 02 72 15 83 fb fb 74 3b 89 de 48 c7 c7 00 70 da 81 
e8 0d c7 cf ff <0f> 0b 89 d9 4c 89 e7 ba 57 0e 00 00 48 c7 c6 d0 91 c3 
81 e8 61 b8
[Thu Oct  4 15:34:51 2018] RSP: e02b:ffffc90042b6fc38 EFLAGS: 00010282
[Thu Oct  4 15:34:51 2018] RAX: 0000000000000000 RBX: 00000000ffffffe4 
RCX: 0000000000000006
[Thu Oct  4 15:34:51 2018] RDX: 0000000000000007 RSI: 0000000000000001 
RDI: ffff8801c9016650
[Thu Oct  4 15:34:51 2018] RBP: ffffc90042b6fc68 R08: 0000000000000001 
R09: 00000000000001ed
[Thu Oct  4 15:34:51 2018] R10: ffff8801c3a527d0 R11: 00000000000001ed 
R12: ffff8801c391abc8
[Thu Oct  4 15:34:51 2018] R13: 0000000008000000 R14: ffff8801c3a52ae8 
R15: ffff88010cc8d380
[Thu Oct  4 15:34:51 2018] FS:  00007f51a15bd700(0000) 
GS:ffff8801c9000000(0000) knlGS:0000000000000000
[Thu Oct  4 15:34:51 2018] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
[Thu Oct  4 15:34:51 2018] CR2: 00007f5199bf4024 CR3: 000000012101e000 
CR4: 0000000000000660
[Thu Oct  4 15:34:51 2018] Call Trace:
[Thu Oct  4 15:34:51 2018]  btrfs_clone+0x956/0x1100
[Thu Oct  4 15:34:51 2018]  btrfs_clone_files+0x16f/0x370
[Thu Oct  4 15:34:51 2018]  vfs_clone_file_range+0x120/0x200
[Thu Oct  4 15:34:51 2018]  ioctl_file_clone+0x9f/0x100
[Thu Oct  4 15:34:51 2018]  do_vfs_ioctl+0x348/0x630
[Thu Oct  4 15:34:51 2018]  ? handle_mm_fault+0xfc/0x1f0
[Thu Oct  4 15:34:51 2018]  ksys_ioctl+0x70/0x80
[Thu Oct  4 15:34:51 2018]  __x64_sys_ioctl+0x16/0x20
[Thu Oct  4 15:34:51 2018]  do_syscall_64+0x55/0x100
[Thu Oct  4 15:34:51 2018] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Thu Oct  4 15:34:51 2018] RIP: 0033:0x7f51a01721c7
[Thu Oct  4 15:34:51 2018] Code: 44 00 00 48 8b 05 c1 3c 2c 00 64 c7 00 
26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 
00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 91 3c 2c 00 f7 d8 
64 89 01 48
[Thu Oct  4 15:34:51 2018] RSP: 002b:00007fffac0f5f18 EFLAGS: 00000246 
ORIG_RAX: 0000000000000010
[Thu Oct  4 15:34:51 2018] RAX: ffffffffffffffda RBX: 00007f519b33df30 
RCX: 00007f51a01721c7
[Thu Oct  4 15:34:51 2018] RDX: 0000000000000008 RSI: 0000000040049409 
RDI: 0000000000000009
[Thu Oct  4 15:34:51 2018] RBP: 00000000027bb4f0 R08: 0000000000000000 
R09: 0000000000000000
[Thu Oct  4 15:34:51 2018] R10: 000000000074c75d R11: 0000000000000246 
R12: 00007f519d3e0a95
[Thu Oct  4 15:34:51 2018] R13: 00000000027bb4f0 R14: 00007f519d3df848 
R15: 00000000027bb4f0
[Thu Oct  4 15:34:51 2018] ---[ end trace 55016eefa01d918e ]---
[Thu Oct  4 15:34:51 2018] BTRFS: error (device xvdg) in 
clone_finish_inode_update:3671: errno=-28 No space left
[Thu Oct  4 15:34:51 2018] BTRFS info (device xvdg): forced readonly
[Thu Oct  4 15:34:51 2018] BTRFS error (device xvdg): pending csums is 
278528



% btrfs fi us /filesystem/
Overall:
     Device size:           7.12TiB
     Device allocated:           6.80TiB
     Device unallocated:         330.93GiB
     Device missing:             0.00B
     Used:               6.51TiB
     Free (estimated):         629.87GiB    (min: 629.87GiB)
     Data ratio:                  1.00
     Metadata ratio:              1.00
     Global reserve:         512.00MiB    (used: 0.00B)

Data+Metadata,single: Size:6.80TiB, Used:6.51TiB
    /dev/xvdf       1.69TiB
    /dev/xvdg       3.12TiB
    /dev/xvdi       1.99TiB

System,single: Size:32.00MiB, Used:780.00KiB
    /dev/xvdf      32.00MiB

Unallocated:
    /dev/xvdf     320.97GiB
    /dev/xvdg     949.00MiB
    /dev/xvdi       9.03GiB


I kind of think there is sufficient free space..... at least globally 
within the filesystem.

Does it require balancing to redistribute the unallocated space better? 
Or is something misbehaving?



thanks

David.

Re: Transaction aborted error -28 clone_finish_inode_update

[Duncan]

David Goodwin posted on Thu, 04 Oct 2018 17:44:46 +0100 as excerpted:

> While trying to run/use bedup ( https://github.com/g2p/bedup ) .... I
> hit this :
> 
> 
> [Thu Oct  4 15:34:51 2018] ------------[ cut here ]------------
> [Thu Oct  4 15:34:51 2018] BTRFS: Transaction aborted (error -28)
> [Thu Oct  4 15:34:51 2018] WARNING: CPU: 0 PID: 28832 at
> fs/btrfs/ioctl.c:3671 clone_finish_inode_update+0xf3/0x140 

> [Thu Oct  4 15:34:51 2018] CPU: 0 PID: 28832 Comm: bedup Not tainted
> 4.18.10-psi-dg1 #1

[snipping a bunch of stuff that I as a non-dev list regular can't do much 
with anyway]

> [Thu Oct  4 15:34:51 2018] BTRFS: error (device xvdg) in
> clone_finish_inode_update:3671: errno=-28 No space left
> [Thu Oct  4 15:34:51 2018] BTRFS info (device xvdg): forced readonly 

> % btrfs fi us /filesystem/
> Overall:
>      Device size:           7.12TiB
>      Device allocated:      6.80TiB
>      Device unallocated:    330.93GiB
>      Device missing:        0.00B
>      Used:                  6.51TiB
>      Free (estimated):      629.87GiB    (min: 629.87GiB)
>      Data ratio:            1.00
>      Metadata ratio:        1.00
>      Global reserve:        512.00MiB    (used: 0.00B)
> 
> Data+Metadata,single: Size:6.80TiB, Used:6.51TiB
>     /dev/xvdf       1.69TiB
>     /dev/xvdg       3.12TiB
>     /dev/xvdi       1.99TiB
> 
> System,single: Size:32.00MiB, Used:780.00KiB
>     /dev/xvdf      32.00MiB
> 
> Unallocated:
>     /dev/xvdf     320.97GiB
>     /dev/xvdg     949.00MiB
>     /dev/xvdi       9.03GiB
> 
> 
> I kind of think there is sufficient free space..... at least globally
> within the filesystem.
> 
> Does it require balancing to redistribute the unallocated space better?
> Or is something misbehaving?

The latter, but unfortunately there's not much you can do about it at 
this point but wait for fixes, unless you want to spit up that huge 
filesystem into several smaller ones.

In general, btrfs has at least four kinds of "space" that it can run out 
of, tho in your case it appears you're running mixed-mode so data and 
metadata space are combined into one.

* Unallocated space:  This is space that remains entirely unallocated in 
the filesystem.  It matters most when the balance between data and 
metadata space gets off.

This isn't a problem for you as in single mode space can be allocated 
from any device and you have one with hundreds of gigs unallocated.  It 
also tends to be less of a problem on mixed-bg mode, which you're 
running, as there's no distinction in mixed-mode between data and 
metadata.

* Data chunk space:
* Metadata chunk space:

Because you're running mixed-bg mode, there's no distinction between 
these two, but for normal mode, running out of one or the other while all 
the free space is allocated to chunks of the other type, can be a problem.

* Global reserve:  Taken from metadata, the global reserve is space the 
system won't normally use, that it tries to keep clear in ordered to be 
able to finish transactions once they're started, as btrfs' copy-on-write 
semantics means even deleting stuff requires a bit of additional space 
temporarily.

This seems to actually be where the problem is, because currently, 
certain btrfs operations such as reflinking/cloning/snapshotting (that 
is, just what you were doing) don't really calculate the needed space 
correctly and use arbitrary figures, which can be *wildly* off, while 
conversely a bare half-gig of global-reserve for a huge 7+ TiB filesystem 
seems rather proportionally small.  (Consider that my small pair-device 
btrfs raid1 root filesystem, 8-GiB/device, 16 GiB total, has a 16 MiB 
reserve, proportionally, your 7+ TB filesystem would have 7+ GiB reserve, 
but it only has a half GiB.)

So relatively small btrfs' don't tend to run into the problem, because 
they have proportionally larger reserves to begin with.  Plus they 
probably don't have proportionally as many snapshots/reflinks/etc, 
either, so the problem simply doesn't trigger for them.

Now I'm not a dev and my own use-case doesn't include either snapshotting 
or deduping, so I haven't paid that much attention to the specifics, but 
I have seen some recent patches on-list that based on the explanations 
should go some way toward fixing this problem by using more realistic 
figures for global-reserve calculations.  At this point those patches 
would be for 4.20 (which might be 5.0), or possibly 4.21, but the devs 
are indeed working on the problem and it should get better within a 
couple kernel cycles.

Alternatively perhaps the global reserve size could be bumped up on such 
large filesystems, but let's see if the more realistic operations-reserve 
calculations can fix things, first, as arguably that shouldn't be 
necessary once the calculations aren't so arbitrarily wild.

-- 
Duncan - List replies preferred.   No HTML msgs.
"Every nonfree program has a lord, a master --
and if you use the program, he is your master."  Richard Stallman