Re: Poor interactive performance with I/O loads with fsync()ing
From: Ben Gamari
Date: Sat Mar 27 2010 - 21:29:21 EST
On Sat, 27 Mar 2010 18:20:37 -0700 (PDT), Ben Gamari <bgamari.foss@xxxxxxxxx> 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@xxxxxxxxx>
Subject: Re: Poor interactive performance with I/O loads with fsync()ing
To: Ingo Molnar <mingo@xxxxxxx>, Nick Piggin <npiggin@xxxxxxx>
Cc: tytso@xxxxxxx, linux-kernel@xxxxxxxxxxxxxxx, Olly Betts
<olly@xxxxxxxxxx>, martin f krafft <madduck@xxxxxxxxxxx>
Bcc: bgamari@xxxxxxxxx
In-Reply-To: <20100317093704.GA17146@xxxxxxx>
References: <4b9fa440.12135e0a.7fc8.ffffe745@xxxxxxxxxxxxx>
<20100317045350.GA2869@laptop> <20100317093704.GA17146@xxxxxxx>
On Wed, 17 Mar 2010 10:37:04 +0100, Ingo Molnar <mingo@xxxxxxx> 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
...
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/