WARNING: at fs/btrfs/inode.c:2198 btrfs_orphan_commit_root+0xa8/0xc0

Hello,

I'm seeing a lot of warnings in dmesg with a BTRFS filesystem. I'm using the 3.1 kernel, I found a patch for these warnings ( http://marc.info/?l=linux-btrfs&m=131547325515336&w=2) <http://marc.info/?l=linux-btrfs&m=131547325515336&w=2>, but that patch has already been included in 3.1. Are there any other patches I can try?

I'm using BTRFS in combination with Ceph and it looks like after a while with a high rsync workload that the IO stalls for some time, could the warnings result in IO stall?

Kind regards,
Stefan Kleijkers

Output of dmesg:

[ 3924.297754] ------------[ cut here ]------------
[ 3924.297772] WARNING: at fs/btrfs/inode.c:2198 btrfs_orphan_commit_root+0xa8/0xc0 [btrfs]()
[ 3924.297774] Hardware name: X8ST3
[ 3924.297776] Modules linked in: nfs lockd nfs_acl sunrpc btrfs zlib_deflate lzo_compress md_mod target_core_mod configfs ahci libahci e1000e mptsas mptscsih mptbase i7core_edac scsi_transport_sas bnx2 i5000_edac edac_core ipmi_devintf ipmi_msghandler
[ 3924.297793] Pid: 7672, comm: kworker/2:1 Not tainted 3.1.0-un13.1-64-nohz #1
[ 3924.297795] Call Trace:
[ 3924.297802]  [<ffffffff81036dca>] warn_slowpath_common+0x7a/0xb0
[ 3924.297806]  [<ffffffff81036e15>] warn_slowpath_null+0x15/0x20
[ 3924.297816]  [<ffffffffa0137478>] btrfs_orphan_commit_root+0xa8/0xc0 [btrfs]
[ 3924.297825]  [<ffffffffa012bc54>] commit_fs_roots+0xc4/0x1b0 [btrfs]
[ 3924.297835]  [<ffffffffa012cc1e>] btrfs_commit_transaction+0x3be/0x7e0 [btrfs]
[ 3924.297840]  [<ffffffff813fa0fb>] ? __schedule+0x2fb/0x940
[ 3924.297845]  [<ffffffff810a1f20>] ? refresh_cpu_vm_stats+0x150/0x150
[ 3924.297849]  [<ffffffff81052840>] ? wake_up_bit+0x40/0x40
[ 3924.297858]  [<ffffffffa012d040>] ? btrfs_commit_transaction+0x7e0/0x7e0 [btrfs]
[ 3924.297868]  [<ffffffffa012d05a>] do_async_commit+0x1a/0x30 [btrfs]
[ 3924.297873]  [<ffffffff81350b70>] ? powersave_bias_target+0x170/0x170
[ 3924.297877]  [<ffffffff8104e0bb>] process_one_work+0x10b/0x3d0
[ 3924.297880]  [<ffffffff8104e7b6>] worker_thread+0x156/0x410
[ 3924.297884]  [<ffffffff81029f59>] ? __wake_up_common+0x59/0x90
[ 3924.297887]  [<ffffffff8104e660>] ? rescuer_thread+0x2e0/0x2e0
[ 3924.297890]  [<ffffffff810523b6>] kthread+0x96/0xa0
[ 3924.297893]  [<ffffffff813feaf4>] kernel_thread_helper+0x4/0x10
[ 3924.297896]  [<ffffffff81052320>] ? kthread_worker_fn+0x130/0x130
[ 3924.297898]  [<ffffffff813feaf0>] ? gs_change+0xb/0xb
[ 3924.297901] ---[ end trace 67e9a1054a2684f7 ]---
[ 4033.512469] ------------[ cut here ]------------
[ 4033.512496] WARNING: at fs/btrfs/inode.c:2198 btrfs_orphan_commit_root+0xa8/0xc0 [btrfs]()
[ 4033.512500] Hardware name: X8ST3
[ 4033.512502] Modules linked in: nfs lockd nfs_acl sunrpc btrfs zlib_deflate lzo_compress md_mod target_core_mod configfs ahci libahci e1000e mptsas mptscsih mptbase i7core_edac scsi_transport_sas bnx2 i5000_edac edac_core ipmi_devintf ipmi_msghandler
[ 4033.512531] Pid: 8, comm: kworker/1:0 Tainted: G        W   3.1.0-un13.1-64-nohz #1
[ 4033.512535] Call Trace:
[ 4033.512546]  [<ffffffff81036dca>] warn_slowpath_common+0x7a/0xb0
[ 4033.512551]  [<ffffffff81036e15>] warn_slowpath_null+0x15/0x20
[ 4033.512570]  [<ffffffffa0137478>] btrfs_orphan_commit_root+0xa8/0xc0 [btrfs]
[ 4033.512586]  [<ffffffffa012bc54>] commit_fs_roots+0xc4/0x1b0 [btrfs]
[ 4033.512604]  [<ffffffffa012cc1e>] btrfs_commit_transaction+0x3be/0x7e0 [btrfs]
[ 4033.512611]  [<ffffffff813fa0fb>] ? __schedule+0x2fb/0x940
[ 4033.512618]  [<ffffffff810a1f20>] ? refresh_cpu_vm_stats+0x150/0x150
[ 4033.512625]  [<ffffffff81052840>] ? wake_up_bit+0x40/0x40
[ 4033.512641]  [<ffffffffa012d040>] ? btrfs_commit_transaction+0x7e0/0x7e0 [btrfs]
[ 4033.512669]  [<ffffffffa012d05a>] do_async_commit+0x1a/0x30 [btrfs]
[ 4033.512681]  [<ffffffff81350b70>] ? powersave_bias_target+0x170/0x170
[ 4033.512693]  [<ffffffff8104e0bb>] process_one_work+0x10b/0x3d0
[ 4033.512702]  [<ffffffff8104e7b6>] worker_thread+0x156/0x410
[ 4033.512713]  [<ffffffff81029f59>] ? __wake_up_common+0x59/0x90
[ 4033.512722]  [<ffffffff8104e660>] ? rescuer_thread+0x2e0/0x2e0
[ 4033.512731]  [<ffffffff810523b6>] kthread+0x96/0xa0
[ 4033.512740]  [<ffffffff813feaf4>] kernel_thread_helper+0x4/0x10
[ 4033.512749]  [<ffffffff81052320>] ? kthread_worker_fn+0x130/0x130
[ 4033.512757]  [<ffffffff813feaf0>] ? gs_change+0xb/0xb
[ 4033.512764] ---[ end trace 67e9a1054a2684f8 ]---
[ 4450.920336] ------------[ cut here ]------------
[ 4450.920364] WARNING: at fs/btrfs/inode.c:2198 btrfs_orphan_commit_root+0xa8/0xc0 [btrfs]()
[ 4450.920368] Hardware name: X8ST3
[ 4450.920370] Modules linked in: nfs lockd nfs_acl sunrpc btrfs zlib_deflate lzo_compress md_mod target_core_mod configfs ahci libahci e1000e mptsas mptscsih mptbase i7core_edac scsi_transport_sas bnx2 i5000_edac edac_core ipmi_devintf ipmi_msghandler
[ 4450.920399] Pid: 7717, comm: kworker/3:2 Tainted: G        W   3.1.0-un13.1-64-nohz #1
[ 4450.920402] Call Trace:
[ 4450.920413]  [<ffffffff81036dca>] warn_slowpath_common+0x7a/0xb0
[ 4450.920419]  [<ffffffff81036e15>] warn_slowpath_null+0x15/0x20
[ 4450.920437]  [<ffffffffa0137478>] btrfs_orphan_commit_root+0xa8/0xc0 [btrfs]
[ 4450.920454]  [<ffffffffa012bc54>] commit_fs_roots+0xc4/0x1b0 [btrfs]
[ 4450.920471]  [<ffffffffa012cc1e>] btrfs_commit_transaction+0x3be/0x7e0 [btrfs]
[ 4450.920479]  [<ffffffff813fa0fb>] ? __schedule+0x2fb/0x940
[ 4450.920486]  [<ffffffff810a1f20>] ? refresh_cpu_vm_stats+0x150/0x150
[ 4450.920492]  [<ffffffff81052840>] ? wake_up_bit+0x40/0x40
[ 4450.920509]  [<ffffffffa012d040>] ? btrfs_commit_transaction+0x7e0/0x7e0 [btrfs]
[ 4450.920526]  [<ffffffffa012d05a>] do_async_commit+0x1a/0x30 [btrfs]
[ 4450.920534]  [<ffffffff81350b70>] ? powersave_bias_target+0x170/0x170
[ 4450.920541]  [<ffffffff8104e0bb>] process_one_work+0x10b/0x3d0
[ 4450.920546]  [<ffffffff8104e7b6>] worker_thread+0x156/0x410
[ 4450.920553]  [<ffffffff81029f59>] ? __wake_up_common+0x59/0x90
[ 4450.920558]  [<ffffffff8104e660>] ? rescuer_thread+0x2e0/0x2e0
[ 4450.920563]  [<ffffffff810523b6>] kthread+0x96/0xa0
[ 4450.920568]  [<ffffffff813feaf4>] kernel_thread_helper+0x4/0x10
[ 4450.920573]  [<ffffffff81052320>] ? kthread_worker_fn+0x130/0x130
[ 4450.920578]  [<ffffffff813feaf0>] ? gs_change+0xb/0xb
[ 4450.920581] ---[ end trace 67e9a1054a2684f9 ]---
[ 5280.880652] ------------[ cut here ]------------
[ 5280.880680] WARNING: at fs/btrfs/inode.c:2198 btrfs_orphan_commit_root+0xa8/0xc0 [btrfs]()
[ 5280.880684] Hardware name: X8ST3
[ 5280.880686] Modules linked in: nfs lockd nfs_acl sunrpc btrfs zlib_deflate lzo_compress md_mod target_core_mod configfs ahci libahci e1000e mptsas mptscsih mptbase i7core_edac scsi_transport_sas bnx2 i5000_edac edac_core ipmi_devintf ipmi_msghandler
[ 5280.880714] Pid: 7645, comm: kworker/0:2 Tainted: G        W   3.1.0-un13.1-64-nohz #1
[ 5280.880718] Call Trace:
[ 5280.880729]  [<ffffffff81036dca>] warn_slowpath_common+0x7a/0xb0
[ 5280.880735]  [<ffffffff81036e15>] warn_slowpath_null+0x15/0x20
[ 5280.880753]  [<ffffffffa0137478>] btrfs_orphan_commit_root+0xa8/0xc0 [btrfs]
[ 5280.880770]  [<ffffffffa012bc54>] commit_fs_roots+0xc4/0x1b0 [btrfs]
[ 5280.880787]  [<ffffffffa012cc1e>] btrfs_commit_transaction+0x3be/0x7e0 [btrfs]
[ 5280.880795]  [<ffffffff813fa0fb>] ? __schedule+0x2fb/0x940
[ 5280.880802]  [<ffffffff8104d698>] ? queue_delayed_work_on+0x78/0x110
[ 5280.880807]  [<ffffffff81052840>] ? wake_up_bit+0x40/0x40
[ 5280.880824]  [<ffffffffa012d040>] ? btrfs_commit_transaction+0x7e0/0x7e0 [btrfs]
[ 5280.880841]  [<ffffffffa012d05a>] do_async_commit+0x1a/0x30 [btrfs]
[ 5280.880847]  [<ffffffff8104e0bb>] process_one_work+0x10b/0x3d0
[ 5280.880853]  [<ffffffff8104e7b6>] worker_thread+0x156/0x410
[ 5280.880859]  [<ffffffff81029f59>] ? __wake_up_common+0x59/0x90
[ 5280.880865]  [<ffffffff8104e660>] ? rescuer_thread+0x2e0/0x2e0
[ 5280.880869]  [<ffffffff810523b6>] kthread+0x96/0xa0
[ 5280.880875]  [<ffffffff813feaf4>] kernel_thread_helper+0x4/0x10
[ 5280.880880]  [<ffffffff81052320>] ? kthread_worker_fn+0x130/0x130
[ 5280.880885]  [<ffffffff813feaf0>] ? gs_change+0xb/0xb
[ 5280.880888] ---[ end trace 67e9a1054a2684fa ]---

2011/11/9 Stefan Kleijkers <[email protected]>:

This seem to be the same issue, I've seen in our ceph cluster. We had a lengthy discussion on the btrfs list about this:

http://marc.info/?l=linux-btrfs&m=132007001119383&w=2

As far as I know josef is still working on it. Some of the latest patches he sent seem to related to this, but I don't know if these fix the problem.

Regards,
Christian

Can you run with this patch and see if you get warnings from extent-tree.c? Thanks,

Josef

index 0b044e5..144cd8e 100644
@@ -3721,6 +3721,7 @@ static void block_rsv_release_bytes(struct btrfs_block_rsv *block_rsv,
 	spin_lock(&block_rsv->lock);
 	if (num_bytes == (u64)-1)
 		num_bytes = block_rsv->size;
+	WARN_ON(block_rsv->size < num_bytes);
 	block_rsv->size -= num_bytes;
 	if (block_rsv->reserved >= block_rsv->size) {
 		num_bytes = block_rsv->reserved - block_rsv->size;

Hello Josef,

I have a workload running at the moment and I'm seeing a lot of these (paste 1) messages in dmesg, this is the 3.1 kernel with your patch applied.

At the end I see a couple of the old warnings (paste 2).

Futhermore it looks like after a while the speed of the filesystem decreases. I have a workload with 20 rsyncs and a total of about 1.5T data. I don't make it to have a full run.

Stefan

Paste 1:

[ 2433.606793] ------------[ cut here ]------------
[ 2433.606810] WARNING: at fs/btrfs/extent-tree.c:3592 block_rsv_release_bytes+0x12b/0x140 [btrfs]()
[ 2433.606814] Hardware name: X8ST3
[ 2433.606816] Modules linked in: btrfs zlib_deflate lzo_compress md_mod target_core_mod configfs ahci libahci e1000e mptsas mptscsih mptbase i7core_edac scsi_transport_sas bnx2 i5000_edac edac_core ipmi_devintf ipmi_msghandler
[ 2433.606838] Pid: 6757, comm: ceph-osd Tainted: G        W   3.1.1-rc1-un13.1-64-nohz #1
[ 2433.606841] Call Trace:
[ 2433.606848]  [<ffffffff81036e0a>] warn_slowpath_common+0x7a/0xb0
[ 2433.606858]  [<ffffffff81036e55>] warn_slowpath_null+0x15/0x20
[ 2433.606871]  [<ffffffffa011ed5b>] block_rsv_release_bytes+0x12b/0x140 [btrfs]
[ 2433.606884]  [<ffffffffa011ed9d>] btrfs_block_rsv_release+0x2d/0x50 [btrfs]
[ 2433.606897]  [<ffffffffa011eeaf>] btrfs_orphan_release_metadata+0x2f/0x40 [btrfs]
[ 2433.606915]  [<ffffffffa013f58d>] btrfs_orphan_del+0xbd/0xf0 [btrfs]
[ 2433.606932]  [<ffffffffa0140ab7>] btrfs_truncate+0x587/0x600 [btrfs]
[ 2433.606950]  [<ffffffffa0140b77>] btrfs_setsize+0x47/0xc0 [btrfs]
[ 2433.606968]  [<ffffffffa0140c95>] btrfs_setattr+0xa5/0xd0 [btrfs]
[ 2433.606973]  [<ffffffff810e552a>] notify_change+0x10a/0x2b0
[ 2433.606979]  [<ffffffff810cb75f>] do_truncate+0x5f/0x90
[ 2433.606985]  [<ffffffff810cb8d4>] sys_truncate+0x144/0x1a0
[ 2433.606991]  [<ffffffff813fd97b>] system_call_fastpath+0x16/0x1b
[ 2433.606995] ---[ end trace 5bebc7a2c26b1a32 ]---

Paste 2:

[ 2433.618285] ------------[ cut here ]------------
[ 2433.618306] WARNING: at fs/btrfs/inode.c:2198 btrfs_orphan_commit_root+0xa8/0xc0 [btrfs]()
[ 2433.618310] Hardware name: X8ST3
[ 2433.618312] Modules linked in: btrfs zlib_deflate lzo_compress md_mod target_core_mod configfs ahci libahci e1000e mptsas mptscsih mptbase i7core_edac scsi_transport_sas bnx2 i5000_edac edac_core ipmi_devintf ipmi_msghandler
[ 2433.618334] Pid: 6756, comm: ceph-osd Tainted: G        W   3.1.1-rc1-un13.1-64-nohz #1
[ 2433.618337] Call Trace:
[ 2433.618344]  [<ffffffff81036e0a>] warn_slowpath_common+0x7a/0xb0
[ 2433.618350]  [<ffffffff81036e55>] warn_slowpath_null+0x15/0x20
[ 2433.618368]  [<ffffffffa013f4b8>] btrfs_orphan_commit_root+0xa8/0xc0 [btrfs]
[ 2433.618384]  [<ffffffffa0133c84>] commit_fs_roots+0xc4/0x1b0 [btrfs]
[ 2433.618396]  [<ffffffffa011a475>] ? btrfs_free_path+0x25/0x30 [btrfs]
[ 2433.618413]  [<ffffffffa0134c4e>] btrfs_commit_transaction+0x3be/0x7e0 [btrfs]
[ 2433.618429]  [<ffffffffa0133fe3>] ? wait_current_trans+0x23/0x110 [btrfs]
[ 2433.618445]  [<ffffffffa0135150>] ? join_transaction+0x20/0x250 [btrfs]
[ 2433.618451]  [<ffffffff81052870>] ? wake_up_bit+0x40/0x40
[ 2433.618463]  [<ffffffffa01134a7>] btrfs_sync_fs+0x47/0x70 [btrfs]
[ 2433.618468]  [<ffffffff8102d80b>] ? pick_next_task_fair+0x10b/0x190
[ 2433.618484]  [<ffffffffa0160754>] btrfs_ioctl+0x4f4/0xd60 [btrfs]
[ 2433.618491]  [<ffffffff810fffb5>] ? fsnotify+0x1e5/0x310
[ 2433.618498]  [<ffffffff810dca7b>] do_vfs_ioctl+0x9b/0x4f0
[ 2433.618504]  [<ffffffff810dcf1a>] sys_ioctl+0x4a/0x80
[ 2433.618510]  [<ffffffff813fd97b>] system_call_fastpath+0x16/0x1b
[ 2433.618514] ---[ end trace 5bebc7a2c26b1a33 ]---

Hmm well thats interesting, and you'd think that would tell me what was wrong but I'm still confused :). Give this debug patch a whirl (unapply the last one I gave you and apply this one instead) and send me your dmesg if you get any of the new warnings. Thanks,

Josef

index 634608d..395a746 100644
@@ -74,6 +74,7 @@ struct btrfs_inode {
 
 	/* the space_info for where this inode's data allocations are done */
 	struct btrfs_space_info *space_info;
+	struct btrfs_block_rsv *rsv;
 
 	/* full 64 bit generation number, struct vfs_inode doesn't have a big
 	 * enough field for this.

@@ -140,7 +141,7 @@ struct btrfs_inode {
 	 */
 	unsigned outstanding_extents;
 	unsigned reserved_extents;
-
+	unsigned orphan_count;
 	/*
 	 * ordered_data_close is set by truncate when a file that used
 	 * to have good data has been truncated to zero.  When it is set

index fa4f602..c73f4b1 100644
@@ -3721,6 +3721,7 @@ static void block_rsv_release_bytes(struct btrfs_block_rsv *block_rsv,
 	spin_lock(&block_rsv->lock);
 	if (num_bytes == (u64)-1)
 		num_bytes = block_rsv->size;
+	BUG_ON(block_rsv->size < num_bytes);
 	block_rsv->size -= num_bytes;
 	if (block_rsv->reserved >= block_rsv->size) {
 		num_bytes = block_rsv->reserved - block_rsv->size;

index e16215f..f59231c 100644
@@ -2018,8 +2018,11 @@ int btrfs_orphan_add(struct btrfs_trans_handle *trans, struct inode *inode)
 
 	if (!BTRFS_I(inode)->orphan_meta_reserved) {
 		BTRFS_I(inode)->orphan_meta_reserved = 1;
+		BTRFS_I(inode)->rsv = root->orphan_block_rsv;
 		reserve = 1;
 	}
+	WARN_ON(BTRFS_I(inode)->orphan_count);
+	BTRFS_I(inode)->orphan_count++;
 	spin_unlock(&root->orphan_lock);
 
 	/* grab metadata reservation from transaction handle */

@@ -2061,9 +2064,12 @@ int btrfs_orphan_del(struct btrfs_trans_handle *trans, struct inode *inode)
 	}
 
 	if (BTRFS_I(inode)->orphan_meta_reserved) {
+		WARN_ON(BTRFS_I(inode)->rsv != root->orphan_block_rsv);
 		BTRFS_I(inode)->orphan_meta_reserved = 0;
 		release_rsv = 1;
 	}
+	WARN_ON(!BTRFS_I(inode)->orphan_count);
+	BTRFS_I(inode)->orphan_count--;
 	spin_unlock(&root->orphan_lock);
 
 	if (trans && delete_item) {

@@ -6629,6 +6635,7 @@ struct inode *btrfs_alloc_inode(struct super_block *sb)
 	spin_lock_init(&ei->lock);
 	ei->outstanding_extents = 0;
 	ei->reserved_extents = 0;
+	ei->orphan_count = 0;
 
 	ei->ordered_data_close = 0;
 	ei->orphan_meta_reserved = 0;

@@ -6638,6 +6645,7 @@ struct inode *btrfs_alloc_inode(struct super_block *sb)
 	ei->force_compress = BTRFS_COMPRESS_NONE;
 
 	ei->delayed_node = NULL;
+	ei->rsv = NULL;
 
 	inode = &ei->vfs_inode;
 	extent_map_tree_init(&ei->extent_tree);

Hello Josef,

We have patched the 3.1.1 kernel with your patch and after a short time one of the ceph osds crashed (core dumped) and I found this in the dmesg, please let me know if that's enough information or if you need more.

Stefan

[11226.207447] ------------[ cut here ]------------
[11226.212107] kernel BUG at fs/btrfs/extent-tree.c:3592!
[11226.217283] invalid opcode: 0000 [#1] SMP
[11226.221442] CPU 2
[11226.223288] Modules linked in: btrfs zlib_deflate lzo_compress md_mod target_core_mod configfs ahci libahci e1000e mptsas i7core_edac mptscsih mptbase scsi_transport_sas bnx2 i5000_edac edac_core ipmi_devintf ipmi_msghandler
[11226.243940]
[11226.245458] Pid: 6845, comm: ceph-osd Not tainted 3.1.1-un13.1-64-nohz #1 Supermicro X8ST3/X8ST3
[11226.254349] RIP: 0010:[<ffffffffa011719a>]  [<ffffffffa011719a>] block_rsv_release_bytes+0x11a/0x120 [btrfs]
[11226.264316] RSP: 0018:ffff8805fb4e1cd8  EFLAGS: 00010206
[11226.269663] RAX: 0000000000000000 RBX: ffff8802c4303d20 RCX: 000000000113be7a
[11226.276831] RDX: 0000000000018000 RSI: 0000000000000000 RDI: ffff8802c4303d58
[11226.284015] RBP: ffff8805fb4e1cf8 R08: ffffffffa0114475 R09: ffff8805fb4e1b98
[11226.291173] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[11226.298396] R13: 0000000000018000 R14: ffff8805fb280800 R15: 0000000000000001
[11226.305579] FS:  00007f34edeae700(0000) GS:ffff88061fc40000(0000) knlGS:0000000000000000
[11226.313709] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[11226.319480] CR2: 00007f34e414e000 CR3: 00000005fc8f9000 CR4: 00000000000006e0
[11226.326637] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[11226.333797] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[11226.340956] Process ceph-osd (pid: 6845, threadinfo ffff8805fb4e0000, task ffff880604292f00)
[11226.349578] Stack:
[11226.351614]  ffff8805e08d5de0 0000000000000001 ffff880602fd8400 ffff8805e092fdc8
[11226.359164]  ffff8805fb4e1d08 ffffffffa01171cd ffff8805fb4e1d18 ffffffffa011721f
[11226.366687]  ffff8805fb4e1d58 ffffffffa0139565 ffff8805fb4e1d58 ffff8805e092fdc8
[11226.374270] Call Trace:
[11226.376776]  [<ffffffffa01171cd>] btrfs_block_rsv_release+0x2d/0x50 [btrfs]
[11226.383852]  [<ffffffffa011721f>] btrfs_orphan_release_metadata+0x2f/0x40 [btrfs]
[11226.391430]  [<ffffffffa0139565>] btrfs_orphan_del+0xe5/0x150 [btrfs]
[11226.398044]  [<ffffffffa013ab27>] btrfs_truncate+0x587/0x600 [btrfs]
[11226.404510]  [<ffffffffa013abe7>] btrfs_setsize+0x47/0xc0 [btrfs]
[11226.410646]  [<ffffffffa013ad05>] btrfs_setattr+0xa5/0xd0 [btrfs]
[11226.416933]  [<ffffffff810e552a>] notify_change+0x10a/0x2b0
[11226.422548]  [<ffffffff810cb75f>] do_truncate+0x5f/0x90
[11226.427840]  [<ffffffff810cb8d4>] sys_truncate+0x144/0x1a0
[11226.433363]  [<ffffffff813fd97b>] system_call_fastpath+0x16/0x1b
[11226.439573] Code: 00 49 8d be b8 00 00 00 e8 64 5d 2e e1 4d 29 6e 20 49 ff 46 48 41 fe 86 b8 00 00 00 eb a1 0f 1f 00 83 ca 04 41 88 54 24 41 eb 87 <0f> 0b eb fe 66 90 55 48 89 f8 48 89 e5 48 89 f7 48 8b 80 20 01
[11226.460355] RIP  [<ffffffffa011719a>] block_rsv_release_bytes+0x11a/0x120 [btrfs]
[11226.468018]  RSP <ffff8805fb4e1cd8>
[11226.472008] ---[ end trace 7a5f53562ba538a2 ]---

Yeah I was hoping for a WARN_ON() that should have shown up before that, do you have the entire dmesg? Thanks,

Josef

Hello Josef,

I've two new dmesg's (ceph osd 0 and 1). Both filesystems wheren't responding anymore. Please let me know if you need more information or another run. Both are made with the 3.1.1 kernel and your patches applied (the patches with the extra warning messages).

Paste:
OSD.0: http://pastebin.com/tPjMk0kH
OSD.1: http://pastebin.com/ef7A16g2

Stefan

Sorry I forgot about you :). Here is a new debug patch, it will print something out right before it panics so make sure to get that info, and it will also be spitting stuff out to the trace buffer. So make sure you have tracing enabled, usually distros mount debugfs so you can cd /sys/kernel/debug/tracing and cat trace and you should see something. When it panics cat trace > somefile and send me the file and the dmesg so I can figure out what went wrong. Thanks,

Josef

index 24cfd10..d887608 100644
@@ -3762,6 +3762,11 @@ static void block_rsv_release_bytes(struct btrfs_block_rsv *block_rsv,
 	spin_lock(&block_rsv->lock);
 	if (num_bytes == (u64)-1)
 		num_bytes = block_rsv->size;
+	if (unlikely(block_rsv->size < num_bytes)) {
+		printk(KERN_ERR "block rsv %p has size %Lu, want to take "
+		       "away %Lu\n", block_rsv, block_rsv->size, num_bytes);
+		BUG();
+	}
 	block_rsv->size -= num_bytes;
 	if (block_rsv->reserved >= block_rsv->size) {
 		num_bytes = block_rsv->reserved - block_rsv->size;

@@ -4064,6 +4069,8 @@ int btrfs_orphan_reserve_metadata(struct btrfs_trans_handle *trans,
 	 * when we are truly done with the orphan item.
 	 */
 	u64 num_bytes = btrfs_calc_trans_metadata_size(root, 1);
+	trace_printk("Reserved %Lu bytes for inode %Lu on rsv %p\n",
+		     num_bytes, btrfs_ino(inode), dst_rsv);
 	return block_rsv_migrate_bytes(src_rsv, dst_rsv, num_bytes);
 }
 

@@ -4071,6 +4078,8 @@ void btrfs_orphan_release_metadata(struct inode *inode)
 {
 	struct btrfs_root *root = BTRFS_I(inode)->root;
 	u64 num_bytes = btrfs_calc_trans_metadata_size(root, 1);
+	trace_printk("Releaseing %Lu bytes for inode %Lu on rsv %p\n",
+		     num_bytes, btrfs_ino(inode), root->orphan_block_rsv);
 	btrfs_block_rsv_release(root, root->orphan_block_rsv, num_bytes);
 }
 

index e16215f..38a4efb 100644
@@ -1994,6 +1994,8 @@ int btrfs_orphan_add(struct btrfs_trans_handle *trans, struct inode *inode)
 
 	spin_lock(&root->orphan_lock);
 	if (!root->orphan_block_rsv) {
+		trace_printk("Added new orphan rsv %p for root %Lu\n",
+			     block_rsv, root->objectid);
 		root->orphan_block_rsv = block_rsv;
 	} else if (block_rsv) {
 		btrfs_free_block_rsv(root, block_rsv);

@@ -2002,6 +2004,8 @@ int btrfs_orphan_add(struct btrfs_trans_handle *trans, struct inode *inode)
 
 	if (list_empty(&BTRFS_I(inode)->i_orphan)) {
 		list_add(&BTRFS_I(inode)->i_orphan, &root->orphan_list);
+		trace_printk("Added inode %Lu to orphan list for %Lu\n",
+			     btrfs_ino(inode), root->objectid);
 #if 0
 		/*
 		 * For proper ENOSPC handling, we should do orphan

@@ -2019,6 +2023,9 @@ int btrfs_orphan_add(struct btrfs_trans_handle *trans, struct inode *inode)
 	if (!BTRFS_I(inode)->orphan_meta_reserved) {
 		BTRFS_I(inode)->orphan_meta_reserved = 1;
 		reserve = 1;
+	} else {
+		trace_printk("Didn't do reservation for inode %Lu on %Lu\n",
+			     btrfs_ino(inode), root->objectid);
 	}
 	spin_unlock(&root->orphan_lock);
 

@@ -2056,6 +2063,8 @@ int btrfs_orphan_del(struct btrfs_trans_handle *trans, struct inode *inode)
 
 	spin_lock(&root->orphan_lock);
 	if (!list_empty(&BTRFS_I(inode)->i_orphan)) {
+		trace_printk("Removed inode %Lu from orphan list for %Lu\n",
+			     btrfs_ino(inode), root->objectid);
 		list_del_init(&BTRFS_I(inode)->i_orphan);
 		delete_item = 1;
 	}

@@ -2063,6 +2072,9 @@ int btrfs_orphan_del(struct btrfs_trans_handle *trans, struct inode *inode)
 	if (BTRFS_I(inode)->orphan_meta_reserved) {
 		BTRFS_I(inode)->orphan_meta_reserved = 0;
 		release_rsv = 1;
+	} else {
+		trace_printk("Inode %Lu didn't release metadata\n",
+			     btrfs_ino(inode));
 	}
 	spin_unlock(&root->orphan_lock);
 

Hello Josef,

I've new results, is this the trace you are looking for?

Trace of OSD0: http://pastebin.com/gddLBXE4
Dmesg of OSD0: http://pastebin.com/Uebzgkjv

OSD1 crashed a while later with the same messages.

Stefan

2011/11/26 Stefan Kleijkers <[email protected]>:

Hi Josef,

I ran your patch on one of our ceph nodes, too. At the first run it hit the BUG_ON and creashed. Unfortunately I was not able to get the trace messages from the server (I'm glad that Stefan managed to fetch it), so I gave it a second spin. This time it did NOT hit the BUG_ON, but I wrote the trace to a file, so I can send you the trace output at that time. You can find dmesg-output here:

http://pastebin.com/pWWsZ79e

The trace messages from 154900 till 154999 are here (don't know if this is interesting):

http://pastebin.com/01EKHqn5

and the tracing output from 206200 till 206399 is here:

http://pastebin.com/50PNtiF7

I hope, that this will give you a better insight into this. I will now reboot and run it a third time, to see if I can hit the BUG_ON again.

Regards,
Christian

Well those look perfect, but that shouldn't be happening, essentially what that tells me is we've somehow thought that we already have space reserved for that inode, but we don't, and the only way we test/set that value is under a spin_lock, so it simply cannot be happening that way. So can you jack up your buffer size for ftrace and re-run and get me the same info again to make sure nothing to lost? You can do that by doing something like this

echo 4096 > /sys/kernel/debug/traceing/buffer_size_kb

and then running the test and gather the same info as before. Thanks,

Josef

Hello Josef,

Will do, thanks! As soon as I have results I will let you know.

I did already a rerun (without the bigger buffer size), but unfortunately I couldn't get the trace (like Christian). If I tried to cat from the trace it hung.

Stefan