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

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

[Stefan Kleijkers]

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 ]---

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

[Christian Brunner]

2011/11/9 Stefan Kleijkers <stefan@unilogicnetworks.net>:
> 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?

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

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

[Josef Bacik]

On Wed, Nov 09, 2011 at 11:24:50AM +0100, Stefan Kleijkers wrote:
> 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?
> 

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

Josef


diff --git a/fs/btrfs/extent-tree.c b/fs/btrfs/extent-tree.c
index 0b044e5..144cd8e 100644
--- a/fs/btrfs/extent-tree.c
+++ b/fs/btrfs/extent-tree.c
@@ -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;

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

[Stefan Kleijkers]

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 ]---

On 11/09/2011 04:35 PM, Josef Bacik wrote:
> On Wed, Nov 09, 2011 at 11:24:50AM +0100, Stefan Kleijkers wrote:
>> 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?
>>
> Can you run with this patch and see if you get warnings from extent-tree.c?
> Thanks,
>
> Josef
>
>
> diff --git a/fs/btrfs/extent-tree.c b/fs/btrfs/extent-tree.c
> index 0b044e5..144cd8e 100644
> --- a/fs/btrfs/extent-tree.c
> +++ b/fs/btrfs/extent-tree.c
> @@ -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;
> --
> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Josef Bacik]

On Thu, Nov 10, 2011 at 01:13:46PM +0100, Stefan Kleijkers wrote:
> 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.
> 

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

diff --git a/fs/btrfs/btrfs_inode.h b/fs/btrfs/btrfs_inode.h
index 634608d..395a746 100644
--- a/fs/btrfs/btrfs_inode.h
+++ b/fs/btrfs/btrfs_inode.h
@@ -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
diff --git a/fs/btrfs/extent-tree.c b/fs/btrfs/extent-tree.c
index fa4f602..c73f4b1 100644
--- a/fs/btrfs/extent-tree.c
+++ b/fs/btrfs/extent-tree.c
@@ -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;
diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
index e16215f..f59231c 100644
--- a/fs/btrfs/inode.c
+++ b/fs/btrfs/inode.c
@@ -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);

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

[Stefan Kleijkers]

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 ]---


On 11/14/2011 05:03 PM, Josef Bacik wrote:
> On Thu, Nov 10, 2011 at 01:13:46PM +0100, Stefan Kleijkers wrote:
>> 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.
>>
> 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
>
> diff --git a/fs/btrfs/btrfs_inode.h b/fs/btrfs/btrfs_inode.h
> index 634608d..395a746 100644
> --- a/fs/btrfs/btrfs_inode.h
> +++ b/fs/btrfs/btrfs_inode.h
> @@ -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
> diff --git a/fs/btrfs/extent-tree.c b/fs/btrfs/extent-tree.c
> index fa4f602..c73f4b1 100644
> --- a/fs/btrfs/extent-tree.c
> +++ b/fs/btrfs/extent-tree.c
> @@ -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;
> diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
> index e16215f..f59231c 100644
> --- a/fs/btrfs/inode.c
> +++ b/fs/btrfs/inode.c
> @@ -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);

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

[Josef Bacik]

On Tue, Nov 15, 2011 at 08:13:43PM +0100, Stefan Kleijkers wrote:
> 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.
> 

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

Josef

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

[Stefan Kleijkers]

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

On 11/15/2011 08:29 PM, Josef Bacik wrote:
> On Tue, Nov 15, 2011 at 08:13:43PM +0100, Stefan Kleijkers wrote:
>> 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.
>>
> Yeah I was hoping for a WARN_ON() that should have shown up before that, do you
> have the entire dmesg?  Thanks,
>
> Josef

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

[Josef Bacik]

On Tue, Nov 15, 2011 at 09:19:12PM +0100, Stefan Kleijkers wrote:
> Hello Josef,
> 
> You can find the complete dmesg paste on: http://pastebin.com/R4dFfSdQ
> 
> But I doubt it will add more information.
> 

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


diff --git a/fs/btrfs/extent-tree.c b/fs/btrfs/extent-tree.c
index 24cfd10..d887608 100644
--- a/fs/btrfs/extent-tree.c
+++ b/fs/btrfs/extent-tree.c
@@ -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);
 }
 
diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
index e16215f..38a4efb 100644
--- a/fs/btrfs/inode.c
+++ b/fs/btrfs/inode.c
@@ -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);
 

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

[Stefan Kleijkers]

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

On 11/18/2011 08:52 PM, Josef Bacik wrote:
> On Tue, Nov 15, 2011 at 09:19:12PM +0100, Stefan Kleijkers wrote:
>> Hello Josef,
>>
>> You can find the complete dmesg paste on: http://pastebin.com/R4dFfSdQ
>>
>> But I doubt it will add more information.
>>
> 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
>
>
> diff --git a/fs/btrfs/extent-tree.c b/fs/btrfs/extent-tree.c
> index 24cfd10..d887608 100644
> --- a/fs/btrfs/extent-tree.c
> +++ b/fs/btrfs/extent-tree.c
> @@ -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);
>   }
>
> diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
> index e16215f..38a4efb 100644
> --- a/fs/btrfs/inode.c
> +++ b/fs/btrfs/inode.c
> @@ -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);
>

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

[Christian Brunner]

2011/11/26 Stefan Kleijkers <stefan@unilogicnetworks.net>:
> 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

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

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

[Josef Bacik]

On Sat, Nov 26, 2011 at 03:14:37PM +0100, Stefan Kleijkers wrote:
> 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.
> 

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

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

[Stefan Kleijkers]

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

On 12/01/2011 04:14 PM, Josef Bacik wrote:
> On Sat, Nov 26, 2011 at 03:14:37PM +0100, Stefan Kleijkers wrote:
>> 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.
>>
> 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
> --
> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html