latency problems with 2.6.24.3 and before (probably xfs related)

latency problems with 2.6.24.3 and before (probably xfs related)

[Hans-Peter Jansen]

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

Re: latency problems with 2.6.24.3 and before (probably xfs related)

[Hans-Peter Jansen]

Am Samstag, 1. März 2008 schrieb Hans-Peter Jansen:
> 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:

Here's a typical situation with medium load :

Cause                                                Maximum     Percentage
sync_page wait_on_page_bit write_cache_pages gener1269.7 msec          7.2 %
sync_page __lock_page block_page_mkwrite xfs_vm_pa997.9 msec          2.5 %
sync_page __lock_page block_page_mkwrite xfs_vm_pa684.4 msec          1.7 %
sync_page __lock_page block_page_mkwrite xfs_vm_pa415.7 msec          4.8 %
lock_super sync_supers do_sync sys_sync sysenter_p221.6 msec          0.6 %
xlog_state_sync _xfs_log_force _xfs_trans_commit x134.3 msec          0.5 %
xfs_iflock xfs_finish_reclaim xfs_sync_inodes xfs_ 35.3 msec          0.1 %
sync_page wait_on_page_bit wait_on_page_writeback_ 29.4 msec          0.1 %
sync_page __lock_page do_generic_mapping_read gene 11.1 msec          0.0 %
_pread64 sysenter_past_esp 0xffffe410

Process muser (5319)                                                                                                    
sync_page wait_on_page_bit write_cache_pages gener1269.7 msec         89.4 %pages do_writepages __writeback_single_inode
lock_super sync_supers do_sync sys_sync sysenter_p221.6 msec          9.2 %odes
xfs_iflock xfs_finish_reclaim xfs_sync_inodes xfs_ 35.3 msec          1.3 %ync_super sync_filesystems do_sync sys_sync s
md_write_start make_request generic_make_request s  3.2 msec          0.1 %d_bio xfs_submit_ioend xfs_page_state_convert
 xfs_vm_writepage __writepage write_cache_pages generic_writepages xfs_vm_writepages

muser is a database application for a terminal based order mgmt system, where
this leads to a very annoying user interface starvation for about 5-10 seconds.

Obviously, this process (already running with nice -20) syncs often (probably
due to its age: we started using it at year 2 B.L.; 1989 on Bull DPX systems, 
oh well..).

I experimented with schedtool and ionice today, by boosting the suffering 
processes and degrading others. But the problem persists.

Could it be, that the write queue is simply too large?

Here's the the block stat of the offended device:

~# cat /sys/block/sda/stat 
 1912195    54104 161804644  9629427  1407367   111132 27530479 572302123        0 12852042 581945330

The "write ticks" value 572302123 looks suspicious, isn't it?

The raid system is a 3ware 9500 controller with 5 WD Raptor WD740GD-00FLA0 
drives in raid 5 mode. 

Any ideas are highly appreciated.

Pete