Messages in this thread | | | Date | Mon, 30 Jul 2012 16:17:53 +0300 | From | Avi Kivity <> | Subject | Re: rcu: INFO: rcu_preempt detected stalls on CPUs/tasks on v3.6 |
| |
On 07/30/2012 03:43 PM, Sasha Levin wrote: >>>>> >>>>>> Then work backwards to see the last place it is >>>>>> programmed (APIC_TMICT/APIC_TDCR). >>>>> >>>>> This looks like what you're looking for: >>>>> >>>>> kvm_apic: apic_write APIC_TMICT = 0x3e >> >> What about APIC_TMICT? Might be configured just once on boot. > > Did you mean APIC_TDCR?
Yes, sorry.
> > I'm seeing both in the trace logs, but it's APIC_TMICT thats shown when the hang occurs. > > vm-19727 [002] ...1 66669.010699: kvm_apic: apic_read APIC_TDCR = 0x0 > vm-19727 [002] ...1 66669.010699: kvm_msr: msr_read 83e = 0x0 > vm-19727 [002] d..2 66669.010699: kvm_entry: vcpu 0 > vm-19727 [002] d..2 66669.010700: kvm_exit: reason MSR_WRITE rip 0xffffffff810a06a8 info 0 0 > vm-19727 [002] ...1 66669.010701: kvm_apic: apic_write APIC_TDCR = 0x3 > vm-19727 [002] ...1 66669.010701: kvm_msr: msr_write 83e = 0x3 > vm-19727 [002] d..2 66669.010701: kvm_entry: vcpu 0
TDCR is needed to interpret TMICT.
> >>>>> >>>>> >>>>> Basically it's spinning on the following 4 lines of trace when it happens: >>>>> >>>>> 16063.549189: kvm_apic: apic_write APIC_TMICT = 0x3e >>>>> 16063.549190: kvm_msr: msr_write 838 = 0x3e >>>>> 16063.549190: kvm_exit: reason EXTERNAL_INTERRUPT rip 0xffffffff8115de02 info 0 0 >>>>> 16063.549190: kvm_entry: vcpu 2 >>>>> >>>> >>>> What, no kvm_inj_virq? >>>> >>>> Are you running with pveoi? Try disabling it. >> >> What's the answer to this question? > > The host is running 3.5, so that shouldn't be enabled.
Ok.
>> Please add hrtimer_start and hrtimer_expire_entry to your traced events. >> > > A bigger log with those two enabled: > > vm-19730 [003] ...1 66730.739585: kvm_apic: apic_write APIC_TMICT = 0x3e > vm-19716 [000] d..3 66730.739586: hrtimer_start: hrtimer=ffff880133cc3f78 function=posix_timer_fn expires=66882054763626 softexpires=66882054763626 > vm-19730 [003] d..2 66730.739586: hrtimer_start: hrtimer=ffff88011e00d3d0 function=kvm_timer_fn expires=66882053774813 softexpires=66882053774813
vcpu 3 programs the timer, and kvm sets an hrtimer, but fat in the future?
> vm-19730 [003] ...1 66730.739586: kvm_msr: msr_write 838 = 0x3e > vm-19730 [003] d..2 66730.739587: kvm_entry: vcpu 3 > vm-19730 [003] d..2 66730.739589: kvm_exit: reason PENDING_INTERRUPT rip 0xffffffff8115c684 info 0 0 > vm-19729 [001] d..2 66730.739590: kvm_exit: reason MSR_WRITE rip 0xffffffff810a06a8 info 0 0 > vm-19730 [003] d.h2 66730.739590: hrtimer_expire_entry: hrtimer=ffff88011e00d3d0 function=kvm_timer_fn now=66882053778032
Nope, the ftrace time and hrtimer time aren't synchronized.
> vm-19729 [001] ...1 66730.739591: kvm_apic: apic_write APIC_TMICT = 0x3e
vcpu 2 sets its timer.
> vm-19730 [003] ...1 66730.739591: kvm_apic_accept_irq: apicid 3 vec 239 (Fixed|edge) (coalesced)
The original vcpu gets its interrupt delivered.
> vm-19729 [001] d..2 66730.739591: hrtimer_start: hrtimer=ffff88020d208490 function=kvm_timer_fn expires=66882053780380 softexpires=66882053780380
vcpu 2 sets its hrtimer.
> vm-19730 [003] ...1 66730.739592: kvm_inj_virq: irq 239 > vm-19729 [001] ...1 66730.739592: kvm_msr: msr_write 838 = 0x3e > vm-19730 [003] d..2 66730.739593: kvm_entry: vcpu 3 > vm-19729 [001] d..2 66730.739593: kvm_entry: vcpu 2 > vm-19730 [003] d..2 66730.739594: kvm_exit: reason MSR_WRITE rip 0xffffffff810a06a8 info 0 0 > vm-19729 [001] d..2 66730.739594: kvm_exit: reason EXTERNAL_INTERRUPT rip 0xffffffff83601f61 info 0 0
vcpu 2 hrtimer fires, but it doesn't know it yet.
> vm-19730 [003] ...1 66730.739595: kvm_apic: apic_write APIC_EOI = 0x0 > vm-19730 [003] ...1 66730.739595: kvm_msr: msr_write 80b = 0x0 > vm-19729 [001] d.h2 66730.739596: hrtimer_expire_entry: hrtimer=ffff88020d208490 function=kvm_timer_fn now=66882053783462
vcpu 2 hrtimer fires.
> vm-19730 [003] ...1 66730.739596: kvm_apic_accept_irq: apicid 3 vec 239 (Fixed|edge) > vm-19729 [001] ...1 66730.739597: kvm_apic_accept_irq: apicid 2 vec 239 (Fixed|edge) (coalesced)
and delivers a guest interrupt, but guest interrupts are still blocked.
> vm-19730 [003] d..2 66730.739597: kvm_entry: vcpu 3 > vm-19729 [001] d..2 66730.739597: kvm_entry: vcpu 2 > vm-19729 [001] d..2 66730.739598: kvm_exit: reason PENDING_INTERRUPT rip 0xffffffff8115c684 info 0 0 > vm-19729 [001] ...1 66730.739599: kvm_apic_accept_irq: apicid 2 vec 239 (Fixed|edge) (coalesced) > vm-19729 [001] ...1 66730.739600: kvm_inj_virq: irq 239 > vm-19729 [001] d..2 66730.739600: kvm_entry: vcpu 2
Interrupts unblocked, interrupt delivered.
So: either the hrtimer is set for way too low a deadline, or perhaps it expires prematurely.
TDCR=3 means divide by 16, together with TMICT=0x3e and a bus frequency of 1GHz this means 992 ns expiration, which is consistent with what we see.
Possible causes: - the APIC calibration in the guest failed, so it is programming too low values into the timer - it actually needs 1 us wakeups and then can't keep up (esp. as kvm interrupt injection is slowing it down)
You can try to find out by changing arch/x86/kvm/lapic.c:start_lapic_timer() to impose a minimum wakeup of (say) 20 microseconds which will let the guest live long enough for you to ftrace it and see what kind of timers it is programming.
> vm-19729 [001] d..2 66730.739601: kvm_exit: reason MSR_WRITE rip 0xffffffff810a06a8 info 0 0 > vm-19729 [001] ...1 66730.739602: kvm_apic: apic_write APIC_EOI = 0x0 > vm-19729 [001] ...1 66730.739602: kvm_msr: msr_write 80b = 0x0 > vm-19730 [003] d..2 66730.739603: kvm_exit: reason MSR_WRITE rip 0xffffffff810a06a8 info 0 0 > vm-19729 [001] ...1 66730.739603: kvm_apic_accept_irq: apicid 2 vec 239 (Fixed|edge) > vm-19730 [003] ...1 66730.739604: kvm_apic: apic_write APIC_TMICT = 0x3e > vm-19729 [001] d..2 66730.739604: kvm_entry: vcpu 2 > vm-19730 [003] d..2 66730.739604: hrtimer_start: hrtimer=ffff88011e00d3d0 function=kvm_timer_fn expires=66882053793430 softexpires=66882053793430 > vm-19730 [003] ...1 66730.739605: kvm_msr: msr_write 838 = 0x3e > vm-19730 [003] d..2 66730.739606: kvm_entry: vcpu 3 > vm-19730 [003] d..2 66730.739607: kvm_exit: reason PENDING_INTERRUPT rip 0xffffffff8115c684 info 0 0 > vm-19729 [001] d..2 66730.739608: kvm_exit: reason EXTERNAL_INTERRUPT rip 0xffffffff8115f2a1 info 0 0 > vm-19730 [003] d.h2 66730.739608: hrtimer_expire_entry: hrtimer=ffff88011e00d3d0 function=kvm_timer_fn now=66882053796355 > vm-19729 [001] ...1 66730.739609: kvm_userspace_exit: reason restart (4) > vm-19730 [003] ...1 66730.739610: kvm_apic_accept_irq: apicid 3 vec 239 (Fixed|edge) (coalesced) > vm-19730 [003] ...1 66730.739611: kvm_userspace_exit: reason restart (4) > vm-19716 [000] ...1 66730.739612: kvm_set_irq: gsi 4 level 1 source 0 > vm-19716 [000] ...2 66730.739614: kvm_pic_set_irq: chip 0 pin 4 (edge) >
-- error compiling committee.c: too many arguments to function
| |