latency problems with 2.6.24.3 and before (probably xfs related)

[Hans-Peter Jansen <hpj@urpla.net>]

Hi,

I'm suffering from latency problems on a openSUSE 10.2 server with kernel
2.6.24.3. To get gripe on it, I finally got around installing latencytop
from git, and that output pretty much reflects the pathologic situation:

Process cupsd (4917)                                                                                                    
xlog_state_sync _xfs_log_force xfs_alloc_search_bu2480.0 msec         59.2 %s_alloc_vextent xfs_bmap_btalloc xfs_bmap_al
vn_iowait xfs_setattr xfs_vn_setattr notify_change1957.5 msec         26.8 %_namei do_filp_open do_sys_open sys_open sys
xfs_buf_lock xfs_getsb xfs_trans_getsb xfs_trans_a1269.6 msec          8.0 %commit xfs_itruncate_finish xfs_setattr xfs_
xfs_buf_lock xfs_getsb xfs_trans_getsb xfs_trans_a968.8 msec          6.1 %_commit xfs_iomap_write_allocate xfs_iomap xf
s_bmap xfs_map_blocks xfs_page_state_convert xfs_vm_writepage __writepage

Process svn (16210)                                                                                                     
sync_page __lock_page do_generic_mapping_read gene2289.2 msec         55.8 % xfs_file_aio_read do_sync_read vfs_read sys
xfs_buf_iowait xfs_buf_iostart xfs_buf_read_flags 1714.8 msec         27.2 %do_buf xfs_da_read_buf xfs_dir2_block_lookup
xfs_buf_iowait xfs_buf_iostart xfs_buf_read_flags 1175.6 msec         15.2 %bp xfs_iread xfs_iget_core xfs_iget xfs_dir_
xfs_buf_lock xfs_getsb xfs_trans_getsb xfs_trans_a191.4 msec          1.7 %_commit xfs_create xfs_vn_mknod xfs_vn_create
 vfs_create open_namei do_filp_open do_sys_open

Process find (15502)                                                                                                    
xfs_buf_iowait xfs_buf_iostart xfs_buf_read_flags 1468.8 msec         43.8 %bp xfs_iread xfs_iget_core xfs_iget xfs_dir_
xfs_buf_iowait xfs_buf_iostart xfs_buf_read_flags 1070.4 msec         56.2 %do_buf xfs_da_read_buf xfs_dir2_block_getden
ts xfs_readdir xfs_file_readdir vfs_readdir sys_getdents64 sysenter_past_esp

Okay, that doesn't look funny in any way. Up to 2,5 sec latency is way too 
much, given the equipment in play: Tyan S2882-D, 2 * AMD Opteron 265 DC, 4GB 
RAM, Areca ARC-1130 12-Port PCI-X to SATA RAID Controller, main system installed 
on 4 * Hitachi 500GB SATA drives in a RAID 5 setup. The kernel config is 
based on the default SUSE setup for i386 with pae extension, compiled with 
HZ 250, running with SCHED_MINTIMESLICE="10000", SCHED_MAXTIMESLICE="100000".

It looks like it's xfs related. I suspect, cupsd mostly operates on 
/var, which has it's own partition:

meta-data=/dev/sda6              isize=256    agcount=16, agsize=2457567 blks
         =                       sectsz=512   attr=0
data     =                       bsize=4096   blocks=39321072, imaxpct=25
         =                       sunit=0      swidth=0 blks, unwritten=1
naming   =version 2              bsize=4096  
log      =internal               bsize=4096   blocks=19199, version=1
         =                       sectsz=512   sunit=0 blks, lazy-count=0
realtime =none                   extsz=65536  blocks=0, rtextents=0

Any ideas, what's wrong here?

Pete