Re: Another preempt folding issue?

[Stefan Bader <stefan.bader@canonical.com>]

[-- Attachment #1: Type: text/plain, Size: 6588 bytes --]

On 13.02.2014 19:25, Peter Zijlstra wrote:
> On Thu, Feb 13, 2014 at 06:00:19PM +0100, Stefan Bader wrote:
>> On 12.02.2014 12:54, Peter Zijlstra wrote:
>>> On Wed, Feb 12, 2014 at 12:09:29PM +0100, Stefan Bader wrote:
>>>> Something else here I run a kernel with CONFIG_PREEMPT not set and NR_CPUS
>>>> limited to 8 (for the 32bit kernel). So the default apic driver is used. Since
>>>> default_send_IPI_mask_logical is only used from there, I assume the trace you
>>>> got does the same. Maybe something there is wrong which would explain why we
>>>> only see it on 32bit hosts.
>>>
>>> Can you try with a different APIC driver to test this?
>>>
>> I don't think I can. And I think the statement about this only be used for 32bit
>> could be wrong. I got mislead to think so because those are only defined in
>> probe_32 but the 64bit counterpart isn't containing much aside that.
>>
>> Anyway, I played around with tracing a bit more. So with this change:
>>
>>                 if (need_resched()) {
>>                         srcu_read_unlock(&kvm->srcu, vcpu->srcu_idx);
>>                         if (need_resched() != should_resched()) {
>> +                               trace_printk("need(%i) != should(%i)\n",
>> +                                       need_resched(), should_resched());
>> +                               trace_printk("exit_reason=%u\n",
>> +                                       vcpu->run->exit_reason);
>> +                                trace_printk("preempt_count=%lx\n",
>> +                                        __this_cpu_read_4(__preempt_count));
>> +                                tracing_stop();
>> +                                printk(KERN_ERR "Stopped tracing, due to
>> inconsistent state.\n");
>>                         }
>>  +                      schedule();
>>  -                      cond_reschedule();
>>                         vcpu->srcu_idx = srcu_read_lock(&kvm->srcu);
>>                 }
>>
>> I get the following (weird) output:
>>
>>             Xorg-1078  [001] d...    71.270251: native_smp_send_reschedule
>> <-resched_task
>>             Xorg-1078  [001] d...    71.270251: default_send_IPI_mask_logical
>> <-native_smp_send_reschedule
>>       bamfdaemon-2318  [001] d...    71.270465: resched_task <-check_preempt_wakeup
>>       bamfdaemon-2318  [001] d...    71.270539: resched_task <-check_preempt_wakeup
>>           compiz-2365  [001] d...    71.270689: resched_task <-check_preempt_wakeup
>>           compiz-2365  [001] d...    71.270827: resched_task <-check_preempt_wakeup
>>           compiz-2365  [001] d...    71.270940: resched_task <-check_preempt_wakeup
>>  qemu-system-x86-2679  [000] dn..    71.270999: smp_reschedule_interrupt
>> <-reschedule_interrupt
>>  qemu-system-x86-2679  [000] dn..    71.270999: scheduler_ipi
>> <-smp_reschedule_interrupt
>>  qemu-system-x86-2679  [000] .N..    71.271001: kvm_arch_vcpu_ioctl_run: need(1)
>> != should(0)
>>  qemu-system-x86-2679  [000] .N..    71.271002: kvm_arch_vcpu_ioctl_run:
>> exit_reason=2
>>  qemu-system-x86-2679  [000] .N..    71.271003: kvm_arch_vcpu_ioctl_run:
>> preempt_count=0
>>
>> So am I reading this right, that the interrupt did get delivered to cpu#0 while
>> the thread info already had the resched flag set. So this really should have
>> cleared the bit in preempt_count. But while the trace info shows 'N' for some
>> reason should_reschedule returns false but at the same time reading the preempt
>> count manually shows it 0?
> 
> So the assembly merges the first and second should_resched(), so its
> possible that load got before the interrupt().
> 
> The 3rd preempt_count load gets re-issued and so that would show the
> 'true' value again.
> 
> If you want to force a reload after the condition; put in a barrier().
> 
> In any case; this looks like a false-positive. Please try again until
> you get one where the interrupt doesn't happen and we stay in 'n' state.
> 
Ok, I think I now got a log of the actual issue. It seems cpu#1 missed out on
handling a reschedule interrupt but did send one to cpu#0 and on cpu#0 while
handling the interrupt the tif flag was not set (yet?) but then when it is,
there is no more interrupt to do the folding... (sorry for the wrapping)...

 qemu-system-x86-2503  [000] d.h.  1145.887872: default_send_IPI_mask_logical
<-native_smp_send_reschedule
 qemu-system-x86-2503  [000] d...  1145.887888: resched_task <-check_preempt_curr
          <idle>-0     [000] d.h.  1145.888001: resched_task <-check_preempt_curr
          <idle>-0     [001] dn..  1145.888788: smp_reschedule_interrupt
<-reschedule_interrupt
          <idle>-0     [001] dn..  1145.888789: scheduler_ipi
<-smp_reschedule_interrupt
  gnome-terminal-2440  [000] d...  1145.888957: resched_task <-check_preempt_curr
  gnome-terminal-2440  [000] d...  1145.888959: native_smp_send_reschedule
<-resched_task
  gnome-terminal-2440  [000] d...  1145.888959: default_send_IPI_mask_logical
<-native_smp_send_reschedule
          <idle>-0     [001] dn..  1145.889296: smp_reschedule_interrupt
<-reschedule_interrupt
          <idle>-0     [001] dn..  1145.889297: scheduler_ipi
<-smp_reschedule_interrupt
  gnome-terminal-2440  [000] d...  1145.889465: resched_task <-check_preempt_curr
  gnome-terminal-2440  [000] d...  1145.889467: native_smp_send_reschedule
<-resched_task
  gnome-terminal-2440  [000] d...  1145.889467: default_send_IPI_mask_logical
<-native_smp_send_reschedule
            Xorg-1054  [001] d.h.  1145.889469: resched_task <-check_preempt_wakeup
            Xorg-1054  [001] d.h.  1145.889469: native_smp_send_reschedule
<-resched_task
            Xorg-1054  [001] d.h.  1145.889469: default_send_IPI_mask_logical
<-native_smp_send_reschedule
 qemu-system-x86-2503  [000] d.s.  1145.889643: smp_reschedule_interrupt
<-reschedule_interrupt
 qemu-system-x86-2503  [000] d.s.  1145.889643: scheduler_ipi
<-smp_reschedule_interrupt
 qemu-system-x86-2503  [000] .n..  1145.889647: kvm_arch_vcpu_ioctl_run: sched
inconsistency
 qemu-system-x86-2503  [000] .n..  1145.889662: kvm_arch_vcpu_ioctl_run: sched
inconsistency
 qemu-system-x86-2503  [000] .n..  1145.889664: kvm_arch_vcpu_ioctl_run: sched
inconsistency
 qemu-system-x86-2503  [000] .n..  1145.889668: kvm_arch_vcpu_ioctl_run: need(1)
!= should(0)
 qemu-system-x86-2503  [000] .n..  1145.889669: kvm_arch_vcpu_ioctl_run:
exit_reason=2
 qemu-system-x86-2503  [000] .n..  1145.889669: kvm_arch_vcpu_ioctl_run:
preempt_count=80000000


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 901 bytes --]