Bug 200255 - call trace on btrfs send/receive
Summary: call trace on btrfs send/receive
Status: RESOLVED OBSOLETE
Alias: None
Product: File System
Classification: Unclassified
Component: btrfs (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: BTRFS virtual assignee
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-06-25 00:59 UTC by Christoph Anton Mitterer
Modified: 2023-02-13 14:03 UTC (History)
1 user (show)

See Also:
Kernel Version: 4.16.16
Subsystem:
Regression: No
Bisected commit-id:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Description Christoph Anton Mitterer 2018-06-25 00:59:04 UTC 
Hi.

The following happens since many kernel versions, whenever I send receive from one btrfs to another.

I do e.g. an incremental backup:
/master# btrfs send -p 2018-03-09_1 2018-06-17_1 | btrfs receive /copy/snapshots/ ; echo $?
At subvol 2018-06-17_1
At snapshot 2018-06-17_1
0
with /master and /copy being two different filesystems.

Right after start, the following call trace appears in the kernel log:
Jun 25 02:54:06 heisenberg kernel: WARNING: CPU: 2 PID: 6362 at /build/linux-s0lf2B/linux-4.16.16/fs/btrfs/send.c:6484 btrfs_ioctl_send+0x48f/0xfb0 [btrfs]
Jun 25 02:54:06 heisenberg kernel: Modules linked in: udp_diag tcp_diag inet_diag algif_skcipher af_alg uas cpuid ctr ccm fuse ebtable_filter ebtables devlink cpufreq_userspace cpufreq_powersave cpufreq_conservative ip6t_REJECT nf_reject_ipv6 xt_tcpudp nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables xt_policy ipt_REJECT nf_reject_ipv4 xt_comment nf_conntrack_ipv4 nf_defrag_ipv4 binfmt_misc xt_multiport xt_conntrack nf_conntrack iptable_filter arc4 rtsx_pci_sdmmc snd_hda_codec_hdmi rtsx_pci_ms mmc_core memstick intel_rapl iTCO_wdt iTCO_vendor_support x86_pkg_temp_thermal snd_hda_codec_realtek intel_powerclamp btusb btrtl coretemp iwldvm btbcm snd_hda_codec_generic btintel kvm_intel bluetooth mac80211 kvm uvcvideo irqbypass crct10dif_pclmul videobuf2_vmalloc snd_hda_intel crc32_pclmul videobuf2_memops drbg iwlwifi
Jun 25 02:54:06 heisenberg kernel:  videobuf2_v4l2 snd_hda_codec ghash_clmulni_intel snd_hda_core snd_hwdep videobuf2_common intel_cstate ansi_cprng videodev cfg80211 snd_pcm rtsx_pci ecdh_generic snd_timer intel_uncore media rfkill crc16 i915 snd intel_rapl_perf joydev sg pcspkr i2c_i801 lpc_ich soundcore shpchp drm_kms_helper fujitsu_laptop button drm sparse_keymap battery mei_me video ac i2c_algo_bit mei loop parport_pc ppdev lp parport sunrpc ip_tables x_tables autofs4 dm_crypt dm_mod raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx libcrc32c raid1 raid0 multipath linear md_mod btrfs crc32c_generic xor zstd_decompress zstd_compress xxhash raid6_pq uhci_hcd sd_mod usb_storage crc32c_intel aesni_intel aes_x86_64 crypto_simd ehci_pci ahci xhci_pci libahci libata xhci_hcd ehci_hcd evdev psmouse
Jun 25 02:54:06 heisenberg kernel:  cryptd glue_helper serio_raw scsi_mod usbcore e1000e usb_common
Jun 25 02:54:06 heisenberg kernel: CPU: 2 PID: 6362 Comm: btrfs Not tainted 4.16.0-2-amd64 #1 Debian 4.16.16-1
Jun 25 02:54:06 heisenberg kernel: Hardware name: FUJITSU LIFEBOOK E782/FJNB253, BIOS Version 2.11 07/15/2014
Jun 25 02:54:06 heisenberg kernel: RIP: 0010:btrfs_ioctl_send+0x48f/0xfb0 [btrfs]
Jun 25 02:54:06 heisenberg kernel: RSP: 0018:ffffab8249ee3c48 EFLAGS: 00010293
Jun 25 02:54:06 heisenberg kernel: RAX: 0000000000000000 RBX: ffff8a5187c9040c RCX: 0000000000000000
Jun 25 02:54:06 heisenberg kernel: RDX: 0000000000000001 RSI: ffff8a518d816690 RDI: ffff8a5187c9040c
Jun 25 02:54:06 heisenberg kernel: RBP: ffff8a4f76dd2f60 R08: 0000000000000048 R09: 0000000000000060
Jun 25 02:54:06 heisenberg kernel: R10: 0000000000000000 R11: 0000000040000000 R12: ffff8a5187c90000
Jun 25 02:54:06 heisenberg kernel: R13: ffff8a4eb1ac51f0 R14: ffff8a4fcb37e000 R15: ffff8a5187c90000
Jun 25 02:54:06 heisenberg kernel: FS:  00007f5bc6eb18c0(0000) GS:ffff8a519e280000(0000) knlGS:0000000000000000
Jun 25 02:54:06 heisenberg kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jun 25 02:54:06 heisenberg kernel: CR2: 00007f5bc5e63e38 CR3: 00000003e8402003 CR4: 00000000001606e0
Jun 25 02:54:06 heisenberg kernel: Call Trace:
Jun 25 02:54:06 heisenberg kernel:  ? _cond_resched+0x15/0x40
Jun 25 02:54:06 heisenberg kernel:  ? kmem_cache_alloc_trace+0x61/0x1b0
Jun 25 02:54:06 heisenberg kernel:  ? btrfs_opendir+0x3e/0x70 [btrfs]
Jun 25 02:54:06 heisenberg kernel:  ? btrfs_opendir+0x3e/0x70 [btrfs]
Jun 25 02:54:06 heisenberg kernel:  ? dput.part.23+0xb1/0x1e0
Jun 25 02:54:06 heisenberg kernel:  ? _cond_resched+0x15/0x40
Jun 25 02:54:06 heisenberg kernel:  ? __kmalloc_track_caller+0x180/0x220
Jun 25 02:54:06 heisenberg kernel:  ? __check_object_size+0xa7/0x1a0
Jun 25 02:54:06 heisenberg kernel:  _btrfs_ioctl_send+0x80/0x110 [btrfs]
Jun 25 02:54:06 heisenberg kernel:  ? task_change_group_fair+0xb3/0x100
Jun 25 02:54:06 heisenberg kernel:  ? cpu_cgroup_fork+0x66/0x90
Jun 25 02:54:06 heisenberg kernel:  btrfs_ioctl+0x1122/0x23d0 [btrfs]
Jun 25 02:54:06 heisenberg kernel:  ? enqueue_entity+0x106/0x640
Jun 25 02:54:06 heisenberg kernel:  ? enqueue_task_fair+0x67/0x7d0
Jun 25 02:54:06 heisenberg kernel:  ? do_vfs_ioctl+0xa4/0x630
Jun 25 02:54:06 heisenberg kernel:  do_vfs_ioctl+0xa4/0x630
Jun 25 02:54:06 heisenberg kernel:  ? _do_fork+0x14d/0x400
Jun 25 02:54:06 heisenberg kernel:  SyS_ioctl+0x74/0x80
Jun 25 02:54:06 heisenberg kernel:  do_syscall_64+0x6c/0x130
Jun 25 02:54:06 heisenberg kernel:  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
Jun 25 02:54:06 heisenberg kernel: RIP: 0033:0x7f5bc5f52f07
Jun 25 02:54:06 heisenberg kernel: RSP: 002b:00007ffca8aff7c8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Jun 25 02:54:06 heisenberg kernel: RAX: ffffffffffffffda RBX: 000055dd05426270 RCX: 00007f5bc5f52f07
Jun 25 02:54:06 heisenberg kernel: RDX: 00007ffca8aff8a0 RSI: 0000000040489426 RDI: 0000000000000004
Jun 25 02:54:06 heisenberg kernel: RBP: 0000000000000001 R08: 0000000000000000 R09: 00007f5bc5e64700
Jun 25 02:54:06 heisenberg kernel: R10: 00007f5bc5e649d0 R11: 0000000000000246 R12: 0000000000000001
Jun 25 02:54:06 heisenberg kernel: R13: 0000000000000004 R14: 0000000000002f83 R15: 0000000000000001
Jun 25 02:54:06 heisenberg kernel: Code: ff 48 8b 83 e0 01 00 00 48 85 c0 0f 85 ce fd ff ff e9 0f fe ff ff 4c 89 e7 e8 0e 6e ff ff 48 c7 04 24 ff ff ff ff e9 06 ff ff ff <0f> 0b e9 f1 fb ff ff 48 8b 45 08 c7 43 1c 00 00 01 00 ba ff ff 
Jun 25 02:54:06 heisenberg kernel: ---[ end trace e7a3d552e15a7ae4 ]---


I doesn't really seem to cause any harm, send/receive user land tools finish with $?=0 and the data seems to be sent/received correctly, it's a bit annoying though.


Reported it several times at the btrfs mailing list, but since there was never a reaction I place it now into bugzilla here for the records.


Cheers,
Chris.
Comment 1 Christoph Anton Mitterer 2018-11-03 01:08:38 UTC 
Still, as of 4.18.0
Comment 2 Christoph Anton Mitterer 2019-03-22 18:43:51 UTC 
Still happens as of 4.19.28, but interestingly I had one case recently, where it didn't occur (normally it happens straight after the btrfs send … | btrfs receive is invoked).

I do however not see the difference between this one time where it worked and the other times when I get the call trace.
It was even on a fs, where I normally get the error.
Comment 3 Christoph Anton Mitterer 2021-02-01 22:36:23 UTC 
This this issue might have disappeared... at least I didn't take note of it since a while.
Comment 4 David Sterba 2021-03-17 09:31:42 UTC 
6480         /*                                                                                                                                                                                                      
6481          * This is done when we lookup the root, it should already be complete                                                                                                                                  
6482          * by the time we get here.                                                                                                                                                                             
6483          */                                                                                                                                                                                                     
6484         WARN_ON(send_root->orphan_cleanup_state != ORPHAN_CLEANUP_DONE);

I checked the exact version 4.16.16 and it's this warning, added by commit https://git.kernel.org/linus/139f807a1eba1e484941a98fb93e . This seems to depend on the state of the fs and once there are no orphan inodes to cleanup on the given root, it won't show. It looks like it could be a problem otherwise but I'm not sure if other changes affected that.

Thanks for the updates, it at least narrows down the versions where it happened for sure.
Comment 5 Christoph Anton Mitterer 2021-03-17 11:13:32 UTC 
(In reply to David Sterba from comment #4)
> This seems to
> depend on the state of the fs and once there are no orphan inodes to cleanup
> on the given root, it won't show. It looks like it could be a problem
> otherwise but I'm not sure if other changes affected that.

You think this could have caused (or still cause) any corruptions?
Comment 6 Christoph Anton Mitterer 2023-02-13 14:03:40 UTC 
Closing this, since I haven't seen it in a long while.
Note You need to log in before you can comment on or make changes to this bug.