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

[Avi Kivity <avi@redhat.com>]

On 07/30/2012 12:13 PM, Sasha Levin wrote:
>>>>>
>>>>> Yup, looks like it. kvm_stats is something like this:
>>>>>
>>>>>  kvm_entry                                142104033  939393
>>>>>  kvm_exit                                 142104004  939390
>>>>>  kvm_apic                                  84781115  582714
>>>>>  kvm_msr                                   84682085  582714
>>>>>  kvm_apic_accept_irq                       65219959  522263
>>>>>  kvm_inj_virq                              43173709  291385
>>>>>
>>>>> With everything else at 0 when it happens.
>>>>
>>>> Please run a trace and verify that the injected vector is indeed the
>>>> timer interrupt.
>>>
>>> Looks like it is.
>>>
>>>> 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.

>>>
>>>
>>> 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?

> 
> I must have looked at a block in the logfile which doesn't represent everything thats going on, sorry.
> 
> Here's a more complete picture:
> 
> 	vm-16567 [000] d..2 16063.549298: kvm_exit: reason PENDING_INTERRUPT rip 0xffffffff83625c80 info 0 0
> 	vm-16567 [000] ...1 16063.549299: kvm_inj_virq: irq 239
> 	vm-16567 [000] d..2 16063.549300: kvm_entry: vcpu 0
> 	vm-16567 [000] d..2 16063.549301: kvm_exit: reason MSR_WRITE rip 0xffffffff8109fef8 info 0 0
> 	vm-16567 [000] ...1 16063.549302: kvm_apic: apic_write APIC_EOI = 0x0
> 	vm-16567 [000] ...1 16063.549302: kvm_msr: msr_write 80b = 0x0
> 	vm-16567 [000] d..2 16063.549303: kvm_entry: vcpu 0
> 	vm-16567 [000] d..2 16063.549308: kvm_exit: reason MSR_WRITE rip 0xffffffff8109fef8 info 0 0
> 	vm-16567 [000] ...1 16063.549309: kvm_apic: apic_write APIC_TMICT = 0x3e
> 	vm-16567 [000] ...1 16063.549310: kvm_msr: msr_write 838 = 0x3e
> 	vm-16567 [000] d..2 16063.549311: kvm_entry: vcpu 0
> 	vm-16567 [000] d..2 16063.549312: kvm_exit: reason PENDING_INTERRUPT rip 0xffffffff83625c80 info 0 0

This must refer to a lower priority interrupt, since 239 hasn't been
injected yet.

> 	vm-16567 [000] ...1 16063.549314: kvm_apic_accept_irq: apicid 0 vec 239 (Fixed|edge)

And now conveniently the hrtimer fires and injects another interrupt.

> 	vm-16567 [000] ...1 16063.549315: kvm_inj_virq: irq 239
> 	vm-16567 [000] d..2 16063.549315: kvm_entry: vcpu 0
> 	vm-16567 [000] d..2 16063.549316: kvm_exit: reason MSR_WRITE rip 0xffffffff8109fef8 info 0 0
> 	vm-16567 [000] ...1 16063.549318: kvm_apic: apic_write APIC_EOI = 0x0
> 	vm-16567 [000] ...1 16063.549318: kvm_msr: msr_write 80b = 0x0

Please add hrtimer_start and hrtimer_expire_entry to your traced events.

-- 
error compiling committee.c: too many arguments to function