2011/10/31 Christian Brunner <chb@xxxxxx>: > 2011/10/31 Christian Brunner <chb@xxxxxx>: >> 2011/10/31 Christian Brunner <chb@xxxxxx>: >>> >>> 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). Thanks, Christian -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
