btrfs / btrfs-todo

An issues only repo to organize our TODO items
21 stars 2 forks source link

Fix problem when aborting transaction in mkdir #23

Open josefbacik opened 3 years ago

josefbacik commented 3 years ago

While testing -o compress,discard=async I got an -ENOSPC where I shouldn't, which resulted in things going horribly wrong. The -ENOSPC was my bug, but things going horribly wrong wasn't. This is where I got the abort

------------[ cut here ]------------
WARNING: CPU: 64 PID: 1660044 at fs/btrfs/inode.c:3646 __btrfs_unlink_inode+0x3a3/0x430
Modules linked in: dm_thin_pool dm_persistent_data dm_bio_prison dm_snapshot dm_bufio dm_flakey ip6table_raw ip6table_mangle iptable_raw iptable_mangle act_gact tls ip6table_filter xt_NFLOG xt_comment xt_statistic iptable_filter cls_bpf nfnetlink_log tcp_diag inet_diag skx_edac nfit libnvdimm x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass iTCO_wdt iTCO_vendor_support evdev ipmi_si lpc_ich efivars i2c_i801 mfd_core ipmi_devintf ipmi_msghandler acpi_cpufreq tpm_crb button sch_fq_codel sunrpc fuse nvme nvme_core xhci_pci xhci_hcd loop efivarfs autofs4 [last unloaded: scsi_debug]
CPU: 64 PID: 1660044 Comm: dbench Kdump: loaded Not tainted 5.6.13-04690-gf37b2a895cfd-dirty #32
Hardware name: Quanta Tioga Pass Single Side 01-0030993006/Tioga Pass Single Side, BIOS F08_3A24 05/13/2020
RIP: 0010:__btrfs_unlink_inode+0x3a3/0x430
Code: e8 0e 00 00 02 0f 92 c2 83 f8 fb 0f 84 ba cb 00 00 84 d2 0f 85 b2 cb 00 00 89 c6 48 c7 c7 f0 71 35 82 89 45 a0 e8 78 6a bf ff <0f> 0b 8b 45 a0 e9 97 cb 00 00 48 8b 4d b8 48 8b 51 50 f0 48 0f ba
RSP: 0018:ffffc9002d7f7dc0 EFLAGS: 00010282
RAX: 0000000000000000 RBX: ffff88bfd2760000 RCX: 0000000000000027
RDX: 0000000000000027 RSI: ffff88bfffa18780 RDI: ffff88bfffa18788
RBP: ffffc9002d7f7e30 R08: 0000000000000002 R09: 000000000002ab40
R10: 00009fc3c5469b1c R11: 000000000009d7c4 R12: ffff88bfc8adfbd0
R13: ffff88bfcaafac60 R14: 0000000000000000 R15: ffff88bfcaafae38
FS:  00007f09dc001740(0000) GS:ffff88bfffa00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f88a780a2c8 CR3: 0000003c6b1a4004 CR4: 00000000007606e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
PKRU: 55555554
Call Trace:
 btrfs_unlink_inode+0x17/0x50
 btrfs_unlink+0x8c/0xd0
 vfs_unlink+0x103/0x1e0
 do_unlinkat+0x220/0x2e0
 do_syscall_64+0x42/0x110
 entry_SYSCALL_64_after_hwframe+0x44/0xa9

watchdog: BUG: soft lockup - CPU#9 stuck for 22s! [kworker/u161:0:1279709]
Modules linked in: dm_thin_pool dm_persistent_data dm_bio_prison dm_snapshot dm_bufio dm_flakey ip6table_raw ip6table_mangle iptable_raw iptable_mangle act_gact tls ip6table_filter xt_NFLOG xt_comment xt_statistic iptable_filter cls_bpf nfnetlink_log tcp_diag inet_diag skx_edac nfit libnvdimm x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass iTCO_wdt iTCO_vendor_support evdev ipmi_si lpc_ich efivars i2c_i801 mfd_core ipmi_devintf ipmi_msghandler acpi_cpufreq tpm_crb button sch_fq_codel sunrpc fuse nvme nvme_core xhci_pci xhci_hcd loop efivarfs autofs4 [last unloaded: scsi_debug]
CPU: 9 PID: 1279709 Comm: kworker/u161:0 Kdump: loaded Tainted: G        W         5.6.13-04690-gf37b2a895cfd-dirty #32
Hardware name: Quanta Tioga Pass Single Side 01-0030993006/Tioga Pass Single Side, BIOS F08_3A24 05/13/2020
Workqueue: btrfs-endio-write btrfs_work_helper
RIP: 0010:queued_spin_lock_slowpath+0x17d/0x1b0
Code: c1 e9 12 83 e0 03 83 e9 01 48 c1 e0 04 48 63 c9 48 05 40 bf 02 00 48 03 04 cd c0 f6 3c 82 48 89 10 8b 42 08 85 c0 75 09 f3 90 <8b> 42 08 85 c0 74 f7 48 8b 02 48 85 c0 0f 84 43 ff ff ff 48 89 c1
RSP: 0018:ffffc9003d437cd8 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
RAX: 0000000000000000 RBX: ffff88bdc2314ce0 RCX: 0000000000000030
RDX: ffff889fffa6bf40 RSI: 0000000000280000 RDI: ffff88bdc2314d40
RBP: ffff889b85712c00 R08: ffff88bfdeeb39e0 R09: 0000000000000000
R10: ffff889fc090e6d0 R11: 0000000000000018 R12: 0000001fc1725000
R13: 0000000000004000 R14: 0000000000000000 R15: ffff889fcaa744e0
FS:  0000000000000000(0000) GS:ffff889fffa40000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f3ebc96b838 CR3: 0000000002a09006 CR4: 00000000007606e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
PKRU: 55555554
Call Trace:
 add_to_discard_unused_list+0x18/0xc0
 btrfs_discard_queue_work.part.12+0x44/0x50
 __btrfs_add_free_space+0xf0/0x4b0
 ? btrfs_drop_extent_cache+0x102/0x3d0
 btrfs_free_reserved_extent+0x37/0xa0
 btrfs_finish_ordered_io+0x4d3/0x710
 btrfs_work_helper+0xb0/0x330
 process_one_work+0x1f8/0x3c0
 worker_thread+0x2d/0x3d0
 ? process_one_work+0x3c0/0x3c0
 kthread+0x111/0x130
 ? kthread_park+0x80/0x80
 ret_from_fork+0x1f/0x30

I'm not sure why we started spinning on the discard_ctl->lock. Just looking at the code I didn't spot any obvious locking mistakes, but I did notice we don't hold a ref for the block_group on the discard lists, which we should probably fix. It may be possible that we freed the block group when we cleaned up the aborted transaction and then we hung when trying to access some free'd discard_ctl. But I can't be sure, it warrants investigation. The code looks like this where we aborted

skip_backref:
        ret = btrfs_delete_delayed_dir_index(trans, dir, index);
        if (ret) {
                btrfs_abort_transaction(trans, ret);
                goto err;
        }

        ret = btrfs_del_inode_ref_in_log(trans, root, name, name_len, inode,
                        dir_ino);
        if (ret != 0 && ret != -ENOENT) {
                btrfs_abort_transaction(trans, ret);
                goto err;
        }

        ret = btrfs_del_dir_entries_in_log(trans, root, name, name_len, dir,
                        index);
        if (ret == -ENOENT)
                ret = 0;
        else if (ret)
                btrfs_abort_transaction(trans, ret);

Probably just rig up some error injection here and try to reproduce the problem.