[prev in list] [next in list] [prev in thread] [next in thread] 

List:       linux-btrfs
Subject:    Re: ceph on btrfs [was Re: ceph on non-btrfs file systems]
From:       Josef Bacik <josef () redhat ! com>
Date:       2011-10-31 14:04:57
Message-ID: 20111031140457.GJ6783 () dhcp231-156 ! rdu ! redhat ! com
[Download RAW message or body]

On Mon, Oct 31, 2011 at 02:29:44PM +0100, Christian Brunner wrote:
> 2011/10/31 Christian Brunner <chb@muc.de>:
> > 2011/10/31 Christian Brunner <chb@muc.de>:
> >> 2011/10/31 Christian Brunner <chb@muc.de>:
> >>>
> >>> The patch didn't hurt, but I've to tell you that I'm still seeing the
> >>> same old problems. Load is going up again:
> >>>
> >>>  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
> >>>  5502 root      20   0     0    0    0 S 52.5 0.0 106:29.97 btrfs-endio-wri
> >>>  1976 root      20   0  601m 211m 1464 S 28.3 0.9 115:10.62 ceph-osd
> >>>
> >>> And I have hit our warning again:
> >>>
> >>> [223560.970713] ------------[ cut here ]------------
> >>> [223560.976043] WARNING: at fs/btrfs/inode.c:2118
> >>> btrfs_orphan_commit_root+0xb0/0xc0 [btrfs]()
> >>> [223560.985411] Hardware name: ProLiant DL180 G6
> >>> [223560.990491] Modules linked in: btrfs zlib_deflate libcrc32c sunrpc
> >>> bonding ipv6 sg serio_raw pcspkr ghes hed iTCO_wdt iTCO_vendor_support
> >>> i7core_edac edac_core ixgbe dca mdio iomemory_vsl(P) hpsa squashfs
> >>> [last unloaded: scsi_wait_scan]
> >>> [223561.014748] Pid: 2079, comm: ceph-osd Tainted: P
> >>> 3.0.6-1.fits.9.el6.x86_64 #1
> >>> [223561.023874] Call Trace:
> >>> [223561.026738]  [<ffffffff8106344f>] warn_slowpath_common+0x7f/0xc0
> >>> [223561.033564]  [<ffffffff810634aa>] warn_slowpath_null+0x1a/0x20
> >>> [223561.040272]  [<ffffffffa0282120>] btrfs_orphan_commit_root+0xb0/0xc0 [btrfs]
> >>> [223561.048278]  [<ffffffffa027ce55>] commit_fs_roots+0xc5/0x1b0 [btrfs]
> >>> [223561.055534]  [<ffffffff8154c231>] ? mutex_lock+0x31/0x60
> >>> [223561.061666]  [<ffffffffa027ddbe>]
> >>> btrfs_commit_transaction+0x3ce/0x820 [btrfs]
> >>> [223561.069876]  [<ffffffffa027d1b8>] ? wait_current_trans+0x28/0x110 [btrfs]
> >>> [223561.077582]  [<ffffffffa027e325>] ? join_transaction+0x25/0x250 [btrfs]
> >>> [223561.085065]  [<ffffffff81086410>] ? wake_up_bit+0x40/0x40
> >>> [223561.091251]  [<ffffffffa025a329>] btrfs_sync_fs+0x59/0xd0 [btrfs]
> >>> [223561.098187]  [<ffffffffa02abc65>] btrfs_ioctl+0x495/0xd50 [btrfs]
> >>> [223561.105120]  [<ffffffff8125ed20>] ? inode_has_perm+0x30/0x40
> >>> [223561.111575]  [<ffffffff81261a2c>] ? file_has_perm+0xdc/0xf0
> >>> [223561.117924]  [<ffffffff8117086a>] do_vfs_ioctl+0x9a/0x5a0
> >>> [223561.124072]  [<ffffffff81170e11>] sys_ioctl+0xa1/0xb0
> >>> [223561.129842]  [<ffffffff81555702>] system_call_fastpath+0x16/0x1b
> >>> [223561.136699] ---[ end trace 176e8be8996f25f6 ]---
> >>
> >> [ Not sending this to the lists, as the attachment is large ].
> >>
> >> I've spent a little time to do some tracing with ftrace. Its output
> >> seems to be right (at least as far as I can tell). I hope that its
> >> output can give you an insight on whats going on.
> >>
> >> The interesting PIDs in the trace are:
> >>
> >>  5502 root      20   0     0    0    0 S 33.6 0.0 118:28.37 btrfs-endio-wri
> >>  5518 root      20   0     0    0    0 S 29.3 0.0 41:23.58 btrfs-endio-wri
> >>  8059 root      20   0  400m  48m 2756 S  8.0  0.2   8:31.56 ceph-osd
> >>  7993 root      20   0  401m  41m 2808 S 13.6  0.2   7:58.38 ceph-osd
> >>
> >
> > [ adding linux-btrfs again ]
> >
> > I've been digging into this a bit further:
> >
> > Attached is another ftrace report that I've filtered for "btrfs_*"
> > calls and limited to CPU0 (this is where PID 5502 was running).
> >
> > From what I can see there is a lot of time consumed in
> > btrfs_reserve_extent(). I this normal?
> 
> Sorry for spamming, but in the meantime I'm almost certain that the
> problem is inside find_free_extent (called from btrfs_reserve_extent).
> 
> When I'm running ftrace for a sample period of 10s my system is
> wasting a total of 4,2 seconds inside find_free_extent(). Each call to
> find_free_extent() is taking an average of 4 milliseconds to complete.
> On a recently rebooted system this is only 1-2 us!
> 
> I'm not sure if the problem is occurring suddenly or slowly over time.
> (At the moment I suspect that its occurring suddenly, but I still have
> to investigate this).
>

Ugh ok then this is lxo's problem with our clustering stuff taking way too much
time.  I guess it's time to actually take a hard look at that code.  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
[prev in list] [next in list] [prev in thread] [next in thread]