Another preempt folding issue?

Hi Peter,

I am currently looking at a weird issue that manifest itself when trying to run kvm enabled qemu on a i386 host (v3.13 kernel, oh and potentially important the cpu is 64bit capable, so qemu-system-x86_64 is called).

Sooner or later this
causes softlockup messages on the host. I tracked this down to __vcpu_run in arch/x86/kvm/x86.c which does a loop which in that case never seems to make progress or exit.

What I found is that vcpu_enter_guest will exit quickly without causing the loop to exit when need_resched() is true. Looking at a crash dump I took, this was the case (thread_info->flags had TIF_NEED_RESCHED set). So after immediately returning __vcpu_run has the following code:

        if (need_resched()) {
                srcu_read_unlock(&kvm->srcu, vcpu->srcu_idx);
                kvm_resched(vcpu); // now cond_resched();
                vcpu->srcu_idx = srcu_read_lock(&kvm->srcu);
        }

The kvm_resched basically would end up doing a cond_resched() which now checks preempt_count() to be 0. If that is zero it will do the reschedule, otherwise it just does nothing. Looking at the percpu variables in the dump, I saw that the preempt_count was 0x8000000 (actually it was 0x80110000 but that was me triggering the kexec crashdump with sysrq-c).

I saw that there have been some changes in the upstream kernel and have picked the following:
1) x86, acpi, idle: Restructure the mwait idle routines
2) x86, idle: Use static_cpu_has() for CLFLUSH workaround, add barriers
3) sched/preempt: Fix up missed PREEMPT_NEED_RESCHED folding
4) sched/preempt/x86: Fix voluntary preempt for x86

Patch 1) and 2) as dependencies of 3) (to get the mwait function correct and to the other file). Finally 4) is fixing up 3). [maybe worth suggesting to do for 3.13.y stable].

Still, with all those I got the softlockup. Since I knew from the dump info that something is wrong with the folding, I made the pragmatic approach and added the following:

        if (need_resched()) {
                srcu_read_unlock(&kvm->srcu, vcpu->srcu_idx);
+               preempt_fold_need_resched();
                kvm_resched(vcpu); // now cond_resched();
                vcpu->srcu_idx = srcu_read_lock(&kvm->srcu);
        }

And this lets the kvm guest run without the softlockups! However I am less than convinced that this is the right thing to do. Somehow something done when converting the preempt_count into percpu has caused at least the i386 side to get into this mess (as there has not been any whining about 64bit). Just fail to see what.

What is the problem exactly?

From the trace:

Quoted 5 lines · Stefan Bader

Hi Peter,

I am currently looking at a weird issue that manifest itself when trying to run kvm enabled qemu on a i386 host (v3.13 kernel, oh and potentially important the cpu is 64bit capable, so qemu-system-x86_64 is called).

AMD or Intel machine?

Quoted 45 lines

Sooner or later this
causes softlockup messages on the host. I tracked this down to __vcpu_run in arch/x86/kvm/x86.c which does a loop which in that case never seems to make progress or exit.

What I found is that vcpu_enter_guest will exit quickly without causing the loop to exit when need_resched() is true. Looking at a crash dump I took, this was the case (thread_info->flags had TIF_NEED_RESCHED set). So after immediately returning __vcpu_run has the following code:

        if (need_resched()) {
                srcu_read_unlock(&kvm->srcu, vcpu->srcu_idx);
                kvm_resched(vcpu); // now cond_resched();
                vcpu->srcu_idx = srcu_read_lock(&kvm->srcu);
        }

The kvm_resched basically would end up doing a cond_resched() which now checks preempt_count() to be 0. If that is zero it will do the reschedule, otherwise it just does nothing. Looking at the percpu variables in the dump, I saw that the preempt_count was 0x8000000 (actually it was 0x80110000 but that was me triggering the kexec crashdump with sysrq-c).

I saw that there have been some changes in the upstream kernel and have picked the following:
1) x86, acpi, idle: Restructure the mwait idle routines
2) x86, idle: Use static_cpu_has() for CLFLUSH workaround, add barriers
3) sched/preempt: Fix up missed PREEMPT_NEED_RESCHED folding
4) sched/preempt/x86: Fix voluntary preempt for x86

Patch 1) and 2) as dependencies of 3) (to get the mwait function correct and to the other file). Finally 4) is fixing up 3). [maybe worth suggesting to do for 3.13.y stable].

Still, with all those I got the softlockup. Since I knew from the dump info that something is wrong with the folding, I made the pragmatic approach and added the following:

        if (need_resched()) {
                srcu_read_unlock(&kvm->srcu, vcpu->srcu_idx);
+               preempt_fold_need_resched();
                kvm_resched(vcpu); // now cond_resched();
                vcpu->srcu_idx = srcu_read_lock(&kvm->srcu);
        }

Quoted 5 lines

And this lets the kvm guest run without the softlockups! However I am less than convinced that this is the right thing to do. Somehow something done when converting the preempt_count into percpu has caused at least the i386 side to get into this mess (as there has not been any whining about 64bit). Just fail to see what.

I've been looking at the same thing too; I've got a trace from someone who can reproduce and its just not making sense.

Looks like the hardware is loosing an interrupt (or worse).

With the below patch on top of current -git (might be whitespace damaged due to copy-paste).

---
 arch/x86/kvm/x86.c | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

arch/x86/kvm/x86.c +5 -2

index 39c28f09dfd5..f8b2fc7ce491 100644
@@ -6115,7 +6115,11 @@ static int __vcpu_run(struct kvm_vcpu *vcpu)
                }
                if (need_resched()) {
                        srcu_read_unlock(&kvm->srcu, vcpu->srcu_idx);
-                       cond_resched();
+                       if (need_resched() != should_resched()) {
+                               tracing_stop();
+                               printk(KERN_ERR "Stopped tracing, due to inconsistent state.\n");
+                       }
+                       schedule();
                        vcpu->srcu_idx = srcu_read_lock(&kvm->srcu);
                }
        }
 
---

I got the following from an Athlon X2 (fam 0xf):

Quoted 1 line · Marcelo Tosatti

What is the problem exactly?

From the trace:

 qemu-system-x86-2455  [001] d.s3   393.630586: smp_reschedule_interrupt <-reschedule_interrupt
 qemu-system-x86-2455  [001] d.s3   393.630586: scheduler_ipi <-smp_reschedule_interrupt
 qemu-system-x86-2455  [001] ..s3   393.630586: preempt_count_sub <-_raw_spin_unlock_irqrestore
 qemu-system-x86-2455  [001] ..s2   393.630586: _raw_spin_lock_irq <-run_timer_softirq
 qemu-system-x86-2455  [001] d.s2   393.630586: preempt_count_add <-_raw_spin_lock_irq
 qemu-system-x86-2455  [001] d.s3   393.630586: _raw_spin_unlock_irq <-run_timer_softirq
 qemu-system-x86-2455  [001] ..s3   393.630586: preempt_count_sub <-_raw_spin_unlock_irq
 qemu-system-x86-2455  [001] ..s2   393.630586: rcu_bh_qs <-__do_softirq
 qemu-system-x86-2455  [001] d.s2   393.630586: irqtime_account_irq <-__do_softirq
 qemu-system-x86-2455  [001] d.s2   393.630586: __local_bh_enable <-__do_softirq
 qemu-system-x86-2455  [001] d.s2   393.630586: preempt_count_sub <-__local_bh_enable

           dmesg-2458  [000] d.s5   393.630614: resched_task <-check_preempt_wakeup
           dmesg-2458  [000] d.s5   393.630614: native_smp_send_reschedule <-resched_task
           dmesg-2458  [000] d.s5   393.630614: default_send_IPI_mask_logical <-native_smp_send_reschedule

 qemu-system-x86-2455  [001] .n..   393.630636: preempt_count_add <-kmap_atomic_prot
 qemu-system-x86-2455  [001] .n.1   393.630639: __kunmap_atomic <-clear_huge_page
 qemu-system-x86-2455  [001] .n.1   393.630639: preempt_count_sub <-__kunmap_atomic
 qemu-system-x86-2455  [001] .n..   393.630639: _cond_resched <-clear_huge_page
 qemu-system-x86-2455  [001] .n..   393.630640: kmap_atomic <-clear_huge_page
 qemu-system-x86-2455  [001] .n..   393.630640: kmap_atomic_prot <-kmap_atomic
 qemu-system-x86-2455  [001] .n..   393.630640: preempt_count_add <-kmap_atomic_prot

The resched_task() in the middle does:

  set_tsk_need_resched();
  smp_mb();
  smp_send_reschedule();

This means that the remote cpu must observe TIF_NEED_RESCHED (.n.. in the traces) when the IPI (smp_reschedule_interrupt) hits.

Now given the machine has unsynchronized TSC the order in the above is not necessarily the true order, but there's only two possible scenarios:

1) its the right order; the smp_reschedule_interrupt() is from a previous resched_task()/rcu kick or any of the other users that sends it.

In which case we should get another smp_reschedule_interrupt() _after_ the resched_task() which should observe the 'n' and promote it to an 'N'.

This doesn't happen and we're stuck with the 'n' state..

2) its the wrong order and the smp_reschedule_interrupt() actually happened after the resched_task(), but in that case we should have observed the 'n', we did not.

Now given that 2) would mean a bug in the coherency fabric and 1) would mean a lost interrupt, 1 seems like the more likely suspect.

Joerg wanted the extra kvm tracepoints to see what the vm-exit reason is.

Quoted 8 lines · Peter Zijlstra

Quoted 5 lines · Stefan Bader

Hi Peter,

I am currently looking at a weird issue that manifest itself when trying to run kvm enabled qemu on a i386 host (v3.13 kernel, oh and potentially important the cpu is 64bit capable, so qemu-system-x86_64 is called).

AMD or Intel machine?

Personally I am reproducing this on an AMD:

cpu family : 15
model : 72
model name : AMD Turion(tm) 64 X2 Mobile Technology TL-64

but the reports I got are showing the same issue on an Intel i7

cpu family : 6
model : 37
model name : Intel(R) Core(TM) i7 CPU M 620 @ 2.67GH

Another reporter also saw this on an AMD and said it could not be reproduced on the same hardware and the same software versions when using 64bit instead of 32.

In my case on a 32bit installation I will see this on every invocation of

Quoted 4 lines

Another reporter also saw this on an AMD and said it could not be reproduced on the same hardware and the same software versions when using 64bit instead of 32.

In my case on a 32bit installation I will see this on every invocation of

Curious.. so its both AMD and Intel.

That makes funny hardware less likely... but how can the vmexit loose an interrupt like this.

Quoted 7 lines · Peter Zijlstra

Quoted 4 lines

Another reporter also saw this on an AMD and said it could not be reproduced on the same hardware and the same software versions when using 64bit instead of 32.

In my case on a 32bit installation I will see this on every invocation of

Curious.. so its both AMD and Intel.

Quoted 2 lines

That makes funny hardware less likely... but how can the vmexit loose an interrupt like this.

Also what I'm wondering about and what's not clear from Stefan's reply is whether this is purely a 32-bit issue, i.e. a 32-bit host running a 64-bit qemu running a 32-bit iso or what is it?

Or do we have reports for both 32-bit and 64-bit hosts?

Thanks.

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.

Quoted 5 lines · Stefan Bader

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?

Quoted 9 lines · Peter Zijlstra

Quoted 5 lines · Stefan Bader

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()) {

(quoted diff) +8 -0

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

Quoted 56 lines · Stefan Bader

Quoted 9 lines · Peter Zijlstra

Quoted 5 lines · Stefan Bader

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()) {

(quoted diff) +8 -0

+                               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

Quoted 5 lines

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?

*blink*... That's weird indeed... do you have the asm that goes along with that?

Yeah... not sure the interleaved source helps or not ...

Quoted 1 line · Stefan Bader

Yeah... not sure the interleaved source helps or not ...

It did, thanks!

Quoted 4 lines · Peter Zijlstra

Quoted 1 line · Stefan Bader

Yeah... not sure the interleaved source helps or not ...

It did, thanks!

Stefan, can you also send sched/core.s? I'm particularly interested in what resched_task() has been turned into by your build env.

Thanks.

Quoted 4 lines · Peter Zijlstra

Quoted 1 line · Stefan Bader

Yeah... not sure the interleaved source helps or not ...

It did, thanks!

Stefan, can you also send sched/core.s? I'm particularly interested in what resched_task() has been turned into by your build env.

Thanks.

Actually, this code just makes so much more sense if I let objdump do relocation info...

Quoted 2 lines · Stefan Bader

Actually, this code just makes so much more sense if I let objdump do relocation info...

Ok, we're pretty sure you have an MFENCE there in resched_task but can you confirm it please.

First, does /proc/cpuinfo have the "sse2" string? It should but nowadays I don't trust anything.

Then, can you boot that kernel in qemu with the -gdb flag so that it starts the gdb stub, here's the manpage about it:

-gdb dev
Wait for gdb connection on device dev. Typical connections will likely be TCP-based, but also UDP, pseudo TTY, or even stdio are reasonable use case. The latter is allowing to start QEMU from within gdb and establish the connection via a pipe:

(gdb) target remote | exec qemu-system-i386 -gdb stdio ...

-s Shorthand for -gdb tcp::1234, i.e. open a gdbserver on TCP port 1234.

then boot the guest and when it is up, do

$ gdb ./vmlinux
$ target remote localhost:1234

and type in the prompt

$ (gdb) x/50i resched_task

It gives here:

(gdb) x/50i resched_task
0xffffffff810836f0 <resched_task>: data32 data32 data32 xchg %ax,%ax
0xffffffff810836f5 <resched_task+5>: push %rbp
0xffffffff810836f6 <resched_task+6>: mov 0x85e123(%rip),%r10d # 0xffffffff818e1820 <debug_locks>

   0xffffffff810836fd <resched_task+13>:        mov    %rsp,%rbp
   0xffffffff81083700 <resched_task+16>:        push   %r12
   0xffffffff81083702 <resched_task+18>:        test   %r10d,%r10d
   0xffffffff81083705 <resched_task+21>:        push   %rbx
   0xffffffff81083706 <resched_task+22>:        mov    %rdi,%rbx
   0xffffffff81083709 <resched_task+25>:        jne    0xffffffff81083760 <resched_task+112>
   0xffffffff8108370b <resched_task+27>:        mov    0x8(%rbx),%rax
   0xffffffff8108370f <resched_task+31>:        mov    0x10(%rax),%rdx
   0xffffffff81083713 <resched_task+35>:        and    $0x8,%edx
   0xffffffff81083716 <resched_task+38>:        jne    0xffffffff8108373c <resched_task+76>
   0xffffffff81083718 <resched_task+40>:        lock orb $0x8,0x10(%rax)
   0xffffffff8108371d <resched_task+45>:        mov    0x8(%rbx),%rax
   0xffffffff81083721 <resched_task+49>:        mov    0x18(%rax),%r12d
   0xffffffff81083725 <resched_task+53>:        callq  0xffffffff812d8fc0 <debug_smp_processor_id>
   0xffffffff8108372a <resched_task+58>:        cmp    %r12d,%eax
   0xffffffff8108372d <resched_task+61>:        je     0xffffffff810837a0 <resched_task+176>
   0xffffffff8108372f <resched_task+63>:        mfence

^^^^^^
I want to make sure the smp_mb() is really replaced with an MFENCE there.

Thanks!

One thing I likely should do is to reinstall the exact same laptop with 64bit kernel and userspace... maybe only 64bit kernel first... and make sure on my side that this does not show up on 64bit, too. I took the word of reporters for that (and the impression that otherwise many more people would have complained).

Quoted 4 lines · Stefan Bader

One thing I likely should do is to reinstall the exact same laptop with 64bit kernel and userspace... maybe only 64bit kernel first... and make sure on my side that this does not show up on 64bit, too. I took the word of reporters for that (and the impression that otherwise many more people would have complained).

Yeha, I'm going to try and install some 32bit userspace on a usb harddisk I've got and see if I can boot my Core2 laptop from that to try and reproduce.

But all that is probably going to be Monday :/

Quoted 10 lines · Peter Zijlstra

Quoted 4 lines · Stefan Bader

One thing I likely should do is to reinstall the exact same laptop with 64bit kernel and userspace... maybe only 64bit kernel first... and make sure on my side that this does not show up on 64bit, too. I took the word of reporters for that (and the impression that otherwise many more people would have complained).

Yeha, I'm going to try and install some 32bit userspace on a usb harddisk I've got and see if I can boot my Core2 laptop from that to try and reproduce.

Quoted 2 lines

But all that is probably going to be Monday :/

*sigh* Already Thursday...

Peter, did you get to reproduce this locally? Unfortunately I had some interruption and have not more Information than on last Friday (which is that the same hw but 64bit kernel does not show it).

Meanwhile I wonder whether it would make sense to push the following (or more?) to stable for 3.13.y:

1) 16824255394f55adf31b9a96a9965d8c15bdac4c
x86, acpi, idle: Restructure the mwait idle routines
2) 7e98b71920464b8d15fa95c74366416cd3c88861
x86, idle: Use static_cpu_has() for CLFLUSH workaround, add barriers
3) 8cb75e0c4ec9786b81439761eac1d18d4a931af3
sched/preempt: Fix up missed PREEMPT_NEED_RESCHED folding
4) 215393bc1fab3d61a5a296838bdffce22f27ffda sched/preempt/x86: Fix voluntary preempt for x86

1+2 would be to avoid touching 3 too much and looked to be improvements on their own. 3+4 would be cherry-picks if not for some fuzz 2.

I saw a few more things labelled preempt between 3.13 and current HEAD but am not sure whether or which of those are strictly required. Namely some fixing to preempt_enable_no_resched() mis-usage and maybe one fixing an issue of ftrace locking up.

Quoted 11 lines

Quoted 11 lines

Quoted 11 lines

Quoted 11 lines

Quoted 4 lines

Quoted 4 lines

One thing I likely should do is to reinstall the exact same laptop with 64bit kernel and userspace... maybe only 64bit kernel first... and make sure on my side that this does not show up on 64bit, too. I took the word of reporters for that (and the impression that otherwise many more people would have complained).

Yeha, I'm going to try and install some 32bit userspace on a usb harddisk I've got and see if I can boot my Core2 laptop from that to try and reproduce.

But all that is probably going to be Monday :/

Quoted 5 lines

Quoted 5 lines

*sigh* Already Thursday...

Peter, did you get to reproduce this locally? Unfortunately I had some interruption and have not more Information than on last Friday (which is that the same hw but 64bit kernel does not show it).

I got side-tracked as well, someone reported crashes, which come above weird behaviour :/

Il 20/02/2014 16:50, Peter Zijlstra ha scritto:

Quoted 20 lines

Quoted 20 lines

Quoted 20 lines

Quoted 15 lines

Quoted 1 line

Quoted 1 line

Quoted 1 line

One thing I likely should do is to reinstall the exact same laptop

with 64bit

Quoted 1 line

Quoted 1 line

Quoted 1 line

kernel and userspace... maybe only 64bit kernel first... and make sure

on my

Quoted 1 line

Quoted 1 line

Quoted 1 line

side that this does not show up on 64bit, too. I took the word of

reporters for

Quoted 1 line

Quoted 1 line

Quoted 1 line

that (and the impression that otherwise many more people would have

complained).

Quoted 7 lines

Yeha, I'm going to try and install some 32bit userspace on a usb harddisk I've got and see if I can boot my Core2 laptop from that to try and reproduce.

But all that is probably going to be Monday :/

*sigh* Already Thursday...

Peter, did you get to reproduce this locally? Unfortunately I had some interruption and have not more Information than on last Friday (which is that the same hw but 64bit kernel does not show it).

Quoted 3 lines

I got side-tracked as well, someone reported crashes, which come above weird behaviour :/

Stefan, Peter, any news here?

Paolo

Okaaay, I think I did what you asked. So yes, there is sse2 in the cpu info. And there is a mfence in the disassembly:

Thinking about it, I guess Peter is quite right saying that I likely will end on the patch that converted preempt_count to percpu.

One thing I likely should do is to reinstall the exact same laptop with 64bit kernel and userspace... maybe only 64bit kernel first... and make sure on my side that this does not show up on 64bit, too. I took the word of reporters for that (and the impression that otherwise many more people would have complained).

Quoted 2 lines · Stefan Bader

Okaaay, I think I did what you asked. So yes, there is sse2 in the cpu info. And there is a mfence in the disassembly:

Btw, I just realized booting the kernel in the guest was a dumb idea, because, doh, the guest is not baremetal. The only reliable thing we can say is that sse2 is present and that MFENCE alternative replacement works :)

But for simplicity's sake let's just assume the machine can do MFENCE just fine and it gets replaced by the alternatives code.

Besides, if that weren't true, we'd have a whole lot of other problems on those boxes.

Quoted 2 lines

Thinking about it, I guess Peter is quite right saying that I likely will end on the patch that converted preempt_count to percpu.

Yeah, c2daa3bed53a81171cf8c1a36db798e82b91afe8 et al.

Quoted 5 lines

One thing I likely should do is to reinstall the exact same laptop with 64bit kernel and userspace... maybe only 64bit kernel first... and make sure on my side that this does not show up on 64bit, too. I took the word of reporters for that (and the impression that otherwise many more people would have complained).

Yeah, that should be a prudent thing to do.

Also, Paolo and I were wondering whether you can trigger this thing without kvm, i.e. virtualization involved... do you have any data on that?

Quoted 26 lines · Borislav Petkov

Quoted 2 lines · Stefan Bader

Okaaay, I think I did what you asked. So yes, there is sse2 in the cpu info. And there is a mfence in the disassembly:

Btw, I just realized booting the kernel in the guest was a dumb idea, because, doh, the guest is not baremetal. The only reliable thing we can say is that sse2 is present and that MFENCE alternative replacement works :)

But for simplicity's sake let's just assume the machine can do MFENCE just fine and it gets replaced by the alternatives code.

Besides, if that weren't true, we'd have a whole lot of other problems on those boxes.

Quoted 2 lines

Thinking about it, I guess Peter is quite right saying that I likely will end on the patch that converted preempt_count to percpu.

Yeah, c2daa3bed53a81171cf8c1a36db798e82b91afe8 et al.

Quoted 5 lines

One thing I likely should do is to reinstall the exact same laptop with 64bit kernel and userspace... maybe only 64bit kernel first... and make sure on my side that this does not show up on 64bit, too. I took the word of reporters for that (and the impression that otherwise many more people would have complained).

Quoted 5 lines

Yeah, that should be a prudent thing to do.

Also, Paolo and I were wondering whether you can trigger this thing without kvm, i.e. virtualization involved... do you have any data on that?

Unfortunately no hard evidence. Kvm just happens to be such a good way to notice this as it is using the reschedule interrupt itself and has this exit before running the guest vcpu to hadnle it in the outer loop by calling cond_resched() and repeat.
I find running kvm seems to make that laptop quite sluggish in responding to other tasks (in that install) and I got some oddness going on when lightdm quite often refuses to take keyboard input without opening some menu with the mouse first... But I could not be sure whether that is the kernel or some new user-space ... errr "feature".
At least Marcello (iirc that other report came from him directly or indirectly) has seen it, too. And he likely has complete different user-space.

So I will go and do that different (64bit) kernel and kernel + user-space test. But like fo Peter, it likely is a Monday thing...

Oh, and just in case this is relatively easy to reproduce and in case we don't have any other idea, bisection might be another option. I'm not saying you should do it right away - I'm just putting it on the table...

:-)

:-)

Oh yeah, bisection is nearly as entertaining as doing my tax records. Hm, on the other hand those will have to be done at some point too... :-P

Oh, and just in case this is relatively easy to reproduce and in case we don't have any other idea, bisection might be another option. I'm not saying you should do it right away - I'm just putting it on the table...

Quoted 9 lines · Peter Zijlstra

Quoted 5 lines · Stefan Bader

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()) {

(quoted diff) +8 -0

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

Quoted 56 lines · Stefan Bader

Quoted 9 lines · Peter Zijlstra

Quoted 5 lines · Stefan Bader

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()) {

(quoted diff) +8 -0

+                               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

Quoted 5 lines

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

Quoted 56 lines · Stefan Bader

Quoted 9 lines · Peter Zijlstra

Quoted 5 lines · Stefan Bader

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()) {

(quoted diff) +8 -0

+                               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

Quoted 5 lines

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.

Oh and one thing I was wondering. Not sure I do understand it right... When initially converting to percpu counts, you changed the 32bit assembly like that:

arch/x86/kernel/entry_32.S +2 -5

@@ -362,12 +362,9 @@ END(ret_from_exception)
 #ifdef CONFIG_PREEMPT
 ENTRY(resume_kernel)
        DISABLE_INTERRUPTS(CLBR_ANY)
-       cmpl $0,TI_preempt_count(%ebp)  # non-zero preempt_count ?
-       jnz restore_all
 need_resched:
-       movl TI_flags(%ebp), %ecx       # need_resched set ?
-       testb $_TIF_NEED_RESCHED, %cl
-       jz restore_all
+       cmpl $0,PER_CPU_VAR(__preempt_count)
+       jnz restore_all
        testl $X86_EFLAGS_IF,PT_EFLAGS(%esp)    # interrupts off (exception path
        jz restore_all
        call preempt_schedule_irq

This seems to say if preempt_count was 0 then then if the thread flag was set and interrupts were not off(?) it would do a preempt ipi and then come back to re-check the thread flag.

This would now be if preempt_count is 0 only... and I wonder whether that would change from doing that loop...

Also what I'm wondering about and what's not clear from Stefan's reply is whether this is purely a 32-bit issue, i.e. a 32-bit host running a 64-bit qemu running a 32-bit iso or what is it?

Or do we have reports for both 32-bit and 64-bit hosts?