Kernel BUG: btrfs send - Incremental backup

Hi there,

I tried to perform an incremental backup as described in
https://btrfs.wiki.kernel.org/index.php/Incremental_Backup between 2 external USB drives,

The 1st "btrfs send foo/snap1 | btrfs receive bar" went well, although it took 5-6 times the time the same workload takes in ZFS.

Then "btrfs send -v -p foo/snap1 foo/snap2 | btrfs receive bar" crashed on me.

After a reboot and retry, I get a KERNEL BUG again :

# uname -a
Linux tethys 3.13.5-1-ARCH #1 SMP PREEMPT Sun Feb 23 00:25:24 CET 2014 x86_64 
GNU/Linux

btrfs send -v -p foo/snap1 foo/snap2 | btrfs receive bar

mars 08 08:22:01 tethys kernel: ------------[ cut here ]------------ mars 08 08:22:01 tethys kernel: kernel BUG at fs/btrfs/send.c:4398! mars 08 08:22:02 tethys kernel: invalid opcode: 0000 [#1] PREEMPT SMP mars 08 08:22:02 tethys kernel: Modules linked in: usb_storage md5 fuse ecb ecryptfs encrypted_keys hmac trusted tpm ctr ccm intel_rapl x86_pkg_temp_thermal rts5139(C)
mars 08 08:22:02 tethys kernel: usbhid hid sr_mod cdrom sd_mod atkbd libps2 crct10dif_pclmul crct10dif_common crc32_pclmul ahci crc32c_intel ghash_clmulni_intel libahc
mars 08 08:22:02 tethys kernel: CPU: 0 PID: 2432 Comm: btrfs Tainted: P C O 3.13.5-1-ARCH #1
mars 08 08:22:02 tethys kernel: Hardware name: TOSHIBA SATELLITE L735/Base Board Product Name, BIOS 2.50 06/26/2012
mars 08 08:22:02 tethys kernel: task: ffff880041724800 ti: ffff88003b84a000 task.ti: ffff88003b84a000
mars 08 08:22:02 tethys kernel: RIP: 0010:[<ffffffffa0363ba5>] [<ffffffffa0363ba5>]

changed_cb+0x9e5/0x9f0 [btrfs]
mars 08 08:22:02 tethys kernel: RSP: 0018:ffff88003b84bb48  EFLAGS: 00010283
mars 08 08:22:02 tethys kernel: RAX: 00000000000579d5 RBX: ffff88013279ea00 RCX: 

0000000000000060
mars 08 08:22:02 tethys kernel: RDX: ffff88003b84bc65 RSI: 00000000000579cd RDI:
ffff88013279ea00
mars 08 08:22:02 tethys kernel: RBP: ffff88003b84bbe0 R08: ffff88003b84bc65 R09:
0000000000000002
mars 08 08:22:02 tethys kernel: R10: ffff88005981a900 R11: 0000000000000000 R12:
0000000000000002
mars 08 08:22:02 tethys kernel: R13: ffff88003b84bc65 R14: ffff88007c628800 R15:
0000000000002ad1
mars 08 08:22:02 tethys kernel: FS: 00007fceade62880(0000) GS:ffff88014f400000(0000) knlGS:0000000000000000
mars 08 08:22:02 tethys kernel: CS: 0010 DS: 0000 ES: 0000 CR0:
0000000080050033
mars 08 08:22:02 tethys kernel: CR2: 00007fb4cc8c8000 CR3: 0000000041a99000
CR4: 00000000000407f0
mars 08 08:22:02 tethys kernel: Stack:
mars 08 08:22:02 tethys kernel: ffff88003b84bb88 ffffffffa03206ec 00000000000008ca ffff88005981a900
mars 08 08:22:02 tethys kernel: 0000000000000000 ffff88005981a900 ffff88005981a870 0000000000000000
mars 08 08:22:02 tethys kernel: ffff88003b84bbe0 ffffffffa03161e9 ffff88003b84bc76 ffff88003b84bbe0
mars 08 08:22:02 tethys kernel: Call Trace:
mars 08 08:22:02 tethys kernel: [<ffffffffa03206ec>] ? read_extent_buffer+0xbc/0x110 [btrfs]
mars 08 08:22:02 tethys kernel: [<ffffffffa03161e9>] ? btrfs_get_token_32+0x59/0xe0 [btrfs]
mars 08 08:22:02 tethys kernel: [<ffffffffa0320e81>] ? memcmp_extent_buffer+0xc1/0x120 [btrfs]
mars 08 08:22:02 tethys kernel: [<ffffffffa02e1b10>] btrfs_compare_trees+0x790/0x970 [btrfs]
mars 08 08:22:02 tethys kernel: [<ffffffffa03631c0>] ?

finish_inode_if_needed+0x4e0/0x4e0 [btrfs]
mars 08 08:22:02 tethys kernel:  [<ffffffffa0364568>] btrfs_ioctl_send+0x8a8/0xc80 
[btrfs]
mars 08 08:22:02 tethys kernel:  [<ffffffffa0332afe>] btrfs_ioctl+0xfee/0x27a0 
[btrfs]
mars 08 08:22:02 tethys kernel:  [<ffffffff81096bc8>] ? __enqueue_entity+0x78/0x80
mars 08 08:22:02 tethys kernel:  [<ffffffff8109c6cb>] ? enqueue_entity+0x29b/0xa10
mars 08 08:22:02 tethys kernel:  [<ffffffff8109cf47>] ? 
enqueue_task_fair+0x107/0x540
mars 08 08:22:02 tethys kernel:  [<ffffffff8108f45a>] ? enqueue_task+0x3a/0x60
mars 08 08:22:02 tethys kernel:  [<ffffffff810902c5>] ? 
check_preempt_curr+0x75/0xa0
mars 08 08:22:02 tethys kernel:  [<ffffffff811b5fe0>] do_vfs_ioctl+0x2e0/0x4c0
mars 08 08:22:02 tethys kernel:  [<ffffffff81060d0f>] ? do_fork+0x12f/0x320
mars 08 08:22:02 tethys kernel:  [<ffffffff811b6241>] SyS_ioctl+0x81/0xa0

mars 08 08:22:02 tethys kernel: [<ffffffff8152142d>] system_call_fastpath+0x1a/0x1f
mars 08 08:22:02 tethys kernel: Code: 48 8d 75 b6 45 31 c0 b9 01 00 00 00 4c 89 e2 4c 89 f7 e8 2f eb f7 ff 85 c0 0f 89 77 ff ff ff e9 a0 fd ff ff 31 c0 e9 99 fd ff ff <
mars 08 08:22:02 tethys kernel: RIP [<ffffffffa0363ba5>] changed_cb+0x9e5/0x9f0 [btrfs]
mars 08 08:22:02 tethys kernel: RSP <ffff88003b84bb48>
mars 08 08:22:02 tethys kernel: ---[ end trace 718b3fc11b4d9241 ]---

HTH, TIA.

Swâmi Petaramesh <[email protected]> http://petaramesh.org PGP 9076E32E

Hi,

Does the filesystem pass the btrfsck?
If not, would you please try btrfsck first?

Thanks. Qu���{.n�+�������+%�����ݶ��w��{.n�+����{���k~���^n�r���z���h����&���z��z�ޗ�+��+zf���h���~����i��������z_��j:+v���)ߣ�m

Le lundi 10 mars 2014 02:16:01 vous avez écrit :

It passes scrub with 0 errors... Do I need to bring it offline to pass btrfsck anyway ?

Swâmi Petaramesh <[email protected]> http://petaramesh.org PGP 9076E32E

Better check it offline, since online check may not comprehensive than offline check.

Thanks. Qu���{.n�+�������+%�����ݶ��w��{.n�+����{���k~���^n�r���z���h����&���z��z�ޗ�+��+zf���h���~����i��������z_��j:+v���)ߣ�m

Here you are. Tested from an Ubuntu 13.10 live USB, kernel 3.11 and btrfs- utils 0.20 - this machine usually runs Arch with kernel 3.13 and btrfs-utils 3.12...

# btrfsck /dev/VG1/TETHYS
Checking filesystem on /dev/VG1/TETHYS
UUID: 9a1ca6f4-1c1b-4a62-a84b-b388066084dc
checking extents
checking free space cache
checking fs roots
checking csums
checking root refs
found 226049665697 bytes used err is 0
total csum bytes: 528376452
total tree bytes: 1692942336
total fs tree bytes: 997363712
total extent tree bytes: 100626432
btree space waste bytes: 287750314
file data blocks allocated: 704903720960
 referenced 691788443648
Btrfs v0.20-rc1

(Exited normally with return code = 0)

Other info you might find relevant (from running system)

# btrfs fi sh
Label: TETHYS  uuid: 9a1ca6f4-1c1b-4a62-a84b-b388066084dc
        Total devices 1 FS bytes used 546.38GiB
        devid    1 size 845.00GiB used 755.04GiB path /dev/dm-3

Label: BOOT uuid: 6a16d133-4b99-47b2-876f-148a8266f58f
Total devices 1 FS bytes used 68.03MiB
devid 1 size 1.00GiB used 236.00MiB path /dev/dm-0

Btrfs v3.12

# btrfs fi df /
Data, single: total=744.01GiB, used=544.80GiB
System, DUP: total=8.00MiB, used=88.00KiB
System, single: total=4.00MiB, used=0.00
Metadata, DUP: total=5.50GiB, used=1.57GiB
Metadata, single: total=8.00MiB, used=0.00

Kind regards.

Swâmi Petaramesh <[email protected]> http://petaramesh.org PGP 9076E32E

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Well that's odd, I can't think of how this would happen. Can pull down btrfs-next and run that and verify you still hit the BUG_ON? If you do please apply this patch and re-run and reply with the dmesg.

http://paste.fedoraproject.org/84393/55775013

This will spit out something like this

cur_ino=<NUMBER>, cmp_key objectid=<OTHER NUMBER>

then I need you to unmount your fs and run

btrfs-debug-tree /dev/whatever > blah.txt

You have about 1.5 gig of metadata so that is going to take a while. Once that is done you want to go through blah.txt and look for

item <number> key (<OTHER NUMBER FROM ABOVE> EXTENT_DATA <number>)

You need to find all of these entries and copy them down, an example output looks like this

item 1 key (286 EXTENT_DATA 577536) itemoff 3889 itemsize 53
extent data disk byte 12763136 nr 4096 extent data offset 0 nr 4096 ram 4096 extent compression 0

That is what I'm looking for, you will have multiple of these. Thanks,

Josef

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQIcBAEBAgAGBQJTH0P+AAoJEANb+wAKly3BA+8QAMuccHP7+IIQ62g9WRRgOuBh Mz/XG+lxpGwbHSwwp7MZPGO10Ee9rJiIJJp/VgHSyNcb/6VHB7HtU1ijifcBFaGj NkgdTTVHRHl/z17wv2cuiRfCZKOyzXtNvRYGY+lhEfITxeGklUSjwMdCBtG73XqK gWU3f9hvBjbTtN8Q7RD0O/TRNyrcUK5sEGtfJGM/a0U+avlZpE+Vu89g716BUi5L F2I5OFRtkVj9WpZLzT6e3PM/5hc0Rg0kgd54fnJoTD34GyNCyqCo1GRhON4DG+ew NCedZI3aY+/yK9iiaAfcdDpm9332xiVfrJt9tq7EJus/EVyHoDGCUbdN4D2JV+TM 8xapBtcRfy4KExORVtxOpsaamx/xPz53mngN9AH+9mLRO0OZ9xYN5SrN7FCSi/ja dhdCSR2ndEXmsy3MvcaK0g+d2DntL4uliHb3S6GUlAsDaJuiKoINa4no/FmISc62 uVEbc/cJD0KUKFlUGEcEKst3ja6ecOKFqvutII3t73R7c0N1cvf0yU4WJCTv44CZ iClBqTI/d23Du6VZpN9hcGSvFap5HiZDO+YCLA/+o5mqMJ2bG8pNQ2cXRzJlSpCN 7zZLAo8Xz0C734F6/SxnoFb+fZATQOz6VX40ZbgL1x931s/jaTJ35c0ZrlBcNSJY Y8HYBWVEOlXCUkbap7XT
=hcwz
-----END PGP SIGNATURE-----

Hi Josef,

I'm afraid I will not have the time to perform the kernel compilations and tests you request in the coming days. I'm sorry but I will really be 120% overloaded already...

Kind regards.

Swâmi Petaramesh <[email protected]> http://petaramesh.org PGP 9076E32E

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

That's fine, if you get a chance to then great, if not that's fine too. Thanks,

Josef

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQIcBAEBAgAGBQJTIJRPAAoJEANb+wAKly3BL0gP/2bFqad7MLB/2v3qWBOreWBC mpuMMQZjPMqqqA5JZxyImr5K6NYJJjdNGH4ZganCP+WUAHOSPjSuIu3TLTkMt6IW UEXEkXcSowLXof+2uHglocz0NDK+XOQnzSKAvRRjlyrCN5dvR2O9UG9aMcP4H05L KJ8a1h+Ic8A+w37roako33+DKYVJrjBiXDAQy7Cw1+dxLyAlARsNbv5am7e93uK3 NZV19K6q3WgrzbbK25v5Z3Qq4QH3GJRD3gfJNwbtoiSKOuphZhcpf85P4JZyT3G0 /xOHfPy4+LOibj/WXUfm/xu3jVgjrSaJi+wtmQdA6DCw01tByNGYWervPEg8BC5e nkjcy/4JdMKgWe6h3UZLXTWjGa2e6wa6kfvac7gkduwphnA8U5kPodx+LMT6xPZq kCtZ3o7E19alnyscz6/0+3GEW4uYNIGZv1BjBc0fCLJf3LzWCiBPaafkuakLJQkJ bNXnfttk/REEVqQ/j7gOF/rVDt1S8uTuEmC8eHxImFSeTkJQ4KYUuX5ujb+wVbrv oPh12EDYSQUDWTfqocANE5lPPVM4iscJ7ZQ3Ae3TTWUtF3GnPMTYAt2at2bQChDK TcNdgONs+4g3W6/JZVn4RypHe+qH7rg8Mu2hGKFq9MM2565NCBBsp6Jfe9sg3e84 bNMGf0EU9zFWV5fxfCu8
=KVKy
-----END PGP SIGNATURE-----