On 06/01/16 07:41, Fan, Jeff wrote:
> Laszlo,
>
> Have you any clue on bisect this issue?
>
> SmiDefaultPFHandler() is used to dynamically setup page entry for
> those address > 4GBytes.
>
> If your platform is really accessing > 4GBytes address, Page Fault
> happened does make sense.
> Otherwise, please check PFAddress value to understand why PFAddress >
> 4GBytes is access.

Right, that's part of what I did last day (and night). I'll add my
update at the end, to keep a better context.

> PageTable[PTIndex] = 7FFF2251 is not one valid page entry.
> Usually, we encountered the similar issue due to SMM page table room
> was crashed.
>
> Thanks!
> Jeff
>
> -----Original Message-----
> From: edk2-devel [mailto:[email protected]] On Behalf Of Laszlo 
> Ersek
> Sent: Tuesday, May 31, 2016 8:20 PM
> To: Kinney, Michael D
> Cc: Paolo Bonzini; edk2-devel-01; Radim Krcmár
> Subject: Re: [edk2] a "strange" branch taken in the SMM fault handler in 
> PiSmmCpuDxe
>
> On 05/31/16 13:42, Laszlo Ersek wrote:
>> Hello Mike,
>>
>> our virt-QE team reported an interesting issue:
>>
>> https://bugzilla.redhat.com/show_bug.cgi?id=1308678#c14
>>
>> We have a small UEFI_APPLICATION ((open source, of course) that
>> enrolls a set of fixed certificates into PK / KEK / DB.
>>
>> In the course of the gRT->SetVariable() call, using the SMM driver
>> stack, the fault handler function that is used in SMM is invoked:
>> SmiDefaultPFHandler() in "UefiCpuPkg/PiSmmCpuDxeSmm/X64/PageTbl.c".
>>
>> Now, I have no clue about any situation when this fault handler
>> should  be invoked as part of normal operation -- perhaps there are
>> such cases. But, in this instance, the function seems to walk the
>> page tables,  find the PTE, and realize that the Present bit is set
>> in the PTE. Then it prints:
>>
>>   PageTable = 7FFA6000, PTIndex = 1FF, PageTable[PTIndex] = 7FFF2251
>>   New page table overlapped with old page table!
>>
>> The code that prints this has a comment (rewrapped here for
>> readability):
>>
>> //
>> // Check if the entry has already existed, this issue may occur when
>> the // different size page entries created under the same entry //
>>
>> Can you please help me interpret this? Is it related to 2MB / 1GB
>> pages, as opposed to 4KB pages? Or should I be looking for a genuine
>> fault in the variable driver?
>>
>> I've never seen this issue, and in my normal work environment I
>> can't  reproduce it. In the report linked above, I noticed
>>
>>   -cpu IvyBridge
>>
>> which makes QEMU emulate "Intel Xeon E3-12xx v2 (Ivy Bridge)".
>>
>> Whereas my laptop has a Haswell CPU ("i7-4810MQ"), and with the
>> virtual machines I use for testing, I (or rather libvirtd) doesn't
>> pass any particular -cpu switch to QEMU. That seems to imply
>> "qemu64"  ("QEMU Virtual CPU version 2.5+").
>>
>> ... I've now tried with "-cpu IvyBridge" myself; I still can't
>> reproduce it.
>
> Hold on, I can reproduce it actually, regardless of CPU type. It
> seems to be an edk2 regression somewhere between d7c0dfa and 90bb4c5,
> that has been fixed between 90bb4c5 and current master (2f7b34b20).
> I'll try to bisect it.

Okay, so this was a terrible, extremely time consuming experience. (And
I'm not finished yet.) Here's what I've done thus far:

(1) I bisected both the introduction of this failure, and the apparent
fix of the failure.

(1a) For the bug-intro bisection, I used the following known-good commit
as starting point

> commit 5e04f4b7e1a48cfa9e6b045f953e84becced2e9e
> Author: Laszlo Ersek <[email protected]>
> Date:   Mon Nov 30 18:49:07 2015 +0000
>
>     OvmfPkg: README: document SMM status
>
>     Cc: Paolo Bonzini <[email protected]>
>     Contributed-under: TianoCore Contribution Agreement 1.0
>     Signed-off-by: Laszlo Ersek <[email protected]>
>     Reviewed-by: Jordan Justen <[email protected]>
>
>     git-svn-id: https://svn.code.sf.net/p/edk2/code/trunk/edk2@19066 
> 6f19259b-4bc3-4df7-8a09-765794883524

This is the commit that completed the SMM feature for OVMF (although
there were going to be minor changes, of course).

> For known-bad commit, I used:
>
> commit 90bb4c577d055e7ac6f0488b21885f65617eec82
> Author: Volker Rümelin <[email protected]>
> Date:   Mon Apr 18 21:51:30 2016 +0200
>
>     OvmfPkg: AcpiPlatformDxe: Don't enable unsupported PCI attributes
>     ...

There was nothing special about this commit, except it was identified in
our virt-QE's bug report, and I reproduced the issue with it.

Here's the bisection log:

> git bisect start
> # good: [5e04f4b7e1a48cfa9e6b045f953e84becced2e9e] OvmfPkg: README: document 
> SMM status
> git bisect good 5e04f4b7e1a48cfa9e6b045f953e84becced2e9e
> # bad: [90bb4c577d055e7ac6f0488b21885f65617eec82] OvmfPkg: AcpiPlatformDxe: 
> Don't enable unsupported PCI attributes
> git bisect bad 90bb4c577d055e7ac6f0488b21885f65617eec82
> # bad: [e6b2c99121963f84b847120044075e7b6ce374cb] CryptoPkg/OpensslLib: 
> Upgrade OpenSSL version to 1.0.2f
> git bisect bad e6b2c99121963f84b847120044075e7b6ce374cb
> # good: [c9f46d31f4846e37ddeee6d04ba48e78daf75456] 
> AppPkg/Applications/Python/Python-2.7.10/*/pyconfig.h: Update pyconfig for 
> Python 2.7.10 compliance.
> git bisect good c9f46d31f4846e37ddeee6d04ba48e78daf75456
> # good: [95055567a626f5d55d46a42fc4c7198a80389467] SourceLevelDebugPkg: 
> DebugCommunicationLibUsb3: Update local variable type.
> git bisect good 95055567a626f5d55d46a42fc4c7198a80389467
> # bad: [4d3948d9cccaf40eafaf0a49247846e84013a782] ArmPlatformPkg: remove 
> ArmVExpress-CTA15-A7.dsc/fdf
> git bisect bad 4d3948d9cccaf40eafaf0a49247846e84013a782
> # good: [e286e118bafaa029fb3078fdc9b32fd52d30777c] DuetPkg FSVariable: Minor 
> update to the Data parameter for GetVariable()
> git bisect good e286e118bafaa029fb3078fdc9b32fd52d30777c
> # bad: [8ae3832df9985f5285aa59102c94d14ba952844b] OvmfPkg: include 
> NvmExpressDxe driver
> git bisect bad 8ae3832df9985f5285aa59102c94d14ba952844b
> # good: [0f4e123f2f471eb9db98678b6f0983ce0193f09b] NetworkPkg: Correct 
> inconsistent function descriptions in DNS
> git bisect good 0f4e123f2f471eb9db98678b6f0983ce0193f09b
> # bad: [98c2d961050603615d1d9307dac3c7ef69e207b4] SecurityPkg: 
> AuthVariableLib: Add new cert database for volatile time based Auth variable
> git bisect bad 98c2d961050603615d1d9307dac3c7ef69e207b4
> # good: [bf46bd46188fd002b3bc7e15d8de50be23c1fd04] PcAtChipsetPkg/Rtc: Don't 
> unnecessarily create timezone variable.
> git bisect good bf46bd46188fd002b3bc7e15d8de50be23c1fd04
> # good: [378ea6e4169c9af0eb45f654ec49b997a0f98408] MdeModulePkg: Add BS+RT+AT 
> variable attribute definition
> git bisect good 378ea6e4169c9af0eb45f654ec49b997a0f98408
> # first bad commit: [98c2d961050603615d1d9307dac3c7ef69e207b4] SecurityPkg: 
> AuthVariableLib: Add new cert database for volatile time based Auth variable

The first bad commit is:

> commit 98c2d961050603615d1d9307dac3c7ef69e207b4
> Author: Chao Zhang <[email protected]>
> Date:   Tue Feb 2 01:02:31 2016 +0000
>
>     SecurityPkg: AuthVariableLib: Add new cert database for volatile time 
> based Auth variable
>
>     Add a new cert data base "certdbv" to store signer certs for volatile 
> time based
>     Auth variable.
>
>     Contributed-under: TianoCore Contribution Agreement 1.0
>     Signed-off-by: Chao Zhang <[email protected]>
>     Reviewed-by: Star Zeng <[email protected]>
>     Reviewed-by: Fu Siyuan <[email protected]>
>
>     git-svn-id: https://svn.code.sf.net/p/edk2/code/trunk/edk2@19786 
> 6f19259b-4bc3-4df7-8a09-765794883524

I have analyzed the heck out of this commit, and found nothing bad in
it. But, more on this later.

(1b) For the fix-intro bisection (that is, for identifying the commit
that made the bug go away, in upstream edk2), I used the bug-introducing
commit identified in step (1a) as starting point (obviously), and used
the current master HEAD (2f7b34b20) as known-good commit (I tested it
and it worked all fine).

Here's the bisection log. Please note that this is an *inverse*
bisection: wherever you see "good", it means "non-functional", and "bad"
stands for "functional".

> git bisect start
> # good: [98c2d961050603615d1d9307dac3c7ef69e207b4] SecurityPkg: 
> AuthVariableLib: Add new cert database for volatile time based Auth variable
> git bisect good 98c2d961050603615d1d9307dac3c7ef69e207b4
> # bad: [2f7b34b20842fcc485b39c0e1e91313c47b4d090] OvmfPkg: raise DXEFV size 
> to 10 MB
> git bisect bad 2f7b34b20842fcc485b39c0e1e91313c47b4d090
> # good: [5c8a5490c4004cbd1f22251cd499bb401ef5fe31] 1. Correct File header to 
> ## @file 2. Remove unnecessary .common] postfix on section.
> git bisect good 5c8a5490c4004cbd1f22251cd499bb401ef5fe31
> # good: [9828cc24208cc43473deb3ca48eaa9f62789365b] 
> OvmfPkg/PlatformBootManagerLib: Remove unused vars and func prototypes
> git bisect good 9828cc24208cc43473deb3ca48eaa9f62789365b
> # bad: [7b13510f2a0a2a118cdafdaa67720ca8e3fe37de] 
> MdeModulePkg/BootMaintenanceManagerUiLib: hide library-internal symbol
> git bisect bad 7b13510f2a0a2a118cdafdaa67720ca8e3fe37de
> # good: [a24f7d6680dd71616b0fcb9c5a65263fce1722be] ArmPkg/ArmDmaLib: reject 
> consistent DMA mappings of cached memory
> git bisect good a24f7d6680dd71616b0fcb9c5a65263fce1722be
> # good: [14b2ebc30c8bc98f668fa78171b659e2cdc33aa5] 
> OvmfPkg/PlatformBootManagerLib: Postpone the shell registration
> git bisect good 14b2ebc30c8bc98f668fa78171b659e2cdc33aa5
> # good: [aa52bace8f4aedb3172dbabb8fed71841e108abd] CorebootPayloadPkg: Use 
> generic SerialDxe driver
> git bisect good aa52bace8f4aedb3172dbabb8fed71841e108abd
> # good: [37c58a68176f039124fafa5f06d5529f0d2152c8] SecurityPkg: Remove 
> non-ASCII character from TPM warning strings
> git bisect good 37c58a68176f039124fafa5f06d5529f0d2152c8
> # good: [846704334c4083b8e86e921d3ffcbf7d886fe5b9] 
> UefiCpuPkg/PiSmmCpuDxeSmm/SmmProfile: Remove unnecessary BTS MSRs
> git bisect good 846704334c4083b8e86e921d3ffcbf7d886fe5b9
> # bad: [8b3ccf16e0b71cceb4ea4d9546f95ba55a6abc6a] EmulatorPkg/EmuGopDxe: Use 
> correct FROM_THIS macro for TextInEx
> git bisect bad 8b3ccf16e0b71cceb4ea4d9546f95ba55a6abc6a
> # bad: [f85d3ce2efc21da5d874b3e4d880e5682c6fe7cb] UefiCpuPkg/PiSmmCpuDxeSmm: 
> Use public MSR_IA32_MISC_ENABLE definition
> git bisect bad f85d3ce2efc21da5d874b3e4d880e5682c6fe7cb
> # first bad commit: [f85d3ce2efc21da5d874b3e4d880e5682c6fe7cb] 
> UefiCpuPkg/PiSmmCpuDxeSmm: Use public MSR_IA32_MISC_ENABLE definition

In other words, the commit fixing the issue was identified as:

> commit f85d3ce2efc21da5d874b3e4d880e5682c6fe7cb
> Author: Jeff Fan <[email protected]>
> Date:   Fri Apr 8 13:55:14 2016 +0800
>
>     UefiCpuPkg/PiSmmCpuDxeSmm: Use public MSR_IA32_MISC_ENABLE definition
>
>     Use the MSR MSR_IA32_MISC_ENABLE definition defined in UefiCpuPkg/Include 
> and
>     remove the local definition.
>
>     Cc: Michael Kinney <[email protected]>
>     Cc: Jiewen Yao <[email protected]>
>     Cc: Feng Tian <[email protected]>
>     Contributed-under: TianoCore Contribution Agreement 1.0
>     Signed-off-by: Jeff Fan <[email protected]>
>     Reviewed-by: Jiewen Yao <[email protected]>
>     Reviewed-by: Michael Kinney <[email protected]>
>     Regression-tested-by: Laszlo Ersek <[email protected]>

I also analyzed the heck out of this commit, and it is valid.

(2) Now, if you actually look at those commits, you will soon see that
they make *absolutely no sense* in relation to the page fault in SMM.
They are unrelated both to each other and to the SMM page fault.

(Of course, I checked reverting the "fix", f85d3ce2efc2, on top of
current master, to see if the error would reappear. Clearly, reverting
f85d3ce2efc2 made no difference :), things continued to work just fine.)

So what I did next was look into the failure itself. First, some test
results (black box). For testing, I always used the commit identified in
step (1a), namely 98c2d961 ("SecurityPkg: AuthVariableLib: Add new cert
database for volatile time based Auth variable").

* The bug reproduces with QEMU 2.5, QEMU 2.6 rc0, and current QEMU
  master (500acc9c410bcea17148a1072e323c08d12e6a6b). The machine type I
  used with all of these was simply "q35".

* The bug reproduces with KVM (several RHEL-7 development kernel
  versions) and TCG too.

* The bug reproduces with both

  -global driver=cfi.pflash01,property=secure,value=on

  and

  -global driver=cfi.pflash01,property=secure,value=off

* The guest is uniprocessor.

(3) At this point I started to suspect the firmware strongly, and added
some instrumentation -- 109 changes, to be exact -- to the code.

First, I wanted to see the actual page fault address (cr2), and also the
RIP. Second, I wanted to see (with DEBUG "tracing") the code
progression, for reconstructing a call stack.

(3a) The fault address (cr2) is invariably in the variable store pflash
range. In the 2MB build of OVMF, the variable store lives in the
smaller, writeable pflash chip that is mapped into guest-physical
address space at 4GB-2MB, that is, 0xFFE00000. The fault addresses
(plural, because they vary!) were *at least* 0xFFE00020 and 0xFFE01460.

Now, 0xFFE00020 looks very special, and I made a big effort to track it
down. At this address, the FvLength field lives. Let me quote
"OvmfPkg/VarStore.fdf.inc":

> 0x00000000|0x0000e000
> #NV_VARIABLE_STORE
> DATA = {
>   ## This is the EFI_FIRMWARE_VOLUME_HEADER
>   # ZeroVector []
>   0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
>   0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
>   # FileSystemGuid: gEfiSystemNvDataFvGuid         =
>   #   { 0xFFF12B8D, 0x7696, 0x4C8B,
>   #     { 0xA9, 0x85, 0x27, 0x47, 0x07, 0x5B, 0x4F, 0x50 }}
>   0x8D, 0x2B, 0xF1, 0xFF, 0x96, 0x76, 0x8B, 0x4C,
>   0xA9, 0x85, 0x27, 0x47, 0x07, 0x5B, 0x4F, 0x50,
>   # FvLength: 0x20000
>   0x00, 0x00, 0x02, 0x00, 0x00, 0x00, 0x00, 0x00,

The last line you see above starts at 0xFFE00020 when OVMF is running.
Why on earth (and where) would an access to this field cause a page
fault in SMM?

(3b) So, I tracked down the following call tree.

Note that the call tree is rooted in the EnrollDefaultKeys application
that I mentioned earier calling gRT->SetVariable(), enrolling a list of
certificates in the "db" variable.

(Before this occurs, a bunch of variables are interrogated with
gRT->GetVariable(), and those work all fine. Also, the firmware updates
a number of other variables as part of normal operation, and those
updates work fine as well. It is only the first *authenticated* variable
update that causes this.)

AuthVariableLibProcessVariable()                     
[SecurityPkg/Library/AuthVariableLib/AuthVariableLib.c]
  ProcessVarWithPk()                                 
[SecurityPkg/Library/AuthVariableLib/AuthService.c]
    AuthServiceInternalUpdateVariableWithTimeStamp() 
[SecurityPkg/Library/AuthVariableLib/AuthService.c]
      VariableExLibUpdateVariable()                  
[MdeModulePkg/Universal/Variable/RuntimeDxe/VariableExLib.c] -- via 
"mAuthVarLibContextIn->UpdateVariable"
        UpdateVariable()                             
[MdeModulePkg/Universal/Variable/RuntimeDxe/Variable.c]
          // step 1
          UpdateVariableStore()                      
[MdeModulePkg/Universal/Variable/RuntimeDxe/Variable.c]

Now, the last function listed above has an "if" statement going

    if ((DataPtr + DataSize) >= ((EFI_PHYSICAL_ADDRESS) (UINTN) ((UINT8 *) 
FwVolHeader + FwVolHeader->FvLength))) {

The evaluation of the expression "FwVolHeader->FvLength" reads the
address 0xFFE00020, and it causes the page fault.

(3c) The problem is, this expression is evaluated a *whole lot* of times
earlier, when all those other (non-authenticated) variables are updated.
So why does it cause a fault here?

As next step, I sprinkled that code path that is visible above in (3b)
with a *huge* number of the following statement -- practically, I added
one right beside every DEBUG I had already inserted for the call tree
tracking:

    *(volatile UINT32 *)0xFFE00020;

Because I wanted to see which one of those would fault first.

Brace yourself: none of them faults. They do absolutely nothing (as they
should, actually) until we reach the expression above. Heck I added such
a volatile read statement *right before* the "if" that I quoted above,
separated only by a DEBUG() statement. It doesn't fault.

(3d) Another thing I noticed: when reproducing the issue under TCG vs.
KVM, both the RIP and the fault address (cr2) were different. Namely,
with TCG, I didn't get nearly as far in the above call tree as with KVM
-- one of the volatile read accesses that I inserted, and KVM breezed
through, *did* trigger a fault with TCG.

Furthermore, as I added more and more DEBUG and volatile read
statements, for tracing purposes, the fault address (cr2) and the RIP
changed under KVM as well. The "if" expression (the
FwVolHeader->FvLength access) I quoted above would no longer fault --
something else would, but *after* evaluating (FwVolHeader->FvLength).

(4) Obviously, I captured a KVM trace as well. It tells me two
interesting things.

(4a) The first is that near the fault, there's nothing interesting to
see. :)

Namely, I added a special character ("~", 0x7E) with a DEBUG() call to
the beginning of SmiPFHandler()
[UefiCpuPkg/PiSmmCpuDxeSmm/X64/PageTbl.c].

Additionally, there was a DEBUG message already being printed right
after evaluating (FwVolHeader->FvLength) -- see (3d) above; this is for
the case when (FwVolHeader->FvLength) did *not* fault.

So, in the OVMF log, we have:

> UpdateVariableStore: 360
> ~SmiPFHandler: PFAddress=0xFFE01460 Rip=0x7FF828B7

And here's the corresponding KVM trace:

> -12276 [006] 18167.656426: kvm_exit:             reason IO_INSTRUCTION rip 
> 0x7fef3a9f info 4020000 0
> -12276 [006] 18167.656426: kvm_pio:              pio_write at 0x402 size 1 
> count 1 val 0x36
> -12276 [006] 18167.656427: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
> -12276 [006] 18167.656427: kvm_fpu:              unload
> -12276 [006] 18167.656429: kvm_fpu:              load
> -12276 [006] 18167.656429: kvm_entry:            vcpu 0

This part is about printing the character "6" to the QEMU debug port,
from the decimally formatted line number "360".

> -12276 [006] 18167.656430: kvm_exit:             reason IO_INSTRUCTION rip 
> 0x7fef3a9f info 4020000 0
> -12276 [006] 18167.656430: kvm_pio:              pio_write at 0x402 size 1 
> count 1 val 0x30
> -12276 [006] 18167.656430: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
> -12276 [006] 18167.656430: kvm_fpu:              unload
> -12276 [006] 18167.656433: kvm_fpu:              load
> -12276 [006] 18167.656433: kvm_entry:            vcpu 0

Here we print the character "0".

> -12276 [006] 18167.656433: kvm_exit:             reason IO_INSTRUCTION rip 
> 0x7fef3a9f info 4020000 0
> -12276 [006] 18167.656434: kvm_pio:              pio_write at 0x402 size 1 
> count 1 val 0xd
> -12276 [006] 18167.656434: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
> -12276 [006] 18167.656434: kvm_fpu:              unload
> -12276 [006] 18167.656437: kvm_fpu:              load
> -12276 [006] 18167.656437: kvm_entry:            vcpu 0
> -12276 [006] 18167.656437: kvm_exit:             reason IO_INSTRUCTION rip 
> 0x7fef3a9f info 4020000 0
> -12276 [006] 18167.656437: kvm_pio:              pio_write at 0x402 size 1 
> count 1 val 0xa
> -12276 [006] 18167.656437: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
> -12276 [006] 18167.656438: kvm_fpu:              unload
> -12276 [006] 18167.656440: kvm_fpu:              load
> -12276 [006] 18167.656440: kvm_entry:            vcpu 0

CR and LF.

> -12276 [006] 18167.656441: kvm_exit:             reason DR_ACCESS rip 
> 0x7ffc6425 info 17 0
> -12276 [006] 18167.656442: kvm_entry:            vcpu 0

Now where does this come from? I'll tell you where: it comes from the
fault handler already!

I disassembled PiSmmCpuDxe with "objdump":

> start address 0x000000000000028f
> [...]

Cross-referenced it with the load address from the OVMF log file:

> Loading SMM driver at 0x0007FFB2000 EntryPoint=0x0007FFB228F 
> PiSmmCpuDxeSmm.efi

(note that (EntryPoint - LoadAddress) = 0x0007FFB228F-0x0007FFB2000 =
0x28F)

and then located 0x7ffc6425 (the RIP in the KVM trace) *minus* load
address (0x0007FFB2000) in the disassembly:

  RIP (0x7ffc6425) - Load Addresss (0x0007FFB2000) = 0x14425

> 000000000001437c <CommonInterruptEntry_al_0000>:
> [...]
>   14425:       0f 21 f8                mov    %db7,%rax

The CommonInterruptEntry_al_0000() function is in file
"UefiCpuPkg/Library/CpuExceptionHandlerLib/X64/ExceptionHandlerAsm.S",
and it goes

> CommonInterruptEntry_al_0000:
> [...]
> #; UINT64  Dr0, Dr1, Dr2, Dr3, Dr6, Dr7;
>     movq    %dr7, %rax

We can look a bit more at the KVM trace:

> -12276 [006] 18167.656444: kvm_exit:             reason IO_INSTRUCTION rip 
> 0x7ffc18ff info b008000b 0
> -12276 [006] 18167.656445: kvm_emulate_insn:     0:7ffc18ff: ed
> -12276 [006] 18167.656446: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
> -12276 [006] 18167.656446: kvm_fpu:              unload
> -12276 [006] 18167.656449: kvm_pio:              pio_read at 0xb008 size 4 
> count 1 val 0xf5ad83
> -12276 [006] 18167.656450: kvm_fpu:              load
> -12276 [006] 18167.656450: kvm_entry:            vcpu 0

Here we read the ACPI PM timer (not sure why, but it doesn't really
matter.)

> -12276 [006] 18167.656455: kvm_exit:             reason IO_INSTRUCTION rip 
> 0x7ffc18a5 info 4020000 0
> -12276 [006] 18167.656455: kvm_pio:              pio_write at 0x402 size 1 
> count 1 val 0x7e
> -12276 [006] 18167.656455: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
> -12276 [006] 18167.656455: kvm_fpu:              unload
> -12276 [006] 18167.656458: kvm_fpu:              load
> -12276 [006] 18167.656458: kvm_entry:            vcpu 0

And this is where the C language fault handler, SmiPFHandler(), prints
the tilde (~, 0x7E) character to the QEMU debug port.

Okay, okay, what does it all tell us? It tells us that there is no exit
from the VM, nothing at all that KVM does, *between* printing
"UpdateVariableStore: 360\r\n" (after FwVolHeader->FvLength is read
successfully) *and* the fault handler accessing debug register #7.

In other words, the fault is raised and delivered (== the handler is
entered) entirely within non-root operation, inside the VM. I find this
amazing. (Amazingly annoying.)

I didn't investigate the fault RIP (0x7FF828B7) reported by
SmiPFHandler() itself -- at this point I'm pretty much convinced the
exact RIP and cr2 values are irrelevant.

(4b) The other interesting thing the KVM trace tells me is the *length*
of the time intervals that we spend in SMM.

As I mentioned above, the EnrollDefaultKeys application reads a bunch of
variables before enrolling certificates in "db", and correspondingly,
there's a bunch of "entering SMM" / "leaving SMM" brackets in the KVM
trace. I have:

-  1 bracket  taking 160 microseconds,
- 27 brackets taking 20-100 microseconds each,
-  1 bracket  taking 34 *milliseconds* (but no fault),
- and the last (unbalanced) bracket, from entering SMM to the dr7 access
  in the fault handler, takes about 4 *millisecons*.

(5) I think the faults may be timing-related somehow. I don't know how.
It's interesting that the longest bracket, and the last (unbalanced one)
are partly executed on a different PCU (I can see a few kvm-pit entries
in both as well). But, I don't understand why it's not the longest
bracket that gets the fault.

(6) I guess the next thing to try is to add various busy-loops to the
affected AuthVariableLib functions, and see if I can force the failure
in current master with them...

Thanks
Laszlo
_______________________________________________
edk2-devel mailing list
[email protected]
https://lists.01.org/mailman/listinfo/edk2-devel

Reply via email to