From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mx1.redhat.com (mx1.redhat.com [209.132.183.28]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ml01.01.org (Postfix) with ESMTPS id 7979E81DA3 for ; Thu, 10 Nov 2016 04:01:39 -0800 (PST) Received: from int-mx11.intmail.prod.int.phx2.redhat.com (int-mx11.intmail.prod.int.phx2.redhat.com [10.5.11.24]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 7A5557DCFC; Thu, 10 Nov 2016 12:01:42 +0000 (UTC) Received: from lacos-laptop-7.usersys.redhat.com (ovpn-116-106.phx2.redhat.com [10.3.116.106]) by int-mx11.intmail.prod.int.phx2.redhat.com (8.14.4/8.14.4) with ESMTP id uAAC1dWP031061; Thu, 10 Nov 2016 07:01:40 -0500 To: "Yao, Jiewen" References: <1478251854-14660-1-git-send-email-jiewen.yao@intel.com> <08406bf5-4377-63a1-8dd9-34479c015d4b@redhat.com> <74D8A39837DF1E4DA445A8C0B3885C50386C0CB8@shsmsx102.ccr.corp.intel.com> <74D8A39837DF1E4DA445A8C0B3885C50386CE375@shsmsx102.ccr.corp.intel.com> Cc: "Tian, Feng" , "edk2-devel@ml01.01.org" , "Kinney, Michael D" , Paolo Bonzini , "Fan, Jeff" , "Zeng, Star" From: Laszlo Ersek Message-ID: Date: Thu, 10 Nov 2016 13:01:39 +0100 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Thunderbird/45.4.0 MIME-Version: 1.0 In-Reply-To: <74D8A39837DF1E4DA445A8C0B3885C50386CE375@shsmsx102.ccr.corp.intel.com> X-Scanned-By: MIMEDefang 2.68 on 10.5.11.24 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.27]); Thu, 10 Nov 2016 12:01:42 +0000 (UTC) Subject: Re: [PATCH V2 0/6] Enable SMM page level protection. X-BeenThere: edk2-devel@lists.01.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: EDK II Development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 10 Nov 2016 12:01:39 -0000 Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: 7bit On 11/10/16 11:41, Yao, Jiewen wrote: > Thanks to report case 3 issue on bugzillar. > > Let's focus on Case 8. > It seems another random failure issue. > > I did more test. > > 1) I tested some other our internal real platform for UEFI32 OS boot. I cannot reproduce the ASSERT. > > 2) I wrote a small test app to call ExitBootServices and send SMI. I run it on current my windows QEMU but I still cannot reproduce the ASSERT. > > It seem your env is the only way to repo the issue. I am trying to follow your step by step to install OS on QEMU/KVM. I haven't finish all thing yet, because of some network proxy issue. :( Right, when you run a guest on TCG (QEMU's emulator) vs. on KVM (the virtualizer / accelerator in the host Linux kernel), you get very-very different timing behavior and interleaving of actions. For one, with KVM, the VCPUs really execute in parallel -- they are represented by host OS threads, and the host OS schedules them to separate "physical logical CPUs". > > Your information and analysis is great. It gives us some clue. > > I guess the same thing as you and checked: InitializeSpinLock (mSmmMpSyncData->CpuData[CpuIndex].Busy); > > This address is initialized in InitializeMpSyncData(), with gSmmCpuPrivate->SmmCoreEntryContext.NumberOfCpus which is got from MpServices->GetNumberOfProcessors(). > I do not know why this address is zero. > > I also did not quite understand below log. > > * CPU #0: pc=0x00000000c1844555 (halted) thread_id=7835 > CPU #1: pc=0x00000000c1844555 (halted) thread_id=7836 > CPU #2: pc=0x00000000c1844555 (halted) thread_id=7837 > CPU #3: pc=0x000000007ffd17ca thread_id=7838 > > As I recall, writing to B2 only cause BSP get SMI on OVMF. AP does not enter SMM mode. > So why #3 can enter SMM mode? Is that expected behavior? Or unexpected behavior? > If this is expected, how this happened? Does OS send SendSmiIpiAllExcludingSelf, after ExitBootServices()? My theory is that the OS is calling a runtime variable service during boot. That is supposed to pull in all APs into SMM, one way or another. Also, during boot, the OS may call the runtime variable services genuinely on VCPU#3. > > I will see if I can finish QEMU/KVM installation tomorrow. Thanks! Once you can test with KVM on your side, that should speed up debugging considerably, I think! > If you have some idea on why and how #3 enter SMM, please let us know. Well, I captured a KVM trace for this as well (fresh boot, up to the failure). Grepping the trace for entering / leaving SMM, we see: (1) the initial SMBASE relocation: CPU-6948 [004] 11545.040294: kvm_enter_smm: vcpu 1: entering SMM, smbase 0x30000 CPU-6948 [004] 11545.040335: kvm_enter_smm: vcpu 1: leaving SMM, smbase 0x7ffb5000 CPU-6949 [000] 11545.040363: kvm_enter_smm: vcpu 2: entering SMM, smbase 0x30000 CPU-6949 [000] 11545.040389: kvm_enter_smm: vcpu 2: leaving SMM, smbase 0x7ffb7000 CPU-6950 [002] 11545.040417: kvm_enter_smm: vcpu 3: entering SMM, smbase 0x30000 CPU-6950 [002] 11545.040443: kvm_enter_smm: vcpu 3: leaving SMM, smbase 0x7ffb9000 CPU-6947 [007] 11545.040453: kvm_enter_smm: vcpu 0: entering SMM, smbase 0x30000 CPU-6947 [007] 11545.040474: kvm_enter_smm: vcpu 0: leaving SMM, smbase 0x7ffb3000 (2) a long stretch of VCPU#0 entering and leaving SMM, while the firmware uses variable services and such: CPU-6947 [007] 11545.053169: kvm_enter_smm: vcpu 0: entering SMM, smbase 0x7ffb3000 CPU-6947 [007] 11545.061272: kvm_enter_smm: vcpu 0: leaving SMM, smbase 0x7ffb3000 ... (3) a write to ioport 0xB2 from VCPU#3, then VCPU#3 entering SMM, then hitting the assert very-very soon: CPU-6950 [005] 11550.521195: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521196: kvm_exit: reason IO_INSTRUCTION rip 0xf7c937b6 info b20000 0 CPU-6950 [005] 11550.521196: kvm_pio: pio_write at 0xb2 size 1 count 1 val 0x0 CPU-6950 [005] 11550.521196: kvm_userspace_exit: reason KVM_EXIT_IO (2) CPU-6947 [003] 11550.521196: kvm_inj_virq: irq 253 CPU-6950 [005] 11550.521196: kvm_fpu: unload CPU-6947 [003] 11550.521197: kvm_fpu: load CPU-6947 [003] 11550.521197: kvm_entry: vcpu 0 CPU-6950 [005] 11550.521200: kvm_enter_smm: vcpu 3: entering SMM, smbase 0x7ffb9000 CPU-6947 [003] 11550.521207: kvm_eoi: apicid 0 vector 253 CPU-6950 [005] 11550.521207: kvm_fpu: load CPU-6947 [003] 11550.521207: kvm_pv_eoi: apicid 0 vector 253 CPU-6950 [005] 11550.521207: kvm_entry: vcpu 3 CPU-6947 [003] 11550.521207: kvm_exit: reason HLT rip 0xc1844554 info 0 0 CPU-6950 [005] 11550.521209: kvm_exit: reason CR_ACCESS rip 0x8045 info 300 0 CPU-6950 [005] 11550.521209: kvm_cr: cr_write 0 = 0x33 CPU-6950 [005] 11550.521212: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521213: kvm_exit: reason CR_ACCESS rip 0x7ffc107d info 3 0 CPU-6950 [005] 11550.521213: kvm_cr: cr_write 3 = 0x7ff9a000 CPU-6950 [005] 11550.521214: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521214: kvm_exit: reason CPUID rip 0x7ffc1085 info 0 0 CPU-6950 [005] 11550.521214: kvm_cpuid: func 1 rax 6e8 rbx 3040800 rcx 80200001 rdx 1f89fbff CPU-6950 [005] 11550.521215: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521215: kvm_exit: reason CR_ACCESS rip 0x7ffc10c4 info 4 0 CPU-6950 [005] 11550.521215: kvm_cr: cr_write 4 = 0x668 CPU-6950 [005] 11550.521217: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521218: kvm_exit: reason CR_ACCESS rip 0x7ffc110e info 300 0 CPU-6950 [005] 11550.521218: kvm_cr: cr_write 0 = 0x80010033 CPU-6950 [005] 11550.521220: kvm_entry: vcpu 3 CPU-6947 [003] 11550.521220: kvm_fpu: unload CPU-6950 [005] 11550.521222: kvm_exit: reason EPT_VIOLATION rip 0x7ffcbe46 info 181 0 CPU-6950 [005] 11550.521223: kvm_page_fault: address 22004ebc error_code 181 CPU-6950 [005] 11550.521231: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521236: kvm_exit: reason IO_INSTRUCTION rip 0x7ffd1e80 info 4020000 0 CPU-6950 [005] 11550.521236: kvm_pio: pio_write at 0x402 size 1 count 1 val 0x41 <----------------- "A" CPU-6950 [005] 11550.521237: kvm_userspace_exit: reason KVM_EXIT_IO (2) CPU-6950 [005] 11550.521237: kvm_fpu: unload CPU-6950 [005] 11550.521253: kvm_fpu: load CPU-6950 [005] 11550.521253: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521254: kvm_exit: reason IO_INSTRUCTION rip 0x7ffd1e80 info 4020000 0 CPU-6950 [005] 11550.521254: kvm_pio: pio_write at 0x402 size 1 count 1 val 0x53 <----------------- "S" CPU-6950 [005] 11550.521254: kvm_userspace_exit: reason KVM_EXIT_IO (2) CPU-6950 [005] 11550.521254: kvm_fpu: unload CPU-6950 [005] 11550.521257: kvm_fpu: load CPU-6950 [005] 11550.521257: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521258: kvm_exit: reason IO_INSTRUCTION rip 0x7ffd1e80 info 4020000 0 CPU-6950 [005] 11550.521258: kvm_pio: pio_write at 0x402 size 1 count 1 val 0x53 <----------------- "S" CPU-6950 [005] 11550.521258: kvm_userspace_exit: reason KVM_EXIT_IO (2) CPU-6950 [005] 11550.521258: kvm_fpu: unload CPU-6950 [005] 11550.521260: kvm_fpu: load CPU-6950 [005] 11550.521260: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521261: kvm_exit: reason IO_INSTRUCTION rip 0x7ffd1e80 info 4020000 0 CPU-6950 [005] 11550.521261: kvm_pio: pio_write at 0x402 size 1 count 1 val 0x45 <----------------- "E" CPU-6950 [005] 11550.521261: kvm_userspace_exit: reason KVM_EXIT_IO (2) CPU-6950 [005] 11550.521262: kvm_fpu: unload CPU-6950 [005] 11550.521264: kvm_fpu: load CPU-6950 [005] 11550.521264: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521264: kvm_exit: reason IO_INSTRUCTION rip 0x7ffd1e80 info 4020000 0 CPU-6950 [005] 11550.521264: kvm_pio: pio_write at 0x402 size 1 count 1 val 0x52 <----------------- "R" CPU-6950 [005] 11550.521264: kvm_userspace_exit: reason KVM_EXIT_IO (2) CPU-6950 [005] 11550.521265: kvm_fpu: unload CPU-6950 [005] 11550.521267: kvm_fpu: load CPU-6950 [005] 11550.521267: kvm_entry: vcpu 3 CPU-6950 [005] 11550.521267: kvm_exit: reason IO_INSTRUCTION rip 0x7ffd1e80 info 4020000 0 CPU-6950 [005] 11550.521267: kvm_pio: pio_write at 0x402 size 1 count 1 val 0x54 <----------------- "T" CPU-6950 [005] 11550.521268: kvm_userspace_exit: reason KVM_EXIT_IO (2) This seems to be consistent with the OS calling a variable service on VCPU#3. Also, as far as I can see, the above trace matches the assembly code in "UefiCpuPkg/PiSmmCpuDxeSmm/Ia32/SmiEntry.nasm". Is perhaps CpuIndex out of bounds?... Hmm, with the following debug patch: > diff --git a/UefiCpuPkg/PiSmmCpuDxeSmm/MpService.c b/UefiCpuPkg/PiSmmCpuDxeSmm/MpService.c > index d0092d2f145a..29f6e783c58f 100644 > --- a/UefiCpuPkg/PiSmmCpuDxeSmm/MpService.c > +++ b/UefiCpuPkg/PiSmmCpuDxeSmm/MpService.c > @@ -1143,6 +1143,9 @@ SmiRendezvous ( > // E.g., with Relaxed AP flow, SmmStartupThisAp() may be called immediately > // after AP's present flag is detected. > // > + if (CpuIndex >= 4) { > + DEBUG ((EFI_D_ERROR, "CpuIndex=%u\n", (UINT32)CpuIndex)); > + } > InitializeSpinLock (mSmmMpSyncData->CpuData[CpuIndex].Busy); > } > > I get the following debug output (note that my SMP configuration is 1x2x2): > SmmInstallProtocolInterface: [EdkiiSmmExitBootServicesProtocol] 0 > MpInitExitBootServicesCallback() done! > CpuIndex=780161211 > ASSERT MdePkg/Library/BaseSynchronizationLib/SynchronizationGcc.c(73): SpinLock != ((void *) 0) Ehm... what? :) SmiRendezvous() is EFIAPI, is the calling convention followed in "Ia32/SmiEntry.nasm"? Thanks, Laszlo > Thank you > Yao Jiewen > > > From: Laszlo Ersek [mailto:lersek@redhat.com] > Sent: Thursday, November 10, 2016 4:46 AM > To: Yao, Jiewen > Cc: Tian, Feng ; edk2-devel@ml01.01.org; Kinney, Michael D ; Paolo Bonzini ; Fan, Jeff ; Zeng, Star > Subject: Re: [edk2] [PATCH V2 0/6] Enable SMM page level protection. > > On 11/09/16 07:25, Yao, Jiewen wrote: >> Hi Laszlo >> I will fix DEBUG message issue in V3 patch. >> >> Below is rest issues: >> >> >> l Case 13: S3 fails randomly. >> A good news: I worked with Jeff Fan to root-cause the S3 resume issue. Here is detail. >> >> >> 1) We believe the dead CPU is AP. Not BSP. >> The reason is that: >> >> 1.1) The BSP already transfer control to OS waking vector. The GDT/IDT/CR3 should be set by OS. >> >> 1.2) The current dead CPU still has GDT/IDT point to a BIOS reserved memory. The CS/DS/SS is typical BIOS X64 mode setting. >> >> 1.3) The current dead CPU still has CR3 in SMM. (Which is obvious wrong) >> >> >> 2) Based upon the 1), we reviewed S3 resume AP flow. >> Current BSP will wake up AP in SMRAM, for security consideration. At that time, we are using SMM mode CR3. It is OK for BSP because BSP is NOT in SMM mode yet. Even after SMM rebase, we can still use it because SMRR is not set in first SMM rebase. >> Current BSP just uses its own context to initialize AP. So that AP takes BSP CR3, which is SMM CR3, unfortunately. >> After BSP initialized APs, the AP is put to HALT-LOOP in X64 mode. It is the last straw, because X64 mode halt still need paging. >> >> >> 3) The error happen, once the AP receives an interrupt (for whatever reason), AP starts executing code. However, that that time the AP might not be in SMM mode. It means SMM CR3 is not available. And then we see this. >> >> >> 4) I guess we did not see the error, or this is RANDOM issue, because it depends on if AP receives an interrupt before BSP send INIT-SIPI-SIPI. >> >> >> 5) The fix, I think, should be below: >> We should always put AP to protected mode, so that no paging is needed. >> We should put AP in above 1M reserved memory, instead of <1M memory, because <1M memory is restored. >> >> >> Would you please file a bugzillar? I think we need assign CPU owner to fix that critical issue. >> >> There is no need to do more investigation. Thanks for your great help on that. :) > > Thank you for your help! > > I filed . The title is > > BSP exits SMM and closes SMRAM on the S3 resume path before > meeting with AP(s) > > I hope the title is mostly right. I didn't add any other details (I > haven't gone through the thread in detail yet, and without that I can't > even write up a semi-reasonable report myself). Instead, I referenced > this message of yours in the report, and I also linked Paolo's analysis > from elsewhere in the thread. I hope this will do for the report. > > (Also, thank you Paolo, from the amazing analysis -- I haven't digested > it yet, but I can already tell it's amazing! :)) > >> l Case 17 - I do not think it is a real issue, because SMM is out of resource. >> >> >> l Case 8 - that is a very weird issue. I talk with Jeff again. I do not have a clear clue yet. >>> ASSERT MdePkg/Library/BaseSynchronizationLib/SynchronizationGcc.c(73): SpinLock != ((void *) 0) >> Here is code. We do not know why there is some code need InitializeSpinLock after ExitBootServices. >> SPIN_LOCK * >> EFIAPI >> InitializeSpinLock ( >> OUT SPIN_LOCK *SpinLock >> ) >> { >> ASSERT (SpinLock != NULL); >> >> _ReadWriteBarrier(); >> *SpinLock = SPIN_LOCK_RELEASED; >> _ReadWriteBarrier(); >> >> return SpinLock; >> } >> >> If you can have a quick check on below, that would be great. >> >> 1) Which processor triggers this ASSERT? BSP or AP. >> >> 2) Which module triggers this ASSERT? Which module contains current RIP value? > > First, one additional piece of info I have learned is that the issue > does not always present itself. Sometimes the boot just works fine, > other times the assert fires. > > Using the QEMU monitor, I managed to get the following information with > the "info cpus" command: > > * CPU #0: pc=0x00000000c1844555 (halted) thread_id=7835 > CPU #1: pc=0x00000000c1844555 (halted) thread_id=7836 > CPU #2: pc=0x00000000c1844555 (halted) thread_id=7837 > CPU #3: pc=0x000000007ffd17ca thread_id=7838 > > VCPU#3 is an AP (the last AP), I think. The instruction pointer seems to > point into SMRAM again. > > In the OVMF log, I see > > Loading SMM driver at 0x0007FFC9000 EntryPoint=0x0007FFC9253 > PiSmmCpuDxeSmm.efi > > So the offset into PiSmmCpuDxeSmm.efi is 0x87CA (or, relative to the > entry point, 0x8577, 0x253 bytes less). > > Running > > objdump -x -S Build/OvmfIa32/DEBUG_GCC48/IA32/PiSmmCpuDxeSmm.debug > > first I see confirmation that > > start address 0x00000253 > > and then > > 000087bd : > VOID > EFIAPI > CpuDeadLoop ( > VOID > ) > { > 87bd: 55 push %ebp > 87be: 89 e5 mov %esp,%ebp > 87c0: 83 ec 10 sub $0x10,%esp > volatile UINTN Index; > > for (Index = 0; Index == 0;); > 87c3: c7 45 fc 00 00 00 00 movl $0x0,-0x4(%ebp) > 87ca: 8b 45 fc mov -0x4(%ebp),%eax <-- HERE > 87cd: 85 c0 test %eax,%eax > 87cf: 74 f9 je 87ca > } > 87d1: c9 leave > 87d2: c3 ret > > This seems consistent with an assertion failure. > > I searched UefiCpuPkg/PiSmmCpuDxeSmm/ for InitializeSpinLock(), and the > SmiRendezvous() function [UefiCpuPkg/PiSmmCpuDxeSmm/MpService.c] looks > like a possible caller: > > // > // The BUSY lock is initialized to Released state. This needs to > // be done early enough to be ready for BSP's SmmStartupThisAp() > // call. E.g., with Relaxed AP flow, SmmStartupThisAp() may be > // called immediately after AP's present flag is detected. > // > InitializeSpinLock (mSmmMpSyncData->CpuData[CpuIndex].Busy); > > Just a guess, of course. > >> At same time, all my OS test is on real platform. I have not setup OVMF env to run an OS yet. >> If you can share a step by step to me, that would be great. > > (1) Grab a host computer with a CPU that supports VMX and EPT. > > (2) Download and install Fedora 24 (for example): > > https://getfedora.org/en/workstation/download/ > http://docs.fedoraproject.org/install-guide > > (3) Install the "qemu-system-x86" package with DNF > > dnf install qemu-system-x86 > > (4) clone edk2 with git > > (5) embed OpenSSL optionally (for secure boot); see > "CryptoPkg/Library/OpensslLib/Patch-HOWTO.txt" > > (6) build OVMF: > > source edksetup.sh > make -C "$EDK_TOOLS_PATH" > > # Ia32 > build \ > -a IA32 \ > -p OvmfPkg/OvmfPkgIa32.dsc \ > -D SMM_REQUIRE -D SECURE_BOOT_ENABLE \ > -t GCC5 -b DEBUG > > # Ia32X64 > build \ > -a IA32 -a X64 \ > -p OvmfPkg/OvmfPkgIa32X64.dsc \ > -D SMM_REQUIRE -D SECURE_BOOT_ENABLE \ > -t GCC5 -b DEBUG > > (7) Create disk images: > > qemu-img create -f qcow2 -o compat=1.1 -o cluster_size=65536 \ > -o preallocation=metadata -o lazy_refcounts=on disk-ia32.img 100G > > qemu-img create -f qcow2 -o compat=1.1 -o cluster_size=65536 \ > -o preallocation=metadata -o lazy_refcounts=on disk-ia32x64.img 100G > > (8) For a 64-bit guest OS, you can again use the Fedora 24 Workstation > that you downloaded already (the ISO image). > > For 32-bit guest OS, this one used to work: > > https://www.happyassassin.net/fedlet-a-fedora-remix-for-bay-trail-tablets/ > > minimally the 20141209 release. Hm... actually, I think the maintainer > of that image has discontinued the downloadable files :( > > So, I don't know what 32-bit UEFI OS to recommend for testing. > > 32-bit Windows doesn't boot on OVMF (I looked into that earlier, several > times, with some help from a Microsoft developer, but we couldn't solve > it), so I can't recommend Windows as an alternative. > > Perhaps you can use > > https://linuxiumcomau.blogspot.com/2016/10/running-ubuntu-on-intel-bay-trail-and.html > > as a 32-bit guest OS, I never tried. > > (9) Anyway, once you have an installer ISO, set the "ISO" environment > variable to the ISO image's full pathname, and then run QEMU like this: > > # Settings for Ia32 only: > > ISO=... > DISK=.../disk-ia32.img > FW=.../Build/OvmfIa32/DEBUG_GCC5/FV/OVMF_CODE.fd > TEMPLATE=.../Build/OvmfIa32/DEBUG_GCC5/FV/OVMF_VARS.fd > VARS=vars-32.fd > QEMU_COMMAND="qemu-system-i386 -cpu coreduo,-nx" > DEBUG=debug-32.log > > # Settings for Ia32X64 only: > > ISO=... > DISK=.../disk-ia32x64.img > FW=.../Build/Ovmf3264/DEBUG_GCC5/FV/OVMF_CODE.fd > TEMPLATE=.../Build/Ovmf3264/DEBUG_GCC5/FV/OVMF_VARS.fd > VARS=vars-3264.fd > QEMU_COMMAND=qemu-system-x86_64 > DEBUG=debug-3264.log > > # Common commands for both target arches: > > # create variable store from varstore template > # if the former doesn't exist yet > if ! [ -e "$VARS" ]; then > cp -- "$TEMPLATE" "$VARS" > fi > > $QEMU_COMMAND \ > -machine q35,smm=on,accel=kvm \ > -m 4096 \ > -smp sockets=1,cores=2,threads=2 \ > -global driver=cfi.pflash01,property=secure,value=on \ > -drive if=pflash,format=raw,unit=0,file=${FW},readonly=on \ > -drive if=pflash,format=raw,unit=1,file=${VARS} \ > \ > -chardev file,id=debugfile,path=$DEBUG \ > -device isa-debugcon,iobase=0x402,chardev=debugfile \ > \ > -chardev stdio,id=char0,signal=off,mux=on \ > -mon chardev=char0,mode=readline,default \ > -serial chardev:char0 \ > \ > -drive id=iso,if=none,format=raw,readonly,file=$ISO \ > -drive id=disk,if=none,format=qcow2,file=$DISK \ > \ > -device virtio-scsi-pci,id=scsi0 \ > -device scsi-cd,drive=iso,bus=scsi0.0,bootindex=2 \ > -device scsi-hd,drive=disk,bus=scsi0.0,bootindex=1 \ > \ > -device VGA > > This will capture the OVMF debug output in the $DEBUG file. Also, the > terminal where you run the command can be switched between the guest's > serial console and the QEMU monitor with [Ctrl-A C]. > > Thanks > Laszlo > >> >> Thank you >> Yao Jiewen >> >> From: edk2-devel [mailto:edk2-devel-bounces@lists.01.org] On Behalf Of Laszlo Ersek >> Sent: Tuesday, November 8, 2016 9:22 AM >> To: Yao, Jiewen > >> Cc: Tian, Feng >; edk2-devel@ml01.01.org; Kinney, Michael D >; Paolo Bonzini >; Fan, Jeff >; Zeng, Star > >> Subject: Re: [edk2] [PATCH V2 0/6] Enable SMM page level protection. >> >> On 11/04/16 10:30, Jiewen Yao wrote: >>> ==== below is V2 description ==== >>> 1) PiSmmCpu: resolve OVMF multiple processors boot hang issue. >>> 2) PiSmmCpu: Add debug info on StartupAp() fails. >>> 3) PiSmmCpu: Add ASSERT for AllocatePages(). >>> 4) PiSmmCpu: Add protection detail in commit message. >>> 5) UefiCpuPkg.dsc: Add page table footprint info in commit message. >>> >>> ==== below is V1 description ==== >>> This series patch enables SMM page level protection. >>> Features are: >>> 1) PiSmmCore reports SMM PE image code/data information >>> in EdkiiPiSmmMemoryAttributeTable, if the SMM image is page aligned. >>> 2) PiSmmCpu consumes EdkiiPiSmmMemoryAttributeTable >>> and set XD for data page and RO for code page. >>> 3) PiSmmCpu enables Static Paging for X64 according to >>> PcdCpuSmmStaticPageTable. If it is true, 1G paging for above 4G >>> is used as long as it is supported. >>> 4) PiSmmCpu sets importance data structure to be read only, >>> such as Gdt, Idt, SmmEntrypoint, and PageTable itself. >>> >>> tested platform: >>> 1) Intel internal platform (X64). >>> 2) EDKII Quark IA32 >>> 3) EDKII Vlv2 X64 >>> 4) EDKII OVMF IA32 and IA32X64. (with -smp 8) >>> >>> Cc: Jeff Fan >> >>> Cc: Feng Tian >> >>> Cc: Star Zeng >> >>> Cc: Michael D Kinney >> >>> Cc: Laszlo Ersek >> >>> Contributed-under: TianoCore Contribution Agreement 1.0 >>> Signed-off-by: Jiewen Yao >> >> >> I have new test results. Let's start with the table again: >> >> Legend: >> >> - "untested" means the test was not executed because the same test >> failed or proved unreliable in a less demanding configuration already, >> >> - "n/a" means a setting or test case was impossible, >> >> - "fail" and "unreliable" (lower case) are outside the scope of this >> series; they either capture the pre-series status, or are expected >> even with the series applied due to the pre-series status, >> >> - "FAIL" and "UNRELIABLE" mean regressions caused (or exposed) by the >> series. >> >> In all cases, 36 bits were used as address width in the CPU HOB (--> up >> to 64GB guest-phys address space). >> >> series OVMF VCPU boot S3 resume >> # applied platform PcdCpuMaxLogicalProcessorNumber PcdCpuSmmStaticPageTable topology result result >> -- ------- -------- ------------------------------- ------------------------ -------- ------ --------- >> 1 no Ia32 64 n/a 1x2x2 pass unreliable >> 2 no Ia32 255 n/a 52x2x2 pass untested >> 3 no Ia32 255 n/a 53x2x2 unreliable untested >> 4 no Ia32X64 64 n/a 1x2x2 pass unreliable >> 5 no Ia32X64 255 n/a 52x2x2 pass untested >> 6 no Ia32X64 255 n/a 54x2x2 fail n/a >> 7 v2 Ia32 64 FALSE 1x2x2 pass untested >> 8 v2 Ia32 64 TRUE 1x2x2 FAIL untested >> 9 v2 Ia32 255 FALSE 52x2x2 pass untested >> 10 v2 Ia32 255 FALSE 53x2x2 untested untested >> 11 v2 Ia32 255 TRUE 52x2x2 untested untested >> 12 v2 Ia32 255 TRUE 53x2x2 untested untested >> 13 v2 Ia32X64 64 FALSE 1x2x2 pass unreliable >> 14 v2 Ia32X64 64 TRUE 1x2x2 pass untested >> 15 v2 Ia32X64 255 FALSE 52x2x2 pass untested >> 16 v2 Ia32X64 255 FALSE 54x2x2 untested untested >> 17 v2 Ia32X64 255 TRUE 52x2x2 FAIL untested >> 18 v2 Ia32X64 255 TRUE 54x2x2 untested untested >> >> * Case 8: this test case failed with v2 as well, but this time with >> different symptoms: >> >>> FSOpen: Open '\EFI\fedora\grubia32.efi' Success >>> InstallProtocolInterface: [EfiLoadedImageProtocol] 7E4037A8 >>> Loading driver at 0x0007DA7F000 EntryPoint=0x0007DA7F400 >>> InstallProtocolInterface: [EfiLoadedImageDevicePathProtocol] 7E403A90 >>> PixelBlueGreenRedReserved8BitPerColor >>> ConvertPages: Incompatible memory types >>> PixelBlueGreenRedReserved8BitPerColor >>> ConvertPages: Incompatible memory types >>> SmmInstallProtocolInterface: [EdkiiSmmExitBootServicesProtocol] 0 >>> MpInitExitBootServicesCallback() done! >>> ASSERT MdePkg/Library/BaseSynchronizationLib/SynchronizationGcc.c(73): SpinLock != ((void *) 0) >> >> I didn't try to narrow this down. >> >> * Case 13 (the "unreliable S3 resume" case): Here the news are both bad >> and good. The good news is for Jiewen: this patch series does not >> cause the unreliability, it "only" amplifies it severely. The bad news >> is correspondingly for everyone else: S3 resume is actually unreliable >> even in case 4, that is, without this series applied, it's just the >> failure rate is much-much lower. >> >> Namely, in my new testing, in case 13, S3 resume failed 8 times out of >> 21 tries. (I stopped testing at the 8th failure.) >> >> Whereas in case 4, S3 resume failed with *identical symptoms* (e.g., >> exact same RIP=000000000009f0fd), 1 time out of 55 tries. (It was try >> #12 that failed; I continued testing and aborted the test after the >> 55th try.) >> >> So, while the series hugely amplifies the failure rate, the failure >> does exist without the series. Which is why I modified the case 4 >> results in the table, and also lower-cased the word "unreliable" in >> case 13. >> >> Below I will return to this problem separately; let's go over the rest >> of the table first. >> >> * Case 17: I guess this is not a real failure, I'm just including it for >> completeness, as PcdCpuSmmStaticPageTable==TRUE is known to present >> additional SMRAM demand (see the commit message on patch V2 4/6). This >> case fails with >> >>> SmmLockBox Command - 4 >>> SmmLockBoxSmmLib SetLockBoxAttributes - Enter >>> SmmLockBoxSmmLib SetLockBoxAttributes - Exit (Success) >>> SmmLockBox SmmLockBoxHandler Exit >>> SmmLockBoxDxeLib SetLockBoxAttributes - Exit (Success) >>> SmmInstallProtocolInterface: [EfiSmmReadyToLockProtocol] 0 >>> ASSERT UefiCpuPkg/PiSmmCpuDxeSmm/CpuS3.c(892): mGdtForAp != ((void *) 0) >> >> which is an SMRAM allocation failure. If I lower the VCPU count to >> 50x2x2, then the guest boots fine. >> >> ----*---- >> >> Before I get to the S3 resume problem (which, again, reproduces without >> this series, although much less frequently), I'd like to comment on the >> removal of the ASSERT(), from v1 to v2, in the FlushTlbForAll() >> function, on the return value of SmmBlockingStartupThisAp(). This change >> allows v2 to proceed past that point; however, I'm seeing a whole lot of >> >>> !mSmmMpSyncData->CpuData[1].Present >>> !mSmmMpSyncData->CpuData[2].Present >>> !mSmmMpSyncData->CpuData[3].Present >>> ... >> >> messages in the OVMF boot log, interspersed with >> >>> ConvertPageEntryAttribute 0x7F92B067->0x7F92B065 >> >> style messages. (That is, one error message for each AP, per >> ConvertPageEntryAttribute() message.) >> >> Is this okay / intentional? The number of these messages can go up to >> several thousands and that sort of drowns out everything else in the >> log. >> >> It's also not easy to mask the message, because it's logged on the >> DEBUG_ERROR level. >> >> ----*---- >> >> * Okay, so the S3 problem. Last time I suspected that the failure point >> (RIP=9f0fd) was in the Linux guest's S3 wakeup vector (which starts at >> 9A1D0, according to the OVMF log). In order to test this idea, I >> exercised this series with S3 against a Windows 8.1 guest (--> case 13 >> again). The failure reproduced on the second S3 resume, with identical >> RIP, despite the Windows wakeup vector being located elsewhere (at >> 0x1000). >> >> Quoting the OVMF log leading up to the resume: >> >>> Call AsmDisablePaging64() to return to S3 Resume in PEI Phase >>> Install PPI: [PeiPostScriptTablePpi] >>> Install PPI: [EfiEndOfPeiSignalPpi] >>> Notify: PPI Guid: [EfiEndOfPeiSignalPpi], Peim notify entry point: 857895 >>> PeiMpInitLib: CpuMpEndOfPeiCallback () invoked >>> Transfer to 16bit OS waking vector - 1000 >> >> QEMU log (same as before): >> >>> KVM internal error. Suberror: 1 >>> KVM internal error. Suberror: 1 >>> emulation failure >>> emulation failure >>> RAX=0000000000000002 RBX=0000000000000000 RCX=000000007ffdb168 RDX=000000007fedd058 >>> RSI=0000000000000004 RDI=000000007fedd040 RBP=0000000000000000 RSP=000000007e1a7000 >>> R8 =0000000000000000 R9 =0000000000000000 R10=0000000000000000 R11=0000000000000000 >>> R12=0000000000000000 R13=0000000000000000 R14=0000000000000000 R15=0000000000000000 >>> RIP=000000000009f0fd RFL=00010006 [-----P-] CPL=0 II=0 A20=1 SMM=0 HLT=0 >>> ES =0030 0000000000000000 ffffffff 00c09300 DPL=0 DS [-WA] >>> CS =0038 0000000000000000 ffffffff 00a09b00 DPL=0 CS64 [-RA] >>> SS =0030 0000000000000000 ffffffff 00c09300 DPL=0 DS [-WA] >>> DS =0030 0000000000000000 ffffffff 00c09300 DPL=0 DS [-WA] >>> FS =0018 0000000000000000 ffffffff 00c09300 DPL=0 DS [-WA] >>> GS =0018 0000000000000000 ffffffff 00c09300 DPL=0 DS [-WA] >>> LDT=0000 0000000000000000 0000ffff 00008200 DPL=0 LDT >>> TR =0000 0000000000000000 0000ffff 00008b00 DPL=0 TSS64-busy >>> GDT= 000000007f294000 00000047 >>> IDT= 000000007f294048 00000fff >>> CR0=e0000011 CR2=0000000000000000 CR3=000000007ff7f000 CR4=00000220 >>> DR0=0000000000000000 DR1=0000000000000000 DR2=0000000000000000 DR3=0000000000000000 >>> DR6=00000000ffff0ff0 DR7=0000000000000400 >>> EFER=0000000000000500 >>> Code=?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? >>> RAX=0000000000000001 RBX=0000000000000000 RCX=000000007ffdb168 RDX=000000007fedd070 >>> RSI=0000000000000004 RDI=000000007fedd058 RBP=0000000000000000 RSP=000000007e19f000 >>> R8 =0000000000000000 R9 =0000000000000000 R10=0000000000000000 R11=0000000000000000 >>> R12=0000000000000000 R13=0000000000000000 R14=0000000000000000 R15=0000000000000000 >>> RIP=000000000009f0fd RFL=00010006 [-----P-] CPL=0 II=0 A20=1 SMM=0 HLT=0 >>> ES =0030 0000000000000000 ffffffff 00c09300 DPL=0 DS [-WA] >>> CS =0038 0000000000000000 ffffffff 00a09b00 DPL=0 CS64 [-RA] >>> SS =0030 0000000000000000 ffffffff 00c09300 DPL=0 DS [-WA] >>> DS =0030 0000000000000000 ffffffff 00c09300 DPL=0 DS [-WA] >>> FS =0018 0000000000000000 ffffffff 00c09300 DPL=0 DS [-WA] >>> GS =0018 0000000000000000 ffffffff 00c09300 DPL=0 DS [-WA] >>> LDT=0000 0000000000000000 0000ffff 00008200 DPL=0 LDT >>> TR =0000 0000000000000000 0000ffff 00008b00 DPL=0 TSS64-busy >>> GDT= 000000007f294000 00000047 >>> IDT= 000000007f294048 00000fff >>> CR0=e0000011 CR2=0000000000000000 CR3=000000007ff7f000 CR4=00000220 >>> DR0=0000000000000000 DR1=0000000000000000 DR2=0000000000000000 DR3=0000000000000000 >>> DR6=00000000ffff0ff0 DR7=0000000000000400 >>> EFER=0000000000000500 >>> Code=?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? >> >> So, we can exclude the suspicion that the problem is guest OS >> dependent. >> >> * Then I looked for the base address of the page containing the >> RIP=9f0fd address, in earlier parts of the OVMF log, on the hunch that >> some firmware component might have allocated that area actually. Here >> we go: >> >>> Loading PEIM at 0x000008552C0 EntryPoint=0x000008554E0 CpuMpPei.efi >>> AP Loop Mode is 1 >>> WakeupBufferStart = 9F000, WakeupBufferSize = 1000 >> >> That is, the failure hits (when it hits -- not always) in the area >> where the CpuMpPei driver *borrows* memory for the startup vector of >> the APs, for the purposes of the MP service PPI. ("Wakeup" is an >> overloaded word here; the "wakeup buffer" has nothing to do with S3 >> resume, it just serves for booting the APs temporarily in PEI, for >> implementing the MP service PPI.) >> >> When exiting the PEI phase (on the S3 resume path), CpuMpPei restores >> the original contents of this area. This occurs just before >> transfering control to the guest OS wakeup vector: see the >> "EfiEndOfPeiSignalPpi" and "CpuMpEndOfPeiCallback" strings just above, >> quoted from the OVMF log. >> >> I documented (parts of) this logic in OVMF commit >> >> https://github.com/tianocore/edk2/commit/e3e3090a959a0 >> >> (see the code comments as well). >> >> * At that time, I thought to have identified a memory management bug in >> CpuMpPei; see the following discussion and bug report for details: >> >> https://www.mail-archive.com/edk2-devel@lists.01.org/msg13892.html >> https://bugzilla.tianocore.org/show_bug.cgi?id=67 >> >> However, with the extraction / introduction of MpInitLib, this issue >> has been fixed: GetWakeupBuffer() now calls >> CheckOverlapWithAllocatedBuffer(), so that "memory management bug" is >> no longer; we shouldn't be looking there for the root cause. >> >> * Either way, I don't understand why anything would want to execute code >> in the one page that happens to host the MP services PPI startup >> buffer for APs during PEI. >> >> Not understanding the "why", I looked at the "what", and resorted to >> tracing KVM. Because the problem readily reproduces with this series >> applied (case 13), it wasn't hard to start the tracing while the guest >> was suspended, and capture just the actions that led from the >> KVM-level wakeup to the failure. >> >> The QEMU state dumps are visible above in the email. I've also >> uploaded the compressed OVMF log and the textual KVM trace here: >> >> http://people.redhat.com/lersek/s3-crash-8d1dfed7-ca92-4e25-8d2b-b1c9ac2a53db/ >> >> I sincerely hope that Paolo will have a field day with the KVM trace >> :) I managed to identify the following curiosities (remember this is >> all on the S3 resume path): >> >> * First, the VCPUs (there are four of them) enter and leave SMM in a >> really funky pattern: >> >> vcpu#0 vcpu#1 vcpu#2 vcpu#3 >> ------ ------ ------ ------ >> enter >> | >> leave >> >> enter >> | >> leave >> >> enter >> | >> leave >> >> enter >> | >> leave >> >> enter enter >> enter | enter | >> | | | | >> leave | | | >> | | | >> enter | | | >> | | | | >> leave leave leave leave >> >> That is, first we have each VCPU enter and leave SMM in complete >> isolation (1, 2, 3, 0). Then VCPUs 1 and 3 enter SMM together, soon >> followed by VPCUS 0 and 2, also together. VCPU#0 drops out of SMM >> temporarily (it comes back in later), while the other three remain >> in SMM. Finally all four of them leave SMM together. >> >> After which the problem occurs. >> >> * Second, the instruction that causes things to blow up is <0f aa>, >> i.e., RSM. I have absolutely no clue why RSM is executed: >> >> (a) in the area that used to host the AP startup routine for the MP >> services PPI -- note that we also have "Transfer to 16bit OS waking >> vector" in the log, so CpuMpEndOfPeiCallback() restores the borrowed >> area completeley! --, >> >> (b) and why *after* all four VCPUs have just left SMM, together. >> >> * The RSM instruction is handled successfully elsewhere, for example >> when all four VCPUs leave SMM, at the bottom of the diagram above: >> >>> CPU-24447 [002] 39841.982810: kvm_emulate_insn: 0:7ffbf179: 0f aa >>> CPU-24446 [000] 39841.982810: kvm_emulate_insn: 0:7ffbd179: 0f aa >>> CPU-24445 [005] 39841.982810: kvm_emulate_insn: 0:7ffbb179: 0f aa >>> CPU-24444 [006] 39841.982811: kvm_emulate_insn: 0:7ffb9179: 0f aa >> >> * The guest-phys address 7ff7f000 that we see just before the error: >> >>> CPU-24447 [002] 39841.982825: kvm_page_fault: address 7ff7f000 error_code 83 >>> CPU-24446 [000] 39841.982825: kvm_page_fault: address 7ff7f000 error_code 83 >>> CPU-24447 [002] 39841.982826: kvm_emulate_insn: 0:9f0fd: 0f aa >>> CPU-24444 [006] 39841.982827: kvm_exit: reason EXTERNAL_INTERRUPT rip 0xffffffff813a954f info 0 800000fc >>> CPU-24447 [002] 39841.982827: kvm_emulate_insn: 0:9f0fd: 0f aa FAIL >>> CPU-24447 [002] 39841.982827: kvm_userspace_exit: reason KVM_EXIT_INTERNAL_ERROR (17) >> >> can be found higher up in the trace; namely, it is written to CR3 >> several times. It's the root of the page tables. >> >> * The 7F80_1000..7FFF_FFFF guest-phys addresses are all in SMRAM. >> >> * I also tried the "info tlb" monitor command, via "virsh >> qemu-monitor-command --hmp", while the guest was auto-paused after the >> crash. >> >> I cannot provide results: QEMU appeared to return a message that would >> be longer than 16MB after encoding by libvirt, and libvirt rejected >> that ("Unable to encode message payload", see VIR_NET_MESSAGE_MAX). >> >> Anyway, the KVM trace, and the QEMU register dump, look consistent >> with what Paolo said about "Code=?? ?? ??...": >> >> The question marks usually mean that the page tables do not map a >> page at that address. >> >> CR3=000000007ff7f000 points into SMRAM, but we are outside of SMM >> (SMM=0). We can't translate *any* guest-virtual address, as we can't >> even begin walking the page tables. >> >> Thanks >> Laszlo >> _______________________________________________ >> edk2-devel mailing list >> edk2-devel@lists.01.org> >> https://lists.01.org/mailman/listinfo/edk2-devel >> _______________________________________________ >> edk2-devel mailing list >> edk2-devel@lists.01.org >> https://lists.01.org/mailman/listinfo/edk2-devel >> > _______________________________________________ > edk2-devel mailing list > edk2-devel@lists.01.org > https://lists.01.org/mailman/listinfo/edk2-devel >