Re: rcu: INFO: rcu_preempt detected stalls on CPUs/tasks on v3.6

[Avi Kivity <avi@redhat.com>]

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