| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <AANLkTimLeCMFO++RYnCXOPSMeNzxf2SAovEZ-q-q5TzF@mail.gmail.com> Date: Fri, 11 Feb 2011 19:35:02 -0500 From: Andrew Lutomirski <andy@...o.us> To: Chris Mason <chris.mason@...cle.com> Cc: linux-btrfs <linux-btrfs@...r.kernel.org>, linux-kernel <linux-kernel@...r.kernel.org> Subject: Re: 2.6.37: Multi-second I/O latency while untarring On Fri, Feb 11, 2011 at 10:44 AM, Chris Mason <chris.mason@...cle.com> wrote: > Excerpts from Andrew Lutomirski's message of 2011-02-11 10:08:52 -0500: >> As I type this, I have an ssh process running that's dumping data into >> a fifo at high speed (maybe 500Mbps) and a tar process that's >> untarring from the same fifo onto btrfs. The btrfs fs is mounted -o >> space_cache,compress. This machine has 8GB ram, 8 logical cores, and >> a fast (i7-2600) CPU, so it's not an issue with the machine struggling >> under load. >> >> Every few tens of seconds, my system stalls for several seconds. >> These stalls cause keyboard input to be lost, firefox to hang, etc. >> >> Setting tar's ionice priority to best effort / 7 or to idle makes no difference. >> >> ionice idle and queue_depth = 1 on the disk (a slow 2TB WD) also makes >> no difference. >> >> max_sectors_kb = 64 in addition to the above doesn't help either. >> >> latencytop shows regular instances of 2-7 *second* latency, variously >> in sync_page, start_transaction, btrfs_start_ordered_extent, and >> do_get_write_access (from jbd2 on my ext4 root partition). >> >> echo 3 >drop_caches gave me 7 GB free RAM. I still had stalls when >> 4-5 GB were still free (so it shouldn't be a problem with important >> pages being evicted). >> >> In case it matters, all of my partitions are on LVM on dm-crypt, but >> this machine has AES-NI so the overhead from that should be minimal. >> In fact, overall CPU usage is only about 10%. >> >> What gives? I thought this stuff was supposed to be better on modern kernels. > > We can tell more if you post the full traces from latencytop. I have a > patch here for latencytop that adds a -c mode, which dumps the traces > out to a text files. > > http://oss.oracle.com/~mason/latencytop.patch > > Based on what you have here, I think it's probably a latency problem > between btrfs and the dm-crypt stuff. How easily can setup a test > partition without dm-crypt? Done, on the same physical disk as before. The latency is just as bad. On this test, I wrote a total of 3.1G, which is under half of my RAM. That should rule out lots of VM issues. latencytop trace below. The impression I get (from watching the disk activity light) is that the disk is mostly idle but every now and then writes out a ton of data. While it's writing, the system often becomes unusable. P.S. How bad is this? I got it on both disks. btrfs: free space inode generation (0) did not match free space cache generation (11070) for block group 1103101952 =============== Fri Feb 11 19:30:57 2011 Globals: Cause Maximum Percentage Writing a page to disk 2009.0 msec 19.7 % fsync() on a file (type 'F' for details) 612.2 msec 5.0 % synchronous write 573.6 msec 1.8 % Page fault 57.3 msec 0.7 % Writing buffer to disk (synchronous) 45.2 msec 0.1 % Unlinking file 12.6 msec 0.0 % Waiting for event (select) 5.0 msec 22.3 % Reading from a pipe 5.0 msec 29.9 % Waiting for event (poll) 5.0 msec 17.8 % Process details: Process kthreadd (2) Total: 1.9 msec kthreadd kernel thread 1.9 msec 100.0 % kthreadd kernel_thread_helper Process ksoftirqd/0 (3) Total: 18.5 msec [run_ksoftirqd] 4.0 msec 100.0 % run_ksoftirqd kthread kernel_thread_helper Process ksoftirqd/1 (10) Total: 19.6 msec [run_ksoftirqd] 4.9 msec 100.0 % run_ksoftirqd kthread kernel_thread_helper Process kworker/0:1 (11) Total: 556.3 msec . 5.0 msec 100.0 % worker_thread kthread kernel_thread_helper Process ksoftirqd/2 (15) Total: 8.1 msec [run_ksoftirqd] 2.9 msec 100.0 % run_ksoftirqd kthread kernel_thread_helper Process ksoftirqd/4 (23) Total: 11.2 msec [run_ksoftirqd] 4.3 msec 100.0 % run_ksoftirqd kthread kernel_thread_helper Process scsi_eh_1 (62) Total: 38.8 msec SCSI error handler 0.9 msec 39.9 % scsi_error_handler kthread kernel_thread_helper Executing internal ATA command 0.7 msec 60.1 % ata_exec_internal_sg ata_exec_internal atapi_eh_request_sense ata_eh_link_autopsy ata_eh_autopsy sata_pmp_error_handler ahci_error_handler ata_scsi_error scsi_error_handler kthread kernel_thread_helper Process kworker/u:4 (69) Total: 616.5 msec Creating block layer request 54.9 msec 77.8 % get_request_wait __make_request generic_make_request kcryptd_crypt_write_io_submit kcryptd_crypt process_one_work worker_thread kthread kernel_thread_helper . 5.0 msec 22.2 % worker_thread kthread kernel_thread_helper Process kworker/u:5 (70) Total: 1712.3 msec Creating block layer request 492.8 msec 94.3 % get_request_wait __make_request generic_make_request kcryptd_io process_one_work worker_thread kthread kernel_thread_helper . 4.9 msec 5.7 % worker_thread kthread kernel_thread_helper Process kworker/7:1 (76) Total: 5.7 msec . 4.8 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/5:1 (117) Total: 31.9 msec . 4.9 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/6:1 (118) Total: 13.6 msec . 4.9 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/1:1 (119) Total: 126.3 msec . 4.9 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/4:1 (120) Total: 377.5 msec . 5.0 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/2:1 (131) Total: 73.1 msec . 4.9 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/3:1 (132) Total: 30.7 msec . 4.9 msec 100.0 % worker_thread kthread kernel_thread_helper Process jbd2/dm-1-8 (372) Total: 137.4 msec Writing buffer to disk (synchronous) 127.3 msec 92.8 % sync_buffer __wait_on_buffer wait_on_buffer jbd2_journal_commit_transaction kjournald2 kthread kernel_thread_helper Writing a page to disk 9.9 msec 7.2 % sync_page wait_on_page_bit filemap_fdatawait_range filemap_fdatawait jbd2_journal_commit_transaction kjournald2 kthread kernel_thread_helper Process btrfs-worker-0 (828) Total: 4.6 msec [worker_loop] 2.2 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-submit-0 (830) Total: 5.8 msec [worker_loop] 2.3 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-delalloc- (831) Total: 1.1 msec [worker_loop] 1.1 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-endio-0 (833) Total: 69.1 msec [worker_loop] 4.7 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-endio-met (834) Total: 56.0 msec [worker_loop] 4.5 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-endio-met (835) Total: 19.8 msec [worker_loop] 4.8 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-freespace (837) Total: 10.0 msec [worker_loop] 1.4 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-transacti (841) Total: 3271.2 msec Writing a page to disk 507.8 msec 89.5 % sync_page __lock_page lock_page extent_write_cache_pages.clone.11.clone.18 extent_writepages btrfs_writepages do_writepages __filemap_fdatawrite_range filemap_flush btrfs_run_ordered_operations btrfs_commit_transaction transaction_kthread Writing buffer to disk (synchronous) 305.5 msec 10.5 % sync_buffer __wait_on_buffer write_dev_supers write_all_supers write_ctree_super btrfs_commit_transaction transaction_kthread kthread kernel_thread_helper Process hald-addon-inpu (1347) Total: 5.4 msec Waiting for event (poll) 5.0 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process hald-addon-stor (1362) Total: 48.2 msec Opening file 3.5 msec 21.7 % bd_prepare_to_claim bd_start_claiming blkdev_open __dentry_open nameidata_to_filp do_last do_filp_open do_sys_open sys_open system_call_fastpath Executing raw SCSI command 1.2 msec 38.7 % blk_execute_rq scsi_execute scsi_execute_req sr_test_unit_ready sr_drive_status cdrom_ioctl sr_block_ioctl __blkdev_driver_ioctl blkdev_ioctl block_ioctl do_vfs_ioctl sys_ioctl opening cdrom device 1.2 msec 33.4 % blk_execute_rq scsi_execute scsi_execute_req sr_test_unit_ready sr_media_change media_changed cdrom_media_changed sr_block_media_changed check_disk_change cdrom_open sr_block_open __blkdev_get SCSI cdrom ioctl 0.6 msec 6.2 % blk_execute_rq scsi_execute sr_do_ioctl sr_packet cdrom_get_media_event sr_drive_status cdrom_ioctl sr_block_ioctl __blkdev_driver_ioctl blkdev_ioctl block_ioctl do_vfs_ioctl Process Xorg (1533) Total: 4718.6 msec Waiting for event (select) 5.0 msec 93.8 % poll_schedule_timeout do_select core_sys_select sys_select system_call_fastpath [i915_do_wait_request] 4.3 msec 3.5 % i915_do_wait_request i915_gem_object_wait_rendering i915_gem_do_execbuffer.clone.29 i915_gem_execbuffer2 drm_ioctl do_vfs_ioctl sys_ioctl system_call_fastpath [__mutex_fastpath_lock_retval] 3.4 msec 2.7 % __mutex_fastpath_lock_retval i915_mutex_lock_interruptible i915_gem_pwrite_ioctl drm_ioctl do_vfs_ioctl sys_ioctl system_call_fastpath Waiting for TTY data 0.3 msec 0.0 % flush_work flush_delayed_work tty_flush_to_ldisc input_available_p n_tty_poll tty_poll do_select core_sys_select sys_select system_call_fastpath Process gnome-settings- (1857) Total: 18.1 msec Waiting for event (poll) 3.9 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process flush-btrfs-1 (1865) Total: 0.7 msec Writing a page to disk 0.1 msec 100.0 % sync_page __lock_page lock_page extent_write_cache_pages.clone.11.clone.18 extent_writepages btrfs_writepages do_writepages writeback_single_inode writeback_sb_inodes writeback_inodes_wb wb_writeback wb_do_writeback Process nautilus (1884) Total: 0.5 msec Waiting for event (poll) 0.2 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process compiz (1893) Total: 650.6 msec Waiting for event (poll) 5.0 msec 79.4 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath [i915_do_wait_request] 2.5 msec 20.2 % i915_do_wait_request i915_gem_object_wait_rendering i915_gem_do_execbuffer.clone.29 i915_gem_execbuffer2 drm_ioctl do_vfs_ioctl sys_ioctl system_call_fastpath [__mutex_fastpath_lock_retval] 1.0 msec 0.4 % __mutex_fastpath_lock_retval i915_mutex_lock_interruptible i915_gem_set_domain_ioctl drm_ioctl do_vfs_ioctl sys_ioctl system_call_fastpath Process wnck-applet (1927) Total: 2.6 msec Waiting for event (poll) 0.7 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process udisks-daemon (2005) Total: 24.1 msec Opening file 3.3 msec 53.0 % bd_prepare_to_claim bd_start_claiming blkdev_open __dentry_open nameidata_to_filp do_last do_filp_open do_sys_open sys_open system_call_fastpath opening cdrom device 1.2 msec 41.6 % blk_execute_rq scsi_execute scsi_execute_req sr_test_unit_ready sr_media_change media_changed cdrom_media_changed sr_block_media_changed check_disk_change cdrom_open sr_block_open __blkdev_get Executing raw SCSI command 0.4 msec 5.4 % blk_execute_rq scsi_execute scsi_execute_req ioctl_internal_command.clone.3 scsi_set_medium_removal sr_lock_door cdrom_release sr_block_release __blkdev_put blkdev_put blkdev_close fput Process btrfs-worker-3 (2097) Total: 1.1 msec [worker_loop] 0.6 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-worker-4 (2098) Total: 0.4 msec [worker_loop] 0.2 msec 100.0 % worker_loop kthread kernel_thread_helper Process gtk-window-deco (2133) Total: 69.0 msec Page fault 57.3 msec 83.1 % sync_page wait_on_page_bit wait_on_page_locked __lock_page_or_retry filemap_fault __do_fault handle_mm_fault do_page_fault page_fault Waiting for event (poll) 3.8 msec 16.9 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process gvfsd-trash (2152) Total: 495.5 msec Waiting for event (poll) 5.0 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process gnome-terminal (2185) Total: 483.3 msec Waiting for event (poll) 4.0 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process firefox (2426) Total: 5028.3 msec Writing a page to disk 867.7 msec 48.5 % sync_page wait_on_page_bit read_extent_buffer_pages btree_read_extent_buffer_pages.clone.56 read_tree_block read_block_for_search.clone.38 btrfs_search_slot btrfs_lookup_csum __btrfs_lookup_bio_sums btrfs_lookup_bio_sums btrfs_submit_bio_hook submit_one_bio fsync() on a file (type 'F' for details) 612.2 msec 24.4 % sync_page __lock_page lock_page extent_write_cache_pages.clone.11.clone.18 extent_writepages btrfs_writepages do_writepages __filemap_fdatawrite_range filemap_write_and_wait_range vfs_fsync_range vfs_fsync do_fsync synchronous write 573.6 msec 11.4 % start_transaction btrfs_join_transaction btrfs_dirty_inode __mark_inode_dirty file_update_time btrfs_file_aio_write do_sync_write vfs_write sys_write system_call_fastpath Page fault 57.0 msec 2.9 % sync_page wait_on_page_bit wait_on_page_locked __lock_page_or_retry filemap_fault __do_fault handle_mm_fault do_page_fault page_fault Writing buffer to disk (synchronous) 45.2 msec 0.9 % sync_buffer __wait_on_buffer ext4_find_entry ext4_lookup d_alloc_and_lookup do_lookup do_last do_filp_open do_sys_open sys_open system_call_fastpath Unlinking file 12.6 msec 0.3 % btrfs_tree_lock btrfs_search_slot btrfs_insert_empty_items run_clustered_refs btrfs_run_delayed_refs __btrfs_end_transaction btrfs_end_transaction_throttle __unlink_end_trans btrfs_unlink vfs_unlink do_unlinkat sys_unlink Waiting for event (poll) 4.9 msec 5.9 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Userspace lock contention 4.9 msec 5.7 % futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath Process btrfs-delalloc- (2453) Total: 1.8 msec [worker_loop] 1.1 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-endio-wri (2454) Total: 44.7 msec Writing a page to disk 31.1 msec 98.1 % sync_page wait_on_page_bit read_extent_buffer_pages btree_read_extent_buffer_pages.clone.56 read_tree_block read_block_for_search.clone.38 btrfs_search_slot btrfs_insert_empty_items alloc_reserved_file_extent.clone.57 run_clustered_refs btrfs_run_delayed_refs __btrfs_end_transaction [worker_loop] 0.7 msec 1.9 % worker_loop kthread kernel_thread_helper Process btrfs-endio-wri (2460) Total: 819.2 msec Writing a page to disk 532.4 msec 99.8 % sync_page __lock_page lock_page read_extent_buffer_pages btree_read_extent_buffer_pages.clone.56 read_tree_block reada_for_balance btrfs_search_slot btrfs_csum_file_blocks add_pending_csums.clone.29 btrfs_finish_ordered_io btrfs_writepage_end_io_hook [worker_loop] 0.8 msec 0.2 % worker_loop kthread kernel_thread_helper Process btrfs-endio-met (2464) Total: 146.5 msec [worker_loop] 4.7 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-genwork-0 (2573) Total: 2.1 msec [worker_loop] 1.8 msec 87.6 % worker_loop kthread kernel_thread_helper [kthread_create] 0.1 msec 12.4 % kthread_create __btrfs_start_workers btrfs_start_workers start_new_worker_func worker_loop kthread kernel_thread_helper Process btrfs-submit-0 (2574) Total: 2797.6 msec Creating block layer request 484.7 msec 99.9 % get_request_wait __make_request generic_make_request submit_bio run_scheduled_bios pending_bios_fn worker_loop kthread kernel_thread_helper [worker_loop] 0.1 msec 0.1 % worker_loop kthread kernel_thread_helper Process btrfs-endio-met (2579) Total: 5.1 msec [worker_loop] 1.9 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-endio-wri (2580) Total: 146.3 msec [worker_loop] 5.0 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-freespace (2581) Total: 0.4 msec [worker_loop] 0.4 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-transacti (2583) Total: 479.7 msec Writing buffer to disk (synchronous) 466.0 msec 97.2 % sync_buffer __wait_on_buffer write_dev_supers write_all_supers write_ctree_super btrfs_commit_transaction transaction_kthread kthread kernel_thread_helper Writing a page to disk 6.4 msec 2.8 % sync_page wait_on_page_bit filemap_fdatawait_range filemap_fdatawait filemap_write_and_wait btrfs_write_out_cache btrfs_write_dirty_block_groups commit_cowonly_roots btrfs_commit_transaction transaction_kthread kthread kernel_thread_helper Process ssh (2659) Total: 2559.8 msec Waiting for event (select) 4.9 msec 100.0 % poll_schedule_timeout do_select core_sys_select sys_select system_call_fastpath Process tar (2662) Total: 9364.3 msec Reading from a pipe 5.0 msec 100.0 % pipe_wait pipe_read do_sync_read vfs_read sys_read system_call_fastpath Process btrfs-endio-wri (2741) Total: 1.1 msec [worker_loop] 1.0 msec 97.6 % worker_loop kthread kernel_thread_helper Process btrfs-endio-met (2742) Total: 2.4 msec [worker_loop] 1.8 msec 99.1 % worker_loop kthread kernel_thread_helper Process btrfs-endio-met (2743) Total: 2.3 msec [worker_loop] 1.8 msec 99.9 % worker_loop kthread kernel_thread_helper Process bash (2753) Total: 483.3 msec Waiting for event (poll) 4.0 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process btrfs-endio-wri (2790) Total: 1.9 msec kthreadd kernel thread 1.9 msec 100.0 % kthreadd kernel_thread_helper Process sudo (2792) Total: 483.3 msec Waiting for event (poll) 4.0 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process latencytop (2798) Total: 486.0 msec Waiting for event (poll) 4.0 msec 99.4 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Waiting for a process to die 2.1 msec 0.6 % do_wait sys_wait4 system_call_fastpath -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@...r.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists