* Latencies writing to memory mapped files
@ 2010-09-15 15:26 Shawn Bohrer
2010-09-16 0:18 ` Dave Chinner
0 siblings, 1 reply; 10+ messages in thread
From: Shawn Bohrer @ 2010-09-15 15:26 UTC (permalink / raw)
To: xfs
Hello,
A little while ago I asked about ways to solve the occasional spikes in
latency that I see when writing to a shared memory mapped file.
http://oss.sgi.com/pipermail/xfs/2010-July/046311.html
With Dave's suggestions I enabled lazy-count=1 which did help a little:
# xfs_info /home/
meta-data=/dev/sda5 isize=256 agcount=32, agsize=8472969 blks
= sectsz=512 attr=1
data = bsize=4096 blocks=271135008, imaxpct=25
= sunit=0 swidth=0 blks
naming =version 2 bsize=4096 ascii-ci=0
log =internal bsize=4096 blocks=32768, version=1
= sectsz=512 sunit=0 blks, lazy-count=1
realtime =none extsz=4096 blocks=0, rtextents=0
I'm also mounting the partition with "noatime,nobarrier,logbufs=8".
The other change I made which helped the most was to use fallocate()
to grow the file instead of lseek() and a write(). The latencies look
acceptable at lower data rates but once I reach 2-3 MB/s I start
seeing spikes when writeback occurs. Perhaps my expectations are
unreasonable, but I would like to keep my latencies under 0.01s and
the lower the better. I don't have hard real-time requirements, but
latencies are important. These systems also only need to log data for
about 7-8 hours, so while I don't exactly know how much data I will
get I can make some guesses and preallocate the files or perform other
tricks if it would help.
Below are some snippets of a trace of a 0.3 second delay I captured
with ftrace on 2.6.32.21. I haven't done enough sampling to know if
all of the delays happen for the same reason, or if there are multiple
code paths that lead to a large delay.
First I see xfsconvertd/7 acquire the xfs_ilock() then try to acquire
the xfs_buf_lock() and block:
xfsconvertd/7-251 [007] 358613.942101: funcgraph_entry: | xfs_end_bio_unwritten() {
xfsconvertd/7-251 [007] 358613.942101: funcgraph_entry: | xfs_iomap_write_unwritten() {
xfsconvertd/7-251 [007] 358613.942102: funcgraph_entry: | _xfs_trans_alloc() {
xfsconvertd/7-251 [007] 358613.942104: funcgraph_exit: 2.582 us | }
xfsconvertd/7-251 [007] 358613.942104: funcgraph_entry: | xfs_trans_reserve() {
xfsconvertd/7-251 [007] 358613.942546: funcgraph_exit: ! 441.449 us | }
xfsconvertd/7-251 [007] 358613.942546: funcgraph_entry: | xfs_ilock() {
xfsconvertd/7-251 [007] 358613.942547: funcgraph_exit: 0.895 us | }
xfsconvertd/7-251 [007] 358613.942547: funcgraph_entry: | xfs_trans_ijoin() {
xfsconvertd/7-251 [007] 358613.942548: funcgraph_exit: 0.667 us | }
xfsconvertd/7-251 [007] 358613.942548: funcgraph_entry: 0.138 us | xfs_trans_ihold();
xfsconvertd/7-251 [007] 358613.942549: funcgraph_entry: | xfs_bmapi() {
xfsconvertd/7-251 [007] 358613.942549: funcgraph_entry: | xfs_bmap_search_extents() {
xfsconvertd/7-251 [007] 358613.942564: funcgraph_exit: + 14.764 us | }
xfsconvertd/7-251 [007] 358613.942565: funcgraph_entry: | xfs_bmbt_init_cursor() {
xfsconvertd/7-251 [007] 358613.942567: funcgraph_exit: 2.740 us | }
xfsconvertd/7-251 [007] 358613.942568: funcgraph_entry: | xfs_bmap_add_extent() {
xfsconvertd/7-251 [007] 358613.942568: funcgraph_entry: | xfs_iext_get_ext() {
xfsconvertd/7-251 [007] 358613.942569: funcgraph_exit: 0.702 us | }
xfsconvertd/7-251 [007] 358613.942569: funcgraph_entry: 0.215 us | xfs_bmbt_get_all();
xfsconvertd/7-251 [007] 358613.942569: funcgraph_entry: | xfs_bmap_add_extent_unwritten_real() {
xfsconvertd/7-251 [007] 358613.942570: funcgraph_entry: | xfs_iext_get_ext() {
xfsconvertd/7-251 [007] 358613.942570: funcgraph_exit: 0.677 us | }
xfsconvertd/7-251 [007] 358613.942571: funcgraph_entry: 0.218 us | xfs_bmbt_get_all();
xfsconvertd/7-251 [007] 358613.942571: funcgraph_entry: | xfs_iext_get_ext() {
xfsconvertd/7-251 [007] 358613.942572: funcgraph_exit: 0.844 us | }
xfsconvertd/7-251 [007] 358613.942572: funcgraph_entry: 0.216 us | xfs_bmbt_get_all();
xfsconvertd/7-251 [007] 358613.942573: funcgraph_entry: | xfs_iext_get_ext() {
xfsconvertd/7-251 [007] 358613.942573: funcgraph_exit: 0.708 us | }
xfsconvertd/7-251 [007] 358613.942574: funcgraph_entry: 0.175 us | xfs_bmbt_get_all();
xfsconvertd/7-251 [007] 358613.942574: funcgraph_entry: | xfs_iext_get_ext() {
xfsconvertd/7-251 [007] 358613.942575: funcgraph_exit: 1.079 us | }
xfsconvertd/7-251 [007] 358613.942575: funcgraph_entry: 0.220 us | xfs_bmbt_set_blockcount();
xfsconvertd/7-251 [007] 358613.942576: funcgraph_entry: 0.303 us | xfs_bmbt_set_startoff();
xfsconvertd/7-251 [007] 358613.942577: funcgraph_entry: 0.216 us | xfs_bmbt_set_startblock();
xfsconvertd/7-251 [007] 358613.942577: funcgraph_entry: 0.423 us | xfs_bmbt_set_blockcount();
xfsconvertd/7-251 [007] 358613.942578: funcgraph_entry: | xfs_bmbt_lookup_eq() {
xfsconvertd/7-251 [007] 358613.942578: funcgraph_entry: | xfs_btree_lookup() {
xfsconvertd/7-251 [007] 358613.942579: funcgraph_entry: 0.212 us | xfs_bmbt_init_ptr_from_cur();
xfsconvertd/7-251 [007] 358613.942579: funcgraph_entry: | xfs_btree_lookup_get_block() {
xfsconvertd/7-251 [007] 358613.942721: funcgraph_exit: ! 141.594 us | }
xfsconvertd/7-251 [007] 358613.942721: funcgraph_entry: | xfs_lookup_get_search_key() {
xfsconvertd/7-251 [007] 358613.942723: funcgraph_exit: 1.205 us | }
xfsconvertd/7-251 [007] 358613.942723: funcgraph_entry: 0.208 us | xfs_bmbt_key_diff();
xfsconvertd/7-251 [007] 358613.942723: funcgraph_entry: | xfs_btree_ptr_addr() {
xfsconvertd/7-251 [007] 358613.942725: funcgraph_exit: 1.686 us | }
xfsconvertd/7-251 [007] 358613.942725: funcgraph_entry: | xfs_btree_lookup_get_block() {
xfsconvertd/7-251 [007] 358613.942726: funcgraph_entry: | xfs_btree_read_buf_block() {
xfsconvertd/7-251 [007] 358613.942726: funcgraph_entry: 0.252 us | xfs_btree_ptr_to_daddr();
xfsconvertd/7-251 [007] 358613.942726: funcgraph_entry: | xfs_trans_read_buf() {
xfsconvertd/7-251 [007] 358613.942727: funcgraph_entry: 0.330 us | xfs_trans_buf_item_match();
xfsconvertd/7-251 [007] 358613.942728: funcgraph_entry: | xfs_buf_read_flags() {
xfsconvertd/7-251 [007] 358613.942728: funcgraph_entry: | xfs_buf_get_flags() {
xfsconvertd/7-251 [007] 358613.942728: funcgraph_entry: | kmem_zone_alloc() {
xfsconvertd/7-251 [007] 358613.942885: funcgraph_exit: ! 156.328 us | }
xfsconvertd/7-251 [007] 358613.942885: funcgraph_entry: | _xfs_buf_find() {
xfsconvertd/7-251 [007] 358613.942885: funcgraph_entry: 0.150 us | _spin_lock();
xfsconvertd/7-251 [007] 358613.942885: funcgraph_entry: | down_trylock() {
xfsconvertd/7-251 [007] 358613.942886: funcgraph_exit: 0.818 us | }
xfsconvertd/7-251 [007] 358613.942886: funcgraph_entry: | xfs_buf_lock() {
xfsconvertd/7-251 [007] 358613.942886: funcgraph_entry: | down() {
xfsconvertd/7-251 [007] 358613.942887: funcgraph_entry: 0.137 us | _spin_lock_irqsave();
xfsconvertd/7-251 [007] 358613.942887: funcgraph_entry: | __down() {
xfsconvertd/7-251 [007] 358613.942887: funcgraph_entry: | schedule_timeout() {
xfsconvertd/7-251 [007] 358613.942887: funcgraph_entry: | schedule() {
xfsconvertd/7-251 [007] 358613.942888: funcgraph_entry: 0.136 us | rcu_sched_qs();
xfsconvertd/7-251 [007] 358613.942888: funcgraph_entry: 0.137 us | _spin_lock_irq();
xfsconvertd/7-251 [007] 358613.942888: funcgraph_entry: | deactivate_task() {
xfsconvertd/7-251 [007] 358613.942891: funcgraph_exit: 3.263 us | }
xfsconvertd/7-251 [007] 358613.942892: funcgraph_entry: 0.140 us | put_prev_task_fair();
xfsconvertd/7-251 [007] 358613.942892: funcgraph_entry: 0.159 us | pick_next_task_fair();
xfsconvertd/7-251 [007] 358613.942892: funcgraph_entry: 0.139 us | pick_next_task_rt();
xfsconvertd/7-251 [007] 358613.942893: funcgraph_entry: 0.151 us | pick_next_task_fair();
xfsconvertd/7-251 [007] 358613.942893: funcgraph_entry: 0.249 us | pick_next_task_idle();
xfsconvertd/7-251 [007] 358613.942893: funcgraph_entry: 0.142 us | perf_event_task_sched_out();
xfsconvertd/7-251 [007] 358613.942894: funcgraph_entry: | ftrace_raw_event_sched_switch() {
xfsconvertd/7-251 [007] 358613.942894: sched_switch: task xfsconvertd/7:251 [120] (D) ==> swapper:0 [120]
Next the flush-8:0 thread tries to aquire the xfs_ilock() and blocks:
flush-8:0-505 [011] 358613.964686: funcgraph_entry: | __writepage() {
flush-8:0-505 [011] 358613.964687: funcgraph_entry: | xfs_vm_writepage() {
flush-8:0-505 [011] 358613.964687: funcgraph_entry: 0.467 us | xfs_count_page_state();
flush-8:0-505 [011] 358613.964688: funcgraph_entry: | xfs_page_state_convert() {
flush-8:0-505 [011] 358613.964688: funcgraph_entry: | xfs_probe_cluster() {
flush-8:0-505 [011] 358613.964694: funcgraph_exit: 6.002 us | }
flush-8:0-505 [011] 358613.964694: funcgraph_entry: | xfs_map_blocks() {
flush-8:0-505 [011] 358613.964695: funcgraph_entry: | xfs_iomap() {
flush-8:0-505 [011] 358613.964695: funcgraph_entry: | xfs_ilock_map_shared() {
flush-8:0-505 [011] 358613.964695: funcgraph_entry: | xfs_ilock() {
flush-8:0-505 [011] 358613.964695: funcgraph_entry: | down_read() {
flush-8:0-505 [011] 358613.964695: funcgraph_entry: 0.139 us | _cond_resched();
flush-8:0-505 [011] 358613.964696: funcgraph_entry: 0.136 us | _spin_lock_irq();
flush-8:0-505 [011] 358613.964696: funcgraph_entry: | schedule() {
flush-8:0-505 [011] 358613.964696: funcgraph_entry: 0.136 us | rcu_sched_qs();
flush-8:0-505 [011] 358613.964697: funcgraph_entry: 0.202 us | _spin_lock_irq();
flush-8:0-505 [011] 358613.964697: funcgraph_entry: | deactivate_task() {
flush-8:0-505 [011] 358613.964700: funcgraph_exit: 2.713 us | }
flush-8:0-505 [011] 358613.964700: funcgraph_entry: 0.140 us | update_shares_locked();
flush-8:0-505 [011] 358613.964700: funcgraph_entry: | find_busiest_group() {
flush-8:0-505 [011] 358613.964702: funcgraph_exit: 1.571 us | }
flush-8:0-505 [011] 358613.964702: funcgraph_entry: 0.136 us | msecs_to_jiffies();
flush-8:0-505 [011] 358613.964702: funcgraph_entry: 0.138 us | update_shares_locked();
flush-8:0-505 [011] 358613.964703: funcgraph_entry: | find_busiest_group() {
flush-8:0-505 [011] 358613.964704: funcgraph_exit: 0.948 us | }
flush-8:0-505 [011] 358613.964704: funcgraph_entry: 0.347 us | find_busiest_queue();
flush-8:0-505 [011] 358613.964704: funcgraph_entry: 0.139 us | msecs_to_jiffies();
flush-8:0-505 [011] 358613.964705: funcgraph_entry: 0.152 us | put_prev_task_fair();
flush-8:0-505 [011] 358613.964705: funcgraph_entry: 0.163 us | pick_next_task_fair();
flush-8:0-505 [011] 358613.964705: funcgraph_entry: 0.139 us | pick_next_task_rt();
flush-8:0-505 [011] 358613.964705: funcgraph_entry: 0.142 us | pick_next_task_fair();
flush-8:0-505 [011] 358613.964706: funcgraph_entry: 0.144 us | pick_next_task_idle();
flush-8:0-505 [011] 358613.964706: funcgraph_entry: 0.159 us | perf_event_task_sched_out();
flush-8:0-505 [011] 358613.964707: funcgraph_entry: | ftrace_raw_event_sched_switch() {
flush-8:0-505 [011] 358613.964707: sched_switch: task flush-8:0:505 [120] (D) ==> swapper:0 [120]
Then my process writes to the file generates a page fault which tries
to acquire the xfs_ilock() and blocks:
file_writer-30495 [013] 358613.968909: print: 00000000 delay start
file_writer-30495 [013] 358613.968913: funcgraph_entry: 0.151 us | down_read_trylock();
file_writer-30495 [013] 358613.968913: funcgraph_entry: 0.152 us | _cond_resched();
file_writer-30495 [013] 358613.968913: funcgraph_entry: 0.520 us | find_vma();
file_writer-30495 [013] 358613.968914: funcgraph_entry: | handle_mm_fault() {
file_writer-30495 [013] 358613.968914: funcgraph_entry: | __do_fault() {
file_writer-30495 [013] 358613.968914: funcgraph_entry: | filemap_fault() {
file_writer-30495 [013] 358613.968915: funcgraph_exit: 1.171 us | }
file_writer-30495 [013] 358613.968916: funcgraph_entry: | unlock_page() {
file_writer-30495 [013] 358613.968916: funcgraph_exit: 0.814 us | }
file_writer-30495 [013] 358613.968917: funcgraph_entry: | xfs_vm_page_mkwrite() {
file_writer-30495 [013] 358613.968917: funcgraph_entry: | block_page_mkwrite() {
file_writer-30495 [013] 358613.968917: funcgraph_entry: 0.137 us | _cond_resched();
file_writer-30495 [013] 358613.968917: funcgraph_entry: | block_prepare_write() {
file_writer-30495 [013] 358613.968917: funcgraph_entry: | __block_prepare_write() {
file_writer-30495 [013] 358613.968918: funcgraph_entry: | create_empty_buffers() {
file_writer-30495 [013] 358613.968920: funcgraph_exit: 2.760 us | }
file_writer-30495 [013] 358613.968921: funcgraph_entry: | xfs_get_blocks() {
file_writer-30495 [013] 358613.968921: funcgraph_entry: | __xfs_get_blocks() {
file_writer-30495 [013] 358613.968921: funcgraph_entry: | xfs_iomap() {
file_writer-30495 [013] 358613.968921: funcgraph_entry: | xfs_ilock() {
file_writer-30495 [013] 358613.968921: funcgraph_entry: | down_write() {
file_writer-30495 [013] 358613.968921: funcgraph_entry: 0.139 us | _cond_resched();
file_writer-30495 [013] 358613.968922: funcgraph_entry: 0.155 us | _spin_lock_irq();
file_writer-30495 [013] 358613.968922: funcgraph_entry: | schedule() {
file_writer-30495 [013] 358613.968922: funcgraph_entry: 0.141 us | rcu_sched_qs();
file_writer-30495 [013] 358613.968923: funcgraph_entry: 0.213 us | _spin_lock_irq();
file_writer-30495 [013] 358613.968923: funcgraph_entry: | deactivate_task() {
file_writer-30495 [013] 358613.968929: funcgraph_exit: 6.462 us | }
file_writer-30495 [013] 358613.968930: funcgraph_entry: | pre_schedule_rt() {
file_writer-30495 [013] 358613.968930: funcgraph_exit: 0.445 us | }
file_writer-30495 [013] 358613.968930: funcgraph_entry: 0.139 us | update_shares_locked();
file_writer-30495 [013] 358613.968931: funcgraph_entry: | find_busiest_group() {
file_writer-30495 [013] 358613.968932: funcgraph_exit: 1.358 us | }
file_writer-30495 [013] 358613.968932: funcgraph_entry: 0.140 us | msecs_to_jiffies();
file_writer-30495 [013] 358613.968932: funcgraph_entry: 0.140 us | update_shares_locked();
file_writer-30495 [013] 358613.968933: funcgraph_entry: 0.491 us | find_busiest_group();
file_writer-30495 [013] 358613.968933: funcgraph_entry: 0.137 us | msecs_to_jiffies();
file_writer-30495 [013] 358613.968934: funcgraph_entry: 0.137 us | update_shares_locked();
file_writer-30495 [013] 358613.968934: funcgraph_entry: 0.677 us | find_busiest_group();
file_writer-30495 [013] 358613.968935: funcgraph_entry: 0.528 us | find_busiest_queue();
file_writer-30495 [013] 358613.968936: funcgraph_entry: 0.137 us | msecs_to_jiffies();
file_writer-30495 [013] 358613.968936: funcgraph_entry: | put_prev_task_rt() {
file_writer-30495 [013] 358613.968937: funcgraph_exit: 1.309 us | }
file_writer-30495 [013] 358613.968937: funcgraph_entry: 0.168 us | pick_next_task_fair();
file_writer-30495 [013] 358613.968938: funcgraph_entry: 0.137 us | pick_next_task_rt();
file_writer-30495 [013] 358613.968938: funcgraph_entry: 0.226 us | pick_next_task_fair();
file_writer-30495 [013] 358613.968938: funcgraph_entry: 0.208 us | pick_next_task_idle();
file_writer-30495 [013] 358613.968939: funcgraph_entry: 0.237 us | perf_event_task_sched_out();
file_writer-30495 [013] 358613.968939: funcgraph_entry: | ftrace_raw_event_sched_switch() {
file_writer-30495 [013] 358613.968940: sched_switch: task file_writer:30495 [79] (D) ==> swapper:0 [120]
Next I see xfslogd/7 release the xfs_buf_lock which wakes up
xfsconvertd/7:
file_reader-31161 [007] 358614.285351: sched_switch: task file_reader:31161 [89] (S) ==> xfslogd/7:219 [120]
xfslogd/7-219 [007] 358614.285352: funcgraph_entry: | finish_task_switch() {
xfslogd/7-219 [007] 358614.285353: funcgraph_exit: 1.327 us | }
xfslogd/7-219 [007] 358614.285353: funcgraph_exit: ! 385801.165 us | }
xfslogd/7-219 [007] 358614.285354: funcgraph_entry: 0.403 us | finish_wait();
xfslogd/7-219 [007] 358614.285355: funcgraph_entry: 0.518 us | kthread_should_stop();
xfslogd/7-219 [007] 358614.285355: funcgraph_entry: 0.336 us | _spin_lock_irq();
xfslogd/7-219 [007] 358614.285356: funcgraph_entry: 0.362 us | _spin_lock_irqsave();
xfslogd/7-219 [007] 358614.285357: funcgraph_entry: 0.331 us | _spin_unlock_irqrestore();
xfslogd/7-219 [007] 358614.285358: funcgraph_entry: | xfs_buf_iodone_work() {
xfslogd/7-219 [007] 358614.285358: funcgraph_entry: | xfs_buf_iodone_callbacks() {
xfslogd/7-219 [007] 358614.285359: funcgraph_entry: | xfs_buf_do_callbacks() {
xfslogd/7-219 [007] 358614.285367: funcgraph_exit: 7.849 us | }
xfslogd/7-219 [007] 358614.285367: funcgraph_entry: | xfs_buf_ioend() {
xfslogd/7-219 [007] 358614.285367: funcgraph_entry: | xfs_buf_iodone_work() {
xfslogd/7-219 [007] 358614.285367: funcgraph_entry: | xfs_buf_unlock() {
xfslogd/7-219 [007] 358614.285368: funcgraph_entry: | up() {
xfslogd/7-219 [007] 358614.285368: funcgraph_entry: 0.229 us | _spin_lock_irqsave();
xfslogd/7-219 [007] 358614.285369: funcgraph_entry: | __up() {
xfslogd/7-219 [007] 358614.285369: funcgraph_entry: | wake_up_process() {
xfslogd/7-219 [007] 358614.285370: funcgraph_entry: | try_to_wake_up() {
xfslogd/7-219 [007] 358614.285370: funcgraph_entry: | task_rq_lock() {
xfslogd/7-219 [007] 358614.285371: funcgraph_exit: 1.087 us | }
xfslogd/7-219 [007] 358614.285372: funcgraph_entry: 0.308 us | _spin_unlock_irqrestore();
xfslogd/7-219 [007] 358614.285372: funcgraph_entry: | select_task_rq_fair() {
xfslogd/7-219 [007] 358614.285375: funcgraph_exit: 2.519 us | }
xfslogd/7-219 [007] 358614.285375: funcgraph_entry: | task_rq_lock() {
xfslogd/7-219 [007] 358614.285376: funcgraph_exit: 0.697 us | }
xfslogd/7-219 [007] 358614.285376: funcgraph_entry: | activate_task() {
xfslogd/7-219 [007] 358614.285380: funcgraph_exit: 4.485 us | }
xfslogd/7-219 [007] 358614.285381: funcgraph_entry: | ftrace_raw_event_sched_wakeup() {
xfslogd/7-219 [007] 358614.285381: sched_wakeup: task xfsconvertd/7:251 [120] success=1 [007]
xfsconvertd/7 releases the xfs_ilock() waking up flush-8:0:
xfsconvertd/7-251 [007] 358614.285468: funcgraph_entry: 0.171 us | xfs_bmap_finish();
xfsconvertd/7-251 [007] 358614.285468: funcgraph_entry: | _xfs_trans_commit() {
xfsconvertd/7-251 [007] 358614.285551: funcgraph_exit: + 82.436 us | }
xfsconvertd/7-251 [007] 358614.285551: funcgraph_entry: | xfs_iunlock() {
xfsconvertd/7-251 [007] 358614.285551: funcgraph_entry: | up_write() {
xfsconvertd/7-251 [007] 358614.285551: funcgraph_entry: 0.137 us | _spin_lock_irqsave();
xfsconvertd/7-251 [007] 358614.285552: funcgraph_entry: | wake_up_process() {
xfsconvertd/7-251 [007] 358614.285552: funcgraph_entry: | try_to_wake_up() {
xfsconvertd/7-251 [007] 358614.285552: funcgraph_entry: | task_rq_lock() {
xfsconvertd/7-251 [007] 358614.285553: funcgraph_exit: 0.690 us | }
xfsconvertd/7-251 [007] 358614.285553: funcgraph_entry: 0.141 us | _spin_unlock_irqrestore();
xfsconvertd/7-251 [007] 358614.285553: funcgraph_entry: | select_task_rq_fair() {
xfsconvertd/7-251 [007] 358614.285555: funcgraph_exit: 1.358 us | }
xfsconvertd/7-251 [007] 358614.285555: funcgraph_entry: | task_rq_lock() {
xfsconvertd/7-251 [007] 358614.285555: funcgraph_exit: 0.418 us | }
xfsconvertd/7-251 [007] 358614.285556: funcgraph_entry: | activate_task() {
xfsconvertd/7-251 [007] 358614.285558: funcgraph_exit: 2.524 us | }
xfsconvertd/7-251 [007] 358614.285558: funcgraph_entry: | ftrace_raw_event_sched_wakeup() {
xfsconvertd/7-251 [007] 358614.285558: sched_wakeup: task flush-8:0:505 [120] success=1 [011]
flush-8:0 releases the xfs_ilock() waking up my process:
flush-8:0-505 [011] 358613.584354: funcgraph_entry: | clear_page_dirty_for_io() {
flush-8:0-505 [011] 358613.584361: funcgraph_exit: 7.365 us | }
flush-8:0-505 [011] 358613.584362: funcgraph_entry: | __writepage() {
flush-8:0-505 [011] 358613.584362: funcgraph_entry: | xfs_vm_writepage() {
flush-8:0-505 [011] 358613.584362: funcgraph_entry: 0.144 us | xfs_count_page_state();
flush-8:0-505 [011] 358613.584362: funcgraph_entry: | xfs_page_state_convert() {
flush-8:0-505 [011] 358613.584362: funcgraph_entry: | xfs_probe_cluster() {
flush-8:0-505 [011] 358613.584367: funcgraph_exit: 4.710 us | }
flush-8:0-505 [011] 358613.584367: funcgraph_entry: | xfs_map_blocks() {
flush-8:0-505 [011] 358613.584367: funcgraph_entry: | xfs_iomap() {
flush-8:0-505 [011] 358613.584367: funcgraph_entry: | xfs_ilock_map_shared() {
flush-8:0-505 [011] 358613.584368: funcgraph_exit: 0.973 us | }
flush-8:0-505 [011] 358613.584369: funcgraph_entry: | xfs_bmapi() {
flush-8:0-505 [011] 358613.584379: funcgraph_exit: + 10.524 us | }
flush-8:0-505 [011] 358613.584379: funcgraph_entry: 0.149 us | xfs_imap_to_bmap();
flush-8:0-505 [011] 358613.584380: funcgraph_entry: | xfs_iunlock() {
flush-8:0-505 [011] 358613.584380: funcgraph_entry: | up_read() {
flush-8:0-505 [011] 358613.584380: funcgraph_entry: 0.138 us | _spin_lock_irqsave();
flush-8:0-505 [011] 358613.584380: funcgraph_entry: | wake_up_process() {
flush-8:0-505 [011] 358613.584380: funcgraph_entry: | try_to_wake_up() {
flush-8:0-505 [011] 358613.584381: funcgraph_entry: | task_rq_lock() {
flush-8:0-505 [011] 358613.584394: funcgraph_exit: + 13.023 us | }
flush-8:0-505 [011] 358613.584394: funcgraph_entry: 0.143 us | _spin_unlock_irqrestore();
flush-8:0-505 [011] 358613.584394: funcgraph_entry: 0.157 us | select_task_rq_rt();
flush-8:0-505 [011] 358613.584394: funcgraph_entry: | task_rq_lock() {
flush-8:0-505 [011] 358613.584395: funcgraph_exit: 0.412 us | }
flush-8:0-505 [011] 358613.584395: funcgraph_entry: | activate_task() {
flush-8:0-505 [011] 358613.584400: funcgraph_exit: 4.642 us | }
flush-8:0-505 [011] 358613.584400: funcgraph_entry: | ftrace_raw_event_sched_wakeup() {
flush-8:0-505 [011] 358613.584401: sched_wakeup: task file_writer:30495 [79] success=1 [015]
And finally my process finishes the write ending the delay:
<idle>-0 [013] 358614.285593: sched_switch: task swapper:0 [120] (R) ==> file_writer:30495 [79]
file_writer-30495 [013] 358614.285594: funcgraph_entry: 0.575 us | __math_state_restore();
file_writer-30495 [013] 358614.285595: funcgraph_entry: | finish_task_switch() {
file_writer-30495 [013] 358614.285596: funcgraph_exit: 0.698 us | }
file_writer-30495 [013] 358614.285596: funcgraph_exit: ! 316673.836 us | }
file_writer-30495 [013] 358614.285596: funcgraph_exit: ! 316675.180 us | }
file_writer-30495 [013] 358614.285597: funcgraph_exit: ! 316675.750 us | }
file_writer-30495 [013] 358614.285597: funcgraph_entry: | xfs_bmapi() {
file_writer-30495 [013] 358614.285607: funcgraph_exit: + 10.271 us | }
file_writer-30495 [013] 358614.285608: funcgraph_entry: 0.159 us | xfs_imap_to_bmap();
file_writer-30495 [013] 358614.285608: funcgraph_entry: | xfs_iunlock() {
file_writer-30495 [013] 358614.285609: funcgraph_exit: 1.155 us | }
file_writer-30495 [013] 358614.285609: funcgraph_exit: ! 316688.329 us | }
file_writer-30495 [013] 358614.285610: funcgraph_entry: 0.283 us | xfs_map_buffer();
file_writer-30495 [013] 358614.285610: funcgraph_exit: ! 316689.328 us | }
file_writer-30495 [013] 358614.285610: funcgraph_exit: ! 316689.619 us | }
file_writer-30495 [013] 358614.285611: funcgraph_entry: | unmap_underlying_metadata() {
file_writer-30495 [013] 358614.285612: funcgraph_exit: 1.429 us | }
file_writer-30495 [013] 358614.285612: funcgraph_entry: | mark_buffer_dirty() {
file_writer-30495 [013] 358614.285616: funcgraph_exit: 3.770 us | }
file_writer-30495 [013] 358614.285617: funcgraph_exit: ! 316699.234 us | }
file_writer-30495 [013] 358614.285617: funcgraph_exit: ! 316699.649 us | }
file_writer-30495 [013] 358614.285617: funcgraph_entry: | block_commit_write() {
file_writer-30495 [013] 358614.285618: funcgraph_exit: 0.822 us | }
file_writer-30495 [013] 358614.285618: funcgraph_exit: ! 316701.509 us | }
file_writer-30495 [013] 358614.285619: funcgraph_exit: ! 316701.950 us | }
file_writer-30495 [013] 358614.285619: funcgraph_entry: 0.228 us | _spin_lock();
file_writer-30495 [013] 358614.285620: funcgraph_entry: | page_add_file_rmap() {
file_writer-30495 [013] 358614.285621: funcgraph_exit: 1.957 us | }
file_writer-30495 [013] 358614.285622: funcgraph_entry: | set_page_dirty() {
file_writer-30495 [013] 358614.285623: funcgraph_exit: 0.919 us | }
file_writer-30495 [013] 358614.285623: funcgraph_entry: | unlock_page() {
file_writer-30495 [013] 358614.285624: funcgraph_exit: 0.858 us | }
file_writer-30495 [013] 358614.285624: funcgraph_entry: 0.151 us | put_page();
file_writer-30495 [013] 358614.285624: funcgraph_entry: 0.197 us | balance_dirty_pages_ratelimited_nr();
file_writer-30495 [013] 358614.285625: funcgraph_entry: | file_update_time() {
file_writer-30495 [013] 358614.285628: funcgraph_exit: 3.053 us | }
file_writer-30495 [013] 358614.285628: funcgraph_exit: ! 316713.745 us | }
file_writer-30495 [013] 358614.285628: funcgraph_exit: ! 316714.374 us | }
file_writer-30495 [013] 358614.285628: funcgraph_entry: 0.174 us | up_read();
file_writer-30495 [013] 358614.285635: print: 00000000 delay stop
Any suggestions on how to improve things are welcome.
Thanks,
Shawn
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Latencies writing to memory mapped files
2010-09-15 15:26 Latencies writing to memory mapped files Shawn Bohrer
@ 2010-09-16 0:18 ` Dave Chinner
2010-09-17 15:45 ` Shawn Bohrer
0 siblings, 1 reply; 10+ messages in thread
From: Dave Chinner @ 2010-09-16 0:18 UTC (permalink / raw)
To: Shawn Bohrer; +Cc: xfs
On Wed, Sep 15, 2010 at 10:26:33AM -0500, Shawn Bohrer wrote:
> Hello,
>
> A little while ago I asked about ways to solve the occasional spikes in
> latency that I see when writing to a shared memory mapped file.
>
> http://oss.sgi.com/pipermail/xfs/2010-July/046311.html
>
> With Dave's suggestions I enabled lazy-count=1 which did help a little:
>
> # xfs_info /home/
> meta-data=/dev/sda5 isize=256 agcount=32, agsize=8472969 blks
> = sectsz=512 attr=1
> data = bsize=4096 blocks=271135008, imaxpct=25
> = sunit=0 swidth=0 blks
> naming =version 2 bsize=4096 ascii-ci=0
> log =internal bsize=4096 blocks=32768, version=1
> = sectsz=512 sunit=0 blks, lazy-count=1
> realtime =none extsz=4096 blocks=0, rtextents=0
>
> I'm also mounting the partition with "noatime,nobarrier,logbufs=8".
You really should add logbsize=262144 there - it won't prevent the
latencies, but with less log writes the incidence should decrease
significantly.
> The other change I made which helped the most was to use fallocate()
> to grow the file instead of lseek() and a write().
Ok, so now you are doing unwritten extent conversion at IO
completion, which is where this new latency issue has come from.
> The latencies look
> acceptable at lower data rates but once I reach 2-3 MB/s I start
> seeing spikes when writeback occurs. Perhaps my expectations are
> unreasonable, but I would like to keep my latencies under 0.01s and
> the lower the better. I don't have hard real-time requirements, but
> latencies are important. These systems also only need to log data for
> about 7-8 hours, so while I don't exactly know how much data I will
> get I can make some guesses and preallocate the files or perform other
> tricks if it would help.
I think doing that is a good idea from a layout persepctive, but it
won't help this particular latency cause because it is a result of
using prealocation.
> Below are some snippets of a trace of a 0.3 second delay I captured
> with ftrace on 2.6.32.21. I haven't done enough sampling to know if
> all of the delays happen for the same reason, or if there are multiple
> code paths that lead to a large delay.
>
> First I see xfsconvertd/7 acquire the xfs_ilock() then try to acquire
> the xfs_buf_lock() and block:
>
>
> xfsconvertd/7-251 [007] 358613.942101: funcgraph_entry: | xfs_end_bio_unwritten() {
> xfsconvertd/7-251 [007] 358613.942101: funcgraph_entry: | xfs_iomap_write_unwritten() {
> xfsconvertd/7-251 [007] 358613.942102: funcgraph_entry: | _xfs_trans_alloc() {
> xfsconvertd/7-251 [007] 358613.942104: funcgraph_exit: 2.582 us | }
> xfsconvertd/7-251 [007] 358613.942104: funcgraph_entry: | xfs_trans_reserve() {
> xfsconvertd/7-251 [007] 358613.942546: funcgraph_exit: ! 441.449 us | }
> xfsconvertd/7-251 [007] 358613.942546: funcgraph_entry: | xfs_ilock() {
> xfsconvertd/7-251 [007] 358613.942547: funcgraph_exit: 0.895 us | }
> xfsconvertd/7-251 [007] 358613.942547: funcgraph_entry: | xfs_trans_ijoin() {
> xfsconvertd/7-251 [007] 358613.942548: funcgraph_exit: 0.667 us | }
> xfsconvertd/7-251 [007] 358613.942548: funcgraph_entry: 0.138 us | xfs_trans_ihold();
> xfsconvertd/7-251 [007] 358613.942549: funcgraph_entry: | xfs_bmapi() {
> xfsconvertd/7-251 [007] 358613.942549: funcgraph_entry: | xfs_bmap_search_extents() {
> xfsconvertd/7-251 [007] 358613.942564: funcgraph_exit: + 14.764 us | }
> xfsconvertd/7-251 [007] 358613.942565: funcgraph_entry: | xfs_bmbt_init_cursor() {
> xfsconvertd/7-251 [007] 358613.942567: funcgraph_exit: 2.740 us | }
> xfsconvertd/7-251 [007] 358613.942568: funcgraph_entry: | xfs_bmap_add_extent() {
> xfsconvertd/7-251 [007] 358613.942568: funcgraph_entry: | xfs_iext_get_ext() {
> xfsconvertd/7-251 [007] 358613.942569: funcgraph_exit: 0.702 us | }
> xfsconvertd/7-251 [007] 358613.942569: funcgraph_entry: 0.215 us | xfs_bmbt_get_all();
> xfsconvertd/7-251 [007] 358613.942569: funcgraph_entry: | xfs_bmap_add_extent_unwritten_real() {
> xfsconvertd/7-251 [007] 358613.942570: funcgraph_entry: | xfs_iext_get_ext() {
> xfsconvertd/7-251 [007] 358613.942570: funcgraph_exit: 0.677 us | }
> xfsconvertd/7-251 [007] 358613.942571: funcgraph_entry: 0.218 us | xfs_bmbt_get_all();
> xfsconvertd/7-251 [007] 358613.942571: funcgraph_entry: | xfs_iext_get_ext() {
> xfsconvertd/7-251 [007] 358613.942572: funcgraph_exit: 0.844 us | }
> xfsconvertd/7-251 [007] 358613.942572: funcgraph_entry: 0.216 us | xfs_bmbt_get_all();
> xfsconvertd/7-251 [007] 358613.942573: funcgraph_entry: | xfs_iext_get_ext() {
> xfsconvertd/7-251 [007] 358613.942573: funcgraph_exit: 0.708 us | }
> xfsconvertd/7-251 [007] 358613.942574: funcgraph_entry: 0.175 us | xfs_bmbt_get_all();
> xfsconvertd/7-251 [007] 358613.942574: funcgraph_entry: | xfs_iext_get_ext() {
> xfsconvertd/7-251 [007] 358613.942575: funcgraph_exit: 1.079 us | }
> xfsconvertd/7-251 [007] 358613.942575: funcgraph_entry: 0.220 us | xfs_bmbt_set_blockcount();
> xfsconvertd/7-251 [007] 358613.942576: funcgraph_entry: 0.303 us | xfs_bmbt_set_startoff();
> xfsconvertd/7-251 [007] 358613.942577: funcgraph_entry: 0.216 us | xfs_bmbt_set_startblock();
> xfsconvertd/7-251 [007] 358613.942577: funcgraph_entry: 0.423 us | xfs_bmbt_set_blockcount();
> xfsconvertd/7-251 [007] 358613.942578: funcgraph_entry: | xfs_bmbt_lookup_eq() {
> xfsconvertd/7-251 [007] 358613.942578: funcgraph_entry: | xfs_btree_lookup() {
> xfsconvertd/7-251 [007] 358613.942579: funcgraph_entry: 0.212 us | xfs_bmbt_init_ptr_from_cur();
> xfsconvertd/7-251 [007] 358613.942579: funcgraph_entry: | xfs_btree_lookup_get_block() {
> xfsconvertd/7-251 [007] 358613.942721: funcgraph_exit: ! 141.594 us | }
> xfsconvertd/7-251 [007] 358613.942721: funcgraph_entry: | xfs_lookup_get_search_key() {
> xfsconvertd/7-251 [007] 358613.942723: funcgraph_exit: 1.205 us | }
> xfsconvertd/7-251 [007] 358613.942723: funcgraph_entry: 0.208 us | xfs_bmbt_key_diff();
> xfsconvertd/7-251 [007] 358613.942723: funcgraph_entry: | xfs_btree_ptr_addr() {
> xfsconvertd/7-251 [007] 358613.942725: funcgraph_exit: 1.686 us | }
> xfsconvertd/7-251 [007] 358613.942725: funcgraph_entry: | xfs_btree_lookup_get_block() {
> xfsconvertd/7-251 [007] 358613.942726: funcgraph_entry: | xfs_btree_read_buf_block() {
> xfsconvertd/7-251 [007] 358613.942726: funcgraph_entry: 0.252 us | xfs_btree_ptr_to_daddr();
> xfsconvertd/7-251 [007] 358613.942726: funcgraph_entry: | xfs_trans_read_buf() {
> xfsconvertd/7-251 [007] 358613.942727: funcgraph_entry: 0.330 us | xfs_trans_buf_item_match();
> xfsconvertd/7-251 [007] 358613.942728: funcgraph_entry: | xfs_buf_read_flags() {
> xfsconvertd/7-251 [007] 358613.942728: funcgraph_entry: | xfs_buf_get_flags() {
> xfsconvertd/7-251 [007] 358613.942728: funcgraph_entry: | kmem_zone_alloc() {
> xfsconvertd/7-251 [007] 358613.942885: funcgraph_exit: ! 156.328 us | }
> xfsconvertd/7-251 [007] 358613.942885: funcgraph_entry: | _xfs_buf_find() {
> xfsconvertd/7-251 [007] 358613.942885: funcgraph_entry: 0.150 us | _spin_lock();
> xfsconvertd/7-251 [007] 358613.942885: funcgraph_entry: | down_trylock() {
> xfsconvertd/7-251 [007] 358613.942886: funcgraph_exit: 0.818 us | }
> xfsconvertd/7-251 [007] 358613.942886: funcgraph_entry: | xfs_buf_lock() {
> xfsconvertd/7-251 [007] 358613.942886: funcgraph_entry: | down() {
....
Ok, so we need access to a buffer to complete the unwritten extent
conversion.
> Next the flush-8:0 thread tries to aquire the xfs_ilock() and blocks:
>
>
> flush-8:0-505 [011] 358613.964686: funcgraph_entry: | __writepage() {
> flush-8:0-505 [011] 358613.964687: funcgraph_entry: | xfs_vm_writepage() {
> flush-8:0-505 [011] 358613.964687: funcgraph_entry: 0.467 us | xfs_count_page_state();
> flush-8:0-505 [011] 358613.964688: funcgraph_entry: | xfs_page_state_convert() {
> flush-8:0-505 [011] 358613.964688: funcgraph_entry: | xfs_probe_cluster() {
> flush-8:0-505 [011] 358613.964694: funcgraph_exit: 6.002 us | }
> flush-8:0-505 [011] 358613.964694: funcgraph_entry: | xfs_map_blocks() {
> flush-8:0-505 [011] 358613.964695: funcgraph_entry: | xfs_iomap() {
> flush-8:0-505 [011] 358613.964695: funcgraph_entry: | xfs_ilock_map_shared() {
> flush-8:0-505 [011] 358613.964695: funcgraph_entry: | xfs_ilock() {
> flush-8:0-505 [011] 358613.964695: funcgraph_entry: | down_read() {
....
Yes, that's normal.
> Then my process writes to the file generates a page fault which tries
> to acquire the xfs_ilock() and blocks:
>
>
> file_writer-30495 [013] 358613.968909: print: 00000000 delay start
> file_writer-30495 [013] 358613.968913: funcgraph_entry: 0.151 us | down_read_trylock();
> file_writer-30495 [013] 358613.968913: funcgraph_entry: 0.152 us | _cond_resched();
> file_writer-30495 [013] 358613.968913: funcgraph_entry: 0.520 us | find_vma();
> file_writer-30495 [013] 358613.968914: funcgraph_entry: | handle_mm_fault() {
> file_writer-30495 [013] 358613.968914: funcgraph_entry: | __do_fault() {
> file_writer-30495 [013] 358613.968914: funcgraph_entry: | filemap_fault() {
> file_writer-30495 [013] 358613.968915: funcgraph_exit: 1.171 us | }
> file_writer-30495 [013] 358613.968916: funcgraph_entry: | unlock_page() {
> file_writer-30495 [013] 358613.968916: funcgraph_exit: 0.814 us | }
> file_writer-30495 [013] 358613.968917: funcgraph_entry: | xfs_vm_page_mkwrite() {
> file_writer-30495 [013] 358613.968917: funcgraph_entry: | block_page_mkwrite() {
> file_writer-30495 [013] 358613.968917: funcgraph_entry: 0.137 us | _cond_resched();
> file_writer-30495 [013] 358613.968917: funcgraph_entry: | block_prepare_write() {
> file_writer-30495 [013] 358613.968917: funcgraph_entry: | __block_prepare_write() {
> file_writer-30495 [013] 358613.968918: funcgraph_entry: | create_empty_buffers() {
> file_writer-30495 [013] 358613.968920: funcgraph_exit: 2.760 us | }
> file_writer-30495 [013] 358613.968921: funcgraph_entry: | xfs_get_blocks() {
> file_writer-30495 [013] 358613.968921: funcgraph_entry: | __xfs_get_blocks() {
> file_writer-30495 [013] 358613.968921: funcgraph_entry: | xfs_iomap() {
> file_writer-30495 [013] 358613.968921: funcgraph_entry: | xfs_ilock() {
> file_writer-30495 [013] 358613.968921: funcgraph_entry: | down_write() {
.....
Yes, I'd expect that to happen, too.
> Next I see xfslogd/7 release the xfs_buf_lock which wakes up
> xfsconvertd/7:
>
>
> file_reader-31161 [007] 358614.285351: sched_switch: task file_reader:31161 [89] (S) ==> xfslogd/7:219 [120]
> xfslogd/7-219 [007] 358614.285352: funcgraph_entry: | finish_task_switch() {
> xfslogd/7-219 [007] 358614.285353: funcgraph_exit: 1.327 us | }
> xfslogd/7-219 [007] 358614.285353: funcgraph_exit: ! 385801.165 us | }
> xfslogd/7-219 [007] 358614.285354: funcgraph_entry: 0.403 us | finish_wait();
> xfslogd/7-219 [007] 358614.285355: funcgraph_entry: 0.518 us | kthread_should_stop();
> xfslogd/7-219 [007] 358614.285355: funcgraph_entry: 0.336 us | _spin_lock_irq();
> xfslogd/7-219 [007] 358614.285356: funcgraph_entry: 0.362 us | _spin_lock_irqsave();
> xfslogd/7-219 [007] 358614.285357: funcgraph_entry: 0.331 us | _spin_unlock_irqrestore();
> xfslogd/7-219 [007] 358614.285358: funcgraph_entry: | xfs_buf_iodone_work() {
> xfslogd/7-219 [007] 358614.285358: funcgraph_entry: | xfs_buf_iodone_callbacks() {
> xfslogd/7-219 [007] 358614.285359: funcgraph_entry: | xfs_buf_do_callbacks() {
> xfslogd/7-219 [007] 358614.285367: funcgraph_exit: 7.849 us | }
> xfslogd/7-219 [007] 358614.285367: funcgraph_entry: | xfs_buf_ioend() {
> xfslogd/7-219 [007] 358614.285367: funcgraph_entry: | xfs_buf_iodone_work() {
> xfslogd/7-219 [007] 358614.285367: funcgraph_entry: | xfs_buf_unlock() {
> xfslogd/7-219 [007] 358614.285368: funcgraph_entry: | up() {
.....
> xfslogd/7-219 [007] 358614.285381: sched_wakeup: task xfsconvertd/7:251 [120] success=1 [007]
Ok, the transaction was blocked on a buffer that had it's IO
completion queued to the xfslogd. But this happened some
320ms after the above page fault occurred, and 340ms after the
xfsconvertd got stuck waiting for it. In other words, it looks
like it it took at least 340ms for the buffer IO to complete after
it was issued.
> xfsconvertd/7 releases the xfs_ilock() waking up flush-8:0:
....
> flush-8:0 releases the xfs_ilock() waking up my process:
....
> And finally my process finishes the write ending the delay:
>
>
> <idle>-0 [013] 358614.285593: sched_switch: task swapper:0 [120] (R) ==> file_writer:30495 [79]
> file_writer-30495 [013] 358614.285594: funcgraph_entry: 0.575 us | __math_state_restore();
> file_writer-30495 [013] 358614.285595: funcgraph_entry: | finish_task_switch() {
> file_writer-30495 [013] 358614.285596: funcgraph_exit: 0.698 us | }
> file_writer-30495 [013] 358614.285596: funcgraph_exit: ! 316673.836 us | }
> file_writer-30495 [013] 358614.285596: funcgraph_exit: ! 316675.180 us | }
> file_writer-30495 [013] 358614.285597: funcgraph_exit: ! 316675.750 us | }
> file_writer-30495 [013] 358614.285597: funcgraph_entry: | xfs_bmapi() {
And so the delay you app saw was ~320ms. Basically, it blocked
waiting for an IO to complete. I don't think there is anything we ca
really do from a filesystem point of view to avoid that - we cannot
avoid metadata buffer writeback indefinitely.
Fundamentally you are seeing the reason why filesystems cannot
easily guarantee maximum bound latencies - if we have to wait for IO
for anything, then the latency is effectively uncontrollable. XFS
does as much as possible to avoid such latencies for data IO, but
even then it's not always possible. Even using the RT device in XFS
won't avoid these latencies - it's caused by latencies in metadata
modification, not data....
Effectively, the only way you can minimise this is to design your
storage layout for minimal IO latency under writes (e.g. use mirrors
instead of RAID5, etc) or use faster drives. Also using the deadline
scheduler (if you aren't already) might help....
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Latencies writing to memory mapped files
2010-09-16 0:18 ` Dave Chinner
@ 2010-09-17 15:45 ` Shawn Bohrer
2010-09-20 0:05 ` Dave Chinner
0 siblings, 1 reply; 10+ messages in thread
From: Shawn Bohrer @ 2010-09-17 15:45 UTC (permalink / raw)
To: Dave Chinner; +Cc: xfs
Hi Dave,
Thanks again for your replies.
On Thu, Sep 16, 2010 at 10:18:37AM +1000, Dave Chinner wrote:
> On Wed, Sep 15, 2010 at 10:26:33AM -0500, Shawn Bohrer wrote:
> > Hello,
> >
> > A little while ago I asked about ways to solve the occasional spikes in
> > latency that I see when writing to a shared memory mapped file.
> >
> > http://oss.sgi.com/pipermail/xfs/2010-July/046311.html
> >
> > With Dave's suggestions I enabled lazy-count=1 which did help a little:
> >
> > # xfs_info /home/
> > meta-data=/dev/sda5 isize=256 agcount=32, agsize=8472969 blks
> > = sectsz=512 attr=1
> > data = bsize=4096 blocks=271135008, imaxpct=25
> > = sunit=0 swidth=0 blks
> > naming =version 2 bsize=4096 ascii-ci=0
> > log =internal bsize=4096 blocks=32768, version=1
> > = sectsz=512 sunit=0 blks, lazy-count=1
> > realtime =none extsz=4096 blocks=0, rtextents=0
> >
> > I'm also mounting the partition with "noatime,nobarrier,logbufs=8".
>
> You really should add logbsize=262144 there - it won't prevent the
> latencies, but with less log writes the incidence should decrease
> significantly.
I initially tested with logbsize=256k but did not notice any
difference. I then later realized that I had been doing a:
mount -o remount,logbsize=256k /home
You may also notice from above that I had version 1 logs and the max
logbsize for version 1 logs is 32k. Apparently the "mount -o remount"
silently ignores the option. If I instead unmount and remount it
complains and refuses to mount.
Yesterday I converted to version 2 logs and ran tests for an hour with
both logbsize=32k and logbsize=256k and I still don't see any
noticeable difference. This of course assumes I tested correctly this
time.
> > The other change I made which helped the most was to use fallocate()
> > to grow the file instead of lseek() and a write().
>
> Ok, so now you are doing unwritten extent conversion at IO
> completion, which is where this new latency issue has come from.
I'm a complete newbie when it comes to filesystems. For my education
would you mind elaborating a little more here, or pointing to
something I could read?
An extent describes a contiguous section of data on disk correct?
So when the page fault occurs and modifies the block the extent is
modified in memory to record the change? What does "conversion" mean
in this context? And as silly as it sounds what exactly does IO
completion refer to? Is this when the data is written to disk?
> Ok, the transaction was blocked on a buffer that had it's IO
> completion queued to the xfslogd. But this happened some
> 320ms after the above page fault occurred, and 340ms after the
> xfsconvertd got stuck waiting for it. In other words, it looks
> like it it took at least 340ms for the buffer IO to complete after
> it was issued.
OK, so xfslogd is writing the log, which frees up log buffers.
Meanwhile xfsconvertd is waiting on a free buffer so it can write more
to the log correct? So setting logbufs=8 gives me 8 log buffers and
logbsize controls how big each of those buffers are correct? When are
these buffers filled and freed? Are they filled when the process
actually performs the write in memory, or at writeback time? Likewise
it seems that they are freed at writeback time correct? Also do the
buffers only get freed when fill they completely or are they also
flushed when partially full?
I get why you suggest increasing logbsize but I'm curious why I don't
see any difference. Could it be because I always end up running out
of log buffers during writeback even at 256k so some of the I/O gets
stalled anyway? Maybe increasing the logbsize increases the threshold
of the amount of data I can writeback before I see a spike?
> And so the delay you app saw was ~320ms. Basically, it blocked
> waiting for an IO to complete. I don't think there is anything we ca
> really do from a filesystem point of view to avoid that - we cannot
> avoid metadata buffer writeback indefinitely.
One more bit of information which may be relevant here is that since I
see these latencies during writeback I've increased
vm.dirty_writeback_centisecs from the default 500 to 30000. I'm OK
with loosing 5 minutes of data in the event of a crash, and at our
data rates we still stay well below the vm.dirty_background_ratio.
This does improve the spikes (I only see them every 5 min) but
intuitively this seems like might actually make the magnitude of the
delays larger since there is more to write back. Strangely from my
point of view it doesn't seem to increase the magnitude of the spikes,
so I'm not entirely sure how it really fits into the big picture. Of
course with higher data rates it does take longer to write out the
data so the duration where the spikes can occur does increase.
> Fundamentally you are seeing the reason why filesystems cannot
> easily guarantee maximum bound latencies - if we have to wait for IO
> for anything, then the latency is effectively uncontrollable. XFS
> does as much as possible to avoid such latencies for data IO, but
> even then it's not always possible. Even using the RT device in XFS
> won't avoid these latencies - it's caused by latencies in metadata
> modification, not data....
>
> Effectively, the only way you can minimise this is to design your
> storage layout for minimal IO latency under writes (e.g. use mirrors
> instead of RAID5, etc) or use faster drives. Also using the deadline
> scheduler (if you aren't already) might help....
I have tested with the deadline and noop schedulers and they actually
make the spikes noticeably worse than cfq. I'm not sure why that would
be but, one thought is that I am writing lots of small sequential
chunks but from a whole disk perspective it would create a lot of
random IO. Perhaps cfq is just better at merging these requests.
Thanks,
Shawn
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Latencies writing to memory mapped files
2010-09-17 15:45 ` Shawn Bohrer
@ 2010-09-20 0:05 ` Dave Chinner
2010-09-20 22:17 ` Shawn Bohrer
0 siblings, 1 reply; 10+ messages in thread
From: Dave Chinner @ 2010-09-20 0:05 UTC (permalink / raw)
To: Shawn Bohrer; +Cc: xfs
On Fri, Sep 17, 2010 at 10:45:23AM -0500, Shawn Bohrer wrote:
> Hi Dave,
>
> Thanks again for your replies.
>
> On Thu, Sep 16, 2010 at 10:18:37AM +1000, Dave Chinner wrote:
> > On Wed, Sep 15, 2010 at 10:26:33AM -0500, Shawn Bohrer wrote:
> > > Hello,
> > >
> > > A little while ago I asked about ways to solve the occasional spikes in
> > > latency that I see when writing to a shared memory mapped file.
> > >
> > > http://oss.sgi.com/pipermail/xfs/2010-July/046311.html
> > >
> > > With Dave's suggestions I enabled lazy-count=1 which did help a little:
> > >
> > > # xfs_info /home/
> > > meta-data=/dev/sda5 isize=256 agcount=32, agsize=8472969 blks
> > > = sectsz=512 attr=1
> > > data = bsize=4096 blocks=271135008, imaxpct=25
> > > = sunit=0 swidth=0 blks
> > > naming =version 2 bsize=4096 ascii-ci=0
> > > log =internal bsize=4096 blocks=32768, version=1
> > > = sectsz=512 sunit=0 blks, lazy-count=1
> > > realtime =none extsz=4096 blocks=0, rtextents=0
> > >
> > > I'm also mounting the partition with "noatime,nobarrier,logbufs=8".
> >
> > You really should add logbsize=262144 there - it won't prevent the
> > latencies, but with less log writes the incidence should decrease
> > significantly.
>
> I initially tested with logbsize=256k but did not notice any
> difference. I then later realized that I had been doing a:
>
> mount -o remount,logbsize=256k /home
>
> You may also notice from above that I had version 1 logs and the max
> logbsize for version 1 logs is 32k. Apparently the "mount -o remount"
> silently ignores the option. If I instead unmount and remount it
> complains and refuses to mount.
>
> Yesterday I converted to version 2 logs and ran tests for an hour with
> both logbsize=32k and logbsize=256k and I still don't see any
> noticeable difference. This of course assumes I tested correctly this
> time.
You may not notice any difference if the log is not the latency you
are tripping over. However, doing up to 8x less log IO is definitely
good for reducing overall IO latency...
> > > The other change I made which helped the most was to use fallocate()
> > > to grow the file instead of lseek() and a write().
> >
> > Ok, so now you are doing unwritten extent conversion at IO
> > completion, which is where this new latency issue has come from.
>
> I'm a complete newbie when it comes to filesystems. For my education
> would you mind elaborating a little more here, or pointing to
> something I could read?
>
> An extent describes a contiguous section of data on disk correct?
yes.
> So when the page fault occurs and modifies the block the extent is
> modified in memory to record the change?
Not exactly.
> What does "conversion" mean
> in this context? And as silly as it sounds what exactly does IO
> completion refer to? Is this when the data is written to disk?
When you preallocate a range, the blocks are allocated on disk, but
nothing is written to them. Hence there has to be some mechanism
recorded with the extent to prevent reads from the extent returning
whatever is on disk (security issue). IOWs we want a read into
preallocated space to be functionally equivalent of reading from a
hole - i.e. like no space was allocated at all.
This means that the extent has state on disk to record the fact it
is an "unwritten extent" - it's allocated but contains nothing but
zeros. When we then write data to that extent, the extent state must
change to remove the "unwritten" flag so that reads will then
reflect the correct data that has been written to disk. The changing
of the extent state from unwritten to written is what I referred to
as "conversion" above.
As to the "conversion at IO completion", if we convert the extent to
written state before the data IO is issued, then there is a window
where a system crash/power-fail/etc could occur between the extent
conversion and the real data being written to disk. IOWs, we could
convert the extent and then never write data to the range we
converted. This would then expose stale data from disk next time the
extent is read.
To avoid this problem, we wait for the data IO to complete (i.e. we
get the interrupt back from the hardware saying "write done") before
we convert the extent from unwritten to written. This means that
even if we crash after the conversion, we will never expose stale
data from the (un)written extent because we've already written the
correct data to it before starting the conversion.
> > Ok, the transaction was blocked on a buffer that had it's IO
> > completion queued to the xfslogd. But this happened some
> > 320ms after the above page fault occurred, and 340ms after the
> > xfsconvertd got stuck waiting for it. In other words, it looks
> > like it it took at least 340ms for the buffer IO to complete after
> > it was issued.
>
> OK, so xfslogd is writing the log, which frees up log buffers.
> Meanwhile xfsconvertd is waiting on a free buffer so it can write more
> to the log correct?
No. The xfslogd runs both metadata buffer and log buffer IO
completion processing - it does not write to the log. In this case,
xfsconvertd is waiting for a metadata buffer IO completion
processing to unlock the buffer (metadata buffers are locked over IO
so they are not modified during writeback) because it needs to use
that metadata buffer in the transaction.
Log buffers and metadata buffers are very different in behaviour and
lifecycle.
> I get why you suggest increasing logbsize but I'm curious why I don't
> see any difference. Could it be because I always end up running out
> of log buffers during writeback even at 256k so some of the I/O gets
> stalled anyway? Maybe increasing the logbsize increases the threshold
> of the amount of data I can writeback before I see a spike?
The cause of this latency event is not at all related to the log
buffer size, which is why changing the size of the buffer will not
prevent it.
>
> > And so the delay you app saw was ~320ms. Basically, it blocked
> > waiting for an IO to complete. I don't think there is anything we ca
> > really do from a filesystem point of view to avoid that - we cannot
> > avoid metadata buffer writeback indefinitely.
>
> One more bit of information which may be relevant here is that since I
> see these latencies during writeback I've increased
> vm.dirty_writeback_centisecs from the default 500 to 30000.
Sure - you see the latency during writeback, so it's no surprise it
happens less often when you increase the writeback period.
> I'm OK
> with loosing 5 minutes of data in the event of a crash, and at our
> data rates we still stay well below the vm.dirty_background_ratio.
> This does improve the spikes (I only see them every 5 min) but
> intuitively this seems like might actually make the magnitude of the
> delays larger since there is more to write back. Strangely from my
> point of view it doesn't seem to increase the magnitude of the spikes,
Because you're still only being held up by waiting for a single
metadata buffer completion?
FWIW, if you can work out the magic necessary (perhaps systemtap) it
woul dbe really interesting to know whether it is the same buffer
that is causing the latency every time (i.e. get the bp->b_bn field
from the metadata buffer). With the block number, we can use xfs_db
to dig out what the buffer actually is....
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Latencies writing to memory mapped files
2010-09-20 0:05 ` Dave Chinner
@ 2010-09-20 22:17 ` Shawn Bohrer
2010-09-20 22:48 ` Dave Chinner
0 siblings, 1 reply; 10+ messages in thread
From: Shawn Bohrer @ 2010-09-20 22:17 UTC (permalink / raw)
To: Dave Chinner; +Cc: xfs
Thanks Dave for your explanations.
On Mon, Sep 20, 2010 at 10:05:35AM +1000, Dave Chinner wrote:
> FWIW, if you can work out the magic necessary (perhaps systemtap) it
> woul dbe really interesting to know whether it is the same buffer
> that is causing the latency every time (i.e. get the bp->b_bn field
> from the metadata buffer). With the block number, we can use xfs_db
> to dig out what the buffer actually is....
I'm working on a dev box right now so I just added a trace_printk() to
print out the bp->b_bn field when the xfs_buf_lock blocks for more
than 300ms. Here are some numbers (I can easily get a lot more):
_xfs_buf_find: xfs_buf_lock blocked for 1843ms on bp->b_bn: 812730376
_xfs_buf_find: xfs_buf_lock blocked for 1504ms on bp->b_bn: 406702514
_xfs_buf_find: xfs_buf_lock blocked for 307ms on bp->b_bn: 881190896
_xfs_buf_find: xfs_buf_lock blocked for 433ms on bp->b_bn: 406703400
_xfs_buf_find: xfs_buf_lock blocked for 420ms on bp->b_bn: 541595968
_xfs_buf_find: xfs_buf_lock blocked for 308ms on bp->b_bn: 44945968
_xfs_buf_find: xfs_buf_lock blocked for 702ms on bp->b_bn: 406027744
_xfs_buf_find: xfs_buf_lock blocked for 454ms on bp->b_bn: 474486504
_xfs_buf_find: xfs_buf_lock blocked for 869ms on bp->b_bn: 881195976
_xfs_buf_find: xfs_buf_lock blocked for 387ms on bp->b_bn: 1287891544
_xfs_buf_find: xfs_buf_lock blocked for 397ms on bp->b_bn: 1220116224
_xfs_buf_find: xfs_buf_lock blocked for 461ms on bp->b_bn: 2101644280
_xfs_buf_find: xfs_buf_lock blocked for 312ms on bp->b_bn: 338919728
_xfs_buf_find: xfs_buf_lock blocked for 356ms on bp->b_bn: 1016769536
_xfs_buf_find: xfs_buf_lock blocked for 593ms on bp->b_bn: 474488848
_xfs_buf_find: xfs_buf_lock blocked for 323ms on bp->b_bn: 1022248984
I should say that not every one of these results in a stall in my
application, since my app needs to generate a page fault while that
lock is held.
What do I need to do to convert the block numbers to a buffer?
Thanks,
Shawn
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Latencies writing to memory mapped files
2010-09-20 22:17 ` Shawn Bohrer
@ 2010-09-20 22:48 ` Dave Chinner
2010-09-21 18:05 ` Shawn Bohrer
0 siblings, 1 reply; 10+ messages in thread
From: Dave Chinner @ 2010-09-20 22:48 UTC (permalink / raw)
To: Shawn Bohrer; +Cc: xfs
On Mon, Sep 20, 2010 at 05:17:26PM -0500, Shawn Bohrer wrote:
> Thanks Dave for your explanations.
>
> On Mon, Sep 20, 2010 at 10:05:35AM +1000, Dave Chinner wrote:
> > FWIW, if you can work out the magic necessary (perhaps systemtap) it
> > woul dbe really interesting to know whether it is the same buffer
> > that is causing the latency every time (i.e. get the bp->b_bn field
> > from the metadata buffer). With the block number, we can use xfs_db
> > to dig out what the buffer actually is....
>
> I'm working on a dev box right now so I just added a trace_printk() to
> print out the bp->b_bn field when the xfs_buf_lock blocks for more
> than 300ms. Here are some numbers (I can easily get a lot more):
>
> _xfs_buf_find: xfs_buf_lock blocked for 1843ms on bp->b_bn: 812730376
> _xfs_buf_find: xfs_buf_lock blocked for 1504ms on bp->b_bn: 406702514
> _xfs_buf_find: xfs_buf_lock blocked for 307ms on bp->b_bn: 881190896
> _xfs_buf_find: xfs_buf_lock blocked for 433ms on bp->b_bn: 406703400
> _xfs_buf_find: xfs_buf_lock blocked for 420ms on bp->b_bn: 541595968
> _xfs_buf_find: xfs_buf_lock blocked for 308ms on bp->b_bn: 44945968
> _xfs_buf_find: xfs_buf_lock blocked for 702ms on bp->b_bn: 406027744
> _xfs_buf_find: xfs_buf_lock blocked for 454ms on bp->b_bn: 474486504
> _xfs_buf_find: xfs_buf_lock blocked for 869ms on bp->b_bn: 881195976
> _xfs_buf_find: xfs_buf_lock blocked for 387ms on bp->b_bn: 1287891544
> _xfs_buf_find: xfs_buf_lock blocked for 397ms on bp->b_bn: 1220116224
> _xfs_buf_find: xfs_buf_lock blocked for 461ms on bp->b_bn: 2101644280
> _xfs_buf_find: xfs_buf_lock blocked for 312ms on bp->b_bn: 338919728
> _xfs_buf_find: xfs_buf_lock blocked for 356ms on bp->b_bn: 1016769536
> _xfs_buf_find: xfs_buf_lock blocked for 593ms on bp->b_bn: 474488848
> _xfs_buf_find: xfs_buf_lock blocked for 323ms on bp->b_bn: 1022248984
>
> I should say that not every one of these results in a stall in my
> application, since my app needs to generate a page fault while that
> lock is held.
Hmmm - it would be good to know which one produced the latency,
given there does not appear to be a pattern in the block numbers.
> What do I need to do to convert the block numbers to a buffer?
# xfs_db -r -c "daddr 812730376" -c "print" <dev>
Will dump the sector at that address. That should be enough to tell
us what is in the buffer (by the magic number).
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Latencies writing to memory mapped files
2010-09-20 22:48 ` Dave Chinner
@ 2010-09-21 18:05 ` Shawn Bohrer
2010-09-21 23:15 ` Dave Chinner
0 siblings, 1 reply; 10+ messages in thread
From: Shawn Bohrer @ 2010-09-21 18:05 UTC (permalink / raw)
To: Dave Chinner; +Cc: xfs
On Tue, Sep 21, 2010 at 08:48:33AM +1000, Dave Chinner wrote:
> On Mon, Sep 20, 2010 at 05:17:26PM -0500, Shawn Bohrer wrote:
> > On Mon, Sep 20, 2010 at 10:05:35AM +1000, Dave Chinner wrote:
> > > FWIW, if you can work out the magic necessary (perhaps systemtap) it
> > > woul dbe really interesting to know whether it is the same buffer
> > > that is causing the latency every time (i.e. get the bp->b_bn field
> > > from the metadata buffer). With the block number, we can use xfs_db
> > > to dig out what the buffer actually is....
> >
> > I'm working on a dev box right now so I just added a trace_printk() to
> > print out the bp->b_bn field when the xfs_buf_lock blocks for more
> > than 300ms. Here are some numbers (I can easily get a lot more):
> >
> > _xfs_buf_find: xfs_buf_lock blocked for 1843ms on bp->b_bn: 812730376
> > _xfs_buf_find: xfs_buf_lock blocked for 1504ms on bp->b_bn: 406702514
> > _xfs_buf_find: xfs_buf_lock blocked for 307ms on bp->b_bn: 881190896
> > _xfs_buf_find: xfs_buf_lock blocked for 433ms on bp->b_bn: 406703400
> > _xfs_buf_find: xfs_buf_lock blocked for 420ms on bp->b_bn: 541595968
> > _xfs_buf_find: xfs_buf_lock blocked for 308ms on bp->b_bn: 44945968
> > _xfs_buf_find: xfs_buf_lock blocked for 702ms on bp->b_bn: 406027744
> > _xfs_buf_find: xfs_buf_lock blocked for 454ms on bp->b_bn: 474486504
> > _xfs_buf_find: xfs_buf_lock blocked for 869ms on bp->b_bn: 881195976
> > _xfs_buf_find: xfs_buf_lock blocked for 387ms on bp->b_bn: 1287891544
> > _xfs_buf_find: xfs_buf_lock blocked for 397ms on bp->b_bn: 1220116224
> > _xfs_buf_find: xfs_buf_lock blocked for 461ms on bp->b_bn: 2101644280
> > _xfs_buf_find: xfs_buf_lock blocked for 312ms on bp->b_bn: 338919728
> > _xfs_buf_find: xfs_buf_lock blocked for 356ms on bp->b_bn: 1016769536
> > _xfs_buf_find: xfs_buf_lock blocked for 593ms on bp->b_bn: 474488848
> > _xfs_buf_find: xfs_buf_lock blocked for 323ms on bp->b_bn: 1022248984
> >
> > I should say that not every one of these results in a stall in my
> > application, since my app needs to generate a page fault while that
> > lock is held.
>
> Hmmm - it would be good to know which one produced the latency,
> given there does not appear to be a pattern in the block numbers.
OK here is a little more information which may be relevant. I've
currently got 12 processes that read data from a socket and each write
to a different memory mapped file. The apps are only appending to the
file, but they don't write the data in one sequential chunk so it is
quite possible that it appears as random IO for a short time period.
This time I made some more modifications so that I would only capture
the bp->b_bn when one of my processes sees a delay of 300ms or greater.
There still is a small chance for false positives, but most of these
should have caused real delays. All of the following came from the
same process:
[001] 81758.886627: _xfs_buf_find: xfs_buf_lock blocked for 871ms on bp->b_bn: 474487328
[001] 81920.808163: _xfs_buf_find: xfs_buf_lock blocked for 1038ms on bp->b_bn: 474487568
[001] 82933.428627: _xfs_buf_find: xfs_buf_lock blocked for 767ms on bp->b_bn: 542273864
[000] 83048.558413: _xfs_buf_find: xfs_buf_lock blocked for 363ms on bp->b_bn: 474488080
[001] 86717.251189: _xfs_buf_find: xfs_buf_lock blocked for 514ms on bp->b_bn: 474487560
[001] 88466.635802: _xfs_buf_find: xfs_buf_lock blocked for 380ms on bp->b_bn: 542274544
[000] 88972.122062: _xfs_buf_find: xfs_buf_lock blocked for 521ms on bp->b_bn: 474487560
[001] 89271.988589: _xfs_buf_find: xfs_buf_lock blocked for 496ms on bp->b_bn: 474487560
[001] 91046.566309: _xfs_buf_find: xfs_buf_lock blocked for 540ms on bp->b_bn: 474487560
[001] 91047.280042: _xfs_buf_find: xfs_buf_lock blocked for 713ms on bp->b_bn: 542274216
[001] 91212.458472: _xfs_buf_find: xfs_buf_lock blocked for 490ms on bp->b_bn: 542274544
[001] 92397.667196: _xfs_buf_find: xfs_buf_lock blocked for 549ms on bp->b_bn: 474487560
> > What do I need to do to convert the block numbers to a buffer?
>
> # xfs_db -r -c "daddr 812730376" -c "print" <dev>
>
> Will dump the sector at that address. That should be enough to tell
> us what is in the buffer (by the magic number).
So I have no idea what I'm looking at but here is the output for the
above numbers (duplicates removed):
xfs_db -r -c "daddr 474487328" -c "print" /dev/sda5
000: 424d4150 0000007f 00000000 07000082 00000000 07000092 00000000 0039a000
020: 0002c085 ede00009 80000000 0039b200 0002c085 ef000017 00000000 0039e000
040: 0002c085 f1e0008d 80000000 003afa00 0002c086 03800007 00000000 003b0800
060: 0002c086 0460000b 80000000 003b1e00 0002c086 05c00001 00000000 003b2000
080: 0002c086 05e000ce 80000000 003cbc00 0002c086 1fa0001a 00000000 003cf000
0a0: 0002c086 22e00027 80000000 003d3e00 0002c086 27c00001 00000000 003d4000
0c0: 0002c086 27e00001 80000000 003d4200 0002c086 28000007 00000000 003d5000
0e0: 0002c086 28e00010 80000000 003d7000 0002c086 2ae00030 00000000 003dd000
100: 0002c086 30e0003a 80000000 003e4400 0002c086 38200006 00000000 003e5000
120: 0002c086 38e00086 80000000 003f5c00 0002c086 49a00002 00000000 003f6000
140: 0002c086 49e00009 80000000 003f7200 0002c086 4b000007 00000000 003f8000
160: 0002c0ac dec00004 80000000 003f8800 0002c0ac df400004 00000000 003f9000
180: 0002c0ac dfc00011 80000000 003fb200 0002c0ac e1e00007 00000000 003fc000
1a0: 0002c0ac e2c00001 80000000 003fc200 0002c0ac e2e00007 00000000 003fd000
1c0: 0002c0ac e3c00072 80000000 0040b400 0002c0ac f200000e 00000000 0040d000
1e0: 0002c0ac f3c00025 80000000 00411a00 0002c0ac f8600007 00000000 00412800
xfs_db -r -c "daddr 474487568" -c "print" /dev/sda5
000: 424d4150 000000be 00000000 070000a1 00000000 070000a4 00000000 008b8800
020: 0002c133 39600003 80000000 008b8e00 0002c133 39c00005 00000000 008b9800
040: 0002c133 3a600001 80000000 008b9a00 0002c133 3a800007 00000000 008ba800
060: 0002c133 3b600001 80000000 008baa00 0002c133 3b800007 00000000 008bb800
080: 0002c133 3c600001 80000000 008bba00 0002c133 3c800007 00000000 008bc800
0a0: 0002c133 3d600001 80000000 008bca00 0002c133 3d800007 00000000 008bd800
0c0: 0002c133 3e600001 80000000 008bda00 0002c133 3e800007 00000000 008be800
0e0: 0002c133 3f60000a 80000000 008bfc00 0002c133 40a00006 00000000 008c0800
100: 0002c133 41600001 80000000 008c0a00 0002c133 41800007 00000000 008c1800
120: 0002c133 4260000c 80000000 008c3000 0002c133 43e00004 00000000 008c3800
140: 0002c133 44600004 80000000 008c4000 0002c133 44e00004 00000000 008c4800
160: 0002c133 45600001 80000000 008c4a00 0002c133 45800007 00000000 008c5800
180: 0002c133 4660000a 80000000 008c6c00 0002c133 47a00006 00000000 008c7800
1a0: 0002c133 48600009 80000000 008c8a00 0002c133 49800007 00000000 008c9800
1c0: 0002c133 4a600003 80000000 008c9e00 0002c133 4ac00005 00000000 008ca800
1e0: 0002c133 4b600009 80000000 008cba00 0002c133 4c800007 00000000 008cc800
xfs_db -r -c "daddr 542273864" -c "print" /dev/sda5
000: 424d4150 000000ce 00000000 080001e3 00000000 0800020b 80000000 05a45600
020: 0002c1a5 34e00005 00000000 05a46000 0002c1a5 3580000c 80000000 05a47800
040: 0002c1a5 37000004 00000000 05a48000 0002c1a5 37800011 80000000 05a4a200
060: 0002c1a5 39a00017 00000000 05a4d000 0002c1a5 3c80000e 80000000 05a4ec00
080: 0002c1a5 3e400002 00000000 05a4f000 0002c1a5 3e800003 80000000 05a4f600
0a0: 0002c1a5 3ee00001 00000000 05a4f800 0002c1a5 3f000009 80000000 05a50a00
0c0: 0002c1a5 40200007 00000000 05a51800 0002c1a5 41000104 80000000 05a72000
0e0: 0002c1a5 61800004 00000000 05a72800 0002c1a5 6200000d 80000000 05a74200
100: 0002c1a5 63a00003 00000000 05a74800 0002c1a5 6400005f 80000000 05a80600
120: 0002c1a5 6fe000a1 00000000 05a94800 0002c1a5 84000001 80000000 05a94a00
140: 0002c1a5 84200007 00000000 05a95800 0002c1a5 85000013 80000000 05a97e00
160: 0002c1a5 8760000d 00000000 05a99800 0002c1a5 89000036 80000000 05aa0400
180: 0002c1a5 8fc0000a 00000000 05aa1800 0002c1a5 91000015 80000000 05aa4200
1a0: 0002c1a5 93a0002b 00000000 05aa9800 0002c1a5 990000ba 80000000 05ac0c00
1c0: 0002c1a5 b0400046 00000000 05ac9800 0002c1a5 b9000014 80000000 05acc000
1e0: 0002c1a5 bb80000c 00000000 05acd800 0002c1a5 bd000015 80000000 05ad0200
xfs_db -r -c "daddr 474488080" -c "print" /dev/sda5
000: 424d4150 000000ab 00000000 070000e2 00000000 070000e4 80000000 00fbb200
020: 0002c13a 3c000003 00000000 00fbb800 0002c13a 3c600005 80000000 00fbc200
040: 0002c13a 3d000003 00000000 00fbc800 0002c13a 3d600002 80000000 00fbcc00
060: 0002c13a 3da00006 00000000 00fbd800 0002c13a 3e60000b 80000000 00fbee00
080: 0002c13a 3fc00005 00000000 00fbf800 0002c13a 40600001 80000000 00fbfa00
0a0: 0002c13a 40800007 00000000 00fc0800 0002c13a 41600005 80000000 00fc1200
0c0: 0002c13a 42000003 00000000 00fc1800 0002c13a 42600009 80000000 00fc2a00
0e0: 0002c13a 43800007 00000000 00fc3800 0002c13a 44600001 80000000 00fc3a00
100: 0002c13a 44800007 00000000 00fc4800 0002c13a 4560000a 80000000 00fc5c00
120: 0002c13a 46a00006 00000000 00fc6800 0002c13a 47600004 80000000 00fc7000
140: 0002c13a 47e00004 00000000 00fc7800 0002c13a 4860000b 80000000 00fc8e00
160: 0002c13a 49c00005 00000000 00fc9800 0002c13a 4a600005 80000000 00fca200
180: 0002c13a 4b000003 00000000 00fca800 0002c13a 4b600002 80000000 00fcac00
1a0: 0002c13a 4ba00006 00000000 00fcb800 0002c13a 4c600002 80000000 00fcbc00
1c0: 0002c13a 4ca00006 00000000 00fcc800 0002c13a 4d600003 80000000 00fcce00
1e0: 0002c13a 4dc00005 00000000 00fcd800 0002c13a 4e60000b 80000000 00fcee00
xfs_db -r -c "daddr 542274216" -c "print" /dev/sda5
000: 424d4150 000000dc 00000000 0800020b 00000000 08000208 80000000 0609fc00
020: 0002c1ab 8f40000e 00000000 060a1800 0002c1ab 9100005f 80000000 060ad600
040: 0002c1ab 9ce000a1 00000000 060c1800 0002c1ab b1000006 80000000 060c2400
060: 0002c1ab b1c00002 00000000 060c2800 0002c1ab b2000012 80000000 060c4c00
080: 0002c1ab b440000e 00000000 060c6800 0002c1ab b6000012 80000000 060c8c00
0a0: 0002c1ab b840002e 00000000 060ce800 0002c1ab be000011 80000000 060d0a00
0c0: 0002c1ab c020002f 00000000 060d6800 0002c1ab c600000b 80000000 060d7e00
0e0: 0002c1ab c7600015 00000000 060da800 0002c1ab ca000011 80000000 060dca00
100: 0002c1ab cc20000f 00000000 060de800 0002c1ab ce00011a 80000000 06101c00
120: 0002c1ab f1400012 00000000 06104000 0002c1ab f3800021 80000000 06108200
140: 0002c1ab f7a00007 00000000 06109000 0002c1ab f8800001 80000000 06109200
160: 0002c1ab f8a00007 00000000 0610a000 0002c1ab f980000c 80000000 0610b800
180: 0002c1ab fb000034 00000000 06112000 0002c1ac 01800009 80000000 06113200
1a0: 0002c1ac 02a00007 00000000 06114000 0002c1ac 03800001 80000000 06114200
1c0: 0002c1ac 03a00007 00000000 06115000 0002c1ac 04800001 80000000 06115200
1e0: 0002c1ac 04a00007 00000000 06116000 0002c1ac 05800011 80000000 06118200
xfs_db -r -c "daddr 542274544" -c "print" /dev/sda5
000: 424d4150 0000007f 00000000 08000234 00000000 08000238 80000000 04089200
020: 0002c18b 78a00007 00000000 0408a000 0002c18b 79800001 80000000 0408a200
040: 0002c18b 79a00007 00000000 0408b000 0002c18b 7a800001 80000000 0408b200
060: 0002c18b 7aa00007 00000000 0408c000 0002c18b 7b800001 80000000 0408c200
080: 0002c18b 7ba00007 00000000 0408d000 0002c18b 7c80002d 80000000 04092a00
0a0: 0002c18b 82200003 00000000 04093000 0002c18b 8280001d 80000000 04096a00
0c0: 0002c18b 86200003 00000000 04097000 0002c18b 86800029 80000000 0409c200
0e0: 0002c18b 8ba00007 00000000 0409d000 0002c18b 8c8000d8 80000000 040b8000
100: 0002c18b a7800004 00000000 040b8800 0002c18b a8000011 80000000 040baa00
120: 0002c18b aa200007 00000000 040bb800 0002c18b ab000001 80000000 040bba00
140: 0002c18b ab200007 00000000 040bc800 0002c18b ac000011 80000000 040bea00
160: 0002c18b ae200007 00000000 040bf800 0002c18b af000179 80000000 040eea00
180: 0002c18b de200007 00000000 040ef800 0002c18b df000011 80000000 040f1a00
1a0: 0002c18b e1200007 00000000 040f2800 0002c18b e2000021 80000000 040f6a00
1c0: 0002c18b e6200003 00000000 040f7000 0002c18b e6800001 80000000 040f7200
1e0: 0002c18b e6a00007 00000000 040f8000 0002c18b e78000a9 80000000 0410d200
xfs_db -r -c "daddr 474487560" -c "print" /dev/sda5
000: 424d4150 0001003e ffffffff ffffffff ffffffff ffffffff 00000000 00000000
020: 00000000 0000257d 00000000 0000297e 00000000 00002d7f 00000000 000031b6
040: 00000000 000035bd 00000000 000039c5 00000000 00003dcd 00000000 000041dd
060: 00000000 000045c4 00000000 000049c0 00000000 00004dd8 00000000 000051d8
080: 00000000 000055e3 00000000 000059c8 00000000 00005dc7 00000000 000061bc
0a0: 00000000 000065b4 00000000 000069b4 00000000 00006dc5 00000000 000071cc
0c0: 00000000 000075cc 00000000 000079d4 00000000 00007dd9 00000000 000081db
0e0: 00000000 000085cd 00000000 000089bd 00000000 00008dcd 00000000 000092f1
100: 00000000 000099ac 00000000 0000a049 00000000 0000a56d 00000000 0000abe8
120: 00000000 0000b349 00000000 0000bd14 00000000 0000cb27 00000000 0000dcd0
140: 00000000 0000f248 00000000 000105e5 00000000 00011fe0 00000000 0001401c
160: 00000000 000149fd 00000000 00014ce9 00000000 00016649 00000000 0001a524
180: 00000000 0001df90 00000000 00020449 00000000 00021e84 00000000 00023c74
1a0: 00000000 00027290 00000000 00028a92 00000000 0002a188 00000000 0002bcbf
1c0: 00000000 0002d22b 00000000 0002e811 00000000 000304fe 00000000 000321a8
1e0: 00000000 00033aca 00000000 000353e5 00000000 00036dc5 00000000 00038a39
Thanks,
Shawn
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Latencies writing to memory mapped files
2010-09-21 18:05 ` Shawn Bohrer
@ 2010-09-21 23:15 ` Dave Chinner
2010-09-29 15:31 ` Shawn Bohrer
0 siblings, 1 reply; 10+ messages in thread
From: Dave Chinner @ 2010-09-21 23:15 UTC (permalink / raw)
To: Shawn Bohrer; +Cc: xfs
On Tue, Sep 21, 2010 at 01:05:41PM -0500, Shawn Bohrer wrote:
> On Tue, Sep 21, 2010 at 08:48:33AM +1000, Dave Chinner wrote:
> > On Mon, Sep 20, 2010 at 05:17:26PM -0500, Shawn Bohrer wrote:
> > > On Mon, Sep 20, 2010 at 10:05:35AM +1000, Dave Chinner wrote:
> > > > FWIW, if you can work out the magic necessary (perhaps systemtap) it
> > > > woul dbe really interesting to know whether it is the same buffer
> > > > that is causing the latency every time (i.e. get the bp->b_bn field
> > > > from the metadata buffer). With the block number, we can use xfs_db
> > > > to dig out what the buffer actually is....
.....
> > Hmmm - it would be good to know which one produced the latency,
> > given there does not appear to be a pattern in the block numbers.
>
> OK here is a little more information which may be relevant. I've
> currently got 12 processes that read data from a socket and each write
> to a different memory mapped file. The apps are only appending to the
> file, but they don't write the data in one sequential chunk so it is
> quite possible that it appears as random IO for a short time period.
>
> This time I made some more modifications so that I would only capture
> the bp->b_bn when one of my processes sees a delay of 300ms or greater.
> There still is a small chance for false positives, but most of these
> should have caused real delays. All of the following came from the
> same process:
>
> [001] 81758.886627: _xfs_buf_find: xfs_buf_lock blocked for 871ms on bp->b_bn: 474487328
> [001] 81920.808163: _xfs_buf_find: xfs_buf_lock blocked for 1038ms on bp->b_bn: 474487568
> [001] 82933.428627: _xfs_buf_find: xfs_buf_lock blocked for 767ms on bp->b_bn: 542273864
> [000] 83048.558413: _xfs_buf_find: xfs_buf_lock blocked for 363ms on bp->b_bn: 474488080
> [001] 86717.251189: _xfs_buf_find: xfs_buf_lock blocked for 514ms on bp->b_bn: 474487560
> [001] 88466.635802: _xfs_buf_find: xfs_buf_lock blocked for 380ms on bp->b_bn: 542274544
> [000] 88972.122062: _xfs_buf_find: xfs_buf_lock blocked for 521ms on bp->b_bn: 474487560
> [001] 89271.988589: _xfs_buf_find: xfs_buf_lock blocked for 496ms on bp->b_bn: 474487560
> [001] 91046.566309: _xfs_buf_find: xfs_buf_lock blocked for 540ms on bp->b_bn: 474487560
> [001] 91047.280042: _xfs_buf_find: xfs_buf_lock blocked for 713ms on bp->b_bn: 542274216
> [001] 91212.458472: _xfs_buf_find: xfs_buf_lock blocked for 490ms on bp->b_bn: 542274544
> [001] 92397.667196: _xfs_buf_find: xfs_buf_lock blocked for 549ms on bp->b_bn: 474487560
>
> > > What do I need to do to convert the block numbers to a buffer?
> >
> > # xfs_db -r -c "daddr 812730376" -c "print" <dev>
> >
> > Will dump the sector at that address. That should be enough to tell
> > us what is in the buffer (by the magic number).
>
> So I have no idea what I'm looking at but here is the output for the
> above numbers (duplicates removed):
>
> xfs_db -r -c "daddr 474487328" -c "print" /dev/sda5
> 000: 424d4150 0000007f 00000000 07000082 00000000 07000092 00000000 0039a000
^^^^^^^^
B M A P
#define XFS_BMAP_MAGIC 0x424d4150 /* 'BMAP' */
So these are inode extent btree blocks your application is getting
stuck on. These only get written back as a result of either log
pressure (i.e. tail pushing) or by the xfsbufd based on age. They
aren't actually flushed with the data because changes are logged.
IOWs, the writeback of the bmap btree blocks is asynchronous to any
operation that modifies them, so there's no direct connection
between modification and writeback.
I'm not sure that there is anything that can really be done to
prevent this. If the cause of writeback is age-based flushing on the
metadata buffers, you could try increasing the xfsbufd writeback age
so that only log pressure will cause them to be flushed.
Alternatively, you could change your application to pre-fault pages
in an async thread so the latency of allocation during the page
fault is not taken by the main writer...
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Latencies writing to memory mapped files
2010-09-21 23:15 ` Dave Chinner
@ 2010-09-29 15:31 ` Shawn Bohrer
2010-09-29 23:19 ` Dave Chinner
0 siblings, 1 reply; 10+ messages in thread
From: Shawn Bohrer @ 2010-09-29 15:31 UTC (permalink / raw)
To: Dave Chinner; +Cc: xfs
On Wed, Sep 22, 2010 at 09:15:31AM +1000, Dave Chinner wrote:
> On Tue, Sep 21, 2010 at 01:05:41PM -0500, Shawn Bohrer wrote:
> > On Tue, Sep 21, 2010 at 08:48:33AM +1000, Dave Chinner wrote:
> > > On Mon, Sep 20, 2010 at 05:17:26PM -0500, Shawn Bohrer wrote:
> > > > On Mon, Sep 20, 2010 at 10:05:35AM +1000, Dave Chinner wrote:
> > > > > FWIW, if you can work out the magic necessary (perhaps systemtap) it
> > > > > woul dbe really interesting to know whether it is the same buffer
> > > > > that is causing the latency every time (i.e. get the bp->b_bn field
> > > > > from the metadata buffer). With the block number, we can use xfs_db
> > > > > to dig out what the buffer actually is....
> .....
> > > Hmmm - it would be good to know which one produced the latency,
> > > given there does not appear to be a pattern in the block numbers.
> >
> > OK here is a little more information which may be relevant. I've
> > currently got 12 processes that read data from a socket and each write
> > to a different memory mapped file. The apps are only appending to the
> > file, but they don't write the data in one sequential chunk so it is
> > quite possible that it appears as random IO for a short time period.
> >
> > This time I made some more modifications so that I would only capture
> > the bp->b_bn when one of my processes sees a delay of 300ms or greater.
> > There still is a small chance for false positives, but most of these
> > should have caused real delays. All of the following came from the
> > same process:
> >
> > [001] 81758.886627: _xfs_buf_find: xfs_buf_lock blocked for 871ms on bp->b_bn: 474487328
> > [001] 81920.808163: _xfs_buf_find: xfs_buf_lock blocked for 1038ms on bp->b_bn: 474487568
> > [001] 82933.428627: _xfs_buf_find: xfs_buf_lock blocked for 767ms on bp->b_bn: 542273864
> > [000] 83048.558413: _xfs_buf_find: xfs_buf_lock blocked for 363ms on bp->b_bn: 474488080
> > [001] 86717.251189: _xfs_buf_find: xfs_buf_lock blocked for 514ms on bp->b_bn: 474487560
> > [001] 88466.635802: _xfs_buf_find: xfs_buf_lock blocked for 380ms on bp->b_bn: 542274544
> > [000] 88972.122062: _xfs_buf_find: xfs_buf_lock blocked for 521ms on bp->b_bn: 474487560
> > [001] 89271.988589: _xfs_buf_find: xfs_buf_lock blocked for 496ms on bp->b_bn: 474487560
> > [001] 91046.566309: _xfs_buf_find: xfs_buf_lock blocked for 540ms on bp->b_bn: 474487560
> > [001] 91047.280042: _xfs_buf_find: xfs_buf_lock blocked for 713ms on bp->b_bn: 542274216
> > [001] 91212.458472: _xfs_buf_find: xfs_buf_lock blocked for 490ms on bp->b_bn: 542274544
> > [001] 92397.667196: _xfs_buf_find: xfs_buf_lock blocked for 549ms on bp->b_bn: 474487560
> >
> > > > What do I need to do to convert the block numbers to a buffer?
> > >
> > > # xfs_db -r -c "daddr 812730376" -c "print" <dev>
> > >
> > > Will dump the sector at that address. That should be enough to tell
> > > us what is in the buffer (by the magic number).
> >
> > So I have no idea what I'm looking at but here is the output for the
> > above numbers (duplicates removed):
> >
> > xfs_db -r -c "daddr 474487328" -c "print" /dev/sda5
> > 000: 424d4150 0000007f 00000000 07000082 00000000 07000092 00000000 0039a000
> ^^^^^^^^
> B M A P
>
> #define XFS_BMAP_MAGIC 0x424d4150 /* 'BMAP' */
>
> So these are inode extent btree blocks your application is getting
> stuck on. These only get written back as a result of either log
> pressure (i.e. tail pushing) or by the xfsbufd based on age. They
> aren't actually flushed with the data because changes are logged.
> IOWs, the writeback of the bmap btree blocks is asynchronous to any
> operation that modifies them, so there's no direct connection
> between modification and writeback.
>
> I'm not sure that there is anything that can really be done to
> prevent this. If the cause of writeback is age-based flushing on the
> metadata buffers, you could try increasing the xfsbufd writeback age
> so that only log pressure will cause them to be flushed.
So setting fs.xfs.age_buffer_centisecs to 720000 does seem to help,
but what are the consequences (if any) of doing this?
> Alternatively, you could change your application to pre-fault pages
> in an async thread so the latency of allocation during the page
> fault is not taken by the main writer...
I've considered this and some other elaborate schemes. We'll see if I
need to go there.
Thanks,
Shawn
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Latencies writing to memory mapped files
2010-09-29 15:31 ` Shawn Bohrer
@ 2010-09-29 23:19 ` Dave Chinner
0 siblings, 0 replies; 10+ messages in thread
From: Dave Chinner @ 2010-09-29 23:19 UTC (permalink / raw)
To: Shawn Bohrer; +Cc: xfs
On Wed, Sep 29, 2010 at 10:31:22AM -0500, Shawn Bohrer wrote:
> On Wed, Sep 22, 2010 at 09:15:31AM +1000, Dave Chinner wrote:
> > On Tue, Sep 21, 2010 at 01:05:41PM -0500, Shawn Bohrer wrote:
> > > So I have no idea what I'm looking at but here is the output for the
> > > above numbers (duplicates removed):
> > >
> > > xfs_db -r -c "daddr 474487328" -c "print" /dev/sda5
> > > 000: 424d4150 0000007f 00000000 07000082 00000000 07000092 00000000 0039a000
> > ^^^^^^^^
> > B M A P
> >
> > #define XFS_BMAP_MAGIC 0x424d4150 /* 'BMAP' */
> >
> > So these are inode extent btree blocks your application is getting
> > stuck on. These only get written back as a result of either log
> > pressure (i.e. tail pushing) or by the xfsbufd based on age. They
> > aren't actually flushed with the data because changes are logged.
> > IOWs, the writeback of the bmap btree blocks is asynchronous to any
> > operation that modifies them, so there's no direct connection
> > between modification and writeback.
> >
> > I'm not sure that there is anything that can really be done to
> > prevent this. If the cause of writeback is age-based flushing on the
> > metadata buffers, you could try increasing the xfsbufd writeback age
> > so that only log pressure will cause them to be flushed.
>
> So setting fs.xfs.age_buffer_centisecs to 720000 does seem to help,
> but what are the consequences (if any) of doing this?
It means that metadata will stay active in the log for longer. That
means it is likely that recovery will take longer if your system
crashes. It also means that there may be more latency on transaction
reservation as tail-pushing the log is much more likely to occur
because metadata is not being pushed out by background flushing.
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2010-09-29 23:18 UTC | newest]
Thread overview: 10+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2010-09-15 15:26 Latencies writing to memory mapped files Shawn Bohrer
2010-09-16 0:18 ` Dave Chinner
2010-09-17 15:45 ` Shawn Bohrer
2010-09-20 0:05 ` Dave Chinner
2010-09-20 22:17 ` Shawn Bohrer
2010-09-20 22:48 ` Dave Chinner
2010-09-21 18:05 ` Shawn Bohrer
2010-09-21 23:15 ` Dave Chinner
2010-09-29 15:31 ` Shawn Bohrer
2010-09-29 23:19 ` Dave Chinner
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox