Bug #563 - osd: btrfs, warning at inode.c ( btrfs_orphan_commit_root )

G'day,

http://tracker.newdream.net/issues/563

I see this bug was closed 5 days ago. Which commit[s] closed it? I'm getting it on ceph-client 9aae8fa + btrfs-work bacae12 when I do a mkcephfs on 3 x 2 GB OSDs, e.g.:

Feb  4 19:09:04 b3 kernel: [16780.260695] ------------[ cut here ]------------
Feb  4 19:09:04 b3 kernel: [16780.260716] WARNING: at fs/btrfs/inode.c:2143 btrfs_orphan_commit_root+0x7f/0x9b [btrfs]()
Feb  4 19:09:04 b3 kernel: [16780.260724] Hardware name: System Product Name
Feb  4 19:09:04 b3 kernel: [16780.260729] Modules linked in: kvm_amd kvm loop btrfs zlib_deflate crc32c libcrc32c dm_mod tpm_tis tpm psmouse tpm_bios i2c_piix4 i2c_core button shpchp pci_hotplug processor nfs lockd nfs_acl auth_rpcgss sunrpc sd_mod ata_generic ahci libahci libata ehci_hcd r8169 mii ohci_hcd scsi_mod thermal fan thermal_sys [last unloaded: scsi_wait_scan]
Feb  4 19:09:04 b3 kernel: [16780.260783] Pid: 5233, comm: kworker/0:2 Tainted: G        W   2.6.37-otn1-33361-ga3f5274 #3
Feb  4 19:09:04 b3 kernel: [16780.260792] Call Trace:
Feb  4 19:09:04 b3 kernel: [16780.260805]  [<ffffffffa0215444>] ? btrfs_orphan_commit_root+0x7f/0x9b [btrfs]
Feb  4 19:09:04 b3 kernel: [16780.260815]  [<ffffffff81044644>] ? warn_slowpath_common+0x78/0x8d
Feb  4 19:09:04 b3 kernel: [16780.260828]  [<ffffffffa0215444>] ? btrfs_orphan_commit_root+0x7f/0x9b [btrfs]
Feb  4 19:09:04 b3 kernel: [16780.260842]  [<ffffffffa020adfe>] ? commit_fs_roots+0x87/0xef [btrfs]
Feb  4 19:09:04 b3 kernel: [16780.260855]  [<ffffffffa020ba71>] ? btrfs_commit_transaction+0x342/0x60f [btrfs]
Feb  4 19:09:04 b3 kernel: [16780.260869]  [<ffffffffa00aef5d>] ? xprt_release_xprt+0x41/0x73 [sunrpc]
Feb  4 19:09:04 b3 kernel: [16780.260877]  [<ffffffff8105df3a>] ? autoremove_wake_function+0x0/0x2e
Feb  4 19:09:04 b3 kernel: [16780.260886]  [<ffffffffa00ace70>] ? call_transmit+0x214/0x24f [sunrpc]
Feb  4 19:09:04 b3 kernel: [16780.260899]  [<ffffffffa020bd50>] ? do_async_commit+0x12/0x1b [btrfs]
Feb  4 19:09:04 b3 kernel: [16780.260906]  [<ffffffff8105903b>] ? process_one_work+0x22c/0x3a5
Feb  4 19:09:04 b3 kernel: [16780.260918]  [<ffffffffa020bd3e>] ? do_async_commit+0x0/0x1b [btrfs]
Feb  4 19:09:04 b3 kernel: [16780.260924]  [<ffffffff81059507>] ? worker_thread+0x1d5/0x353
Feb  4 19:09:04 b3 kernel: [16780.260930]  [<ffffffff81059332>] ? worker_thread+0x0/0x353
Feb  4 19:09:04 b3 kernel: [16780.260936]  [<ffffffff8105daf0>] ? kthread+0x7e/0x86
Feb  4 19:09:04 b3 kernel: [16780.260942]  [<ffffffff8100a7e4>] ? kernel_thread_helper+0x4/0x10
Feb  4 19:09:04 b3 kernel: [16780.260949]  [<ffffffff8105da72>] ? kthread+0x0/0x86
Feb  4 19:09:04 b3 kernel: [16780.260954]  [<ffffffff8100a7e0>] ? kernel_thread_helper+0x0/0x10
Feb  4 19:09:04 b3 kernel: [16780.260961] ---[ end trace e1f5276f9dfbd540 ]---
Feb  4 19:09:05 b3 kernel: [16782.127219] ------------[ cut here ]------------
Feb  4 19:09:05 b3 kernel: [16782.127241] WARNING: at fs/btrfs/inode.c:2143 btrfs_orphan_commit_root+0x7f/0x9b [btrfs]()
Feb  4 19:09:05 b3 kernel: [16782.127248] Hardware name: System Product Name
Feb  4 19:09:05 b3 kernel: [16782.127253] Modules linked in: kvm_amd kvm loop btrfs zlib_deflate crc32c libcrc32c dm_mod tpm_tis tpm psmouse tpm_bios i2c_piix4 i2c_core button shpchp pci_hotplug processor nfs lockd nfs_acl auth_rpcgss sunrpc sd_mod ata_generic ahci libahci libata ehci_hcd r8169 mii ohci_hcd scsi_mod thermal fan thermal_sys [last unloaded: scsi_wait_scan]
Feb  4 19:09:05 b3 kernel: [16782.127306] Pid: 5848, comm: kworker/1:2 Tainted: G        W   2.6.37-otn1-33361-ga3f5274 #3
Feb  4 19:09:05 b3 kernel: [16782.127314] Call Trace:
Feb  4 19:09:05 b3 kernel: [16782.127326]  [<ffffffffa0215444>] ? btrfs_orphan_commit_root+0x7f/0x9b [btrfs]
Feb  4 19:09:05 b3 kernel: [16782.128628]  [<ffffffff81044644>] ? warn_slowpath_common+0x78/0x8d
Feb  4 19:09:05 b3 kernel: [16782.128642]  [<ffffffffa0215444>] ? btrfs_orphan_commit_root+0x7f/0x9b [btrfs]
Feb  4 19:09:05 b3 kernel: [16782.128658]  [<ffffffffa020adfe>] ? commit_fs_roots+0x87/0xef [btrfs]
Feb  4 19:09:05 b3 kernel: [16782.128672]  [<ffffffffa020ba71>] ? btrfs_commit_transaction+0x342/0x60f [btrfs]
Feb  4 19:09:05 b3 kernel: [16782.128682]  [<ffffffff8105df3a>] ? autoremove_wake_function+0x0/0x2e
Feb  4 19:09:05 b3 kernel: [16782.128695]  [<ffffffffa020bd50>] ? do_async_commit+0x12/0x1b [btrfs]
Feb  4 19:09:05 b3 kernel: [16782.128701]  [<ffffffff8105903b>] ? process_one_work+0x22c/0x3a5
Feb  4 19:09:05 b3 kernel: [16782.128713]  [<ffffffffa020bd3e>] ? do_async_commit+0x0/0x1b [btrfs]
Feb  4 19:09:05 b3 kernel: [16782.128719]  [<ffffffff81059507>] ? worker_thread+0x1d5/0x353
Feb  4 19:09:05 b3 kernel: [16782.128725]  [<ffffffff81059332>] ? worker_thread+0x0/0x353
Feb  4 19:09:05 b3 kernel: [16782.128732]  [<ffffffff8105daf0>] ? kthread+0x7e/0x86
Feb  4 19:09:05 b3 kernel: [16782.128738]  [<ffffffff8100a7e4>] ? kernel_thread_helper+0x4/0x10
Feb  4 19:09:05 b3 kernel: [16782.128745]  [<ffffffff8105da72>] ? kthread+0x0/0x86
Feb  4 19:09:05 b3 kernel: [16782.128750]  [<ffffffff8100a7e0>] ? kernel_thread_helper+0x0/0x10
Feb  4 19:09:05 b3 kernel: [16782.128756] ---[ end trace e1f5276f9dfbd541 ]---

Cheers,

Chris.

Hi,

From what I've heard they are working on it upstream (btrfs). Not sure what the state is though.

Wido

They're not waiting still for Sage?

From your initial report at the top of the ticket:

#btrfs
20:00 < widodh> I've just upgraded to 2.6.37-rc1 to test Ceph, but I'm seeing this right now in my dmesg:
http://pastebin.com/3HiGiNgy ( inode.c / btrfs_orphan_commit_root )
20:01 < josef> hrm looks like sage screwed something up with async commit
20:02 < widodh> aha, file it over there then?
20:03 < josef> well tell sage about it, he's the one who wrote the code so he'll probably be able to fix it quicker 20:03 < widodh> yes, sure. I thought it was a btrfs bug, that's why I came along here
20:03 < widodh> thanks!
20:05 < josef> well it is a bug in btrfs, but he will be able to fix it quicker than i will

I'll see what the linux-btrfs mailing list has to say about it...

Cheers,

Chris.

G'day,

Using Josef's btrfs-work bacae123 (+ ceph-client 9aae8faf), I can consistently reproduce the following btrfs warning by simply creating and starting a new btrfs-based ceph file system:

[  549.767234] ------------[ cut here ]------------
[  549.767276] WARNING: at fs/btrfs/inode.c:2143 btrfs_orphan_commit_root+0x7f/0x9b [btrfs]()
[  549.767305] Hardware name: System Product Name
[  549.767331] Modules linked in: loop btrfs zlib_deflate crc32c libcrc32c dm_mod tpm_tis psmouse tpm tpm_bios i2c_piix4 i2c_core shpchp pci_hotplug button processor nfs lockd nfs_acl auth_rpcgss sunrpc sd_mod ata_generic ahci libahci libata r8169 mii ohci_hcd ehci_hcd scsi_mod thermal fan thermal_sys [last unloaded: scsi_wait_scan]
[  549.768192] Pid: 10, comm: kworker/0:1 Tainted: G        W   2.6.37-otn1-33361-ga3f5274 #3
[  549.768221] Call Trace:
[  549.768255]  [<ffffffffa0217444>] ? btrfs_orphan_commit_root+0x7f/0x9b [btrfs]
[  549.768286]  [<ffffffff81044644>] ? warn_slowpath_common+0x78/0x8d
[  549.768319]  [<ffffffffa0217444>] ? btrfs_orphan_commit_root+0x7f/0x9b [btrfs]
[  549.768354]  [<ffffffffa020cdfe>] ? commit_fs_roots+0x87/0xef [btrfs]
[  549.768388]  [<ffffffffa020da71>] ? btrfs_commit_transaction+0x342/0x60f [btrfs]
[  549.768422]  [<ffffffffa00aef5d>] ? xprt_release_xprt+0x41/0x73 [sunrpc]
[  549.768450]  [<ffffffff8105df3a>] ? autoremove_wake_function+0x0/0x2e
[  549.768480]  [<ffffffffa00ace70>] ? call_transmit+0x214/0x24f [sunrpc]
[  549.768513]  [<ffffffffa020dd50>] ? do_async_commit+0x12/0x1b [btrfs]
[  549.768541]  [<ffffffff8105903b>] ? process_one_work+0x22c/0x3a5
[  549.768574]  [<ffffffffa020dd3e>] ? do_async_commit+0x0/0x1b [btrfs]
[  549.768601]  [<ffffffff81059507>] ? worker_thread+0x1d5/0x353
[  549.768628]  [<ffffffff81059332>] ? worker_thread+0x0/0x353
[  549.768656]  [<ffffffff8105daf0>] ? kthread+0x7e/0x86
[  549.768683]  [<ffffffff8100a7e4>] ? kernel_thread_helper+0x4/0x10
[  549.768710]  [<ffffffff8105da72>] ? kthread+0x0/0x86
[  549.768737]  [<ffffffff8100a7e0>] ? kernel_thread_helper+0x0/0x10
[  549.768765] ---[ end trace 38bb7d3c072c3ca5 ]---

This or similar warnings look to have previously been reported by others, e.g.:

2010-11-19 http://article.gmane.org/gmane.comp.file-systems.btrfs/7707/match=btrfs_orphan_commit_root
2011-01-06 http://article.gmane.org/gmane.comp.file-systems.btrfs/8512/match=btrfs_orphan_commit_root
2011-01-26 http://article.gmane.org/gmane.comp.file-systems.ceph.devel/1726/match=btrfs_orphan_commit_root

The process I use to reproduce is:

mkcephfs -v -c /etc/ceph/ceph.conf --allhosts --mkbtrfs -k /etc/ceph/keyring.bin umount /data/osd0
/etc/init.d/ceph start

This is using a minimal ceph.conf file:
------------------------------------------------------------
[global]
[mon]
mon data = /data/mon$id
[mon0]

	host = b3
	mon addr = ip.ip.ip.ip:6789

[mds]
keyring = /data/keyring.$name
[mds.b3]
host = b3
[osd]
osd data = /data/osd$id
[osd0]
host = b3
btrfs devs = /dev/sda
------------------------------------------------------------

Cheers,

Chris.

Sorry, just found I've been booting wrong kernel. I've been seeing the warning *without* Josef's btrfs-work. Will re-test tomorrow.

OK, the line number has changed slightly, but still getting the same thing with:

git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git

commit cb5520f02c010e3cb974b9ac06f30aafa2eebc38
Merge: eee4da2... 3a90983...
Author: Linus Torvalds <[email protected]>
Date: Mon Feb 7 14:06:18 2011 -0800

Merge git://git.kernel.org/pub/scm/linux/kernel/git/mason/btrfs-unstable

[ 129.524029] ------------[ cut here ]------------
[ 129.524080] WARNING: at fs/btrfs/inode.c:2161 btrfs_orphan_commit_root+0x7f/0x9b [btrfs]()
[ 129.524111] Hardware name: System Product Name
[ 129.524140] Modules linked in: loop netconsole configfs dm_mod sd_mod i2c_piix4 k10temp i2c_core asus_atk0110 ata_generic ahci libahci libata scsi_mod shpchp button pci_hotplug processor nfs lockd nfs_acl auth_rpcgss sunrpc r8169 mii ohci_hcd ehci_hcd thermal fan thermal_sys btrfs zlib_deflate crc32c libcrc32c
[ 129.525057] Pid: 10, comm: kworker/0:1 Tainted: G        W   2.6.38-rc3-otn1-00323-gc88f808 #5
[ 129.525088] Call Trace:
[ 129.525125]  [<ffffffffa003db51>] ? btrfs_orphan_commit_root+0x7f/0x9b [btrfs]
[ 129.525158]  [<ffffffff81043a20>] ? warn_slowpath_common+0x78/0x8d
[ 129.525195]  [<ffffffffa003db51>] ? btrfs_orphan_commit_root+0x7f/0x9b [btrfs]
[ 129.525232]  [<ffffffffa0033729>] ? commit_fs_roots+0x87/0xef [btrfs]
[ 129.525268]  [<ffffffffa00343a2>] ? btrfs_commit_transaction+0x348/0x615 [btrfs]
[ 129.525300]  [<ffffffff8105d14a>] ? autoremove_wake_function+0x0/0x2e
[ 129.525336]  [<ffffffffa00c8e49>] ? call_transmit+0x214/0x24f [sunrpc]
[ 129.525372]  [<ffffffffa0034681>] ? do_async_commit+0x12/0x1b [btrfs]
[ 129.525400]  [<ffffffff81057df4>] ? process_one_work+0x22c/0x3a5
[ 129.525437]  [<ffffffffa003466f>] ? do_async_commit+0x0/0x1b [btrfs]
[ 129.525465]  [<ffffffff810582c0>] ? worker_thread+0x1d5/0x353
[ 129.525495]  [<ffffffff810580eb>] ? worker_thread+0x0/0x353
[ 129.525526]  [<ffffffff8105cd08>] ? kthread+0x7e/0x86
[ 129.525557]  [<ffffffff8100a764>] ? kernel_thread_helper+0x4/0x10
[ 129.525588]  [<ffffffff8105cc8a>] ? kthread+0x0/0x86
[ 129.525617]  [<ffffffff8100a760>] ? kernel_thread_helper+0x0/0x10
[ 129.525649] ---[ end trace deccd3c0dec6c2ba ]---

Hi Chris,

Can you try to reproduce this with the following patch applied to the server side? This will disable the async snapshot ioctl. It doesn't look like it's related to me, but let's be sure.

Thanks!
sage

index dc78451..d5530c5 100644
@@ -865,7 +865,7 @@ int FileStore::_detect_fs()
       dout(0) << "mount btrfs SNAP_CREATE_V2 got " << r << " " << strerror_r(-r, buf, sizeof(buf)) << dendl;
       if (r == 0 || errno == EEXIST) {
        dout(0) << "mount btrfs SNAP_CREATE_V2 is supported" << dendl;
-       btrfs_snap_create_v2 = true;
+       //btrfs_snap_create_v2 = true;
       
        // clean up
        r = ::ioctl(fd, BTRFS_IOC_SNAP_DESTROY, &vol_args);

Hi Chris,

I closed it because it seems to be a btrfs issue that's not specific to Ceph. Have you tried Josef's latest tree? See

http://git.kernel.org/?p=linux/kernel/git/josef/btrfs-work.git;a=summary

Chris should also be sending a pull request shortly that includes these (and other fixes) to Linus.

sage

Yup, this warning came up using:

ceph-client 9aae8faf
+ Josef's btrfs-work bacae123

Cheers,

Chris

Sorry, just found I've been booting wrong kernel. I've been seeing the warning *without* Josef's btrfs-work. Will re-test tomorrow.

[  282.347591] ------------[ cut here ]------------
[  282.352289] WARNING: at fs/btrfs/inode.c:2161 btrfs_orphan_commit_root+0x7f/0x9b()
[  282.360045] Hardware name: X7SBi-LN4
[  282.363710] Pid: 2297, comm: kworker/0:2 Not tainted 2.6.38-rc3+ #23
[  282.370170] Call Trace:
[  282.372725]  [<ffffffff8103baa9>] ? warn_slowpath_common+0x73/0x87
[  282.379002]  [<ffffffff81260508>] ? btrfs_orphan_commit_root+0x7f/0x9b
[  282.385633]  [<ffffffff81257e0c>] ? commit_fs_roots+0x8d/0xf4
[  282.391487]  [<ffffffff81258acc>] ? btrfs_commit_transaction+0x349/0x61c
[  282.398293]  [<ffffffff81053d3b>] ? autoremove_wake_function+0x0/0x2a
[  282.404842]  [<ffffffff81258d9f>] ? do_async_commit+0x0/0x1b
[  282.410602]  [<ffffffff81258db1>] ? do_async_commit+0x12/0x1b
[  282.416468]  [<ffffffff8104f025>] ? process_one_work+0x1cc/0x2e9
[  282.422605]  [<ffffffff81050dbd>] ? worker_thread+0x123/0x234
[  282.428459]  [<ffffffff81050c9a>] ? worker_thread+0x0/0x234
[  282.434152]  [<ffffffff81050c9a>] ? worker_thread+0x0/0x234
[  282.439848]  [<ffffffff81053915>] ? kthread+0x7a/0x82
[  282.445001]  [<ffffffff810036d4>] ? kernel_thread_helper+0x4/0x10
[  282.451199]  [<ffffffff8105389b>] ? kthread+0x0/0x82
[  282.456263]  [<ffffffff810036d0>] ? kernel_thread_helper+0x0/0x10
[  282.462456] ---[ end trace 466f4ef3f2383e7f ]--- 

With

commit 0eb30e7f58a0a2794211f39ff5b87aae97d784ec
Merge: 410fd12 aba63cd
Author: root <root@bolt.(none)>
Date: Mon Feb 7 10:04:00 2011 +0100

Merge branch 'master' of http://git.kernel.org/pub/scm/linux/kernel/git/josef/btrfs-work into HEAD

commit 410fd12a9067d97ffaac5a950a3d42273f0091db
Merge: 8dbdea8 9c01177
Author: root <root@bolt.(none)>
Date: Mon Feb 7 09:42:26 2011 +0100

Merge branch 'unstable' of http://ceph.newdream.net/git/ceph-client into HEAD

And

ceph version 0.25~rc (commit:06fe1320efe7285f2bc76bcf81c19671f44a70df)

- Jan

;a=summary