/latencytop
Created May 31, 2012
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