Re: [PATCH] SeaBios: Fix reset procedure reentrancy problem on qemu-kvm platform

["Gonglei (Arei)" <arei.gonglei@huawei.com>]

Hi Kevin & Paolo,

Luckily, I reproduced this problem last night. And I got the below log when SeaBIOS is stuck.

[BTW, the whole SeaBIOS log attached]

[2015-12-18 10:38:10] >>>>>gonglei: enter smp_setup()...
[2015-12-18 10:38:10] >>>>>gonglei: begine to enable local APIC...
[2015-12-18 10:38:10] >>>>>gonglei: finish enable local APIC...
[2015-12-18 10:38:10] >>>gonglei: cmos_smp_count=8
[2015-12-18 10:38:10] >>> enter handle_smp...
[2015-12-18 10:38:10] handle_smp: apic_id=5
[2015-12-18 10:38:10] ===: CountCPUs=2, SMPStack=0x6d84
[2015-12-18 10:38:10] >>> enter handle_smp...
[2015-12-18 10:38:10] handle_smp: apic_id=7
[2015-12-18 10:38:10] ===: CountCPUs=3, SMPStack=0x6d84
[2015-12-18 10:38:10] >>> enter handle_smp...
[2015-12-18 10:38:10] handle_smp: apic_id=1
[2015-12-18 10:38:10] ===: CountCPUs=4, SMPStack=0x6d84
[2015-12-18 10:38:10] >>> enter handle_smp...
[2015-12-18 10:38:10] handle_smp: apic_id=2
[2015-12-18 10:38:10] ===: CountCPUs=5, SMPStack=0x6d84
[2015-12-18 10:38:10] >>> enter handle_smp...
[2015-12-18 10:38:10] handle_smp: apic_id=4
[2015-12-18 10:38:10] ===: CountCPUs=6, SMPStack=0x6d84
[2015-12-18 10:38:10] >>> enter handle_smp...
[2015-12-18 10:38:10] handle_smp: apic_id=3
[2015-12-18 10:38:10] ===: CountCPUs=7, SMPStack=0x6d84
[2015-12-18 10:38:10] >>> enter handle_smp...
[2015-12-18 10:38:10] handle_smp: apic_id=6
[2015-12-18 10:38:10] ===: CountCPUs=8, SMPStack=0x6d84
[2015-12-18 10:38:10]  gonglei: finish while   

[pid 31509 is a vcpu thread used 100% cpu overhead]

# cat /proc/31509/stack  
[<ffffffffa05c337c>] vmx_vcpu_run+0x35c/0x580 [kvm_intel]
[<ffffffffa06b0f10>] em_push+0x0/0x20 [kvm]
[<ffffffffa06a30dc>] x86_emulate_instruction+0x20c/0x440 [kvm]
[<ffffffffa05c9224>] handle_exception+0xe4/0x1b58 [kvm_intel]
[<ffffffffa06a24c5>] vcpu_enter_guest+0x565/0x790 [kvm]
[<ffffffffa05bf990>] vmx_get_segment_base+0x0/0xb0 [kvm_intel]
[<ffffffffa06a2888>] __vcpu_run+0x198/0x260 [kvm]
[<ffffffffa06a3508>] kvm_arch_vcpu_ioctl_run+0x68/0x1a0 [kvm]
[<ffffffffa068f92e>] vcpu_load+0x4e/0x80 [kvm]
[<ffffffffa068fcee>] kvm_vcpu_ioctl+0x38e/0x580 [kvm]
[<ffffffff8109618d>] futex_wake+0xfd/0x110
[<ffffffff811ed57c>] security_file_permission+0x1c/0xa0
[<ffffffff8116bedb>] do_vfs_ioctl+0x8b/0x3b0
[<ffffffff8116c2a1>] sys_ioctl+0xa1/0xb0
[<ffffffff81469272>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff

And kvm tracing information:

<...>-31509 [035] 154753.180077: kvm_exit: reason EXCEPTION_NMI rip 0x3 info 0 80000306
<...>-31509 [035] 154753.180077: kvm_emulate_insn: 0:3:f0 53 (real)
<...>-31509 [035] 154753.180077: kvm_inj_exception: #UD (0x0)
<...>-31509 [035] 154753.180077: kvm_entry: vcpu 0
<...>-31509 [035] 154753.180078: kvm_exit: reason EXCEPTION_NMI rip 0x3 info 0 80000306
<...>-31509 [035] 154753.180078: kvm_emulate_insn: 0:3:f0 53 (real)
<...>-31509 [035] 154753.180079: kvm_inj_exception: #UD (0x0)
<...>-31509 [035] 154753.180079: kvm_entry: vcpu 0
<...>-31509 [035] 154753.180079: kvm_exit: reason EXCEPTION_NMI rip 0x3 info 0 80000306
<...>-31509 [035] 154753.180080: kvm_emulate_insn: 0:3:f0 53 (real)
<...>-31509 [035] 154753.180080: kvm_inj_exception: #UD (0x0)
<...>-31509 [035] 154753.180080: kvm_entry: vcpu 0
<...>-31509 [035] 154753.180081: kvm_exit: reason EXCEPTION_NMI rip 0x3 info 0 80000306
<...>-31509 [035] 154753.180081: kvm_emulate_insn: 0:3:f0 53 (real)
<...>-31509 [035] 154753.180081: kvm_inj_exception: #UD (0x0)
<...>-31509 [035] 154753.180081: kvm_entry: vcpu 0
<...>-31509 [035] 154753.180082: kvm_exit: reason EXCEPTION_NMI rip 0x3 info 0 80000306
<...>-31509 [035] 154753.180083: kvm_emulate_insn: 0:3:f0 53 (real)
<...>-31509 [035] 154753.180083: kvm_inj_exception: #UD (0x0)
<...>-31509 [035] 154753.180083: kvm_entry: vcpu 0
<...>-31509 [035] 154753.180084: kvm_exit: reason EXCEPTION_NMI rip 0x3 info 0 80000306
<...>-31509 [035] 154753.180084: kvm_emulate_insn: 0:3:f0 53 (real)
<...>-31509 [035] 154753.180084: kvm_inj_exception: #UD (0x0)
<...>-31509 [035] 154753.180084: kvm_entry: vcpu 0
<...>-31509 [035] 154753.180085: kvm_exit: reason EXCEPTION_NMI rip 0x3 info 0 80000306
<...>-31509 [035] 154753.180085: kvm_emulate_insn: 0:3:f0 53 (real)
<...>-31509 [035] 154753.180085: kvm_inj_exception: #UD (0x0)
<...>-31509 [035] 154753.180085: kvm_entry: vcpu 0
<...>-31509 [035] 154753.180086: kvm_exit: reason EXCEPTION_NMI rip 0x3 info 0 80000306

Now, it's very clear that the guest stuck in yiled(), and then kvm encounter the exception #UD.

Do you have any thoughts? Thanks!


The Seabios patch below:

diff --git a/roms/seabios/src/boot.c b/roms/seabios/src/boot.c
index f23e9e1..552914a 100644
--- a/roms/seabios/src/boot.c
+++ b/roms/seabios/src/boot.c
@@ -93,7 +93,7 @@ glob_prefix(const char *glob, const char *str)
 static int
 find_prio(const char *glob)
 {
-    dprintf(1, "Searching bootorder for: %s\n", glob);
+    //dprintf(1, "Searching bootorder for: %s\n", glob);
     int i;
     for (i = 0; i < BootorderCount; i++)
         if (glob_prefix(glob, Bootorder[i]))
diff --git a/roms/seabios/src/fw/smp.c b/roms/seabios/src/fw/smp.c
index a466ea6..46ec607 100644
--- a/roms/seabios/src/fw/smp.c
+++ b/roms/seabios/src/fw/smp.c
@@ -46,12 +46,16 @@ int apic_id_is_present(u8 apic_id)
     return !!(FoundAPICIDs[apic_id/32] & (1ul << (apic_id % 32)));
 }
 
+// Atomic lock for shared stack across processors.
+u32 SMPLock __VISIBLE;
+u32 SMPStack __VISIBLE;
+
 void VISIBLE32FLAT
 handle_smp(void)
 {
     if (!CONFIG_QEMU)
         return;
-
+    dprintf(1, ">>> enter handle_smp...\n");
     // Enable CPU caching
     setcr0(getcr0() & ~(CR0_CD|CR0_NW));
 
@@ -70,19 +74,16 @@ handle_smp(void)
     FoundAPICIDs[apic_id/32] |= (1 << (apic_id % 32));
 
     CountCPUs++;
+    dprintf(1, "===: CountCPUs=%d, SMPStack=0x%x\n", CountCPUs, SMPStack);
 }
 
-// Atomic lock for shared stack across processors.
-u32 SMPLock __VISIBLE;
-u32 SMPStack __VISIBLE;
-
 // find and initialize the CPUs by launching a SIPI to them
 void
 smp_setup(void)
 {
     if (!CONFIG_QEMU)
         return;
-
+    dprintf(1, ">>>>>gonglei: enter smp_setup()...\n");
     ASSERT32FLAT();
     u32 eax, ebx, ecx, cpuid_features;
     cpuid(1, &eax, &ebx, &ecx, &cpuid_features);
@@ -106,7 +107,7 @@ smp_setup(void)
     u64 new = (0xea | ((u64)SEG_BIOS<<24)
                | (((u32)entry_smp - BUILD_BIOS_ADDR) << 8));
     *(u64*)BUILD_AP_BOOT_ADDR = new;
-
+    dprintf(1, ">>>>>gonglei: begine to enable local APIC...\n");
     // enable local APIC
     u32 val = readl(APIC_SVR);
     writel(APIC_SVR, val | APIC_ENABLED);
@@ -125,10 +126,21 @@ smp_setup(void)
     writel(APIC_ICR_LOW, 0x000C4500);
     u32 sipi_vector = BUILD_AP_BOOT_ADDR >> 12;
     writel(APIC_ICR_LOW, 0x000C4600 | sipi_vector);
-
+    dprintf(1, ">>>>>gonglei: finish enable local APIC...\n");
     // Wait for other CPUs to process the SIPI.
     u8 cmos_smp_count = rtc_read(CMOS_BIOS_SMP_COUNT) + 1;
-    while (cmos_smp_count != CountCPUs)
+    dprintf(1, ">>>gonglei: cmos_smp_count=%d\n", cmos_smp_count);
+    while (cmos_smp_count != CountCPUs) {
         asm volatile(
             // Release lock and allow other processors to use the stack.
             "  movl %%esp, %1\n"
@@ -139,8 +151,11 @@ smp_setup(void)
             "  jc 1b\n"
             : "+m" (SMPLock), "+m" (SMPStack)
             : : "cc", "memory");
+       //yield();
+    }
+    dprintf(1, " gonglei: finish while\n");
     yield();
-
+    dprintf(1, " gonglei: finish yield\n");
     // Restore memory.
     *(u64*)BUILD_AP_BOOT_ADDR = old;
 
diff --git a/roms/seabios/src/misc.c b/roms/seabios/src/misc.c
index 8caaf31..77f6be3 100644
--- a/roms/seabios/src/misc.c
+++ b/roms/seabios/src/misc.c
@@ -64,6 +64,10 @@ void VISIBLE16
 handle_02(void)
 {
     debug_isr(DEBUG_ISR_02);
+    dprintf(1, "gonglei hand nmi inject, write rtc \n");
 }
 
 void
diff --git a/roms/seabios/src/stacks.c b/roms/seabios/src/stacks.c
index 1dbdfe9..c1b5203 100644
--- a/roms/seabios/src/stacks.c
+++ b/roms/seabios/src/stacks.c
@@ -174,6 +174,7 @@ call16_smm(u32 eax, u32 edx, void *func)
 static void
 call32_sloppy_prep(void)
 {
+    dprintf(1, ">>> enter call32_sloppy_prep...\n");
     // Backup cmos index register and disable nmi
     u8 cmosindex = inb(PORT_CMOS_INDEX);
     outb(cmosindex | NMI_DISABLE_BIT, PORT_CMOS_INDEX);


Regards,
-Gonglei


> -----Original Message-----
> From: Kevin O'Connor [mailto:kevin@koconnor.net]
> Sent: Thursday, November 19, 2015 9:41 PM
> To: Xulei (Stone)
> Cc: Gonglei (Arei); qemu-devel; seabios@seabios.org; Huangweidong (C)
> Subject: Re: [Qemu-devel] [PATCH] SeaBios: Fix reset procedure reentrancy
> problem on qemu-kvm platform
> 
> On Thu, Nov 19, 2015 at 12:42:50PM +0000, Xulei (Stone) wrote:
> > Kevin,
> >
> > After deeply analyzing, i think there may be 3 possible reasons:
> > 1)wrong CountCPUs value. It seems CountCPUs++ in handle_smp() has no
> > lock to protect.  So, sometimes, 2 or more vcpu may get the same
> > current value of CountCPUs. Then we'll get a single incrementation
> > instead of 2 or more and "while (cmos_smp_count != CountCPUs)" will
> > loop forever;
> 
> The handle_smp() code is called from romlayout.S:entry_smp() which does take
> a lock.  So, all of handle_smp() should run synchronous.
> 
> > 2)wrong cmos_smp_count value. SeaBIOS rtc reads an incorrect number?
> 
> Not sure - the last time there were problems in this area of the code others
> used kvmtrace to try and track this down.  Since you are getting dprintf
> statements, you could also try outputting cmos_smp_count prior to the loop
> (see patch below).
> 
> > 3)yield() stuck. Is it possible that SeaBIOS is stuck during yield?
> > I've tested, when yield() is running, SeaBIOS seems has not created
> > some other threads except the main thread. So I don't know what's the
> > function of yield() here.?
> 
> The yield() allows hardware interrupts to occur.  But note that
> yield() isn't called in the loop - is is only called after the loop completes.
> 
> If you are only getting this on massive repetitive reboot requests, there are
> some other possible explanations:
> 
> - perhaps the SIPI is getting lost because one of the CPUs is still
>   resetting or still processing a SIPI from the last reboot?
> 
> - the seabios code itself may have been corrupted if the memcpy() in
>   qemu_prep_reset() got far enough along to clear HaveRunPost, but did
>   not get far enough along to fully complete the memcpy().
> 
> If the failure is reproducible, the patch below could help narrow the
> possibilities.
> 
> -Kevin
> 
> 
> --- a/src/fw/smp.c
> +++ b/src/fw/smp.c
> @@ -125,6 +125,7 @@ smp_setup(void)
> 
>      // Wait for other CPUs to process the SIPI.
>      u8 cmos_smp_count = rtc_read(CMOS_BIOS_SMP_COUNT) + 1;
> +    dprintf(1, "cmos_smp_count=%d\n", cmos_smp_count);
>      while (cmos_smp_count != CountCPUs)
>          asm volatile(
>              // Release lock and allow other processors to use the stack.
> @@ -136,6 +137,7 @@ smp_setup(void)
>              "  jc 1b\n"
>              : "+m" (SMPLock), "+m" (SMPStack)
>              : : "cc", "memory");
> +    dprintf(1, "finish smp\n");
>      yield();
> 
>      // Restore memory.