Messages in this thread | | | Date | Sat, 27 Mar 2010 18:29:14 -0700 (PDT) | From | Ben Gamari <> | Subject | Re: Poor interactive performance with I/O loads with fsync()ing |
| |
On Sat, 27 Mar 2010 18:20:37 -0700 (PDT), Ben Gamari <bgamari.foss@gmail.com> wrote: > Hey all, > > I have posted another profile[1] from an incident yesterday. As you can see, > both swapper and init (strange?) show up prominently in the profile. Moreover, > most processes seem to be in blk_peek_request a disturbingly large percentage > of the time. Both of these profiles were taken with 2.6.34-rc kernels. >
Apparently my initial email announcing my first set of profiles never made it out. Sorry for the confusion. I've included it below.
From: Ben Gamari <bgamari.foss@gmail.com> Subject: Re: Poor interactive performance with I/O loads with fsync()ing To: Ingo Molnar <mingo@elte.hu>, Nick Piggin <npiggin@suse.de> Cc: tytso@mit.edu, linux-kernel@vger.kernel.org, Olly Betts <olly@survex.com>, martin f krafft <madduck@madduck.net> Bcc: bgamari@gmail.com In-Reply-To: <20100317093704.GA17146@elte.hu> References: <4b9fa440.12135e0a.7fc8.ffffe745@mx.google.com> <20100317045350.GA2869@laptop> <20100317093704.GA17146@elte.hu> On Wed, 17 Mar 2010 10:37:04 +0100, Ingo Molnar <mingo@elte.hu> wrote: > A call-graph profile will show the precise reason for IO latencies, and their > relatively likelihood.
Well, here is something for now. I'm not sure how valid the reproduction workload is (git pull, rsync, and 'notmuch new' all running at once), but I certainly did produce a few stalls and swapper is highest on the profile. This was on 2.6.34-rc2. I've included part of the profile below, although more complete set of data is available at [1].
Thanks,
- Ben
[1] http://mw0.mooo.com/~ben/latency-2010-03-25-a/
# Samples: 25295 # # Overhead Command Shared Object Symbol # ........ ............... ................. ...... # 24.50% swapper [kernel.kallsyms] [k] blk_peek_request | --- blk_peek_request scsi_request_fn __blk_run_queue | |--98.32%-- blk_run_queue | scsi_run_queue | scsi_next_command | scsi_io_completion | scsi_finish_command | scsi_softirq_done | blk_done_softirq | __do_softirq | call_softirq | do_softirq | irq_exit | | | |--99.56%-- do_IRQ | | ret_from_intr | | | | | |--98.02%-- cpuidle_idle_call | | | cpu_idle | | | rest_init | | | start_kernel | | | x86_64_start_reservations | | | x86_64_start_kernel | | | | | |--0.91%-- clockevents_notify | | | lapic_timer_state_broadcast | | | | | | | |--83.64%-- acpi_idle_enter_bm | | | | cpuidle_idle_call | | | | cpu_idle | | | | rest_init | | | | start_kernel | | | | x86_64_start_reservations | | | | x86_64_start_kernel | | | | | | | --16.36%-- acpi_idle_enter_simple | | | cpuidle_idle_call | | | cpu_idle | | | rest_init | | | start_kernel | | | x86_64_start_reservations | | | x86_64_start_kernel | | | | | |--0.81%-- cpu_idle | | | rest_init | | | start_kernel | | | x86_64_start_reservations | | | x86_64_start_kernel | | --0.26%-- [...] | --0.44%-- [...] | --1.68%-- elv_completed_request __blk_put_request blk_finish_request blk_end_bidi_request blk_end_request scsi_io_completion scsi_finish_command scsi_softirq_done blk_done_softirq __do_softirq call_softirq do_softirq irq_exit do_IRQ ret_from_intr | |--96.15%-- cpuidle_idle_call | cpu_idle | rest_init | start_kernel | x86_64_start_reservations | x86_64_start_kernel | |--1.92%-- cpu_idle | rest_init | start_kernel | x86_64_start_reservations | x86_64_start_kernel | |--0.96%-- schedule | cpu_idle | rest_init | start_kernel | x86_64_start_reservations | x86_64_start_kernel | --0.96%-- clockevents_notify lapic_timer_state_broadcast acpi_idle_enter_bm cpuidle_idle_call cpu_idle rest_init start_kernel x86_64_start_reservations x86_64_start_kernel
23.74% init [kernel.kallsyms] [k] blk_peek_request | --- blk_peek_request scsi_request_fn __blk_run_queue | |--98.77%-- blk_run_queue | scsi_run_queue | scsi_next_command | scsi_io_completion | scsi_finish_command | scsi_softirq_done | blk_done_softirq | __do_softirq | call_softirq | do_softirq | irq_exit | | | |--99.87%-- do_IRQ | | ret_from_intr | | | | | |--98.38%-- cpuidle_idle_call | | | cpu_idle | | | start_secondary | | | | | |--0.81%-- schedule | | | cpu_idle | | | start_secondary | | | | | |--0.56%-- cpu_idle | | | start_secondary | | --0.25%-- [...] | --0.13%-- [...] | --1.23%-- elv_completed_request __blk_put_request blk_finish_request blk_end_bidi_request blk_end_request scsi_io_completion scsi_finish_command scsi_softirq_done blk_done_softirq __do_softirq call_softirq do_softirq irq_exit do_IRQ ret_from_intr cpuidle_idle_call cpu_idle start_secondary
5.85% chromium-browse [kernel.kallsyms] [k] blk_peek_request | --- blk_peek_request scsi_request_fn __blk_run_queue blk_run_queue scsi_run_queue scsi_next_command scsi_io_completion scsi_finish_command scsi_softirq_done blk_done_softirq __do_softirq call_softirq do_softirq irq_exit do_IRQ ret_from_intr | |--50.00%-- check_match.8653 | --50.00%-- unlink_anon_vmas free_pgtables exit_mmap mmput exit_mm do_exit do_group_exit sys_exit_group system_call ...
| |