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@xxxxxxxxxxx http://oss.sgi.com/mailman/listinfo/xfs
