Re: [COMMAND HANGS] The command 'btrfs subvolume sync -s 2 xyz' can hangs.

[Jeff Mahoney <jeffm@suse.com>]

[-- Attachment #1.1: Type: text/plain, Size: 8981 bytes --]

On 1/1/19 11:37 AM, Giuseppe Della Bianca wrote:
> In data giovedì 9 agosto 2018 20:48:03 CEST, Jeff Mahoney ha scritto:
>> On 8/9/18 11:15 AM, Giuseppe Della Bianca wrote:
>>> Hi.
>>>
>>> My system:
>>> - Fedora 28 x86_64
>>> - kernel-4.17.7-200
>>> - btrfs-progs-4.15.1-1
>>>
>>> The command 'btrfs subvolume sync -s 2 xyz' hangs in this case:
>>>
>>> - Run command 'btrfs subvolume sync -s 2 xyz' .
>>> - After some time the kernel reports an error on the filesystem.
>>>
>>>   (error that existed before the command was launched.)
>>>
>>> - The filesystem goes in read-only mode.
>>> - The command hangs.
>>
>> Can you provide the output of 'dmesg' and the contents of
>> /proc/<pid>/stack where <pid> is the pid of the btrfs command process?
>>
>> -Jeff
> 
> I had the problem again.
> This is the information you asked for:
> 
> root     17133 17127  0 17:17 ?        00:00:00 btrfs subvolume sync -s 2 /
> tmp/tmp.p9SiQ1GnpV
> 
> cat /proc/17133/stack 
> [<0>] hrtimer_nanosleep+0xce/0x1e0
> [<0>] __x64_sys_nanosleep+0x77/0xa0
> [<0>] do_syscall_64+0x5b/0x160
> [<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [<0>] 0xffffffffffffffff

Ok, so this is it just sleeping between tree searches.

> ...............
> [ 1558.053812] CPU: 0 PID: 16871 Comm: btrfs-cleaner Not tainted 
> 4.17.19-200.fc28.x86_64 #1
> [ 1558.053815] Hardware name: System manufacturer System Product Name/M2N, 
> BIOS 0902    02/16/2009
> [ 1558.053904] RIP: 0010:__btrfs_free_extent.isra.70+0x782/0xb10 [btrfs]
> [ 1558.053907] RSP: 0018:ffffa63985f8fc30 EFLAGS: 00010246
> [ 1558.053912] RAX: 00000000fffffffe RBX: ffff8b71313f8380 RCX: 
> 0000000000000000
> [ 1558.053914] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 
> ffff8b711d8ef578
> [ 1558.053916] RBP: 00000011cb804000 R08: ffffa63985f8fba4 R09: 
> 0000000000000018
> [ 1558.053919] R10: 0000000000000835 R11: 0000000000000000 R12: 
> ffff8b715f5d4000
> [ 1558.053921] R13: 00000000fffffffe R14: 0000000000000000 R15: 
> 00000000000005aa
> [ 1558.053925] FS:  0000000000000000(0000) GS:ffff8b717fa00000(0000) knlGS:
> 0000000000000000
> [ 1558.053928] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 1558.053930] CR2: 00007fdfdffffa08 CR3: 00000000b05b0000 CR4: 
> 00000000000006f0
> [ 1558.053934] Call Trace:
> [ 1558.054011]  __btrfs_run_delayed_refs+0x216/0x10b0 [btrfs]
> [ 1558.054011]  ? btrfs_free_tree_block+0x82/0x2c0 [btrfs]
> [ 1558.054011]  btrfs_run_delayed_refs+0x78/0x180 [btrfs]
> [ 1558.054011]  btrfs_should_end_transaction+0x3e/0x60 [btrfs]
> [ 1558.054011]  btrfs_drop_snapshot+0x3cf/0x820 [btrfs]
> [ 1558.054011]  ? btree_submit_bio_start+0x20/0x20 [btrfs]
> [ 1558.054011]  btrfs_clean_one_deleted_snapshot+0xba/0xe0 [btrfs]
> [ 1558.054011]  cleaner_kthread+0x129/0x160 [btrfs]
> [ 1558.054011]  kthread+0x112/0x130
> [ 1558.054011]  ? kthread_create_worker_on_cpu+0x70/0x70
> [ 1558.054011]  ret_from_fork+0x35/0x40
> [ 1558.054011] Code: b8 00 00 00 48 8b 7c 24 18 e8 bb b7 ff ff 41 89 c5 58 5a 
> c6 44 24 24 00 45 85 ed 0f 84 97 f9 ff ff 41 83 fd fe 0f 85 63 fc ff ff <0f> 
> 0b 48 8b 3b e8 84 ca 00 00 4d 89 f8 4c 89 f1 48 89 ea ff b4 
> [ 1558.054011] ---[ end trace c4eefd1fdc016cea ]---
> [ 1558.054832] BTRFS info (device sda3): leaf 62678286336 gen 6388 total ptrs 
> 148 free space 6202 owner 2
> [ 1558.054837]  item 0 key (76427296768 169 0) itemoff 16250 itemsize 33
> [ 1558.054841]          extent refs 1 gen 6256 flags 258
> [ 1558.054844]          ref#0: shared block backref parent 76512641024
> [ 1558.054850]  item 1 key (76427313152 169 0) itemoff 16217 itemsize 33
> [ 1558.054853]          extent refs 1 gen 6256 flags 258
> [ 1558.054854]          ref#0: shared block backref parent 76512641024
> 
> ]zac[
> ...................................
> ]zac[

This part is actually important since we see below that we're searching
for bytenr 76428623872 which, if present, would be in the cut portion of
your log.

> [ 1558.056504]  item 145 key (76429721600 169 1) itemoff 10004 itemsize 33
> [ 1558.056506]          extent refs 1 gen 6303 flags 258
> [ 1558.056508]          ref#0: tree block backref root 1434
> [ 1558.056512]  item 146 key (76429737984 169 0) itemoff 9962 itemsize 42
> [ 1558.056515]          extent refs 2 gen 6277 flags 258
> [ 1558.056516]          ref#0: shared block backref parent 81665769472
> [ 1558.056519]          ref#1: shared block backref parent 66383904768
> [ 1558.056524]  item 147 key (76429754368 169 0) itemoff 9902 itemsize 60
> [ 1558.056526]          extent refs 4 gen 6256 flags 258
> [ 1558.056528]          ref#0: shared block backref parent 81731174400
> [ 1558.056531]          ref#1: shared block backref parent 76512641024
> [ 1558.056533]          ref#2: shared block backref parent 76450250752
> [ 1558.056536]          ref#3: shared block backref parent 66397339648
> [ 1558.056544] BTRFS error (device sda3): unable to find ref byte nr 
> 76428623872 parent 0 root 1450  owner 1 offset 0
> [ 1558.056554] ------------[ cut here ]------------
> [ 1558.056556] BTRFS: Transaction aborted (error -2)
> [ 1558.056718] WARNING: CPU: 0 PID: 16871 at fs/btrfs/extent-tree.c:7007 
> __btrfs_free_extent.isra.70+0x7e2/0xb10 [btrfs]
> [ 1558.056720] Modules linked in: fuse xt_CHECKSUM ipt_MASQUERADE 
> nf_nat_masquerade_ipv4 tun nf_conntrack_netbios_ns nf_conntrack_broadcast 
> xt_CT ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack devlink ip_set 
> nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat 
> nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_raw 
> ip6table_security iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 
> nf_nat nf_conntrack iptable_mangle iptable_raw iptable_security ebtable_filter 
> ebtables ip6table_filter ip6_tables it87 hwmon_vid sunrpc snd_hda_codec_analog 
> snd_hda_codec_generic snd_hda_codec_hdmi btrfs powernow_k8 amd64_edac_mod 
> edac_mce_amd snd_hda_intel snd_hda_codec kvm_amd xor ccp zstd_compress 
> snd_hda_core snd_hwdep kvm snd_seq snd_seq_device ppdev snd_pcm raid6_pq 
> irqbypass
> [ 1558.056785]  libcrc32c k8temp snd_timer zstd_decompress xxhash i2c_nforce2 
> snd asus_atk0110 soundcore shpchp parport_pc parport ata_generic pata_acpi 
> nouveau video mxm_wmi wmi i2c_algo_bit drm_kms_helper ttm drm serio_raw 
> sata_nv forcedeth
> [ 1558.056819] CPU: 0 PID: 16871 Comm: btrfs-cleaner Tainted: G        W         
> 4.17.19-200.fc28.x86_64 #1
> [ 1558.056821] Hardware name: System manufacturer System Product Name/M2N, 
> BIOS 0902    02/16/2009
> [ 1558.056905] RIP: 0010:__btrfs_free_extent.isra.70+0x7e2/0xb10 [btrfs]
> [ 1558.056908] RSP: 0018:ffffa63985f8fc30 EFLAGS: 00010286
> [ 1558.056912] RAX: 0000000000000000 RBX: ffff8b71313f8380 RCX: 
> 0000000000000006
> [ 1558.056914] RDX: 0000000000000007 RSI: 0000000000000086 RDI: 
> ffff8b717fa16930
> [ 1558.056916] RBP: 00000011cb804000 R08: 0000000000000038 R09: 
> 000000000000059a
> [ 1558.056918] R10: 0000000000000000 R11: 0000000000000001 R12: 
> ffff8b715f5d4000
> [ 1558.056920] R13: 00000000fffffffe R14: 0000000000000000 R15: 
> 00000000000005aa
> [ 1558.056924] FS:  0000000000000000(0000) GS:ffff8b717fa00000(0000) knlGS:
> 0000000000000000
> [ 1558.056927] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 1558.056929] CR2: 00007fdfdffffa08 CR3: 00000000b05b0000 CR4: 
> 00000000000006f0
> [ 1558.056931] Call Trace:
> [ 1558.057011]  __btrfs_run_delayed_refs+0x216/0x10b0 [btrfs]
> [ 1558.057011]  ? btrfs_free_tree_block+0x82/0x2c0 [btrfs]
> [ 1558.057011]  btrfs_run_delayed_refs+0x78/0x180 [btrfs]
> [ 1558.057011]  btrfs_should_end_transaction+0x3e/0x60 [btrfs]
> [ 1558.057011]  btrfs_drop_snapshot+0x3cf/0x820 [btrfs]
> [ 1558.057011]  ? btree_submit_bio_start+0x20/0x20 [btrfs]
> [ 1558.057011]  btrfs_clean_one_deleted_snapshot+0xba/0xe0 [btrfs]
> [ 1558.057011]  cleaner_kthread+0x129/0x160 [btrfs]
> [ 1558.057011]  kthread+0x112/0x130
> [ 1558.057011]  ? kthread_create_worker_on_cpu+0x70/0x70
> [ 1558.057011]  ret_from_fork+0x35/0x40
> [ 1558.057011] Code: 10 48 8b 40 50 f0 48 0f ba a8 30 23 00 00 02 0f 92 c0 41 
> 59 84 c0 0f 85 cc a4 09 00 44 89 ee 48 c7 c7 98 9e 75 c0 e8 58 33 a0 e7 <0f> 
> 0b e9 b6 a4 09 00 48 89 df e8 bf 0c ff ff 49 8b 74 24 28 4d 
> [ 1558.057011] ---[ end trace c4eefd1fdc016ceb ]---
> [ 1558.057734] BTRFS: error (device sda3) in __btrfs_free_extent:7007: 
> errno=-2 No such entry
> [ 1558.057742] BTRFS info (device sda3): forced readonly
> [ 1558.057757] BTRFS: error (device sda3) in btrfs_run_delayed_refs:3076: 
> errno=-2 No such entry

This is the more important part.  The file system has gone read-only due
to a missing extent backref.  This is corruption.

It also means that the subvolume is never going to disappear during this
mount and 'btrfs subvol sync' will wait forever.

-Jeff
-- 
Jeff Mahoney
SUSE Labs



[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 833 bytes --]