| 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
| ||
|
Date: Fri, 11 Feb 2011 14:56:00 -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 Big dump at end of email from latencytop git + your 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? Not so easily on that disk. I left some space inside the LVM to play with but none outside. I'll try hooking up another disk over eSATA l (on a Cougar Point 3Gbps controller, so it might blow up). And here's the dump: =============== Fri Feb 11 14:44:07 2011 Globals: Cause Maximum Percentage synchronous write 4249.1 msec 35.5 % Writing to a pipe 4248.5 msec 35.5 % Writing a page to disk 105.9 msec 2.1 % Page fault 23.7 msec 0.2 % Reading from a pipe 4.7 msec 19.8 % Waiting for event (select) 4.6 msec 6.4 % Waiting for event (poll) 1.3 msec 0.0 % Executing raw SCSI command 1.3 msec 0.2 % opening cdrom device 1.3 msec 0.3 % Process details: Process ksoftirqd/1 (10) Total: 50.0 msec [run_ksoftirqd] 4.8 msec 100.0 % run_ksoftirqd kthread kernel_thread_helper Process ksoftirqd/2 (15) Total: 8.7 msec [run_ksoftirqd] 4.9 msec 100.0 % run_ksoftirqd kthread kernel_thread_helper Process ksoftirqd/3 (19) Total: 2.9 msec [run_ksoftirqd] 2.9 msec 100.0 % run_ksoftirqd kthread kernel_thread_helper Process ksoftirqd/5 (27) Total: 80.6 msec [run_ksoftirqd] 5.0 msec 100.0 % run_ksoftirqd kthread kernel_thread_helper Process scsi_eh_1 (62) Total: 45.0 msec Executing internal ATA command 0.7 msec 62.3 % 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 SCSI error handler 0.6 msec 37.7 % scsi_error_handler kthread kernel_thread_helper Process kworker/7:1 (76) Total: 8.7 msec . 3.9 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/4:1 (139) Total: 124.0 msec . 4.9 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/6:1 (140) Total: 11.7 msec . 3.8 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/5:1 (141) Total: 12.5 msec . 4.9 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/2:1 (142) Total: 26.1 msec . 4.9 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/1:1 (143) Total: 47.1 msec . 4.9 msec 100.0 % worker_thread kthread kernel_thread_helper Process kworker/3:1 (150) Total: 4.6 msec . 3.1 msec 100.0 % worker_thread kthread kernel_thread_helper Process jbd2/dm-1-8 (376) Total: 66.7 msec Writing buffer to disk (synchronous) 66.7 msec 100.0 % sync_buffer __wait_on_buffer wait_on_buffer jbd2_journal_commit_transaction kjournald2 kthread kernel_thread_helper Process btrfs-submit-0 (829) Total: 1719.4 msec [worker_loop] 2.2 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-endio-met (833) Total: 540.5 msec [worker_loop] 4.8 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-freespace (836) Total: 31.7 msec [worker_loop] 1.8 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-transacti (838) Total: 5567.3 msec Writing buffer to disk (synchronous) 352.5 msec 6.8 % 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 91.4 msec 93.2 % 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 lookup_inline_extent_backref __btrfs_free_extent run_clustered_refs btrfs_run_delayed_refs btrfs_commit_transaction Process hald-addon-stor (1349) Total: 39.5 msec Executing raw SCSI command 1.3 msec 49.1 % 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.3 msec 43.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 7.5 % 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 gdm-binary (1486) Total: 0.3 msec Waiting for event (poll) 0.3 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process Xorg (1520) Total: 0.9 msec [i915_do_wait_request] 0.3 msec 70.7 % i915_do_wait_request i915_gem_object_wait_rendering i915_gem_object_set_to_gtt_domain i915_gem_set_domain_ioctl drm_ioctl do_vfs_ioctl sys_ioctl system_call_fastpath Process upowerd (1645) Total: 0.2 msec Waiting for event (poll) 0.2 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process gnome-session (1752) Total: 0.1 msec Waiting for event (poll) 0.1 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process udisks-daemon (1880) Total: 0.1 msec Waiting for event (poll) 0.1 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process udisks-daemon (1881) Total: 19.2 msec opening cdrom device 1.2 msec 88.1 % 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.5 msec 11.9 % 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 bluetooth-apple (1915) Total: 0.2 msec Waiting for event (poll) 0.2 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process gpk-update-icon (1942) Total: 0.2 msec Waiting for event (poll) 0.2 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process gnome-screensav (2040) Total: 0.3 msec Waiting for event (poll) 0.2 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process flush-btrfs-1 (2120) Total: 173.3 msec Writing a page to disk 161.4 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 btrfs-delalloc- (2402) Total: 0.2 msec [worker_loop] 0.2 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-endio-met (2408) Total: 52.1 msec [worker_loop] 2.5 msec 100.0 % worker_loop kthread kernel_thread_helper Process btrfs-endio-wri (2768) Total: 1561.5 msec [worker_loop] 4.1 msec 100.0 % worker_loop kthread kernel_thread_helper Process compiz (6845) Total: 0.8 msec Waiting for event (poll) 0.2 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process clock-applet (6928) Total: 1.4 msec Waiting for event (poll) 1.3 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process kworker/0:0 (20743) Total: 1867.9 msec . 5.0 msec 100.0 % worker_thread kthread kernel_thread_helper Process tar (22372) Total: 6614.1 msec synchronous write 4249.1 msec 64.2 % btrfs_throttle btrfs_file_aio_write do_sync_write vfs_write sys_write system_call_fastpath Reading from a pipe 4.7 msec 35.8 % pipe_wait pipe_read do_sync_read vfs_read sys_read system_call_fastpath Process ssh (22533) Total: 4974.4 msec Writing to a pipe 4248.5 msec 85.4 % start_transaction btrfs_join_transaction btrfs_dirty_inode __mark_inode_dirty file_update_time pipe_write do_sync_write vfs_write sys_write system_call_fastpath Waiting for event (select) 4.6 msec 14.6 % poll_schedule_timeout do_select core_sys_select sys_select system_call_fastpath Process kworker/u:3 (23092) Total: 1901.4 msec Creating block layer request 14.7 msec 84.7 % get_request_wait __make_request generic_make_request kcryptd_crypt_write_io_submit kcryptd_crypt process_one_work worker_thread kthread kernel_thread_helper . 4.7 msec 15.3 % worker_thread kthread kernel_thread_helper Process kworker/u:0 (23763) Total: 2108.1 msec . 5.0 msec 100.0 % worker_thread kthread kernel_thread_helper Process packagekitd (24691) Total: 0.2 msec Waiting for event (poll) 0.2 msec 100.0 % poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath Process sshd (24718) Total: 35.8 msec Waiting for event (select) 3.1 msec 99.9 % poll_schedule_timeout do_select core_sys_select sys_select system_call_fastpath Process bash (24719) Total: 5.1 msec Reading from a pipe 1.0 msec 82.5 % pipe_wait pipe_read do_sync_read vfs_read sys_read system_call_fastpath Waiting for a process to die 0.9 msec 17.5 % do_wait sys_wait4 system_call_fastpath It seems a little sad that ssh took a big latency hit just marking the fifo dirty. --Andy -- 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