On Thu, Jul 28, 2011 at 04:51:24PM -0400, Chris Mason wrote:

Sorry, hit send too soon.  Here is the latencytop patch, after you
recompile run latencytop -c for a few minutes.  Send the output here.

http://oss.oracle.com/~mason/latencytop.patch

Ok, I ran it for more than a few minutes.  Early on (shortly after boot), the output shows this for a long time:

=============== Mon Aug  1 21:09:30 2011
Globals: Cause Maximum Percentage
Process details:
Process ksoftirqd/0 (3) Total:   3.9 msec
        [run_ksoftirqd]   3.9 msec        100.0 %
                run_ksoftirqd kthread kernel_thread_helper 
Process kworker/1:1 (983) Total:  31.2 msec
        .         3.9 msec        100.0 %
                worker_thread kthread kernel_thread_helper 
Process sshd (3948) Total:   3.9 msec
        Waiting for event (select)        3.9 msec        100.0 %
                poll_schedule_timeout do_select core_sys_select sys_select 
                system_call_fastpath 
Process btrfs-cleaner (4345) Total: 2433.6 msec
        [sleep_on_page]  31.3 msec        100.0 %
                sleep_on_page wait_on_page_bit read_extent_buffer_pages 
                btree_read_extent_buffer_pages read_tree_block 
                read_block_for_search btrfs_search_slot 
                lookup_inline_extent_backref __btrfs_free_extent 
                run_clustered_refs btrfs_run_delayed_refs __btrfs_end_transaction 
Process btrfs-transacti (4346) Total: 2437.5 msec
        [sleep_on_page]  27.3 msec        100.0 %
                sleep_on_page wait_on_page_bit read_extent_buffer_pages 
                btree_read_extent_buffer_pages read_tree_block 
                read_block_for_search btrfs_search_slot 
                lookup_inline_extent_backref __btrfs_free_extent 
                run_clustered_refs btrfs_run_delayed_refs btrfs_commit_transaction 

This repeats identically (all numbers and backtrace is very stable) for
a long time.  Much later, I see this:

=============== Tue Aug  2 13:46:29 2011
Globals: Cause Maximum Percentage
Process details:
Process btrfs-submit-0 (4332) Total: 199.2 msec
        Creating block layer request     58.6 msec        100.0 %
                get_request_wait __make_request generic_make_request 
                submit_bio run_scheduled_bios pending_bios_fn worker_loop 
                kthread kernel_thread_helper 
Process btrfs-cleaner (4345) Total:   3.9 msec
        Creating block layer request      3.9 msec        100.0 %
                get_request_wait __make_request generic_make_request 
                submit_bio btrfs_map_bio btree_submit_bio_hook submit_one_bio 
                read_extent_buffer_pages readahead_tree_block reada_walk_down 
                do_walk_down walk_down_tree 
Process btrfs-endio-met (4700) Total:  35.2 msec
        [worker_loop]     3.9 msec        100.0 %
                worker_loop kthread kernel_thread_helper 
Process kworker/1:2 (26315) Total:  50.8 msec
        .         3.9 msec        100.0 %
                worker_thread kthread kernel_thread_helper 
[...snip...]
=============== Thu Aug  4 12:34:08 2011
Globals: Cause Maximum Percentage
Process details:
Process btrfs-submit-0 (4332) Total: 199.2 msec
        Creating block layer request     58.6 msec        100.0 %
                get_request_wait __make_request generic_make_request 
                submit_bio run_scheduled_bios pending_bios_fn worker_loop 
                kthread kernel_thread_helper 
Process btrfs-cleaner (4345) Total:   3.9 msec
        Creating block layer request      3.9 msec        100.0 %
                get_request_wait __make_request generic_make_request 
                submit_bio btrfs_map_bio btree_submit_bio_hook submit_one_bio 
                read_extent_buffer_pages readahead_tree_block reada_walk_down 
                do_walk_down walk_down_tree 
Process btrfs-endio-met (4700) Total:  35.2 msec
        [worker_loop]     3.9 msec        100.0 %
                worker_loop kthread kernel_thread_helper 


-- 
Bruce Guenter [off-list ref]                http://untroubled.org/