rendered paste bodymount: none already mounted or /sys/kernel/debug/ busy
mount: according to mtab, none is already mounted on /sys/kernel/debug
=============== Wed Feb 10 11:35:17 2010
Globals: Cause Maximum Percentage
Page fault 309.5 msec 83.6 %
Executing a program 17.5 msec 4.3 %
Writing a page to disk 15.8 msec 7.9 %
Reading EXT3 indirect blocks 14.6 msec 3.5 %
Walking directory tree 0.5 msec 0.6 %
[rpc_wait_bit_killable] 0.5 msec 0.1 %
Process details:
Process kblockd/1 (253) Total: 3.7 msec
. 3.7 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process rpciod/1 (407) Total: 1.8 msec
. 1.8 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process nfsiod (444) Total: 2.1 msec
. 1.8 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process latencytop (4042) Total: 5.4 msec
Writing a page to disk 4.1 msec 84.9 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read nfs_file_read do_sync_read vfs_read
sys_read system_call_fastpath
[rpc_wait_bit_killable] 0.5 msec 8.5 %
rpc_wait_bit_killable __rpc_execute rpc_execute rpc_run_task
rpc_call_sync T.906 nfs3_proc_access nfs_do_access
nfs_permission inode_permission may_open do_filp_open
Walking directory tree 0.4 msec 6.6 %
rpc_wait_bit_killable __rpc_execute rpc_execute rpc_run_task
rpc_call_sync T.906 nfs3_proc_lookup nfs_lookup do_lookup
link_path_walk path_walk do_path_lookup
=============== Wed Feb 10 11:35:27 2010
Globals: Cause Maximum Percentage
Writing a page to disk 1082.9 msec 29.4 %
Deleting an inode 226.7 msec 2.4 %
Scheduler: waiting for cpu 24.0 msec 67.0 %
Walking directory tree 7.6 msec 0.1 %
Writing to file 4.8 msec 0.3 %
Reading directory content 3.4 msec 0.4 %
Opening file 3.4 msec 0.1 %
Unlinking file 3.4 msec 0.1 %
Reading from file 3.3 msec 0.0 %
Process details:
Process ksoftirqd/0 (4) Total: 154.5 msec
Scheduler: waiting for cpu 8.0 msec 22.1 %
[run_ksoftirqd] 3.9 msec 77.9 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/1 (7) Total: 178.6 msec
Scheduler: waiting for cpu 4.0 msec 34.7 %
[run_ksoftirqd] 3.9 msec 65.3 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/2 (10) Total: 182.8 msec
Scheduler: waiting for cpu 8.0 msec 34.7 %
[run_ksoftirqd] 3.9 msec 65.3 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/3 (13) Total: 205.5 msec
Scheduler: waiting for cpu 4.0 msec 43.3 %
[run_ksoftirqd] 3.9 msec 56.7 %
run_ksoftirqd kthread kernel_thread_helper
Process events/2 (17) Total: 22.4 msec
Scheduler: waiting for cpu 6.5 msec 30.4 %
. 3.9 msec 69.6 %
worker_thread kthread kernel_thread_helper
Process kblockd/0 (252) Total: 159.1 msec
Scheduler: waiting for cpu 7.2 msec 36.0 %
. 5.0 msec 64.0 %
worker_thread kthread kernel_thread_helper
Process kblockd/1 (253) Total: 125.4 msec
Scheduler: waiting for cpu 5.4 msec 18.1 %
. 4.8 msec 81.9 %
worker_thread kthread kernel_thread_helper
Process kblockd/2 (254) Total: 145.6 msec
Scheduler: waiting for cpu 8.4 msec 27.4 %
. 4.9 msec 72.6 %
worker_thread kthread kernel_thread_helper
Process kblockd/3 (255) Total: 120.2 msec
. 4.9 msec 90.2 %
worker_thread kthread kernel_thread_helper
Scheduler: waiting for cpu 2.4 msec 9.8 %
Process sshd (2141) Total: 1.3 msec
Scheduler: waiting for cpu 0.1 msec 100.0 %
Process flush-btrfs-1 (2963) Total: 22.8 msec
Scheduler: waiting for cpu 5.3 msec 84.5 %
[bdi_writeback_task] 1.7 msec 15.5 %
bdi_writeback_task bdi_start_fn kthread kernel_thread_helper
Process btrfs-submit-0 (3511) Total: 42.7 msec
Scheduler: waiting for cpu 3.5 msec 15.0 %
[worker_loop] 3.3 msec 85.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-wri (3517) Total: 89.7 msec
Scheduler: waiting for cpu 5.8 msec 71.0 %
[worker_loop] 2.8 msec 29.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-worker-1 (3565) Total: 31.0 msec
Scheduler: waiting for cpu 5.8 msec 100.0 %
Process latencytop (4042) Total: 1.7 msec
Scheduler: waiting for cpu 1.2 msec 100.0 %
Process dbench (4044) Total: 2.3 msec
Page fault 0.7 msec 28.7 %
sync_page __lock_page find_lock_page filemap_fault __do_fault
handle_mm_fault do_page_fault page_fault clear_user padzero
load_elf_binary search_binary_handler
Walking directory tree 0.5 msec 20.2 %
rpc_wait_bit_killable __rpc_execute rpc_execute rpc_run_task
rpc_call_sync T.906 nfs3_proc_getattr __nfs_revalidate_inode
nfs_lookup_revalidate do_lookup link_path_walk path_walk
[rpc_wait_bit_killable] 0.4 msec 18.2 %
rpc_wait_bit_killable __rpc_execute rpc_execute rpc_run_task
rpc_call_sync T.906 nfs3_proc_access nfs_do_access
nfs_permission inode_permission may_open do_filp_open
Scheduler: waiting for cpu 0.3 msec 32.1 %
Process dbench (4045) Total: 2791.1 msec
Scheduler: waiting for cpu 20.1 msec 99.5 %
Writing a page to disk 13.0 msec 0.5 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read
system_call_fastpath
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4046) Total: 3910.2 msec
Writing a page to disk 861.0 msec 28.2 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read
system_call_fastpath
Scheduler: waiting for cpu 24.0 msec 71.7 %
Writing to file 0.9 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Process dbench (4047) Total: 3887.4 msec
Writing a page to disk 1082.9 msec 29.8 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read
system_call_fastpath
Scheduler: waiting for cpu 16.4 msec 70.1 %
Writing to file 3.8 msec 0.1 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Opening file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items btrfs_new_inode btrfs_create
vfs_create do_filp_open do_sys_open sys_open
system_call_fastpath
Process dbench (4048) Total: 3918.3 msec
Writing a page to disk 1018.5 msec 29.6 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read
system_call_fastpath
Scheduler: waiting for cpu 19.8 msec 70.3 %
Opening file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
Process dbench (4049) Total: 3981.7 msec
Writing a page to disk 1081.8 msec 28.6 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read
system_call_fastpath
Scheduler: waiting for cpu 20.0 msec 71.3 %
Writing to file 3.8 msec 0.1 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Process dbench (4050) Total: 3963.4 msec
Writing a page to disk 1081.7 msec 27.9 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read
system_call_fastpath
Scheduler: waiting for cpu 24.0 msec 71.9 %
Writing to file 3.7 msec 0.2 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Process dbench (4051) Total: 3196.9 msec
Writing a page to disk 194.8 msec 9.8 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read
system_call_fastpath
Scheduler: waiting for cpu 18.8 msec 90.1 %
Writing to file 1.2 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Process dbench (4052) Total: 3900.1 msec
Writing a page to disk 949.8 msec 28.8 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read
system_call_fastpath
Scheduler: waiting for cpu 20.0 msec 71.2 %
Writing to file 2.1 msec 0.1 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Process dbench (4053) Total: 4009.6 msec
Writing a page to disk 1050.8 msec 28.9 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read
system_call_fastpath
Scheduler: waiting for cpu 20.1 msec 71.0 %
Process dbench (4054) Total: 3962.4 msec
Writing a page to disk 912.2 msec 27.8 %
sync_page sync_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read
system_call_fastpath
Scheduler: waiting for cpu 20.0 msec 72.1 %
Writing to file 4.0 msec 0.1 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Opening file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
=============== Wed Feb 10 11:35:37 2010
Globals: Cause Maximum Percentage
Writing a page to disk 60.1 msec 0.1 %
Scheduler: waiting for cpu 22.0 msec 98.2 %
Walking directory tree 11.7 msec 0.4 %
Waiting for a process to die 3.4 msec 0.0 %
Opening file 2.5 msec 0.2 %
Writing to file 2.5 msec 0.2 %
Unlinking file 2.5 msec 0.2 %
Reading directory content 2.5 msec 0.6 %
Deleting an inode 1.0 msec 0.1 %
Process details:
Process ksoftirqd/0 (4) Total: 223.1 msec
Scheduler: waiting for cpu 6.3 msec 46.0 %
[run_ksoftirqd] 3.9 msec 54.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/1 (7) Total: 250.4 msec
[run_ksoftirqd] 4.8 msec 48.4 %
run_ksoftirqd kthread kernel_thread_helper
Scheduler: waiting for cpu 4.0 msec 51.6 %
Process ksoftirqd/2 (10) Total: 282.9 msec
Scheduler: waiting for cpu 8.0 msec 57.5 %
[run_ksoftirqd] 3.9 msec 42.5 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/3 (13) Total: 294.8 msec
Scheduler: waiting for cpu 8.0 msec 59.1 %
[run_ksoftirqd] 4.1 msec 40.9 %
run_ksoftirqd kthread kernel_thread_helper
Process events/2 (17) Total: 4.1 msec
. 3.9 msec 94.2 %
worker_thread kthread kernel_thread_helper
Process kblockd/0 (252) Total: 1.3 msec
Scheduler: waiting for cpu 0.7 msec 100.0 %
Process kblockd/2 (254) Total: 2.2 msec
Scheduler: waiting for cpu 1.5 msec 100.0 %
Process latencytop (4042) Total: 30.9 msec
Scheduler: waiting for cpu 10.5 msec 100.0 %
Process dbench (4045) Total: 6037.7 msec
Scheduler: waiting for cpu 20.1 msec 99.9 %
Unlinking file 3.4 msec 0.1 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_inode btrfs_update_inode btrfs_unlink_inode
btrfs_unlink vfs_unlink do_unlinkat sys_unlink
system_call_fastpath
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4046) Total: 5855.7 msec
Scheduler: waiting for cpu 19.8 msec 99.9 %
Opening file 3.4 msec 0.1 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_inode btrfs_update_inode btrfs_add_link
btrfs_add_nondir btrfs_create vfs_create do_filp_open
do_sys_open sys_open
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4047) Total: 5869.8 msec
Scheduler: waiting for cpu 21.8 msec 100.0 %
Process dbench (4048) Total: 6011.6 msec
Scheduler: waiting for cpu 20.1 msec 100.0 %
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4049) Total: 5880.6 msec
Scheduler: waiting for cpu 20.1 msec 100.0 %
Process dbench (4050) Total: 6009.2 msec
Scheduler: waiting for cpu 20.1 msec 100.0 %
Deleting an inode 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_truncate_inode_items btrfs_delete_inode
generic_delete_inode generic_drop_inode btrfs_drop_inode
iput do_unlinkat sys_unlink system_call_fastpath
Process dbench (4051) Total: 5896.3 msec
Scheduler: waiting for cpu 20.0 msec 100.0 %
Unlinking file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_dir_item btrfs_unlink_inode btrfs_unlink
vfs_unlink do_unlinkat sys_unlink system_call_fastpath
Process dbench (4052) Total: 5955.8 msec
Scheduler: waiting for cpu 20.2 msec 100.0 %
Deleting an inode 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_del_orphan_item btrfs_orphan_del btrfs_delete_inode
generic_delete_inode generic_drop_inode btrfs_drop_inode
iput do_unlinkat sys_unlink
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4053) Total: 5955.2 msec
Scheduler: waiting for cpu 20.1 msec 100.0 %
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4054) Total: 6040.5 msec
Scheduler: waiting for cpu 22.0 msec 100.0 %
Reading from file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_inode btrfs_update_inode btrfs_dirty_inode
__mark_inode_dirty touch_atime generic_file_aio_read
do_sync_read vfs_read sys_pread64
=============== Wed Feb 10 11:35:47 2010
Globals: Cause Maximum Percentage
Writing a page to disk 221.4 msec 3.7 %
Scheduler: waiting for cpu 21.1 msec 94.1 %
Writing to file 14.6 msec 0.3 %
Deleting an inode 13.9 msec 0.1 %
Walking directory tree 13.7 msec 0.5 %
Reading directory content 4.2 msec 0.7 %
Opening file 4.2 msec 0.3 %
Waiting for a process to die 4.0 msec 0.0 %
Unlinking file 2.1 msec 0.2 %
Process details:
Process init (1) Total: 1.1 msec
Scheduler: waiting for cpu 1.1 msec 100.0 %
Process ksoftirqd/0 (4) Total: 227.9 msec
Scheduler: waiting for cpu 4.8 msec 47.4 %
[run_ksoftirqd] 3.9 msec 52.6 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/1 (7) Total: 257.7 msec
Scheduler: waiting for cpu 6.9 msec 52.9 %
[run_ksoftirqd] 4.9 msec 47.1 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/2 (10) Total: 289.0 msec
Scheduler: waiting for cpu 13.9 msec 60.0 %
[run_ksoftirqd] 3.9 msec 40.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/3 (13) Total: 311.2 msec
Scheduler: waiting for cpu 8.0 msec 62.1 %
[run_ksoftirqd] 3.9 msec 37.9 %
run_ksoftirqd kthread kernel_thread_helper
Process events/0 (15) Total: 1.0 msec
Scheduler: waiting for cpu 0.9 msec 100.0 %
Process events/2 (17) Total: 4.0 msec
Scheduler: waiting for cpu 3.7 msec 100.0 %
Process events/3 (18) Total: 0.8 msec
Scheduler: waiting for cpu 0.6 msec 100.0 %
Process kblockd/0 (252) Total: 129.2 msec
. 4.6 msec 66.5 %
worker_thread kthread kernel_thread_helper
Scheduler: waiting for cpu 3.0 msec 33.5 %
Process kblockd/1 (253) Total: 102.5 msec
. 4.5 msec 81.6 %
worker_thread kthread kernel_thread_helper
Scheduler: waiting for cpu 3.6 msec 18.4 %
Process kblockd/2 (254) Total: 104.3 msec
. 4.0 msec 88.0 %
worker_thread kthread kernel_thread_helper
Scheduler: waiting for cpu 2.9 msec 12.0 %
Process kblockd/3 (255) Total: 132.7 msec
Scheduler: waiting for cpu 5.7 msec 26.8 %
. 4.6 msec 73.2 %
worker_thread kthread kernel_thread_helper
Process sshd (2141) Total: 0.2 msec
Scheduler: waiting for cpu 0.1 msec 100.0 %
Process btrfs-endio-met (2175) Total: 19.2 msec
[worker_loop] 4.8 msec 92.4 %
worker_loop kthread kernel_thread_helper
Scheduler: waiting for cpu 0.2 msec 7.6 %
Process flush-btrfs-1 (2963) Total: 34.0 msec
Scheduler: waiting for cpu 4.2 msec 52.8 %
[bdi_writeback_task] 3.9 msec 47.2 %
bdi_writeback_task bdi_start_fn kthread kernel_thread_helper
Process btrfs-submit-0 (3511) Total: 61.4 msec
Scheduler: waiting for cpu 6.9 msec 90.5 %
[worker_loop] 1.3 msec 9.5 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-wri (3517) Total: 275.0 msec
Scheduler: waiting for cpu 10.9 msec 98.5 %
[worker_loop] 0.7 msec 1.2 %
worker_loop kthread kernel_thread_helper
[btrfs_tree_lock] 0.3 msec 0.3 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_file_extent btrfs_drop_extents T.1059
btrfs_finish_ordered_io btrfs_writepage_end_io_hook
end_bio_extent_writepage bio_endio end_workqueue_fn
worker_loop
Process btrfs-transacti (3520) Total: 159.9 msec
Writing a page to disk 30.9 msec 92.1 %
sync_page wait_on_page_bit btrfs_wait_marked_extents
btrfs_write_and_wait_marked_extents
btrfs_write_and_wait_transaction btrfs_commit_transaction
transaction_kthread kthread kernel_thread_helper
Writing buffer to disk (synchronous) 6.9 msec 4.3 %
sync_buffer __wait_on_buffer write_dev_supers write_all_supers
write_ctree_super btrfs_commit_transaction transaction_kthread
kthread kernel_thread_helper
Scheduler: waiting for cpu 5.3 msec 3.5 %
Process btrfs-worker-1 (3565) Total: 174.6 msec
Scheduler: waiting for cpu 10.0 msec 100.0 %
Process latencytop (4042) Total: 7.7 msec
Scheduler: waiting for cpu 4.0 msec 100.0 %
Process dbench (4045) Total: 5868.3 msec
Scheduler: waiting for cpu 20.0 msec 100.0 %
Walking directory tree 1.1 msec 0.0 %
do_lookup link_path_walk path_walk do_path_lookup do_filp_open
do_sys_open sys_open system_call_fastpath
Opening file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
Unlinking file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_search_slot btrfs_del_inode_ref
btrfs_unlink_inode btrfs_unlink vfs_unlink do_unlinkat
sys_unlink system_call_fastpath
Process dbench (4046) Total: 5856.6 msec
Scheduler: waiting for cpu 17.5 msec 100.0 %
Writing to file 0.3 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Walking directory tree 0.2 msec 0.0 %
do_lookup link_path_walk path_walk do_path_lookup do_filp_open
do_sys_open sys_open system_call_fastpath
Opening file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
Process dbench (4047) Total: 5652.6 msec
Scheduler: waiting for cpu 20.0 msec 100.0 %
Opening file 0.4 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
Unlinking file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_inode btrfs_update_inode btrfs_unlink_inode
btrfs_unlink vfs_unlink do_unlinkat sys_unlink
system_call_fastpath
Process dbench (4048) Total: 5764.2 msec
Scheduler: waiting for cpu 19.5 msec 100.0 %
Unlinking file 0.3 msec 0.0 %
btrfs_tree_lock btrfs_search_slot btrfs_lookup_inode
btrfs_update_inode btrfs_unlink_inode btrfs_unlink vfs_unlink
do_unlinkat sys_unlink system_call_fastpath
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4049) Total: 5795.9 msec
Scheduler: waiting for cpu 20.0 msec 100.0 %
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4050) Total: 5720.4 msec
Scheduler: waiting for cpu 20.0 msec 100.0 %
Writing to file 0.3 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_search_slot btrfs_real_readdir
vfs_readdir sys_getdents system_call_fastpath
Process dbench (4051) Total: 5912.2 msec
Scheduler: waiting for cpu 21.0 msec 100.0 %
Opening file 0.5 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
Writing to file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_search_slot btrfs_lookup_file_extent
btrfs_get_extent btrfs_cont_expand prepare_pages
btrfs_file_write vfs_write sys_pwrite64 system_call_fastpath
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Reading from file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_inode btrfs_update_inode btrfs_dirty_inode
__mark_inode_dirty touch_atime generic_file_aio_read
do_sync_read vfs_read sys_pread64
Process dbench (4052) Total: 5787.4 msec
Scheduler: waiting for cpu 17.4 msec 100.0 %
Reading directory content 0.3 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4053) Total: 5721.3 msec
Scheduler: waiting for cpu 21.1 msec 100.0 %
[btrfs_tree_lock] 0.4 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_del_inode_ref btrfs_unlink_inode btrfs_rename vfs_rename
sys_renameat sys_rename system_call_fastpath
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Unlinking file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_inode btrfs_update_inode btrfs_unlink_inode
btrfs_unlink vfs_unlink do_unlinkat sys_unlink
system_call_fastpath
Process dbench (4054) Total: 5845.3 msec
Scheduler: waiting for cpu 18.5 msec 100.0 %
Walking directory tree 1.1 msec 0.0 %
do_lookup link_path_walk path_walk do_path_lookup do_filp_open
do_sys_open sys_open system_call_fastpath
Writing to file 0.4 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Opening file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
=============== Wed Feb 10 11:35:57 2010
Globals: Cause Maximum Percentage
Writing a page to disk 118.2 msec 1.0 %
Scheduler: waiting for cpu 24.2 msec 97.1 %
Walking directory tree 14.3 msec 0.5 %
Writing to file 8.1 msec 0.2 %
Opening file 2.8 msec 0.3 %
Reading directory content 2.7 msec 0.6 %
[btrfs_tree_lock] 2.7 msec 0.0 %
Unlinking file 2.7 msec 0.2 %
Deleting an inode 1.2 msec 0.1 %
Process details:
Process ksoftirqd/0 (4) Total: 253.9 msec
Scheduler: waiting for cpu 7.6 msec 52.5 %
[run_ksoftirqd] 3.9 msec 47.5 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/1 (7) Total: 294.1 msec
Scheduler: waiting for cpu 8.0 msec 60.2 %
[run_ksoftirqd] 3.9 msec 39.8 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/2 (10) Total: 314.7 msec
Scheduler: waiting for cpu 7.3 msec 61.8 %
[run_ksoftirqd] 3.9 msec 38.2 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/3 (13) Total: 284.6 msec
Scheduler: waiting for cpu 6.0 msec 58.1 %
[run_ksoftirqd] 3.9 msec 41.9 %
run_ksoftirqd kthread kernel_thread_helper
Process events/2 (17) Total: 4.0 msec
. 3.9 msec 95.4 %
worker_thread kthread kernel_thread_helper
Process kblockd/0 (252) Total: 126.7 msec
. 4.9 msec 78.1 %
worker_thread kthread kernel_thread_helper
Scheduler: waiting for cpu 2.6 msec 21.9 %
Process kblockd/1 (253) Total: 132.3 msec
. 5.0 msec 80.9 %
worker_thread kthread kernel_thread_helper
Scheduler: waiting for cpu 4.7 msec 19.1 %
Process kblockd/2 (254) Total: 123.9 msec
. 4.9 msec 84.5 %
worker_thread kthread kernel_thread_helper
Scheduler: waiting for cpu 4.8 msec 15.5 %
Process kblockd/3 (255) Total: 133.1 msec
. 4.9 msec 74.8 %
worker_thread kthread kernel_thread_helper
Scheduler: waiting for cpu 4.2 msec 25.2 %
Process flush-btrfs-1 (2963) Total: 24.2 msec
[bdi_writeback_task] 4.7 msec 98.4 %
bdi_writeback_task bdi_start_fn kthread kernel_thread_helper
Scheduler: waiting for cpu 0.2 msec 1.6 %
Process btrfs-submit-0 (3511) Total: 41.5 msec
Scheduler: waiting for cpu 6.7 msec 77.5 %
[worker_loop] 3.6 msec 22.5 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-wri (3517) Total: 135.8 msec
Scheduler: waiting for cpu 5.9 msec 84.6 %
[worker_loop] 4.5 msec 15.2 %
worker_loop kthread kernel_thread_helper
[btrfs_tree_lock] 0.3 msec 0.3 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items T.1059 btrfs_finish_ordered_io
btrfs_writepage_end_io_hook end_bio_extent_writepage bio_endio
end_workqueue_fn worker_loop kthread
Process btrfs-worker-1 (3565) Total: 286.1 msec
Scheduler: waiting for cpu 8.9 msec 99.8 %
[worker_loop] 0.6 msec 0.2 %
worker_loop kthread kernel_thread_helper
Process latencytop (4042) Total: 7.8 msec
Scheduler: waiting for cpu 3.8 msec 100.0 %
Process dbench (4045) Total: 5856.9 msec
Scheduler: waiting for cpu 24.2 msec 99.9 %
Unlinking file 2.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_dir_item btrfs_unlink_inode btrfs_unlink
vfs_unlink do_unlinkat sys_unlink system_call_fastpath
[btrfs_tree_lock] 0.2 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_dir_item btrfs_unlink_inode btrfs_rename
vfs_rename sys_renameat sys_rename system_call_fastpath
Deleting an inode 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_truncate_inode_items btrfs_delete_inode
generic_delete_inode generic_drop_inode btrfs_drop_inode
iput do_unlinkat sys_unlink system_call_fastpath
Process dbench (4046) Total: 6037.1 msec
Scheduler: waiting for cpu 24.0 msec 99.9 %
Reading directory content 2.0 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Opening file 0.2 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
Process dbench (4047) Total: 5878.3 msec
Scheduler: waiting for cpu 20.0 msec 100.0 %
Opening file 2.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
Reading directory content 0.2 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_inode btrfs_update_inode btrfs_dirty_inode
__mark_inode_dirty touch_atime vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4048) Total: 6016.0 msec
Scheduler: waiting for cpu 24.0 msec 100.0 %
Reading directory content 2.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Unlinking file 0.2 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_del_inode_ref btrfs_unlink_inode btrfs_unlink vfs_unlink
do_unlinkat sys_unlink system_call_fastpath
Process dbench (4049) Total: 5904.4 msec
Scheduler: waiting for cpu 24.1 msec 100.0 %
Reading directory content 2.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_next_leaf btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4050) Total: 5910.0 msec
Scheduler: waiting for cpu 21.7 msec 99.9 %
Unlinking file 2.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_del_inode_ref btrfs_unlink_inode btrfs_unlink vfs_unlink
do_unlinkat sys_unlink system_call_fastpath
Opening file 0.2 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
Writing to file 0.2 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_search_slot btrfs_real_readdir
vfs_readdir sys_getdents system_call_fastpath
Process dbench (4051) Total: 5900.5 msec
Scheduler: waiting for cpu 20.3 msec 99.9 %
Writing to file 2.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_xattr __btrfs_getxattr btrfs_getxattr
cap_inode_need_killpriv file_remove_suid btrfs_file_write
vfs_write sys_pwrite64 system_call_fastpath
Reading directory content 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4052) Total: 5924.7 msec
Scheduler: waiting for cpu 20.0 msec 100.0 %
Reading directory content 0.2 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_real_readdir vfs_readdir sys_getdents
system_call_fastpath
Process dbench (4053) Total: 6011.0 msec
Scheduler: waiting for cpu 22.2 msec 99.9 %
Reading directory content 2.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_inode btrfs_update_inode btrfs_dirty_inode
__mark_inode_dirty touch_atime vfs_readdir sys_getdents
system_call_fastpath
Opening file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_insert_empty_items insert_with_overflow
btrfs_insert_dir_item btrfs_add_link btrfs_add_nondir
btrfs_create vfs_create do_filp_open do_sys_open
Unlinking file 0.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_dir_item btrfs_unlink_inode btrfs_unlink
vfs_unlink do_unlinkat sys_unlink system_call_fastpath
Process dbench (4054) Total: 5983.9 msec
Scheduler: waiting for cpu 20.8 msec 100.0 %
[btrfs_tree_lock] 2.1 msec 0.0 %
btrfs_tree_lock btrfs_lock_root_node btrfs_search_slot
btrfs_lookup_dir_item btrfs_unlink_inode btrfs_rename
vfs_rename sys_renameat sys_rename system_call_fastpath