lkml.org 
[lkml]   [2005]   [Jan]   [13]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: High write latency, iowait, slow writes 2.6.9
    Thanks much. I still seem to be getting latency, etc. w/ 2.6.11 rc1 bk 
    w/ the patch... Here you go (vmstat.log is a little long).

    Jens Axboe wrote:
    > On Wed, Jan 12 2005, Paul A. Sumner wrote:
    >
    >>Thanks... I've tried the as, deadline and cfq schedulers. Deadline is
    >>giving me the best results. I've also tried tweaking the stuff in
    >>/sys/block/sda/queue/iosched/.
    >>
    >>For lack of a better way of describing it, it seems like something is
    >>thrashing.
    >
    >
    > I you have time, I would like you to try current BK with this patch:
    >
    > http://www.kernel.org/pub/linux/kernel/people/axboe/patches/v2.6/2.6.11-rc1/cfq-time-slices-20.gz
    >
    > You should enable CONFIG_IOPRIO_WRITE, it is in the io scheduler config
    > section, if you do a make oldconfig it should pop up for you. Boot with
    > elevator=cfq to select cfq.
    >
    > A simple profile of the bad period would also be nice, along with
    > vmstat 1 info from that period. If you boot with profile=2, do:
    >
    > # readprofile -r
    > # run bad workload
    > # readprofile | sort -nr +2 > result_file
    >
    > And send that along with the logged vmstat 1 from that same period.
    >
    > Oh, and lastly, remember to CC people on lkml when you respond, thanks.
    >
    + uname -a
    Linux taz 2.6.11-rc1-bk1 #1 SMP Thu Jan 13 09:11:26 PST 2005 x86_64 AMD Opteron(tm) Processor 250 AuthenticAMD GNU/Linux
    + grep MemTotal /proc/meminfo
    MemTotal: 16126744 kB
    + dmesg
    + grep Bootdata
    Bootdata ok (command line is root=/dev/ram0 init=/linuxrc ramdisk=8192 real_root=/dev/sda3 console=tty0 console=ttyS0,115200n8 elevator=cfq profile=2 gentoo=udev)
    + readprofile -r
    + vmstat 1
    + tiotest -d /data/scratch -f 8192
    Tiotest results for 4 concurrent io threads:
    ,----------------------------------------------------------------------.
    | Item | Time | Rate | Usr CPU | Sys CPU |
    +-----------------------+----------+--------------+----------+---------+
    | Write 32768 MBs | 484.3 s | 67.662 MB/s | 0.8 % | 12.9 % |
    | Random Write 16 MBs | 3.2 s | 4.913 MB/s | 0.1 % | 1.6 % |
    | Read 32768 MBs | 155.1 s | 211.207 MB/s | 1.5 % | 22.9 % |
    | Random Read 16 MBs | 8.7 s | 1.795 MB/s | 0.1 % | 0.3 % |
    `----------------------------------------------------------------------'
    Tiotest latency results:
    ,-------------------------------------------------------------------------.
    | Item | Average latency | Maximum latency | % >2 sec | % >10 sec |
    +--------------+-----------------+-----------------+----------+-----------+
    | Write | 0.152 ms | 178448.837 ms | 0.00032 | 0.00015 |
    | Random Write | 0.007 ms | 6.228 ms | 0.00000 | 0.00000 |
    | Read | 0.073 ms | 363.501 ms | 0.00000 | 0.00000 |
    | Random Read | 8.515 ms | 270.383 ms | 0.00000 | 0.00000 |
    |--------------+-----------------+-----------------+----------+-----------|
    | Total | 0.115 ms | 178448.837 ms | 0.00016 | 0.00008 |
    `--------------+-----------------+-----------------+----------+-----------'

    + pkill vmstat
    + readprofile
    + sort -nr +2
    ./lkml.sh: line 10: 8599 Terminated vmstat 1 >vmstat.log
    1171085 default_idle 24397.6042
    34154 copy_user_generic_c 898.7895
    1160 __wake_up_bit 24.1667
    2697 find_get_page 21.0703
    2122 find_trylock_page 18.9464
    1755 kmem_cache_free 18.2812
    85 ret_from_sys_call 17.0000
    1072 kmem_cache_alloc 16.7500
    3659 add_to_page_cache 15.2458
    842 unlock_page 13.1562
    201 xfs_bmap 12.5625
    1061 page_waitqueue 11.0521
    990 truncate_complete_page 10.3125
    1713 fget_light 9.7330
    2246 end_buffer_async_write 9.3583
    562 bio_put 8.7812
    259 mark_buffer_async_write 8.0938
    1896 test_clear_page_dirty 7.9000
    1876 test_clear_page_writeback 7.3281
    569 current_kernel_time 7.1125
    565 end_page_writeback 7.0625
    99 xfs_size_fn 6.1875
    295 bio_add_page 6.1458
    191 fput 5.9688
    1043 __smp_call_function 5.9261
    1040 find_lock_page 5.9091
    740 mpage_end_io_read 5.7812
    1102 dnotify_parent 5.7396
    1783 __set_page_dirty_nobuffers 5.5719
    1277 __pagevec_lru_add 5.3208
    1575 free_hot_cold_page 5.1809
    1625 test_set_page_writeback 5.0781
    792 xfs_map_at_offset 4.9500
    150 xfs_bmbt_get_startoff 4.6875
    574 system_call 4.3817
    138 linvfs_prepare_write 4.3125
    412 xfs_trans_unlocked_item 4.2917
    671 create_empty_buffers 4.1937
    577 xfs_count_page_state 4.0069
    5929 __make_request 3.9845
    940 __do_softirq 3.9167
    605 __down_write 3.7812
    3015 buffered_rmqueue 3.7687
    230 mark_page_accessed 3.5938
    333 generic_commit_write 3.4688
    485 finish_task_switch 3.3681
    604 memset 3.2128
    599 __block_commit_write 3.1198
    136 mark_buffer_dirty 2.8333
    43 xfs_bmbt_get_blockcount 2.6875
    414 put_page 2.5875
    39 mempool_alloc_slab 2.4375
    2605 scsi_request_fn 2.3943
    1138 linvfs_get_block_core 2.3708
    354 __down_read 2.2987
    434 try_to_free_buffers 2.2604
    35 mempool_free_slab 2.1875
    675 __find_get_block_slow 2.1094
    364 alloc_page_buffers 2.0682
    129 end_bio_bh_io_sync 2.0156
    313 alloc_pages_current 1.9563
    480 scsi_end_request 1.8750
    298 mempool_free 1.8625
    551 __up_write 1.8125
    290 find_get_pages 1.8125
    737 mempool_alloc 1.7716
    170 set_bh_page 1.7708
    140 free_buffer_head 1.7500
    275 xfs_iunlock 1.7188
    546 vfs_write 1.7063
    190 linvfs_write 1.6964
    539 vfs_read 1.6844
    160 bad_range 1.6667
    260 __up_read 1.6250
    544 submit_bh 1.6190
    714 __mark_inode_dirty 1.5938
    250 update_atime 1.5625
    75 block_prepare_write 1.5625
    146 current_fs_time 1.5208
    170 xfs_mod_incore_sb 1.5179
    213 sys_write 1.4792
    496 xfs_ichgtime 1.4762
    233 drop_buffers 1.4563
    23 xfs_extent_state 1.4375
    6439 shrink_zone 1.4271
    815 __end_that_request_first 1.4149
    225 radix_tree_preload 1.4062
    244 xfs_ilock 1.3864
    664 __bio_add_page 1.3833
    796 generic_make_request 1.3819
    44 linvfs_get_blocks_direct 1.3750
    401 xfs_submit_page 1.3191
    839 __do_page_cache_readahead 1.2790
    225 zone_watermark_ok 1.2784
    142 xfs_bmap_worst_indlen 1.2679
    634 scsi_dispatch_cmd 1.2008
    518 bio_alloc 1.1562
    73 alloc_buffer_head 1.1406
    359 submit_bio 1.1219
    465 release_pages 1.1178
    87 smp_call_function_all_cpus 1.0875
    240 do_sync_write 1.0714
    51 xfs_ilock_map_shared 1.0625
    34 xfs_bmbt_get_state 1.0625
    935 __alloc_pages 1.0435
    131 bio_endio 1.0234
    32 linvfs_get_block 1.0000
    156 __pagevec_release_nonlru 0.9750
    684 xfs_read 0.9716
    45 __pagevec_free 0.9375
    15 set_page_refs 0.9375
    74 bio_destructor 0.9250
    1149 generic_file_buffered_write 0.9207
    103 linvfs_read 0.9196
    102 smp_call_function 0.9107
    301 page_referenced 0.8958
    269 mpage_readpages 0.8849
    181 inode_update_time 0.8702
    1073 xfs_iomap 0.8489
    271 file_read_actor 0.8469
    119 zonelist_policy 0.8264
    178 linvfs_release_page 0.7946
    25 xfs_bmbt_get_startblock 0.7812
    172 __cache_shrink 0.7679
    61 flat_send_IPI_allbutself 0.7625
    164 do_sync_read 0.7321
    635 xfs_bmap_do_search_extents 0.7216
    33 xfs_inode_shake 0.6875
    218 shrink_slab 0.6813
    75 cond_resched 0.6696
    259 generic_write_checks 0.6475
    23 init_buffer_head 0.6389
    254 balance_dirty_pages_ratelimited 0.6350
    10 xfs_ail_min 0.6250
    137 xfs_bmap_search_extents 0.6116
    87 sys_read 0.6042
    1565 xfs_write 0.6038
    572 do_mpage_readpage 0.5958
    33 do_softirq_thunk 0.5690
    45 try_to_release_page 0.5625
    320 xfs_convert_page 0.5556
    62 put_io_context 0.5536
    26 xfs_rwunlock 0.5417
    932 xfs_page_state_convert 0.5295
    8 fs_noerr 0.5000
    480 __block_prepare_write 0.4839
    37 timespec_trunc 0.4625
    551 do_generic_mapping_read 0.4592
    44 cpu_idle 0.4583
    60 get_io_context 0.4167
    237 try_to_wake_up 0.4115
    52 __read_page_state 0.4062
    24 io_schedule 0.3750
    1301831 total 0.3712
    231 get_request 0.3208
    15 xfs_offset_to_map 0.3125
    10 scsi_next_command 0.3125
    5 free_hot_page 0.3125
    175 blk_recount_segments 0.2878
    18 unmap_underlying_metadata 0.2812
    49 wakeup_kswapd 0.2784
    22 __down_read_trylock 0.2292
    11 elv_set_request 0.2292
    21 blockable_page_cache_readahead 0.2188
    37 wait_on_page_bit 0.2102
    140 blk_queue_bounce 0.2083
    96 __generic_file_aio_read 0.2000
    48 scsi_put_command 0.2000
    30 do_page_cache_readahead 0.1875
    3 xfs_iunlock_map_shared 0.1875
    1482 xfs_bmapi 0.1856
    34 scsi_finish_command 0.1771
    34 recalc_bh_state 0.1771
    48 get_request_wait 0.1765
    14 sysret_check 0.1687
    8 add_disk_randomness 0.1667
    93 truncate_inode_pages 0.1571
    10 wake_up_bit 0.1562
    7 scsi_free_sgtable 0.1458
    20 task_rq_lock 0.1389
    17 kref_put 0.1328
    61 xfs_mod_incore_sb_unlocked 0.1271
    95 page_cache_readahead 0.1263
    16 thread_return 0.1250
    10 xfs_bmbt_get_all 0.1250
    8 xfs_bmap_cancel 0.1250
    4 xfs_bmbt_set_blockcount 0.1250
    4 sched_clock 0.1250
    2 pagebuf_ispin 0.1250
    9 shrink_dcache_memory 0.1125
    7 bio_get_nr_vecs 0.1094
    36 __mod_timer 0.1071
    164 cfq_set_request 0.1068
    5 pagebuf_daemon_wakeup 0.1042
    5 kmem_cache_shrink 0.1042
    8 lru_add_drain 0.1000
    8 block_sync_page 0.1000
    37 mb_cache_shrink_fn 0.0964
    3 put_device 0.0938
    3 handle_ra_miss 0.0938
    7 xfs_trans_tail_ail 0.0875
    20 scsi_softirq 0.0833
    9 remove_from_page_cache 0.0804
    88 cache_grow 0.0797
    41 pagebuf_daemon 0.0777
    11 finish_wait 0.0764
    13 memcpy 0.0739
    111 xfs_iomap_write_delay 0.0738
    21 copy_user_generic 0.0705
    10 scsi_device_unbusy 0.0694
    30 __bitmap_weight 0.0670
    9 scsi_add_timer 0.0625
    7 alloc_io_context 0.0625
    3 mpage_bio_submit 0.0625
    2 blk_backing_dev_unplug 0.0625
    1 xfs_trans_find_item 0.0625
    20 xfs_log_move_tail 0.0595
    8 del_timer 0.0556
    7 prepare_to_wait_exclusive 0.0547
    52 scsi_io_completion 0.0524
    10 __clear_page_dirty 0.0521
    9 xfs_bmap_eof 0.0511
    4 get_next_ra_size 0.0500
    6 .text.lock.buffer 0.0484
    2 xfs_bmbt_set_startblock 0.0417
    2 __pagevec_release 0.0417
    49 kswapd 0.0414
    22 add_timer_randomness 0.0382
    16 scsi_run_queue 0.0345
    3 __get_free_pages 0.0312
    2 ioc_set_batching 0.0312
    1 linvfs_readpages 0.0312
    1 kobject_put 0.0312
    1 retint_careful 0.0303
    9 scsi_decide_disposition 0.0281
    44 schedule 0.0264
    1 del_singleshot_timer_sync 0.0208
    4 schedule_timeout 0.0192
    4 find_get_pages_tag 0.0192
    4 generic_file_direct_IO 0.0179
    2 percpu_counter_mod 0.0179
    2 __wake_up 0.0179
    12 xfs_map_unwritten 0.0163
    2 __wait_on_bit_lock 0.0156
    4 generic_cont_expand 0.0139
    2 mpage_alloc 0.0125
    1 sync_page 0.0125
    2 background_writeout 0.0114
    3 profile_hit 0.0094
    1 schedule_tail 0.0089
    1 journal_unfile_buffer 0.0089
    1 end_buffer_write_sync 0.0089
    40 xfs_bmap_add_extent 0.0078
    6 shrink_icache_memory 0.0078
    2 linvfs_writepage 0.0078
    2 get_dirty_limits 0.0078
    1 sys_lseek 0.0078
    1 clear_page_dirty_for_io 0.0078
    1 __wait_on_bit 0.0078
    4 sd_rw_intr 0.0074
    3 prune_dcache 0.0063
    1 lookup_mnt 0.0063
    1 devfs_d_iput 0.0063
    1 sched_fork 0.0057
    1 __lock_page 0.0057
    1 xfs_mod_incore_sb_batch 0.0048
    1 kfree 0.0045
    1 writeback_inodes 0.0042
    1 ext3_get_branch 0.0042
    1 __sched_text_start 0.0037
    2 try_to_free_pages 0.0036
    1 release_task 0.0027
    1 journal_write_revoke_records 0.0026
    2 __generic_file_aio_write_nolock 0.0022
    1 page_referenced_one 0.0021
    1 __getblk_slow 0.0018
    1 journal_stop 0.0016
    1 xfs_getattr 0.0015
    1 __journal_file_buffer 0.0014
    1 do_wp_page 0.0010
    1 start_this_handle 0.0009
    1 clear_page_range 0.0009
    1 copy_page_range 0.0007
    1 journal_commit_transaction 0.0002
    [unhandled content-type:application/gzip]
    \
     
     \ /
      Last update: 2005-03-22 14:09    [W:0.048 / U:60.192 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site