Skip to content

Instantly share code, notes, and snippets.

@cataliniacob
Created May 31, 2012 19:38
Show Gist options
  • Select an option

  • Save cataliniacob/2845725 to your computer and use it in GitHub Desktop.

Select an option

Save cataliniacob/2845725 to your computer and use it in GitHub Desktop.
results-mount-from-liveusb-1
=============== Thu May 31 21:08:42 2012
Globals: Cause Maximum Percentage
Waiting for event (poll) 3.9 msec 28.2 %
Waiting for event (select) 3.6 msec 41.0 %
Waiting for GPU command to complete 1.5 msec 9.1 %
Reading from file 0.8 msec 17.7 %
Userspace lock contention 0.5 msec 3.9 %
Process details:
Process ksoftirqd/0 (3) Total: 5.2 msec
[run_ksoftirqd] 4.8 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/1 (16) Total: 1.4 msec
[run_ksoftirqd] 1.2 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process kworker/1:1 (60) Total: 8.7 msec
. 4.8 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kworker/2:1 (291) Total: 2.4 msec
Executing raw SCSI command 0.9 msec 66.5 %
blk_execute_rq scsi_execute scsi_execute_req
scsi_test_unit_ready sd_check_events disk_events_workfn
process_one_work worker_thread kthread kernel_thread_helper
. 0.8 msec 33.5 %
worker_thread kthread kernel_thread_helper
Process usb-storage (300) Total: 0.7 msec
[usb_stor_msg_common] 0.2 msec 100.0 %
usb_stor_msg_common usb_stor_bulk_transfer_buf
usb_stor_Bulk_transport usb_stor_invoke_transport
usb_stor_control_thread kthread kernel_thread_helper
Process clicfs (808) Total: 8.4 msec
Reading from file 0.8 msec 100.0 %
fuse_dev_do_read.isra.11 fuse_dev_read do_sync_read vfs_read
sys_read system_call_fastpath
Process loop0 (817) Total: 0.9 msec
synchronous write 0.1 msec 93.2 %
wait_answer_interruptible fuse_request_send fuse_perform_write
fuse_file_aio_write do_sync_write __do_lo_send_write
do_lo_send_direct_write loop_thread kthread kernel_thread_helper
Process kjournald (818) Total: 4.4 msec
EXT3: committing transaction 3.0 msec 100.0 %
sleep_on_buffer journal_commit_transaction kjournald kthread
kernel_thread_helper
Process kworker/6:2 (1478) Total: 0.4 msec
. 0.4 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kworker/7:2 (1481) Total: 1.5 msec
. 0.8 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process Xorg (1621) Total: 20.7 msec
Waiting for event (select) 3.6 msec 93.7 %
poll_schedule_timeout do_select core_sys_select sys_select
system_call_fastpath
Waiting for GPU command to complete 0.4 msec 6.3 %
i915_wait_request i915_gem_do_execbuffer.isra.7
i915_gem_execbuffer2 drm_ioctl do_vfs_ioctl sys_ioctl
system_call_fastpath
Process gnome-shell (2352) Total: 11.8 msec
Waiting for event (poll) 3.7 msec 74.5 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Waiting for GPU command to complete 1.5 msec 25.5 %
i915_wait_request i915_gem_object_set_to_gtt_domain
i915_gem_set_domain_ioctl drm_ioctl do_vfs_ioctl sys_ioctl
system_call_fastpath
Process gnome-terminal (2456) Total: 4.7 msec
Waiting for event (poll) 3.9 msec 98.9 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Process firefox-bin (2483) Total: 1.9 msec
Userspace lock contention 0.5 msec 100.0 %
futex_wait_queue_me futex_wait do_futex sys_futex
system_call_fastpath
Process kworker/0:0 (2933) Total: 15.1 msec
. 4.8 msec 69.1 %
worker_thread kthread kernel_thread_helper
Executing raw SCSI command 2.4 msec 30.9 %
blk_execute_rq scsi_execute scsi_execute_req sr_check_events
cdrom_check_events disk_events_workfn process_one_work
worker_thread kthread kernel_thread_helper
=============== Thu May 31 21:08:52 2012
Globals: Cause Maximum Percentage
Synchronous buffer read 295.2 msec 22.2 %
[call_usermodehelper_exec] 121.5 msec 7.7 %
[sleep_on_page] 51.5 msec 32.1 %
Page fault 12.5 msec 5.3 %
Reading from file 10.0 msec 10.9 %
Waiting for event (select) 5.0 msec 10.7 %
Waiting for event (poll) 4.9 msec 7.7 %
Reading EXT3 inode 4.0 msec 0.3 %
[i915_gem_madvise_ioctl] 3.8 msec 0.2 %
Process details:
Process kthreadd (2) Total: 4.7 msec
kthreadd kernel thread 0.5 msec 100.0 %
kthreadd kernel_thread_helper
Process ksoftirqd/0 (3) Total: 15.3 msec
[run_ksoftirqd] 4.0 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/1 (16) Total: 9.4 msec
[run_ksoftirqd] 3.0 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/2 (22) Total: 9.8 msec
[run_ksoftirqd] 2.5 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/3 (27) Total: 4.2 msec
[run_ksoftirqd] 2.7 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/4 (32) Total: 2.9 msec
[run_ksoftirqd] 1.5 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/5 (37) Total: 3.8 msec
[run_ksoftirqd] 3.0 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/6 (42) Total: 1.6 msec
[run_ksoftirqd] 0.9 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/7 (47) Total: 5.2 msec
[run_ksoftirqd] 1.8 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process kworker/1:1 (60) Total: 24.6 msec
. 4.8 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kworker/3:2 (85) Total: 14.5 msec
. 3.4 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kworker/2:1 (291) Total: 26.7 msec
. 4.9 msec 87.0 %
worker_thread kthread kernel_thread_helper
Executing raw SCSI command 0.9 msec 13.0 %
blk_execute_rq scsi_execute scsi_execute_req
scsi_test_unit_ready sd_check_events disk_events_workfn
process_one_work worker_thread kthread kernel_thread_helper
Process usb-storage (300) Total: 47.3 msec
[usb_sg_wait] 6.9 msec 91.8 %
usb_sg_wait usb_stor_bulk_transfer_sglist.part.5
usb_stor_bulk_srb usb_stor_Bulk_transport
usb_stor_invoke_transport usb_stor_control_thread kthread
kernel_thread_helper
[usb_stor_msg_common] 0.2 msec 7.7 %
usb_stor_msg_common usb_stor_bulk_transfer_buf
usb_stor_Bulk_transport usb_stor_invoke_transport
usb_stor_control_thread kthread kernel_thread_helper
Process kworker/2:2 (499) Total: 0.1 msec
. 0.1 msec 100.0 %
kthread_create_on_node create_worker manage_workers.isra.25
worker_thread kthread kernel_thread_helper
Process clicfs (808) Total: 151.2 msec
Reading from file 7.3 msec 100.0 %
fuse_dev_do_read.isra.11 fuse_dev_read do_sync_read vfs_read
sys_read system_call_fastpath
Process loop0 (817) Total: 44.6 msec
[wait_answer_interruptible] 4.7 msec 86.4 %
wait_answer_interruptible fuse_request_send fuse_readpage
__generic_file_splice_read generic_file_splice_read
splice_direct_to_actor lo_receive loop_thread kthread kernel_thread_helper
synchronous write 3.2 msec 12.1 %
wait_answer_interruptible fuse_request_send fuse_perform_write
fuse_file_aio_write do_sync_write __do_lo_send_write
do_lo_send_direct_write loop_thread kthread kernel_thread_helper
[loop_thread] 0.3 msec 1.5 %
loop_thread kthread kernel_thread_helper
Process kjournald (818) Total: 15.2 msec
EXT3: committing transaction 6.0 msec 100.0 %
sleep_on_buffer journal_commit_transaction kjournald kthread
kernel_thread_helper
Process udevd (1122) Total: 1.1 msec
Waiting for event (epoll) 0.3 msec 100.0 %
sys_epoll_wait system_call_fastpath
Process udevd (1236) Total: 0.4 msec
Waiting for event (epoll) 0.4 msec 100.0 %
sys_epoll_wait system_call_fastpath
Process kworker/6:2 (1478) Total: 0.2 msec
. 0.2 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process Xorg (1621) Total: 179.1 msec
Waiting for event (select) 5.0 msec 94.3 %
poll_schedule_timeout do_select core_sys_select sys_select
system_call_fastpath
[i915_gem_madvise_ioctl] 3.8 msec 2.1 %
i915_gem_madvise_ioctl drm_ioctl do_vfs_ioctl sys_ioctl
system_call_fastpath
Waiting for GPU command to complete 0.7 msec 3.6 %
i915_wait_request i915_gem_do_execbuffer.isra.7
i915_gem_execbuffer2 drm_ioctl do_vfs_ioctl sys_ioctl
system_call_fastpath
Process dbus-daemon (2114) Total: 6.6 msec
Waiting for event (epoll) 2.1 msec 100.0 %
sys_epoll_wait system_call_fastpath
Process gnome-settings- (2254) Total: 4.6 msec
Waiting for event (poll) 0.5 msec 100.0 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Process gnome-shell (2352) Total: 82.3 msec
Waiting for event (poll) 4.9 msec 79.4 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Waiting for GPU command to complete 3.7 msec 20.6 %
i915_wait_request i915_gem_object_set_to_gtt_domain
i915_gem_set_domain_ioctl drm_ioctl do_vfs_ioctl sys_ioctl
system_call_fastpath
Process tracker-store (2363) Total: 2.8 msec
Waiting for event (poll) 1.4 msec 100.0 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Process tracker-miner-f (2370) Total: 14.2 msec
Waiting for event (poll) 2.7 msec 94.1 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Userspace lock contention 0.8 msec 5.9 %
futex_wait_queue_me futex_wait do_futex sys_futex
system_call_fastpath
Process gnome-terminal (2456) Total: 32.2 msec
Waiting for event (poll) 4.7 msec 97.2 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Waiting for TTY data 0.8 msec 2.8 %
flush_work n_tty_poll tty_poll do_sys_poll sys_poll
system_call_fastpath
Process firefox-bin (2483) Total: 6.2 msec
Waiting for event (poll) 1.8 msec 28.7 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Userspace lock contention 0.5 msec 71.3 %
futex_wait_queue_me futex_wait do_futex sys_futex
system_call_fastpath
Process kworker/0:0 (2933) Total: 147.5 msec
. 4.7 msec 92.1 %
worker_thread kthread kernel_thread_helper
Executing raw SCSI command 2.3 msec 7.9 %
blk_execute_rq scsi_execute scsi_execute_req sr_check_events
cdrom_check_events disk_events_workfn process_one_work
worker_thread kthread kernel_thread_helper
Process kworker/1:0 (3114) Total: 0.4 msec
. 0.4 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process tracker-extract (3354) Total: 1.9 msec
Waiting for event (poll) 1.3 msec 100.0 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Process mount (3393) Total: 978.6 msec
Synchronous buffer read 295.2 msec 35.7 %
sleep_on_buffer __bread btrfs_read_dev_super
btrfs_scan_one_device btrfs_mount mount_fs vfs_kern_mount
do_kern_mount do_mount sys_mount system_call_fastpath
[call_usermodehelper_exec] 121.5 msec 12.4 %
call_usermodehelper_exec __request_module get_fs_type
do_kern_mount do_mount sys_mount system_call_fastpath
[sleep_on_page] 51.5 msec 51.6 %
sleep_on_page wait_on_page_bit read_extent_buffer_pages
btree_read_extent_buffer_pages.constprop.113 read_tree_block
open_ctree btrfs_mount mount_fs vfs_kern_mount do_kern_mount
do_mount sys_mount
[kthread_create_on_node] 0.2 msec 0.2 %
kthread_create_on_node __btrfs_start_workers open_ctree
btrfs_mount mount_fs vfs_kern_mount do_kern_mount do_mount
sys_mount system_call_fastpath
Process btrfs-endio-met (3402) Total: 31.0 msec
[worker_loop] 3.7 msec 99.8 %
worker_loop kthread kernel_thread_helper
=============== Thu May 31 21:09:02 2012
Globals: Cause Maximum Percentage
[sleep_on_page] 30.1 msec 85.3 %
Userspace lock contention 4.8 msec 0.8 %
Waiting for event (select) 4.7 msec 4.0 %
Waiting for event (poll) 4.4 msec 3.1 %
Waiting for GPU command to complete 3.6 msec 0.5 %
[i915_gem_set_tiling] 3.6 msec 0.1 %
Waiting for event (epoll) 2.5 msec 0.3 %
fsync() on a file (type 'F' for details) 2.3 msec 1.5 %
Reading from file 1.4 msec 4.4 %
Process details:
Process kthreadd (2) Total: 0.4 msec
kthreadd kernel thread 0.4 msec 100.0 %
kthreadd kernel_thread_helper
Process ksoftirqd/0 (3) Total: 14.2 msec
[run_ksoftirqd] 4.0 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/1 (16) Total: 4.7 msec
[run_ksoftirqd] 1.4 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/2 (22) Total: 6.3 msec
[run_ksoftirqd] 2.7 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/3 (27) Total: 4.7 msec
[run_ksoftirqd] 1.1 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/4 (32) Total: 3.7 msec
[run_ksoftirqd] 2.8 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process ksoftirqd/7 (47) Total: 0.4 msec
[run_ksoftirqd] 0.4 msec 100.0 %
run_ksoftirqd kthread kernel_thread_helper
Process kworker/1:1 (60) Total: 13.2 msec
. 4.9 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kworker/3:2 (85) Total: 15.2 msec
. 4.9 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kworker/4:1 (290) Total: 7.7 msec
. 4.1 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kworker/2:1 (291) Total: 16.4 msec
. 4.9 msec 80.0 %
worker_thread kthread kernel_thread_helper
Executing raw SCSI command 0.8 msec 20.0 %
blk_execute_rq scsi_execute scsi_execute_req
scsi_test_unit_ready sd_check_events disk_events_workfn
process_one_work worker_thread kthread kernel_thread_helper
Process usb-storage (300) Total: 1.5 msec
[usb_stor_msg_common] 0.2 msec 100.0 %
usb_stor_msg_common usb_stor_bulk_transfer_buf
usb_stor_Bulk_transport usb_stor_invoke_transport
usb_stor_control_thread kthread kernel_thread_helper
Process clicfs (808) Total: 123.3 msec
Reading from file 1.4 msec 100.0 %
fuse_dev_do_read.isra.11 fuse_dev_read do_sync_read vfs_read
sys_read system_call_fastpath
Process loop0 (817) Total: 17.5 msec
synchronous write 1.1 msec 96.0 %
wait_answer_interruptible fuse_request_send fuse_perform_write
fuse_file_aio_write do_sync_write __do_lo_send_write
do_lo_send_direct_write loop_thread kthread kernel_thread_helper
[loop_thread] 0.4 msec 4.0 %
loop_thread kthread kernel_thread_helper
Process kjournald (818) Total: 27.4 msec
EXT3: committing transaction 18.1 msec 100.0 %
journal_commit_transaction kjournald kthread kernel_thread_helper
Process Xorg (1621) Total: 120.1 msec
Waiting for event (select) 4.7 msec 93.7 %
poll_schedule_timeout do_select core_sys_select sys_select
system_call_fastpath
[i915_gem_set_tiling] 3.6 msec 3.0 %
i915_gem_set_tiling drm_ioctl do_vfs_ioctl sys_ioctl
system_call_fastpath
Waiting for GPU command to complete 0.6 msec 3.3 %
i915_wait_request i915_gem_do_execbuffer.isra.7
i915_gem_execbuffer2 drm_ioctl do_vfs_ioctl sys_ioctl
system_call_fastpath
Process dbus-daemon (2114) Total: 9.6 msec
Waiting for event (epoll) 2.5 msec 100.0 %
sys_epoll_wait system_call_fastpath
Process gnome-settings- (2254) Total: 1.6 msec
Waiting for event (poll) 0.5 msec 100.0 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Process gnome-shell (2352) Total: 60.7 msec
Waiting for event (poll) 4.4 msec 83.1 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Waiting for GPU command to complete 3.6 msec 16.9 %
i915_wait_request i915_gem_object_set_to_gtt_domain
i915_gem_set_domain_ioctl drm_ioctl do_vfs_ioctl sys_ioctl
system_call_fastpath
Process tracker-miner-f (2370) Total: 14.7 msec
Waiting for event (poll) 2.6 msec 94.4 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Userspace lock contention 0.8 msec 5.6 %
futex_wait_queue_me futex_wait do_futex sys_futex
system_call_fastpath
Process applet.py (2376) Total: 2.3 msec
Waiting for event (poll) 2.3 msec 100.0 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Process gnome-terminal (2456) Total: 4.9 msec
Waiting for event (poll) 0.3 msec 100.0 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Process firefox-bin (2483) Total: 73.6 msec
Userspace lock contention 4.8 msec 28.3 %
futex_wait_queue_me futex_wait do_futex sys_futex
system_call_fastpath
Waiting for event (poll) 3.8 msec 12.3 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
fsync() on a file (type 'F' for details) 2.3 msec 59.3 %
sleep_on_buffer __block_write_full_page __writepage
write_cache_pages generic_writepages
__filemap_fdatawrite_range filemap_write_and_wait_range
ext3_sync_file do_fsync sys_fsync system_call_fastpath
Process kworker/0:0 (2933) Total: 272.6 msec
. 5.0 msec 95.8 %
worker_thread kthread kernel_thread_helper
Executing raw SCSI command 2.3 msec 4.2 %
blk_execute_rq scsi_execute scsi_execute_req sr_check_events
cdrom_check_events disk_events_workfn process_one_work
worker_thread kthread kernel_thread_helper
Process tracker-extract (3354) Total: 4.0 msec
Waiting for event (poll) 2.3 msec 100.0 %
poll_schedule_timeout do_sys_poll sys_poll
system_call_fastpath
Process btrfs-endio-met (3402) Total: 110.3 msec
[worker_loop] 4.9 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-cleaner (3409) Total: 0.5 msec
[cleaner_kthread] 0.4 msec 88.5 %
cleaner_kthread kthread kernel_thread_helper
linux:/home/linux/latencytop/src # time mount -onoatime,space_cache,inode_cache,autodefrag,compress=lzo -t btrfs /dev/sda8 /mnt/
real 0m3.769s
user 0m0.005s
sys 0m0.273s
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment