I recently looked at improving the bootup performance of virtual machines
and was amazed by the fact that there is no logging / tracing framework
available that would give me a full picture of the Pre-OS phase including
time stamps and boot loaders (such as grub) without writing data to the
serial port - which taints all measurements.

The only place that I did find was PerformanceLib, which creates an FPDT.
I had 2 problems with that though:

  1) Discoverability - The best debugging tools give you all information
     you need as quickly as possible. The sub table FBPT which contains
     performance data is very condensed: It contains a modules GUID and up
     to 24 bytes of text per entry. Entries are limited to 255 bytes. It
     also only logs load events by default, nothing as fancy as FS reads.

  2) Ease of use - The best kernel engineers I know still use printk()
     and trace_printk() to identify issues: Because it's easy. You can
     quickly extract data into text and analyze later.

  3) Extensability to other payloads - The FPDT infrastructure considers
     everything as owned by PerformanceLib. I would like to create a one
     stop place for arbitrary UEFI applications to also put performance
     measurement data.

So I wrote a small configuration table (very similar to FPDT) that
contains references to boot logs, each with an array of strings as well
as time stamp. This patch set contains everything needed to set this up
and hook it into the 2 main DebugLib implementations in virtual machines:
Serial and DebugIO. That way, I can see every debug message after boot
with time stamp included, with very little impact on boot time.

I tried to see if I can call PERF_EVENT() instead of my Bootlog
infrastructure, but was unsuccessful. Let's use this patch set to open
the conversation on how to best move forward.

Eventually, I want to be able to log into Linux, fetch a sysfs file and
get a human readable, synchronized, time stamped log file with enough
information that allow me to create at least a bug report against the
actual firmware owner.


Github: https://github.com/agraf/edk2/tree/bootlog-v1

Alex


Alexander Graf (12):
  MdePkg: Add DebugBootlog header
  MdePkg: Add Null BaseDebugBootlog
  MdePkg: Add Fallback timer support for BaseDebugBootlog
  MdePkg: Add X86 timer support for BaseDebugBootlog
  MdePkg: Add ARM timer support for BaseDebugBootlog
  MdePkg: Add Pei phase BaseDebugBootlog
  MdePkg: Add Dxe phase BaseDebugBootlog
  MdePkg: Add BaseDebugLibBootlog
  Scripts: Add bootlog decyphering script
  BaseDebugLibSerialPort: Include BaseDebugBootlog in all dscs
  BaseDebugLibSerialPort: Emit messages to boot log
  OvmfPkg/PlatformDebugLibIoPort: Add Bootlog support

 ArmVirtPkg/ArmVirt.dsc.inc                    |   5 +
 BaseTools/Scripts/ShowDebugLog.py             |  88 +++++
 EmulatorPkg/EmulatorPkg.dsc                   |   3 +
 IntelFsp2Pkg/Tools/Tests/QemuFspPkg.dsc       |   1 +
 MdePkg/Include/Library/DebugBootlog.h         | 141 +++++++
 .../BaseDebugBootlog/BaseDebugBootlog.h       |  43 +++
 .../BaseDebugBootlog/BaseDebugBootlogLib.inf  |  61 +++
 .../BaseDebugBootlogLibPei.inf                |  60 +++
 .../BaseDebugBootlogNullLib.inf               |  26 ++
 .../Library/BaseDebugBootlog/DebugBootlog.c   |  22 ++
 .../BaseDebugBootlog/DebugBootlogArm.c        |  32 ++
 .../BaseDebugBootlog/DebugBootlogDxe.c        | 349 ++++++++++++++++++
 .../BaseDebugBootlog/DebugBootlogNotime.c     |  31 ++
 .../BaseDebugBootlog/DebugBootlogNull.c       |  32 ++
 .../BaseDebugBootlog/DebugBootlogPei.c        |  36 ++
 .../BaseDebugBootlog/DebugBootlogX86.c        |  50 +++
 .../BaseDebugLibBootlog.inf                   |  44 +++
 .../BaseDebugLibBootlog.uni                   |  17 +
 MdePkg/Library/BaseDebugLibBootlog/DebugLib.c | 338 +++++++++++++++++
 .../BaseDebugLibSerialPort.inf                |   1 +
 .../Library/BaseDebugLibSerialPort/DebugLib.c |  22 +-
 MdePkg/MdePkg.dec                             |  29 ++
 OvmfPkg/AmdSev/AmdSevX64.dsc                  |  10 +
 OvmfPkg/Bhyve/BhyveX64.dsc                    |  10 +
 OvmfPkg/CloudHv/CloudHvX64.dsc                |  10 +
 OvmfPkg/IntelTdx/IntelTdxX64.dsc              |   8 +
 .../Library/PlatformDebugLibIoPort/DebugLib.c |  23 +-
 .../PlatformDebugLibIoPort.inf                |   1 +
 .../PlatformRomDebugLibIoPort.inf             |   1 +
 .../PlatformRomDebugLibIoPortNocheck.inf      |   1 +
 OvmfPkg/Microvm/MicrovmX64.dsc                |  10 +
 OvmfPkg/OvmfPkgIa32.dsc                       |  10 +
 OvmfPkg/OvmfPkgIa32X64.dsc                    |  10 +
 OvmfPkg/OvmfPkgX64.dsc                        |   7 +
 OvmfPkg/OvmfXen.dsc                           |   1 +
 SourceLevelDebugPkg/SourceLevelDebugPkg.dsc   |   1 +
 UefiPayloadPkg/UefiPayloadPkg.dsc             |   1 +
 37 files changed, 1526 insertions(+), 9 deletions(-)
 create mode 100755 BaseTools/Scripts/ShowDebugLog.py
 create mode 100644 MdePkg/Include/Library/DebugBootlog.h
 create mode 100644 MdePkg/Library/BaseDebugBootlog/BaseDebugBootlog.h
 create mode 100644 MdePkg/Library/BaseDebugBootlog/BaseDebugBootlogLib.inf
 create mode 100644 MdePkg/Library/BaseDebugBootlog/BaseDebugBootlogLibPei.inf
 create mode 100644 MdePkg/Library/BaseDebugBootlog/BaseDebugBootlogNullLib.inf
 create mode 100644 MdePkg/Library/BaseDebugBootlog/DebugBootlog.c
 create mode 100644 MdePkg/Library/BaseDebugBootlog/DebugBootlogArm.c
 create mode 100644 MdePkg/Library/BaseDebugBootlog/DebugBootlogDxe.c
 create mode 100644 MdePkg/Library/BaseDebugBootlog/DebugBootlogNotime.c
 create mode 100644 MdePkg/Library/BaseDebugBootlog/DebugBootlogNull.c
 create mode 100644 MdePkg/Library/BaseDebugBootlog/DebugBootlogPei.c
 create mode 100644 MdePkg/Library/BaseDebugBootlog/DebugBootlogX86.c
 create mode 100644 MdePkg/Library/BaseDebugLibBootlog/BaseDebugLibBootlog.inf
 create mode 100644 MdePkg/Library/BaseDebugLibBootlog/BaseDebugLibBootlog.uni
 create mode 100644 MdePkg/Library/BaseDebugLibBootlog/DebugLib.c

-- 
2.28.0.394.ge197136389




Amazon Development Center Germany GmbH
Krausenstr. 38
10117 Berlin
Geschaeftsfuehrung: Christian Schlaeger, Jonathan Weiss
Eingetragen am Amtsgericht Charlottenburg unter HRB 149173 B
Sitz: Berlin
Ust-ID: DE 289 237 879





-=-=-=-=-=-=-=-=-=-=-=-
Groups.io Links: You receive all messages sent to this group.
View/Reply Online (#90067): https://edk2.groups.io/g/devel/message/90067
Mute This Topic: https://groups.io/mt/91368904/1787277
Group Owner: devel+owner@edk2.groups.io
Unsubscribe: https://edk2.groups.io/g/devel/unsub [importer@patchew.org]
-=-=-=-=-=-=-=-=-=-=-=-

On Fri, May 27, 2022 at 04:43:05AM +0200, Alexander Graf via groups.io wrote:
> I recently looked at improving the bootup performance of virtual machines
> and was amazed by the fact that there is no logging / tracing framework
> available that would give me a full picture of the Pre-OS phase including
> time stamps and boot loaders (such as grub) without writing data to the
> serial port - which taints all measurements.

Hmm.  Maybe it's time to tackle the log performance problem for virtual
machines?  Create a debug log device with DMA support, so we don't need
a vmexit for every single character we want log?

That will not completely kill the boot slowdown / measurement tainting
problem, but it should be an order of magnitude smaller.

Advantages:  We can leave the time stamp collection to the host, avoiding
issues like not knowing the tsc frequency in early firmware code.  You
can read the log even in case the guest doesn't boot up successfully.

>   3) Extensability to other payloads - The FPDT infrastructure considers
>      everything as owned by PerformanceLib. I would like to create a one
>      stop place for arbitrary UEFI applications to also put performance
>      measurement data.

How does that relate to coreboot?  coreboot has logging-to-memory too.
Not sure what the state is, there have been discussions on the coreboot
list about changing that from a pure text log to something structed with
timestamps a while back.  Don't know whenever this did actually happen.

So, when adding logging-to-memory to edk2 it surely make sense to
coordinate that with coreboot, so we'll have both coreboot and edk2 logs
there in case edk2 runs as coreboot payload.

take care,
  Gerd



-=-=-=-=-=-=-=-=-=-=-=-
Groups.io Links: You receive all messages sent to this group.
View/Reply Online (#90125): https://edk2.groups.io/g/devel/message/90125
Mute This Topic: https://groups.io/mt/91368904/1787277
Group Owner: devel+owner@edk2.groups.io
Unsubscribe: https://edk2.groups.io/g/devel/unsub [importer@patchew.org]
-=-=-=-=-=-=-=-=-=-=-=-

On Wed, Jun 1, 2022 at 05:33 AM, Gerd Hoffmann wrote:

> 
> Hmm. Maybe it's time to tackle the log performance problem for virtual
> machines? Create a debug log device with DMA support, so we don't need
> a vmexit for every single character we want log?

Of course, that doesn't work for native systems. I don't know how other developers perform debugging (possibly via a serial port), but I developed a library stack similar to this one to help me with GSoC last year ( https://github.com/benjamindoron/edk2/commit/db888a928c1c6fc94f6a7670f3402718c10c01d2 ). It's WIP, modelled after the simple coreboot ringbuffer and is missing tracing facilities.

Regardless, having a true complement to PcdStatusCodeUseSerial would often be helpful, I suspect (presently, PcdStatusCodeUseMemory only logs the PI status code for the debug messages).

> 
> How does that relate to coreboot? coreboot has logging-to-memory too.
> Not sure what the state is, there have been discussions on the coreboot
> list about changing that from a pure text log to something structed with
> timestamps a while back. Don't know whenever this did actually happen.
> 
> So, when adding logging-to-memory to edk2 it surely make sense to
> coordinate that with coreboot, so we'll have both coreboot and edk2 logs
> there in case edk2 runs as coreboot payload.

I'm working on getting a SerialPortLib that logs to CBMEM merged. It's on the list at the moment.

Some comments on DebugLibBootlog:
- It's possible to support ASSERTs. If PcdDebugPropertyMask & 0x31 == 0x01, then non-fatal ASSERTs are logged. As a DebugLib, this would require handling in `DebugAssert()`.
- SMM-phase logging can be implemented, but I'm not convinced that sharing DXE's buffer is entirely safe. Using SMM communicate could be safer, but would be more complicated. I stopped working on it when the return-on-investment was too low.

Regards,
Benjamin


-=-=-=-=-=-=-=-=-=-=-=-
Groups.io Links: You receive all messages sent to this group.
View/Reply Online (#90129): https://edk2.groups.io/g/devel/message/90129
Mute This Topic: https://groups.io/mt/91368904/1787277
Group Owner: devel+owner@edk2.groups.io
Unsubscribe: https://edk2.groups.io/g/devel/unsub [importer@patchew.org]
-=-=-=-=-=-=-=-=-=-=-=-

  Hi,

> > Hmm. Maybe it's time to tackle the log performance problem for virtual
> > machines? Create a debug log device with DMA support, so we don't need
> > a vmexit for every single character we want log?
> 
> Of course, that doesn't work for native systems.

Yep.  Maybe we should have both ;)

> > How does that relate to coreboot? coreboot has logging-to-memory too.
> > Not sure what the state is, there have been discussions on the coreboot
> > list about changing that from a pure text log to something structed with
> > timestamps a while back. Don't know whenever this did actually happen.
> > 
> > So, when adding logging-to-memory to edk2 it surely make sense to
> > coordinate that with coreboot, so we'll have both coreboot and edk2 logs
> > there in case edk2 runs as coreboot payload.
> 
> I'm working on getting a SerialPortLib that logs to CBMEM merged. It's on the list at the moment.

> Some comments on DebugLibBootlog:

> - SMM-phase logging can be implemented, but I'm not convinced that sharing DXE's buffer is entirely safe. Using SMM communicate could be safer, but would be more complicated. I stopped working on it when the return-on-investment was too low.

DebugLibBootlog supports multiple buffers.  So we could have one for
coreboot, one for edk2 pei/dxe, one for edk2 smm, one for shim, one for
grub, ...

take care,
  Gerd



-=-=-=-=-=-=-=-=-=-=-=-
Groups.io Links: You receive all messages sent to this group.
View/Reply Online (#90137): https://edk2.groups.io/g/devel/message/90137
Mute This Topic: https://groups.io/mt/91368904/1787277
Group Owner: devel+owner@edk2.groups.io
Unsubscribe: https://edk2.groups.io/g/devel/unsub [importer@patchew.org]
-=-=-=-=-=-=-=-=-=-=-=-