From: Peter Zijlstra <a.p.zijlstra@chello.nl>
To: Kevin Shanahan <kmshanah@ucwb.org.au>
Cc: "Ingo Molnar" <mingo@elte.hu>, "Avi Kivity" <avi@redhat.com>,
"Steven Rostedt" <rostedt@goodmis.org>,
"Rafael J. Wysocki" <rjw@sisk.pl>,
"Linux Kernel Mailing List" <linux-kernel@vger.kernel.org>,
"Kernel Testers List" <kernel-testers@vger.kernel.org>,
"Mike Galbraith" <efault@gmx.de>,
"Frédéric Weisbecker" <fweisbec@gmail.com>,
bugme-daemon@bugzilla.kernel.org
Subject: Re: [Bug #12465] KVM guests stalling on 2.6.28 (bisected)
Date: Mon, 26 Jan 2009 12:35:05 +0100 [thread overview]
Message-ID: <1232969705.4863.46.camel@laptop> (raw)
In-Reply-To: <1232963730.4921.12.camel@kulgan.wumi.org.au>
On Mon, 2009-01-26 at 20:25 +1030, Kevin Shanahan wrote:
> Just carrying out the steps was okay, but I don't really know what I'm
> looking at. I've uploaded the trace here (about 10 seconds worth, I
> think):
>
> http://disenchant.net/tmp/bug-12465/trace-1/
>
> The guest being pinged is process 4353:
>
> kmshanah@flexo:~$ pstree -p 4353
> qemu-system-x86(4353)─┬─{qemu-system-x86}(4354)
> ├─{qemu-system-x86}(4355)
> └─{qemu-system-x86}(4772)
>
> I guess the larger overhead/duration values are what we are looking for,
> e.g.:
>
> kmshanah@flexo:~$ bzgrep -E '[[:digit:]]{6,}' trace.txt.bz2
> 0) ksoftir-4 | ! 3010470 us | }
> 0) qemu-sy-4354 | ! 250406.2 us | }
> 0) qemu-sy-4354 | ! 250407.0 us | }
> 0) qemu-sy-4354 | ! 362946.3 us | }
> 0) qemu-sy-4354 | ! 362947.0 us | }
> 0) qemu-sy-4177 | ! 780480.3 us | }
> 0) qemu-sy-4354 | ! 117685.7 us | }
> 0) qemu-sy-4354 | ! 117686.5 us | }
>
> That ksoftirqd value is a bit strange (> 3 seconds, or is the formatting
> wrong?). I guess I still need some guidance to know what I'm looking at
> with this trace and/or what to do next.
What happens is that it gets preempted a few times while running a
particular function, say do_softirqd(), or kvm_arch_vcpu_ioctl_run().
Now, when this function ends, it prints the wall-time delay between
start and end of that function, instead of the task-time delay.
So by having been preempted several times, that gets inflated.
That said, the output is slightly 'buggy' in that is seems to miss
context switches at times:
0) qemu-sy-4339 | | schedule() {
0) qemu-sy-4131 | ! 6750.369 us | }
I also find it very hard to attribute all time:
0) qemu-sy-4354 | | kvm_vcpu_ioctl() {
0) qemu-sy-4354 | | kvm_arch_vcpu_ioctl_run() {
0) qemu-sy-4354 | | kvm_arch_vcpu_load() {
0) qemu-sy-4354 | | kvm_write_guest_time() {
0) qemu-sy-4354 | 0.289 us | }
0) qemu-sy-4354 | 0.956 us | }
0) qemu-sy-4354 | | kvm_inject_pending_timer_irqs() {
0) qemu-sy-4354 | | kvm_inject_apic_timer_irqs() {
0) qemu-sy-4354 | 0.295 us | }
0) qemu-sy-4354 | | kvm_inject_pit_timer_irqs() {
0) qemu-sy-4354 | 0.304 us | }
0) qemu-sy-4354 | 1.488 us | }
0) qemu-sy-4354 | | kvm_lapic_enabled() {
0) qemu-sy-4354 | 0.294 us | }
0) qemu-sy-4354 | | kvm_lapic_find_highest_irr() {
0) qemu-sy-4354 | 0.307 us | }
0) qemu-sy-4354 | | kvm_cpu_has_interrupt() {
0) qemu-sy-4354 | | kvm_apic_has_interrupt() {
0) qemu-sy-4354 | 0.325 us | }
0) qemu-sy-4354 | | kvm_apic_accept_pic_intr() {
0) qemu-sy-4354 | 0.298 us | }
0) qemu-sy-4354 | 1.521 us | }
0) qemu-sy-4354 | | kvm_lapic_sync_to_vapic() {
0) qemu-sy-4354 | 0.295 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | autoremove_wake_function() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | | wakeup_preempt_entity() {
0) qemu-sy-4354 | 0.309 us | }
0) qemu-sy-4354 | | resched_task() {
0) qemu-sy-4354 | 0.324 us | }
0) qemu-sy-4354 | 1.614 us | }
0) qemu-sy-4354 | 2.934 us | }
0) qemu-sy-4354 | 3.529 us | }
0) qemu-sy-4354 | 4.118 us | }
0) qemu-sy-4354 | 4.743 us | }
0) qemu-sy-4354 | 5.432 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | autoremove_wake_function() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 => qemu-sy-4294
0) qemu-sy-4237 => qemu-sy-4354
0) qemu-sy-4354 | 5.500 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.316 us | }
0) qemu-sy-4354 | 1.250 us | }
0) qemu-sy-4354 | 1.834 us | }
0) qemu-sy-4354 | 2.434 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.418 us | }
0) qemu-sy-4354 | 1.001 us | }
0) qemu-sy-4354 | 1.608 us | }
0) qemu-sy-4354 | 4.987 us | }
0) qemu-sy-4354 | 5.597 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.325 us | }
0) qemu-sy-4354 | 1.247 us | }
0) qemu-sy-4354 | 1.831 us | }
0) qemu-sy-4354 | 2.435 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.415 us | }
0) qemu-sy-4354 | 0.995 us | }
0) qemu-sy-4354 | 1.587 us | }
0) qemu-sy-4354 | 5.026 us | }
0) qemu-sy-4354 | 5.639 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.313 us | }
0) qemu-sy-4354 | 1.331 us | }
0) qemu-sy-4354 | 1.903 us | }
0) qemu-sy-4354 | 2.507 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.415 us | }
0) qemu-sy-4354 | 0.998 us | }
0) qemu-sy-4354 | 1.596 us | }
0) qemu-sy-4354 | 5.017 us | }
0) qemu-sy-4354 | 5.630 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.318 us | }
0) qemu-sy-4354 | 1.275 us | }
0) qemu-sy-4354 | 1.860 us | }
0) qemu-sy-4354 | 2.474 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.406 us | }
0) qemu-sy-4354 | 0.989 us | }
0) qemu-sy-4354 | 1.581 us | }
0) qemu-sy-4354 | 4.953 us | }
0) qemu-sy-4354 | 5.567 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.313 us | }
0) qemu-sy-4354 | 2.645 us | }
0) qemu-sy-4354 | 3.219 us | }
0) qemu-sy-4354 | 3.824 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.396 us | }
0) qemu-sy-4354 | 0.968 us | }
0) qemu-sy-4354 | 1.557 us | }
0) qemu-sy-4354 | 6.390 us | }
0) qemu-sy-4354 | 7.004 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.310 us | }
0) qemu-sy-4354 | 1.160 us | }
0) qemu-sy-4354 | 1.731 us | }
0) qemu-sy-4354 | 2.330 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.397 us | }
0) qemu-sy-4354 | 0.965 us | }
0) qemu-sy-4354 | 1.554 us | }
0) qemu-sy-4354 | 4.768 us | }
0) qemu-sy-4354 | 5.383 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.307 us | }
0) qemu-sy-4354 | 1.208 us | }
0) qemu-sy-4354 | 1.777 us | }
0) qemu-sy-4354 | 2.377 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.394 us | }
0) qemu-sy-4354 | 0.964 us | }
0) qemu-sy-4354 | 1.554 us | }
0) qemu-sy-4354 | 4.855 us | }
0) qemu-sy-4354 | 5.482 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.307 us | }
0) qemu-sy-4354 | 1.193 us | }
0) qemu-sy-4354 | 1.765 us | }
0) qemu-sy-4354 | 2.368 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.394 us | }
0) qemu-sy-4354 | 0.974 us | }
0) qemu-sy-4354 | 1.560 us | }
0) qemu-sy-4354 | 4.831 us | }
0) qemu-sy-4354 | 5.461 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.318 us | }
0) qemu-sy-4354 | 1.175 us | }
0) qemu-sy-4354 | 1.747 us | }
0) qemu-sy-4354 | 2.344 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 2.029 us | }
0) qemu-sy-4354 | 2.597 us | }
0) qemu-sy-4354 | 3.186 us | }
0) qemu-sy-4354 | 6.430 us | }
0) qemu-sy-4354 | 7.046 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.310 us | }
0) qemu-sy-4354 | 1.199 us | }
0) qemu-sy-4354 | 1.780 us | }
0) qemu-sy-4354 | 2.378 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.397 us | }
0) qemu-sy-4354 | 0.968 us | }
0) qemu-sy-4354 | 1.560 us | }
0) qemu-sy-4354 | 4.933 us | }
0) qemu-sy-4354 | 5.549 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | autoremove_wake_function() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.316 us | }
0) qemu-sy-4354 | 1.202 us | }
0) qemu-sy-4354 | 1.792 us | }
0) qemu-sy-4354 | 2.357 us | }
0) qemu-sy-4354 | 2.973 us | }
0) qemu-sy-4354 | 3.607 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.304 us | }
0) qemu-sy-4354 | 1.149 us | }
0) qemu-sy-4354 | 1.713 us | }
0) qemu-sy-4354 | 2.309 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.405 us | }
0) qemu-sy-4354 | 0.971 us | }
0) qemu-sy-4354 | 1.569 us | }
0) qemu-sy-4354 | 4.800 us | }
0) qemu-sy-4354 | 5.408 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.298 us | }
0) qemu-sy-4354 | 1.127 us | }
0) qemu-sy-4354 | 1.695 us | }
0) qemu-sy-4354 | 2.291 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.403 us | }
0) qemu-sy-4354 | 0.974 us | }
0) qemu-sy-4354 | 1.575 us | }
0) qemu-sy-4354 | 4.888 us | }
0) qemu-sy-4354 | 5.482 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | autoremove_wake_function() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.303 us | }
0) qemu-sy-4354 | 2.428 us | }
0) qemu-sy-4354 | 2.991 us | }
0) qemu-sy-4354 | 3.559 us | }
0) qemu-sy-4354 | 4.157 us | }
0) qemu-sy-4354 | 4.752 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.313 us | }
0) qemu-sy-4354 | 1.437 us | }
0) qemu-sy-4354 | 2.002 us | }
0) qemu-sy-4354 | 2.594 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.418 us | }
0) qemu-sy-4354 | 1.016 us | }
0) qemu-sy-4354 | 1.587 us | }
0) qemu-sy-4354 | 5.077 us | }
0) qemu-sy-4354 | 5.699 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.309 us | }
0) qemu-sy-4354 | 1.314 us | }
0) qemu-sy-4354 | 1.884 us | }
0) qemu-sy-4354 | 2.480 us | }
0) qemu-sy-4354 | | pollwake() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | 0.405 us | }
0) qemu-sy-4354 | 0.977 us | }
0) qemu-sy-4354 | 1.560 us | }
0) qemu-sy-4354 | 4.962 us | }
0) qemu-sy-4354 | 5.591 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | autoremove_wake_function() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.304 us | }
0) qemu-sy-4354 | 1.199 us | }
0) qemu-sy-4354 | 1.765 us | }
0) qemu-sy-4354 | 2.330 us | }
0) qemu-sy-4354 | 2.952 us | }
0) qemu-sy-4354 | 3.547 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | autoremove_wake_function() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.322 us | }
0) qemu-sy-4354 | 1.278 us | }
0) qemu-sy-4354 | 1.839 us | }
0) qemu-sy-4354 | 2.402 us | }
0) qemu-sy-4354 | 3.032 us | }
0) qemu-sy-4354 | 3.658 us | }
0) qemu-sy-4354 | | __wake_up() {
0) qemu-sy-4354 | | __wake_up_common() {
0) qemu-sy-4354 | | autoremove_wake_function() {
0) qemu-sy-4354 | | default_wake_function() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.303 us | }
0) qemu-sy-4354 | 1.208 us | }
0) qemu-sy-4354 | 1.759 us | }
0) qemu-sy-4354 | 2.341 us | }
0) qemu-sy-4354 | 2.949 us | }
0) qemu-sy-4354 | 3.556 us | }
0) qemu-sy-4354 | | scheduler_tick() {
0) qemu-sy-4354 | | sched_slice() {
0) qemu-sy-4354 | 0.342 us | }
0) qemu-sy-4354 | 3.222 us | }
0) qemu-sy-4354 | | wake_up_process() {
0) qemu-sy-4354 | | try_to_wake_up() {
0) qemu-sy-4354 | | check_preempt_wakeup() {
0) qemu-sy-4354 | 0.343 us | }
0) qemu-sy-4354 | 1.331 us | }
0) qemu-sy-4354 | 1.915 us | }
0) qemu-sy-4354 | | kvm_lapic_sync_from_vapic() {
0) qemu-sy-4354 | 0.294 us | }
0) qemu-sy-4354 | | kvm_handle_exit() {
0) qemu-sy-4354 | 0.457 us | }
0) qemu-sy-4354 | | kvm_resched() {
0) qemu-sy-4354 | | _cond_resched() {
0) qemu-sy-4354 | | __cond_resched() {
0) qemu-sy-4354 | | schedule() {
0) qemu-sy-4354 | | wakeup_preempt_entity() {
0) qemu-sy-4354 | 0.294 us | }
0) qemu-sy-4354 | | kvm_sched_out() {
0) qemu-sy-4354 | | kvm_arch_vcpu_put() {
0) qemu-sy-4354 | 0.592 us | }
0) qemu-sy-4354 | 1.218 us | }
0) qemu-sy-4354 => kipmi0-496
0) qemu-sy-4213 => qemu-sy-4354
0) qemu-sy-4354 | | kvm_sched_in() {
0) qemu-sy-4354 | | kvm_arch_vcpu_load() {
0) qemu-sy-4354 | | kvm_write_guest_time() {
0) qemu-sy-4354 | 0.298 us | }
0) qemu-sy-4354 | 1.070 us | }
0) qemu-sy-4354 | 1.665 us | }
0) qemu-sy-4354 | ! 9172.159 us | }
0) qemu-sy-4354 | ! 9172.793 us | }
0) qemu-sy-4354 | ! 9173.422 us | }
0) qemu-sy-4354 | ! 9174.032 us | }
0) qemu-sy-4354 | | kvm_inject_pending_timer_irqs() {
0) qemu-sy-4354 | | kvm_inject_apic_timer_irqs() {
0) qemu-sy-4354 | | kvm_vcpu_kick() {
0) qemu-sy-4354 | 0.291 us | }
0) qemu-sy-4354 | 1.151 us | }
0) qemu-sy-4354 | | kvm_inject_pit_timer_irqs() {
0) qemu-sy-4354 | 0.352 us | }
0) qemu-sy-4354 | 2.429 us | }
0) qemu-sy-4354 | | kvm_lapic_enabled() {
0) qemu-sy-4354 | 0.291 us | }
0) qemu-sy-4354 | | kvm_lapic_find_highest_irr() {
0) qemu-sy-4354 | 0.312 us | }
0) qemu-sy-4354 | | kvm_lapic_get_cr8() {
0) qemu-sy-4354 | 0.298 us | }
0) qemu-sy-4354 | | kvm_cpu_has_interrupt() {
0) qemu-sy-4354 | | kvm_apic_has_interrupt() {
0) qemu-sy-4354 | 0.385 us | }
0) qemu-sy-4354 | 0.980 us | }
0) qemu-sy-4354 | | kvm_lapic_sync_to_vapic() {
0) qemu-sy-4354 | 0.295 us | }
0) qemu-sy-4354 | | kvm_lapic_sync_from_vapic() {
0) qemu-sy-4354 | 0.331 us | }
0) qemu-sy-4354 | | kvm_handle_exit() {
0) qemu-sy-4354 | 0.568 us | }
0) qemu-sy-4354 | | kvm_inject_pending_timer_irqs() {
0) qemu-sy-4354 | | kvm_inject_apic_timer_irqs() {
0) qemu-sy-4354 | | kvm_vcpu_kick() {
0) qemu-sy-4354 | 0.295 us | }
0) qemu-sy-4354 | 0.959 us | }
0) qemu-sy-4354 | | kvm_inject_pit_timer_irqs() {
0) qemu-sy-4354 | 0.313 us | }
0) qemu-sy-4354 | 2.170 us | }
0) qemu-sy-4354 | | kvm_lapic_enabled() {
0) qemu-sy-4354 | 0.310 us | }
0) qemu-sy-4354 | | kvm_lapic_find_highest_irr() {
0) qemu-sy-4354 | 0.295 us | }
0) qemu-sy-4354 | | kvm_lapic_get_cr8() {
0) qemu-sy-4354 | 0.295 us | }
0) qemu-sy-4354 | | kvm_cpu_has_interrupt() {
0) qemu-sy-4354 | | kvm_apic_has_interrupt() {
0) qemu-sy-4354 | 0.325 us | }
0) qemu-sy-4354 | 0.938 us | }
0) qemu-sy-4354 | | kvm_cpu_get_interrupt() {
0) qemu-sy-4354 | | kvm_get_apic_interrupt() {
0) qemu-sy-4354 | | kvm_apic_has_interrupt() {
0) qemu-sy-4354 | 0.322 us | }
0) qemu-sy-4354 | 0.944 us | }
0) qemu-sy-4354 | 1.542 us | }
0) qemu-sy-4354 | | kvm_timer_intr_post() {
0) qemu-sy-4354 | | kvm_apic_timer_intr_post() {
0) qemu-sy-4354 | 0.309 us | }
0) qemu-sy-4354 | 2.059 us | }
0) qemu-sy-4354 | | kvm_cpu_has_interrupt() {
0) qemu-sy-4354 | | kvm_apic_has_interrupt() {
0) qemu-sy-4354 | 0.340 us | }
0) qemu-sy-4354 | | kvm_apic_accept_pic_intr() {
0) qemu-sy-4354 | 0.313 us | }
0) qemu-sy-4354 | 1.560 us | }
0) qemu-sy-4354 | | kvm_lapic_sync_to_vapic() {
0) qemu-sy-4354 | 0.298 us | }
0) qemu-sy-4354 | | kvm_lapic_sync_from_vapic() {
0) qemu-sy-4354 | 0.319 us | }
0) qemu-sy-4354 | | kvm_handle_exit() {
0) qemu-sy-4354 | | kvm_mmu_page_fault() {
0) qemu-sy-4354 | | kvm_read_guest() {
0) qemu-sy-4354 | | kvm_read_guest_page() {
0) qemu-sy-4354 | 0.764 us | }
0) qemu-sy-4354 | 1.377 us | }
0) qemu-sy-4354 | | kvm_read_guest() {
0) qemu-sy-4354 | | kvm_read_guest_page() {
0) qemu-sy-4354 | 0.499 us | }
0) qemu-sy-4354 | 1.088 us | }
0) qemu-sy-4354 | | kvm_release_pfn_clean() {
0) qemu-sy-4354 | 0.349 us | }
0) qemu-sy-4354 | | kvm_read_guest() {
0) qemu-sy-4354 | | kvm_read_guest_page() {
0) qemu-sy-4354 | 0.451 us | }
0) qemu-sy-4354 | 1.046 us | }
0) qemu-sy-4354 | | kvm_read_guest() {
0) qemu-sy-4354 | | kvm_read_guest_page() {
0) qemu-sy-4354 | 0.361 us | }
0) qemu-sy-4354 | 0.956 us | }
0) qemu-sy-4354 | | kvm_read_guest() {
0) qemu-sy-4354 | | kvm_read_guest_page() {
0) qemu-sy-4354 | 0.381 us | }
0) qemu-sy-4354 | 0.974 us | }
0) qemu-sy-4354 | | kvm_read_guest() {
0) qemu-sy-4354 | | kvm_read_guest_page() {
0) qemu-sy-4354 | 0.345 us | }
0) qemu-sy-4354 | 0.959 us | }
0) qemu-sy-4354 | | kvm_read_guest() {
0) qemu-sy-4354 | | kvm_read_guest_page() {
0) qemu-sy-4354 | 0.364 us | }
0) qemu-sy-4354 | 0.965 us | }
0) qemu-sy-4354 | | kvm_ioapic_update_eoi() {
0) qemu-sy-4354 | 0.358 us | }
0) qemu-sy-4354 | + 13.782 us | }
0) qemu-sy-4354 | + 14.681 us | }
0) qemu-sy-4354 | | kvm_inject_pending_timer_irqs() {
0) qemu-sy-4354 | | kvm_inject_apic_timer_irqs() {
0) qemu-sy-4354 | | kvm_vcpu_kick() {
0) qemu-sy-4354 | 0.291 us | }
0) qemu-sy-4354 | 0.953 us | }
0) qemu-sy-4354 | | kvm_inject_pit_timer_irqs() {
0) qemu-sy-4354 | 0.304 us | }
0) qemu-sy-4354 | 2.150 us | }
0) qemu-sy-4354 | | kvm_lapic_enabled() {
0) qemu-sy-4354 | 0.304 us | }
0) qemu-sy-4354 | | kvm_lapic_find_highest_irr() {
0) qemu-sy-4354 | 0.295 us | }
0) qemu-sy-4354 | | kvm_lapic_get_cr8() {
0) qemu-sy-4354 | 0.309 us | }
0) qemu-sy-4354 | | kvm_cpu_has_interrupt() {
0) qemu-sy-4354 | | kvm_apic_has_interrupt() {
0) qemu-sy-4354 | 0.315 us | }
0) qemu-sy-4354 | 0.914 us | }
0) qemu-sy-4354 | | kvm_lapic_sync_to_vapic() {
0) qemu-sy-4354 | 0.297 us | }
0) qemu-sy-4354 | | kvm_lapic_sync_from_vapic() {
0) qemu-sy-4354 | 0.318 us | }
0) qemu-sy-4354 | | kvm_handle_exit() {
0) qemu-sy-4354 | | kvm_emulate_pio() {
0) qemu-sy-4354 | | kvm_io_bus_find_dev() {
0) qemu-sy-4354 | 0.406 us | }
0) qemu-sy-4354 | 1.115 us | }
0) qemu-sy-4354 | 2.026 us | }
0) qemu-sy-4354 | | kvm_get_cr8() {
0) qemu-sy-4354 | | kvm_lapic_get_cr8() {
0) qemu-sy-4354 | 0.292 us | }
0) qemu-sy-4354 | 2.257 us | }
0) qemu-sy-4354 | | kvm_arch_vcpu_put() {
0) qemu-sy-4354 | 0.574 us | }
0) qemu-sy-4354 | ! 250406.2 us | }
0) qemu-sy-4354 | ! 250407.0 us | }
There's 2 preemptions in there, accounting for perhaps 15ms
Then there's about 20 __wake_up()s in there (wth do those come from?)
accounting for 5ms each, totaling 100ms.
There's a scheduler_tick() in there but no IRQ entry ?!
All in all its very hard to get to the total of 250ms.
I suspect __vcpu_run() and vcpu_enter_guest() get inlined, and we might
just be looking at time spend in the guest... bit hard to tell for me,
as this is the first time ever I looked at all this kvm code.
Is there a way to add a wall-time column to this output so that we can
see where the time goes?
Another something nice would be to have ctx switches like:
foo-1 => bar-2 ran: ${time foo spend on the cpu} since: ${time bar spend away from the cpu}
I'll poke me a little at this function graph tracer thingy to see if I
can do that.
next prev parent reply other threads:[~2009-01-26 11:36 UTC|newest]
Thread overview: 133+ messages / expand[flat|nested] mbox.gz Atom feed top
2009-01-19 21:41 2.6.29-rc2-git1: Reported regressions 2.6.27 -> 2.6.28 Rafael J. Wysocki
2009-01-19 21:41 ` [Bug #11849] default IRQ affinity change in v2.6.27 (breaking several SMP PPC based systems) Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12061] snd_hda_intel: power_save: sound cracks on powerdown Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12208] uml is very slow on 2.6.28 host Rafael J. Wysocki
2009-01-26 11:35 ` Miklos Szeredi
2009-01-19 21:45 ` [Bug #12160] networking oops after resume from s2ram (2.6.28-rc6) Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12159] 2.6.28-rc6-git1 -- No sound produced from Intel HDA ALSA driver Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12263] Sata soft reset filling log Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12260] Regression due to commit 2b80848e3818fb1c (p54usb: support LM87 firmwares) Rafael J. Wysocki
2009-01-20 22:11 ` [PATCH -stable] p54usb: fix traffic stalls / packet drop Christian Lamparter
2009-01-20 22:36 ` Rafael J. Wysocki
2009-01-20 22:39 ` Greg KH
2009-01-20 23:56 ` John W. Linville
2009-01-21 14:03 ` Christian Lamparter
2009-01-19 21:45 ` [Bug #12224] journal activity on inactive partition causes inactive harddrive spinup Rafael J. Wysocki
2009-01-20 13:03 ` Theodore Tso
2009-01-19 21:45 ` [Bug #12209] oldish top core dumps (in its meminfo() function) Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12265] FPU emulation broken in 2.6.28-rc8 ? Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12264] i915: switching from kwin in opengl mode to a VT then back to x11, x11 freezes Rafael J. Wysocki
2009-01-20 18:13 ` Caleb Cushing
2009-01-19 21:45 ` [Bug #12337] ~100 extra wakeups reported by powertop Rafael J. Wysocki
2009-01-20 9:38 ` Alberto Gonzalez
2009-01-19 21:45 ` [Bug #12391] Processor does not go below C2 state until usb.autosuspend is enabled Rafael J. Wysocki
2009-01-27 10:27 ` Pavel Machek
2009-01-19 21:45 ` [Bug #12395] 2.6.28-rc9: oprofile regression Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12393] debugging in dosemu causes lots of 'scheduling while atomic' Rafael J. Wysocki
2009-01-20 9:58 ` Michal Suchanek
2009-01-19 21:45 ` [Bug #12396] hwinfo problem since 2.6.28 Rafael J. Wysocki
2009-01-26 14:00 ` Beschorner Daniel
2009-01-19 21:45 ` [Bug #12404] Oops in 2.6.28-rc9 and -rc8 -- mtrr issues / e1000e Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12403] TTY problem on linux-2.6.28-rc7 Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12401] 2.6.28 regression: xbacklight broken on ThinkPad X61s Rafael J. Wysocki
2009-01-20 7:30 ` Tino Keitel
2009-01-19 21:45 ` [Bug #12406] 2.6.28 thinks that my PS/2 mouse is a touchpad Rafael J. Wysocki
2009-01-20 1:45 ` Arjan Opmeer
2009-01-20 9:19 ` Dmitry Torokhov
2009-01-22 6:29 ` Alexander E. Patrakov
2009-01-19 21:45 ` [Bug #12407] Kernel 2.6.28 regression: Hang after hibernate Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12408] Funny problem with 2.6.28: Kernel stalls Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12405] oops in __bounce_end_io_read under kvm Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12409] NULL pointer dereference at get_stats() Rafael J. Wysocki
2009-01-21 16:18 ` Frederik Deweerdt
2009-01-24 0:39 ` Tetsuo Handa
2009-02-07 2:34 ` Tetsuo Handa
2009-02-09 11:19 ` Tetsuo Handa
2009-02-11 22:54 ` Alok Kataria
2009-02-11 23:02 ` Alok Kataria
2009-02-13 11:54 ` Tetsuo Handa
2009-01-19 21:45 ` [Bug #12465] KVM guests stalling on 2.6.28 (bisected) Rafael J. Wysocki
2009-01-20 0:12 ` Kevin Shanahan
2009-01-20 11:35 ` Ingo Molnar
2009-01-20 12:37 ` Avi Kivity
2009-01-20 12:42 ` Kevin Shanahan
2009-01-20 12:56 ` Ingo Molnar
2009-01-20 13:07 ` Ingo Molnar
2009-01-20 14:59 ` Steven Rostedt
2009-01-20 15:04 ` Ingo Molnar
2009-01-20 17:53 ` Steven Rostedt
2009-01-20 18:39 ` Ingo Molnar
2009-01-20 17:47 ` Avi Kivity
2009-01-21 14:25 ` Kevin Shanahan
2009-01-21 14:34 ` Avi Kivity
2009-01-21 14:51 ` Kevin Shanahan
2009-01-21 14:59 ` Avi Kivity
2009-01-21 15:13 ` Steven Rostedt
2009-01-22 1:48 ` Steven Rostedt
2009-01-21 15:10 ` Steven Rostedt
2009-01-21 15:18 ` Ingo Molnar
2009-01-22 19:57 ` Kevin Shanahan
2009-01-22 20:31 ` Ingo Molnar
2009-01-26 9:55 ` Kevin Shanahan
2009-01-26 11:35 ` Peter Zijlstra [this message]
2009-01-26 14:38 ` [RFC][PATCH] ftrace: function graph trace context switches Peter Zijlstra
2009-01-26 15:39 ` Frédéric Weisbecker
2009-01-26 15:41 ` Steven Rostedt
2009-03-16 17:57 ` Frederic Weisbecker
2009-01-26 15:00 ` [Bug #12465] KVM guests stalling on 2.6.28 (bisected) Ingo Molnar
2009-01-20 14:23 ` Kevin Shanahan
2009-01-20 14:25 ` Ingo Molnar
2009-01-20 15:51 ` Kevin Shanahan
2009-01-20 16:06 ` Ingo Molnar
2009-01-20 16:19 ` Peter Zijlstra
2009-01-20 14:46 ` Frédéric Weisbecker
2009-01-20 13:04 ` Avi Kivity
2009-01-20 17:54 ` Kevin Shanahan
2009-01-20 18:42 ` Ingo Molnar
2009-01-19 21:45 ` [Bug #12411] 2.6.28: BUG in r8169 Rafael J. Wysocki
2009-01-19 21:45 ` [Bug #12426] TMDC Joystick no longer works in kernel 2.6.28 Rafael J. Wysocki
2009-01-21 0:48 ` Andrew S. Johnson
2009-01-22 13:34 ` Jiri Kosina
2009-01-23 2:06 ` Andrew S. Johnson
2009-01-26 11:49 ` Jiri Kosina
2009-01-19 21:45 ` [Bug #12483] Reference to inexistent struct dmi_device_id breaks the build Rafael J. Wysocki
2009-01-20 8:15 ` Jean Delvare
2009-01-19 21:45 ` [Bug #12500] r8169: NETDEV WATCHDOG: eth0 (r8169): transmit timed out Rafael J. Wysocki
2009-01-22 16:43 ` 2.6.29-rc2-git1: Reported regressions 2.6.27 -> 2.6.28 Jörg-Volker Peetz
2009-01-24 13:25 ` Rolf Eike Beer
2009-02-04 10:55 2.6.29-rc3-git6: " Rafael J. Wysocki
2009-02-04 10:58 ` [Bug #12465] KVM guests stalling on 2.6.28 (bisected) Rafael J. Wysocki
2009-02-05 19:35 ` Kevin Shanahan
2009-02-05 22:37 ` Rafael J. Wysocki
2009-02-14 20:48 2.6.29-rc5: Reported regressions 2.6.27 -> 2.6.28 Rafael J. Wysocki
2009-02-14 20:50 ` [Bug #12465] KVM guests stalling on 2.6.28 (bisected) Rafael J. Wysocki
2009-02-23 22:00 2.6.29-rc6: Reported regressions 2.6.27 -> 2.6.28 Rafael J. Wysocki
2009-02-23 22:03 ` [Bug #12465] KVM guests stalling on 2.6.28 (bisected) Rafael J. Wysocki
2009-02-24 0:59 ` Kevin Shanahan
2009-02-24 1:37 ` Rafael J. Wysocki
2009-02-24 12:09 ` Avi Kivity
2009-02-24 22:11 ` Kevin Shanahan
2009-03-03 19:34 2.6.29-rc6-git7: Reported regressions 2.6.27 -> 2.6.28 Rafael J. Wysocki
2009-03-03 19:41 ` [Bug #12465] KVM guests stalling on 2.6.28 (bisected) Rafael J. Wysocki
2009-03-04 3:08 ` Kevin Shanahan
2009-03-08 10:04 ` Avi Kivity
2009-03-14 19:11 2.6.29-rc8: Reported regressions 2.6.27 -> 2.6.28 Rafael J. Wysocki
2009-03-14 19:20 ` [Bug #12465] KVM guests stalling on 2.6.28 (bisected) Rafael J. Wysocki
2009-03-15 9:03 ` Kevin Shanahan
2009-03-15 9:18 ` Avi Kivity
2009-03-15 9:48 ` Ingo Molnar
2009-03-15 9:56 ` Avi Kivity
2009-03-15 10:03 ` Ingo Molnar
2009-03-15 10:13 ` Avi Kivity
2009-03-16 9:49 ` Avi Kivity
2009-03-16 12:46 ` Kevin Shanahan
2009-03-16 20:07 ` Frederic Weisbecker
2009-03-16 22:55 ` Kevin Shanahan
2009-03-18 0:20 ` Frederic Weisbecker
2009-03-18 1:16 ` Kevin Shanahan
2009-03-18 2:24 ` Frederic Weisbecker
2009-03-18 21:24 ` Kevin Shanahan
2009-03-21 5:00 ` Kevin Shanahan
2009-03-21 14:08 ` Frederic Weisbecker
2009-03-24 11:44 ` Frederic Weisbecker
2009-03-24 11:47 ` Frederic Weisbecker
2009-03-25 23:40 ` Kevin Shanahan
2009-03-25 23:48 ` Frederic Weisbecker
2009-03-26 20:22 ` Kevin Shanahan
2009-03-21 17:01 2.6.29-rc8-git5: Reported regressions 2.6.27 -> 2.6.28 Rafael J. Wysocki
2009-03-21 17:07 ` [Bug #12465] KVM guests stalling on 2.6.28 (bisected) Rafael J. Wysocki
2009-03-21 19:50 ` Ingo Molnar
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=1232969705.4863.46.camel@laptop \
--to=a.p.zijlstra@chello.nl \
--cc=avi@redhat.com \
--cc=bugme-daemon@bugzilla.kernel.org \
--cc=efault@gmx.de \
--cc=fweisbec@gmail.com \
--cc=kernel-testers@vger.kernel.org \
--cc=kmshanah@ucwb.org.au \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@elte.hu \
--cc=rjw@sisk.pl \
--cc=rostedt@goodmis.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).