Random crashes with i386 and efi boots

PATCH Guenter Roeck 4 participants 9 messages Sep 10, 2018 – Sep 11, 2018

Subsystems (2)

x86 EFI

lore

Share & tools

lore

Guenter Roeck

author

2018-09-10 21:56 UTC #0 lore raw

Hi folks,

even after commit eeb89e2bb1ac ("x86/efi: Load fixmap GDT in efi_call_phys_epilog()"), my i386/efi qemu boot tests still crash randomly (roughly 5-10% of the time). As before, I don't see much useful output in the qemu log (this time it doesn't even complain about a triple fault).

Debugging shows that the crash happens in efi_call_phys_epilog(). A sample log from a crashed test run is attached below. It appears that the crash happens if there is an interrupt at a critical section of the code.

While playing with the code, I found a possible fix.

arch/x86/platform/efi/efi_32.c +1 -2

index 05ca14222463..9959657127f4 100644
@@ -85,10 +85,9 @@ pgd_t * __init efi_call_phys_prolog(void)
 
 void __init efi_call_phys_epilog(pgd_t *save_pgd)
 {
+	load_fixmap_gdt(0);
 	load_cr3(save_pgd);
 	__flush_tlb_all();
-
-	load_fixmap_gdt(0);
 }

This restores the execution order prior to commit eeb89e2bb1ac. I have no real idea what I am doing, so this change is to be taken with a grain of salt. All I can say is that 100 boots with the above change were successful while the current upstream code (v4.19-rc3) crashes on a regular basis (in a controlled test I observed 6 failures out of 100 boots).

It would be great if someone with a bit more experience can have another look and figure out the underlying problem. Please let me know if I can provide additional information.

Thanks,
Guenter

----------------
IN:
# efi_call_phys_epilog(save_pgd);

0xd8f9c12c:  8b 45 f0                 movl     -0x10(%ebp), %eax
0xd8f9c12f:  e8 49 01 00 00           calll    0xd8f9c27d

----------------
IN:
# efi_call_phys_epilog():
# load_cr3();

0xd8f9c27d:  55                       pushl    %ebp
0xd8f9c27e:  05 00 00 00 40           addl     $0x40000000, %eax
0xd8f9c283:  89 e5                    movl     %esp, %ebp
0xd8f9c285:  0f 22 d8                 movl     %eax, %cr3

CR3 update: CR3=1904e000
----------------
IN:
# __flush_tlb_all();
0xd8f9c288: e8 c8 5e 2b ff calll 0xd8252155

EAX=1904e000 EBX=00000000 ECX=d8f9c126 EDX=d8eafd60
ESI=1f09a000 EDI=00000030 EBP=d8e99f3c ESP=d8e99f3c
EIP=d8f9c288 EFL=00200207 [-----PC] CPL=0 II=0 A20=1 SMM=0 HLT=0
ES =007b 00000000 ffffffff 00cff300 DPL=3 DS [-WA]
CS =0060 00000000 ffffffff 00cf9a00 DPL=0 CS32 [-R-]
SS =0068 00000000 ffffffff 00cf9300 DPL=0 DS [-WA]
DS =007b 00000000 ffffffff 00cff300 DPL=3 DS [-WA]
FS =00d8 06c92000 ffffffff 008f9300 DPL=0 DS16 [-WA]
GS =00e0 dfcd09c0 00000018 00409100 DPL=0 DS [--A]
LDT=0000 00000000 00000000 00008200 DPL=0 LDT
TR =0080 ff803000 0000206b 00008900 DPL=0 TSS32-avl
GDT= 1fcc0000 000000ff
IDT= ff800000 000007ff
CR0=80050033 CR2=ffd17000 CR3=1904e000 CR4=00040690
DR0=00000000 DR1=00000000 DR2=00000000 DR3=00000000
DR6=ffff0ff0 DR7=00000400
CCS=40000000 CCD=1904e000 CCO=ADDL
EFER=0000000000000000
Servicing hardware INT=0x30
508: v=30 e=0000 i=0 cpl=0 IP=0060:d8f9c288 pc=d8f9c288 SP=0068:d8e99f3c env->regs[R_EAX]=1904e000
X=1904e000 EBX=00000000 ECX=d8f9c126 EDX=d8eafd60
ESI=1f09a000 EDI=00000030 EBP=d8e99f3c ESP=d8e99f3c
EIP=d8f9c288 EFL=00200207 [-----PC] CPL=0 II=0 A20=1 SMM=0 HLT=0
ES =007b 00000000 ffffffff 00cff300 DPL=3 DS [-WA]
CS =0060 00000000 ffffffff 00cf9a00 DPL=0 CS32 [-R-]
SS =0068 00000000 ffffffff 00cf9300 DPL=0 DS [-WA]
DS =007b 00000000 ffffffff 00cff300 DPL=3 DS [-WA]
FS =00d8 06c92000 ffffffff 008f9300 DPL=0 DS16 [-WA]
GS =00e0 dfcd09c0 00000018 00409100 DPL=0 DS [--A]
LDT=0000 00000000 00000000 00008200 DPL=0 LDT
TR =0080 ff803000 0000206b 00008900 DPL=0 TSS32-avl
GDT= 1fcc0000 000000ff
IDT= ff800000 000007ff
CR0=80050033 CR2=ffd17000 CR3=1904e000 CR4=00040690
DR0=00000000 DR1=00000000 DR2=00000000 DR3=00000000
DR6=ffff0ff0 DR7=00000400
CCS=00000005 CCD=1904e000 CCO=EFLAGS
EFER=0000000000000000
check_exception old: 0xffffffff new 0xe
509: v=0e e=0000 i=0 cpl=0 IP=0060:d8f9c288 pc=d8f9c288 SP=0068:d8e99f3c CR2=1fcc0060
EAX=1904e000 EBX=00000000 ECX=d8f9c126 EDX=d8eafd60
ESI=1f09a000 EDI=00000030 EBP=d8e99f3c ESP=d8e99f3c
EIP=d8f9c288 EFL=00200207 [-----PC] CPL=0 II=0 A20=1 SMM=0 HLT=0
ES =007b 00000000 ffffffff 00cff300 DPL=3 DS [-WA]
CS =0060 00000000 ffffffff 00cf9a00 DPL=0 CS32 [-R-]
SS =0068 00000000 ffffffff 00cf9300 DPL=0 DS [-WA]
DS =007b 00000000 ffffffff 00cff300 DPL=3 DS [-WA]
FS =00d8 06c92000 ffffffff 008f9300 DPL=0 DS16 [-WA]
GS =00e0 dfcd09c0 00000018 00409100 DPL=0 DS [--A]
LDT=0000 00000000 00000000 00008200 DPL=0 LDT
TR =0080 ff803000 0000206b 00008900 DPL=0 TSS32-avl
GDT= 1fcc0000 000000ff
IDT= ff800000 000007ff
CR0=80050033 CR2=1fcc0060 CR3=1904e000 CR4=00040690
DR0=00000000 DR1=00000000 DR2=00000000 DR3=00000000
DR6=ffff0ff0 DR7=00000400
CCS=00000005 CCD=1904e000 CCO=EFLAGS
EFER=0000000000000000
check_exception old: 0xe new 0xe
510: v=08 e=0000 i=0 cpl=0 IP=0060:d8f9c288 pc=d8f9c288 SP=0068:d8e99f3c env->regs[R_EAX]=1904e000
EAX=1904e000 EBX=00000000 ECX=d8f9c126 EDX=d8eafd60
ESI=1f09a000 EDI=00000030 EBP=d8e99f3c ESP=d8e99f3c
EIP=d8f9c288 EFL=00200207 [-----PC] CPL=0 II=0 A20=1 SMM=0 HLT=0
ES =007b 00000000 ffffffff 00cff300 DPL=3 DS [-WA]
CS =0060 00000000 ffffffff 00cf9a00 DPL=0 CS32 [-R-]
SS =0068 00000000 ffffffff 00cf9300 DPL=0 DS [-WA]
DS =007b 00000000 ffffffff 00cff300 DPL=3 DS [-WA]
FS =00d8 06c92000 ffffffff 008f9300 DPL=0 DS16 [-WA]
GS =00e0 dfcd09c0 00000018 00409100 DPL=0 DS [--A]
LDT=0000 00000000 00000000 00008200 DPL=0 LDT
TR =0080 ff803000 0000206b 00008900 DPL=0 TSS32-avl
GDT= 1fcc0000 000000ff
IDT= ff800000 000007ff
CR0=80050033 CR2=1fcc0060 CR3=1904e000 CR4=00040690
DR0=00000000 DR1=00000000 DR2=00000000 DR3=00000000
DR6=ffff0ff0 DR7=00000400
CCS=00000005 CCD=1904e000 CCO=EFLAGS
EFER=0000000000000000
check_exception old: 0x8 new 0xe

# qemu dies silently here

---

In another log, the code proceeeds a little further:

CR3 update: CR3=13668000
----------------
IN:
0xd35b6412: e8 ae cb 29 ff calll 0xd2852fc5

----------------
IN:

0xd35b6417:  31 c0                    xorl     %eax, %eax
0xd35b6419:  e8 12 2e 27 ff           calll    0xd2829230

----------------
IN:

0xd2829230:  55                       pushl    %ebp
0xd2829231:  89 e5                    movl     %esp, %ebp
0xd2829233:  83 ec 08                 subl     $8, %esp
0xd2829236:  e8 75 6c 02 00           calll    0xd284feb0

Servicing hardware INT=0x30

... subsequent log messages and crash are as before.

Andy Lutomirski

2018-09-11 11:52 UTC #1 lore raw

Quoted 23 lines · Guenter Roeck

Hi folks,
even after commit eeb89e2bb1ac ("x86/efi: Load fixmap GDT in efi_call_phys_epilog()"), my i386/efi qemu boot tests still crash randomly (roughly 5-10% of the time). As before, I don't see much useful output in the qemu log (this time it doesn't even complain about a triple fault).
Debugging shows that the crash happens in efi_call_phys_epilog(). A sample log from a crashed test run is attached below. It appears that the crash happens if there is an interrupt at a critical section of the code.
While playing with the code, I found a possible fix.
arch/x86/platform/efi/efi_32.c +0 -0
index 05ca14222463..9959657127f4 100644

arch/x86/platform/efi/efi_32.c pgd_t * __init efi_call_phys_prolog(void) · line 91

Quoted 9 lines

arch/x86/platform/efi/efi_32.c +1 -2

@@ -85,10 +85,9 @@ pgd_t * __init efi_call_phys_prolog(void)
 
 void __init efi_call_phys_epilog(pgd_t *save_pgd)
 {
+    load_fixmap_gdt(0);
   load_cr3(save_pgd);
   __flush_tlb_all();
-
-    load_fixmap_gdt(0);
 }

We have IRQs on here? It seems plausible that we’re in a window where the EFI pgd doesn’t have cpu_entry_area mapped. Also, the hard coded CPU 0 is suspicious.

Maybe try instrumenting the code to check whether the clone_pgd_range calls in setup_percpu.c have happened yet?

Your patch may well be correct, but, if we have IRQs on, we should really have cpu_entry_area mapped in both pgds.

Or we could turn off IRQs. Why on Earth are IRQs on in a context where the fixmap gdt is unusable?

Guenter Roeck

author

2018-09-11 13:30 UTC #2 lore raw

Quoted 24 lines · Andy Lutomirski

Quoted 24 lines · Guenter Roeck
Hi folks,
even after commit eeb89e2bb1ac ("x86/efi: Load fixmap GDT in efi_call_phys_epilog()"), my i386/efi qemu boot tests still crash randomly (roughly 5-10% of the time). As before, I don't see much useful output in the qemu log (this time it doesn't even complain about a triple fault).
Debugging shows that the crash happens in efi_call_phys_epilog(). A sample log from a crashed test run is attached below. It appears that the crash happens if there is an interrupt at a critical section of the code.
While playing with the code, I found a possible fix.
arch/x86/platform/efi/efi_32.c +0 -0
index 05ca14222463..9959657127f4 100644
@@ -85,10 +85,9 @@ pgd_t * __init efi_call_phys_prolog(void)
 

Quoted 11 lines

arch/x86/platform/efi/efi_32.c pgd_t * __init efi_call_phys_prolog(void) · line 91
Quoted 8 lines
arch/x86/platform/efi/efi_32.c +1 -2
 void __init efi_call_phys_epilog(pgd_t *save_pgd)
 {
+    load_fixmap_gdt(0);
    load_cr3(save_pgd);
    __flush_tlb_all();
-
-    load_fixmap_gdt(0);
 }
We have IRQs on here? It seems plausible that we’re in a window where the EFI pgd doesn’t have cpu_entry_area mapped. Also, the hard coded CPU 0 is suspicious.

The hard coded CPU 0 was always there. The call is ultimately from efi_enter_virtual_mode(), which is called from start_kernel(). so presumably it is guaranteed to run on CPU 0.

Quoted 2 lines

Maybe try instrumenting the code to check whether the clone_pgd_range calls in setup_percpu.c have happened yet?

The crash is seen late in the boot process, so I am quite sure it happened, but I can add a check if needed. I think that might be a different problem, though.

Quoted 4 lines

Your patch may well be correct, but, if we have IRQs on, we should really have cpu_entry_area mapped in both pgds.
Or we could turn off IRQs. Why on Earth are IRQs on in a context where the fixmap gdt is unusable?

From arch/x86/platform/efi/efi.c:phys_efi_set_virtual_address_map():

	save_pgd = efi_call_phys_prolog();
	local_irq_save(flags);
	status = efi_call_phys(...);
        local_irq_restore(flags);

        efi_call_phys_epilog(save_pgd);

So, yes, interrupts are very much enabled.

I ran several additional test sequences. With above patch, no failures with 500 boots. Without it, failure rate (long term average) across 500 boots is around 10%. Another data point: Moving load_fixmap_gdt(0); after load_cr3(save_pgd); does not help; it has to come first.

Guenter

Andy Lutomirski

2018-09-11 16:36 UTC #3 lore raw

Quoted 50 lines · Guenter Roeck

Quoted 22 lines · Andy Lutomirski
Quoted 22 lines · Guenter Roeck
Hi folks,
even after commit eeb89e2bb1ac ("x86/efi: Load fixmap GDT in efi_call_phys_epilog()"), my i386/efi qemu boot tests still crash randomly (roughly 5-10% of the time). As before, I don't see much useful output in the qemu log (this time it doesn't even complain about a triple fault).
Debugging shows that the crash happens in efi_call_phys_epilog(). A sample log from a crashed test run is attached below. It appears that the crash happens if there is an interrupt at a critical section of the code.
While playing with the code, I found a possible fix.
arch/x86/platform/efi/efi_32.c +0 -1
index 05ca14222463..9959657127f4 100644
--- a/arch/x86/platform/efi/efi_32.c
 +++ b/arch/x86/platform/efi/efi_32.c
@@ -85,10 +85,9 @@ pgd_t * __init efi_call_phys_prolog(void)
 
Quoted 9 lines
arch/x86/platform/efi/efi_32.c pgd_t * __init efi_call_phys_prolog(void) · line 91
Quoted 8 lines
arch/x86/platform/efi/efi_32.c +1 -2
 void __init efi_call_phys_epilog(pgd_t *save_pgd)
 {
+    load_fixmap_gdt(0);
   load_cr3(save_pgd);
   __flush_tlb_all();
-
-    load_fixmap_gdt(0);
 }
We have IRQs on here? It seems plausible that we’re in a window where the EFI pgd doesn’t have cpu_entry_area mapped. Also, the hard coded CPU 0 is suspicious.
The hard coded CPU 0 was always there. The call is ultimately from efi_enter_virtual_mode(), which is called from start_kernel(). so presumably it is guaranteed to run on CPU 0.
Quoted 1 line
Maybe try instrumenting the code to check whether the clone_pgd_range calls in setup_percpu.c have happened yet?
The crash is seen late in the boot process, so I am quite sure it happened, but I can add a check if needed. I think that might be a different problem, though.
Quoted 2 lines
Your patch may well be correct, but, if we have IRQs on, we should really have cpu_entry_area mapped in both pgds. Or we could turn off IRQs. Why on Earth are IRQs on in a context where the fixmap gdt is unusable?
From arch/x86/platform/efi/efi.c:phys_efi_set_virtual_address_map():

Quoted 8 lines

   save_pgd = efi_call_phys_prolog();
   local_irq_save(flags);
   status = efi_call_phys(...);
       local_irq_restore(flags);

       efi_call_phys_epilog(save_pgd);

So, yes, interrupts are very much enabled.

Does fixing that solve the problem? It seems more robust.

Quoted 7 lines

I ran several additional test sequences. With above patch, no failures with 500 boots. Without it, failure rate (long term average) across 500 boots is around 10%. Another data point: Moving load_fixmap_gdt(0); after load_cr3(save_pgd); does not help; it has to come first.
Guenter

Joerg Roedel

2018-09-11 17:41 UTC #4 lore raw

Quoted 10 lines · Andy Lutomirski

Quoted 8 lines
   save_pgd = efi_call_phys_prolog();
   local_irq_save(flags);
   status = efi_call_phys(...);
       local_irq_restore(flags);
       efi_call_phys_epilog(save_pgd);
So, yes, interrupts are very much enabled.
Does fixing that solve the problem? It seems more robust.

The problem is still that in efi_call_phys_prolog() we load the gdt with its physical address, and when we reload the %cr3 in _epilog from initial_page_table to swapper_pg_dir again the gdt is no longer mapped. Blocking interrupts is more robust, but we can't block NMIs that way that would also trigger the issue, no?

So I am in favor of changing the order in efi_call_phys_epilog() too.

Regards,

Joerg

Linus Torvalds

2018-09-11 17:59 UTC #5 lore raw

Quoted 2 lines · Joerg Roedel

So I am in favor of changing the order in efi_call_phys_epilog() too.

Yeah, the only reason the order was changed was that it seemed more logical to use the new cr3 to load the GDT. But that was clearly wrong.

So ack on just changing the order, and my bad for suggesting the change in the first place.

Linus

Guenter Roeck

author

2018-09-11 17:59 UTC #6 lore raw

In reply to Joerg Roedel

Quoted 12 lines · Joerg Roedel

Quoted 10 lines · Andy Lutomirski
Quoted 8 lines
   save_pgd = efi_call_phys_prolog();
   local_irq_save(flags);
   status = efi_call_phys(...);
       local_irq_restore(flags);
       efi_call_phys_epilog(save_pgd);
So, yes, interrupts are very much enabled.
Does fixing that solve the problem? It seems more robust.

Quoted 8 lines

The problem is still that in efi_call_phys_prolog() we load the gdt with its physical address, and when we reload the %cr3 in _epilog from initial_page_table to swapper_pg_dir again the gdt is no longer mapped. Blocking interrupts is more robust, but we can't block NMIs that way that would also trigger the issue, no?
So I am in favor of changing the order in efi_call_phys_epilog() too.

Blocking the interrupts across efi_call_phys_prolog() / efi_call_phys() / efi_call_phys_epilog() does solve the issue, but I am concerned about its negative effect on 64-bit operation (not sure if blocking interrupts in the prolog/epilog functions there is ok). Adding another set of local_irq_save() / local_irq_restore() to efi_call_phys_epilog() seems wasteful if the problem can be solved by reordering instructions.

So, yes, I also prefer changing the order in efi_call_phys_epilog(). I'll submit a patch along that line.

Thanks,
Guenter

Andy Lutomirski

2018-09-11 18:05 UTC #7 lore raw

In reply to Joerg Roedel

Quoted 16 lines · Joerg Roedel

Quoted 10 lines · Andy Lutomirski
Quoted 8 lines
  save_pgd = efi_call_phys_prolog();
  local_irq_save(flags);
  status = efi_call_phys(...);
      local_irq_restore(flags);
      efi_call_phys_epilog(save_pgd);
So, yes, interrupts are very much enabled.
Does fixing that solve the problem? It seems more robust.

Quoted 8 lines

The problem is still that in efi_call_phys_prolog() we load the gdt with its physical address, and when we reload the %cr3 in _epilog from initial_page_table to swapper_pg_dir again the gdt is no longer mapped. Blocking interrupts is more robust, but we can't block NMIs that way that would also trigger the issue, no?
So I am in favor of changing the order in efi_call_phys_epilog() too.

I’m rather confused here. We’re loading CR3 with page tables that don’t have the fixmap mapped? With interrupts on? And we expect it to work? This is *nuts*.

There are IMO only three sane fixes here:

1. Load the fixmap, cpu_entry_area, etc into the EFI page table. Drop the GDT reload entirely.

2. Do this whole virtual map dance earlier so we don’t have IRQs and NMIs and such. Maybe while we’re still using the initial page table?

3. Just identity map all the EFI regions. Make EFI page tables that literally map them at their physical addresses *and* map the entire kernel, just like we do for normal user mms.

Sure, as a stopgap, turning off IRQs and applying Guenter’s patch seems okay, but this code is not okay.

Guenter Roeck

author

2018-09-11 18:22 UTC #8 lore raw

Quoted 29 lines · Andy Lutomirski

Quoted 16 lines · Joerg Roedel
Quoted 10 lines · Andy Lutomirski
Quoted 8 lines
  save_pgd = efi_call_phys_prolog();
  local_irq_save(flags);
  status = efi_call_phys(...);
      local_irq_restore(flags);
      efi_call_phys_epilog(save_pgd);
So, yes, interrupts are very much enabled.
Does fixing that solve the problem? It seems more robust.
Quoted 8 lines
The problem is still that in efi_call_phys_prolog() we load the gdt with its physical address, and when we reload the %cr3 in _epilog from initial_page_table to swapper_pg_dir again the gdt is no longer mapped. Blocking interrupts is more robust, but we can't block NMIs that way that would also trigger the issue, no?
So I am in favor of changing the order in efi_call_phys_epilog() too.
I’m rather confused here. We’re loading CR3 with page tables that don’t have the fixmap mapped? With interrupts on? And we expect it to work? This is *nuts*.
There are IMO only three sane fixes here:

Quoted 7 lines

1. Load the fixmap, cpu_entry_area, etc into the EFI page table. Drop the GDT reload entirely.
2. Do this whole virtual map dance earlier so we don’t have IRQs and NMIs and such. Maybe while we’re still using the initial page table?
3. Just identity map all the EFI regions. Make EFI page tables that literally map them at their physical addresses *and* map the entire kernel, just like we do for normal user mms.
Sure, as a stopgap, turning off IRQs and applying Guenter’s patch seems okay, but this code is not okay.

I submitted a patch with the diff I suggested above; it seems to be the least invasive solution and addresses the immediate problem.

I am way out of league regarding the other suggested changes. I'll be happy to test the code if someone is willing to rearrange the code accordingly, but I don't think it would make sense to even try doing it myself.

Thanks,
Guenter