I became curious this past week on how UEFI handles POST codes. These are “markers” for the boot process, and tells you at what stage the platform initialization is. Can we easily correlate POST codes with the operation of the UEFI firmware?
What is a POST code? During an x86 board power-on, the BIOS sends progress codes (POST codes) to I/O port x’80’. If anywhere during the boot process, the board fails, it will be frozen at the last POST code, which gives a hint as to where the problem is. Often, the POST code is displayed on an LED display on motherboards (typically server class). Alternatively, and for the purposes of this article, the POST code is output from the serial port while a debug image that I built for the UP Squared board boots. So, from the PuTTY console, below are some examples as to how the POST codes manifest themselves:
……
Re-install Si CPU Policy Ppi in Post-Memory CPU PEI Policy Initialization Done in Post-Memory PeiPolicyInit – End POSTCODE=<0019>
……
PlatformBootManagerBeforeConsole POSTCODE=<92>
……
PCI Bus First Scanning POSTCODE=<94>
……
XhCDriverBindingStart: XHCI started for controller @ 76E39818 POSTCODE=<9A>
The actual “write” to port x’80’ is done via the x86 OUT instruction, which copies the value from the second operand (often programmatically the AX register) to the I/O port specified in the first operand (often the DX register):
OUT DX, AX
So, for POST codes, DX is set to x’80’, and AX contains the specific progress or POST code that is to be output.
With SourcePoint, it’s easy to stop the Intel CPU at each write to port 80, by setting a breakpoint at the OUT instruction that manifests it. Using our powerful macro language, you set a breakpoint at port 80 writes, run until you hit it, and then display the contents of the AX register (the POST code) all by concatenating three commands on one line of the Command CLI window:
go til 80io; wait; ax
And, if you’re really clever, you set up Intel Processor Trace to trigger on these breakpoints, and capture a ton of instruction execution trace leading up to the OUT instruction. Then walk backwards through the code flow to see what is happening.
I booted up the UP Squared, halted at a random spot in the code, and then used the above Go command string to halt at the next POST code. The SourcePoint Code window is displayed below, with the code display pick list at the bottom set to “Source”. Note we are in postcodestatuscodeworker.c, within the function PostCodeStatusCodeReportWorker, halted at the PostCode() function:
Switching the Code window view to Mixed mode shows that we halted exactly immediately after the OUT instruction, and in the General Registers window on the right, the AX register is set to x’94’ (you can see this as well in the Command window docked at the bottom):
It’s easier if we look at the code within postcodestatuscodeworker.c in its entirety:
/** @file
PostCode status code implementation.
Copyright (c) 2010 - 2016, Intel Corporation. All rights reserved.<BR>
This program and the accompanying materials
are licensed and made available under the terms and conditions of the BSD License
which accompanies this distribution. The full text of the license may be found at
http://opensource.org/licenses/bsd-license.php.
THE PROGRAM IS DISTRIBUTED UNDER THE BSD LICENSE ON AN "AS IS" BASIS,
WITHOUT WARRANTIES OR REPRESENTATIONS OF ANY KIND, EITHER EXPRESS OR IMPLIED.
**/
#include "PlatformPort80HandlerRuntimeDxe.h"
/**
Convert status code value and write data to port code.
@param[in] CodeType Indicates the type of status code being reported.
@param[in] Value Describes the current status of a hardware or
software entity. This includes information about the class
and subclass that is used to classify the entity as well as an
operation.
For progress codes, the operation is the current activity.
For error codes, it is the exception. For debug codes, it is
not defined at this time.
@param[in] Instance The enumeration of a hardware or software entity within
the system. A system may contain multiple entities that match
a class/subclass pairing. The instance differentiates between
them. An instance of 0 indicates that instance information is
unavailable, not meaningful, or not relevant.
Valid instance numbers start with 1.
@param[in] CallerId This optional parameter may be used to identify the caller.
This parameter allows the status code driver to apply
different rules to different callers.
@param[in] Data This optional parameter may be used to pass additional data.
@retval EFI_SUCCESS Status code reported to port code successfully.
**/
EFI_STATUS
EFIAPI
PostCodeStatusCodeReportWorker (
IN EFI_STATUS_CODE_TYPE CodeType,
IN EFI_STATUS_CODE_VALUE Value,
IN UINT32 Instance,
IN EFI_GUID *CallerId,
IN EFI_STATUS_CODE_DATA *Data OPTIONAL
)
{
UINT32 PostCodeValue;
PostCodeValue = GetPostCodeFromStatusCode (CodeType, Value);
if (PostCodeValue != 0) {
DEBUG ((DEBUG_INFO, "POSTCODE=<%02x>\n", PostCodeValue));
PostCode (PostCodeValue);
}
if ((CodeType & EFI_STATUS_CODE_TYPE_MASK) == EFI_PROGRESS_CODE) {
//
// Print PROGRESS information into output buffer.
//
DEBUG ((DEBUG_INFO, "PROGRESS CODE: V%x I%x\n\r", Value, Instance));
}
return EFI_SUCCESS;
}
The main function is PostCodeStatusCodeReportWorker(). Since we are halted there, we can use the SourcePoint Symbols window to display the parameters on the stack:
Note that the PostCodeValue is x’94’, as expected.
CodeType must be a global, and stored on the heap, and not on the stack, so it’s out of context.
Glancing over at the serial console, I walked from POSTCODE 90 to 92 to 94, and what came out the serial console near the end was:
PlatformBootManagerBeforeConsole POSTCODE=<92> PROGRESS CODE: v2010000 I0 PCI Bus First Scanning POSTCODE=<94>
See that the progress code 2010000 appears as the “Value” parameter of type EFI_STATUS_CODE_VALUE from the stack window.
From the prefix text, you can surmise that POSTCODE 94 has something to do with “PCI Bus First Scanning”, but you have to look at the code to know more. And scanning through the build directory, we find that this text string comes from PciLib.c, within function PciHostBridgeEnumerator():
EFI_STATUS
PciHostBridgeEnumerator (
IN EFI_PCI_HOST_BRIDGE_RESOURCE_ALLOCATION_PROTOCOL *PciResAlloc
)
{
EFI_HANDLE RootBridgeHandle;
PCI_IO_DEVICE *RootBridgeDev;
EFI_STATUS Status;
EFI_PCI_ROOT_BRIDGE_IO_PROTOCOL *PciRootBridgeIo;
UINT16 MinBus;
EFI_ACPI_ADDRESS_SPACE_DESCRIPTOR *Descriptors;
EFI_ACPI_ADDRESS_SPACE_DESCRIPTOR *Configuration;
UINT8 StartBusNumber;
LIST_ENTRY RootBridgeList;
LIST_ENTRY *Link;
if (FeaturePcdGet (PcdPciBusHotplugDeviceSupport)) {
InitializeHotPlugSupport ();
}
InitializeListHead (&RootBridgeList);
//
// Notify the bus allocation phase is about to start
//
Status = NotifyPhase (PciResAlloc, EfiPciHostBridgeBeginBusAllocation);
if (EFI_ERROR (Status)) {
return Status;
}
DEBUG((EFI_D_INFO, "PCI Bus First Scanning\n"));
Using Intel Processor Trace can yield us this insight, as to how post codes are handled. I used the same means as in the prior blog to capture processor execution trace data in going to POSTCODE 94, and here is what I saw when I opened SourcePoint’s instruction “Call Chart”:
The black vertical line near the right marks the beginning of the entry to MmioRead32and its calling functions. At Cycle -1851 (that you can see near the top, under the title bar), code flow is shown to be ReportDispatcher -> PostCodeStatusCodeReportWorker -> DebugPrint ->PchSerialIoUartOut -> FindSerialIoBar -> MmioRead32. This seems intuitively correct, because for a debug image, the post codes are always also sent out the serial console.
Backing up just a bit to Cycle -1856, the new flow is below:
This differs only since it’s invoking MmPciBase just prior to the MmioRead32, as you can see. That also makes sense.
Sliding the instruction pointer to the left and watching the function calls evolve makes it apparent that the routine ReportDispatcher is setting up a call to PostCodeStatusCodeReportWorker, but does not directly invoke it. Looking at ReportDispatcher in some level of detail indicates a degree of complexity:
213 /**
214 Provides an interface that a software module can call to report a status code.
215
216 @param Type Indicates the type of status code being reported.
217 @param Value Describes the current status of a hardware or software entity.
218 This included information about the class and subclass that is used to
219 classify the entity as well as an operation.
220 @param Instance The enumeration of a hardware or software entity within
221 the system. Valid instance numbers start with 1.
222 @param CallerId This optional parameter may be used to identify the caller.
223 This parameter allows the status code driver to apply different rules to
224 different callers.
225 @param Data This optional parameter may be used to pass additional data.
226
227 @retval EFI_SUCCESS The function completed successfully
228 @retval EFI_DEVICE_ERROR The function should not be completed due to a device error.
229
230 **/
231 EFI_STATUS
232 EFIAPI
233 ReportDispatcher (
234 IN EFI_STATUS_CODE_TYPE Type,
235 IN EFI_STATUS_CODE_VALUE Value,
236 IN UINT32 Instance,
237 IN EFI_GUID *CallerId OPTIONAL,
238 IN EFI_STATUS_CODE_DATA *Data OPTIONAL
239 )
240 {
241 LIST_ENTRY *Link;
242 RSC_HANDLER_CALLBACK_ENTRY *CallbackEntry;
243 RSC_DATA_ENTRY *RscData;
244 EFI_STATUS Status;
245 VOID *NewBuffer;
246
247 //
248 // Use atom operation to avoid the reentant of report.
249 // If current status is not zero, then the function is reentrancy.
250 //
251 if (InterlockedCompareExchange32 (&mStatusCodeNestStatus, 0, 1) == 1) {
252 return EFI_DEVICE_ERROR;
253 }
254
255 for (Link = GetFirstNode (&mCallbackListHead); !IsNull (&mCallbackListHead, Link);) {
256 CallbackEntry = CR (Link, RSC_HANDLER_CALLBACK_ENTRY, Node, RSC_HANDLER_CALLBACK_ENTRY_SIGNATURE);
257 //
258 // The handler may remove itself, so get the next handler in advance.
259 //
260 Link = GetNextNode (&mCallbackListHead, Link);
261 if ((CallbackEntry->Tpl == TPL_HIGH_LEVEL) || EfiAtRuntime ()) {
262 CallbackEntry->RscHandlerCallback (
263 Type,
264 Value,
265 Instance,
266 CallerId,
267 Data
268 );
269 continue;
270 }
271
272 //
273 // If callback is registered with TPL lower than TPL_HIGH_LEVEL, event must be signaled at boot time to possibly wait for
274 // allowed TPL to report status code. Related data should also be stored in data buffer.
275 //
276 CallbackEntry->EndPointer = ALIGN_VARIABLE (CallbackEntry->EndPointer);
277 RscData = (RSC_DATA_ENTRY *) (UINTN) CallbackEntry->EndPointer;
278 CallbackEntry->EndPointer += sizeof (RSC_DATA_ENTRY);
279 if (Data != NULL) {
280 CallbackEntry->EndPointer += Data->Size;
281 }
282
283 //
284 // If data buffer is about to be used up (7/8 here), try to reallocate a buffer with double size, if not at TPL_HIGH_LEVEL.
285 //
286 if (CallbackEntry->EndPointer > (CallbackEntry->StatusCodeDataBuffer + (CallbackEntry->BufferSize / 8) * 7)) {
287 if (EfiGetCurrentTpl () < TPL_HIGH_LEVEL) {
288 NewBuffer = ReallocatePool (
289 CallbackEntry->BufferSize,
290 CallbackEntry->BufferSize * 2,
291 (VOID *) (UINTN) CallbackEntry->StatusCodeDataBuffer
292 );
293 if (NewBuffer != NULL) {
294 CallbackEntry->EndPointer = (EFI_PHYSICAL_ADDRESS) (UINTN) NewBuffer + (CallbackEntry->EndPointer - CallbackEntry->StatusCodeDataBuffer);
295 CallbackEntry->StatusCodeDataBuffer = (EFI_PHYSICAL_ADDRESS) (UINTN) NewBuffer;
296 CallbackEntry->BufferSize *= 2;
297 }
298 }
299 }
300
301 //
302 // If data buffer is used up, do not report for this time.
303 //
304 if (CallbackEntry->EndPointer > (CallbackEntry->StatusCodeDataBuffer + CallbackEntry->BufferSize)) {
305 continue;
306 }
307
308 RscData->Type = Type;
309 RscData->Value = Value;
310 RscData->Instance = Instance;
311 if (CallerId != NULL) {
312 CopyGuid (&RscData->CallerId, CallerId);
313 }
314 if (Data != NULL) {
315 CopyMem (&RscData->Data, Data, Data->HeaderSize + Data->Size);
316 }
317
318 Status = gBS->SignalEvent (CallbackEntry->Event);
319 ASSERT_EFI_ERROR (Status);
320 }
321
322 //
323 // Restore the nest status of report
324 //
325 InterlockedCompareExchange32 (&mStatusCodeNestStatus, 1, 0);
326
327 return EFI_SUCCESS;
Digging into this a bit more, we see that ReportDispatcher() is defined further within ReportStatusCodeRouterSmm.c as:
EFI_SMM_STATUS_CODE_PROTOCOL mSmmStatusCodeProtocol = {
ReportDispatcher
};
I’ve gone back in the trace history, but I can’t connect the dots between the call to ReportDispatcher() and PciHostBridgeEnumerator() within PciLib.c, looking for the string “PCI Bus First Scanning”. I think I need to trace further back in time to associate the call to ReportDispatcher with the “PCI Bus First Scanning” message that precedes it. So, I increased the Processor Trace buffer to 512MB (Wow! And you can make it bigger, of course, based upon how much system memory you have; it just makes it slower based upon the amount of trace data you’re collecting) and, by also expanding the scale from x1 to x64 to zero in on the code area of interest, can now see the flow back to PciHostBridgeEnumerator():
The ReportDispatcher() code is to the right of the Trace discontinuity white gap (callback function) and the PCI routines about to do the heavy lifting are to the left.
When I did a “Go” on the target and stopped at the next POST code, which happens to be x’95’, the PuTTY console displays the output of the device discovery:
PciBus: Discovered PCI @ [00|00|00] PciBus: Discovered PCI @ [00|00|02] BAR[0]: Type = Mem64; Alignment = 0xFFFFF; Length = 0x100000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0x7FFFFF; Length = 0x800000; Offset = 0x18 BAR[2]: Type = Mem64; Alignment = 0xFFF; Length = 0x200; Offset = 0x20 PciBus: Discovered PCI @ [00|02|00] BAR[0]: Type = Mem64; Alignment = 0xFFFFFF; Length = 0x1000000; Offset = 0x10 BAR[1]: Type = PMem64; Alignment = 0xFFFFFFF; Length = 0x10000000; Offset = 0x18 BAR[2]: Type = Io16; Alignment = 0x3F; Length = 0x40; Offset = 0x20 PciBus: Discovered PCI @ [00|0D|00] BAR[0]: Type = Mem64; Alignment = 0xFFFFFF; Length = 0x1000000; Offset = 0x10 PciBus: Discovered PCI @ [00|0D|01] BAR[0]: Type = Mem64; Alignment = 0x1FFF; Length = 0x2000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 PciBus: Discovered PCI @ [00|0D|02] BAR[0]: Type = Mem32; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 PciBus: Discovered PCI @ [00|0D|03] BAR[0]: Type = Mem64; Alignment = 0x1FFF; Length = 0x2000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 PciBus: Discovered PCI @ [00|0E|00] BAR[0]: Type = Mem64; Alignment = 0x3FFF; Length = 0x4000; Offset = 0x10 BAR[3]: Type = Mem64; Alignment = 0xFFFFF; Length = 0x100000; Offset = 0x20 PciBus: Discovered PCI @ [00|0F|00] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 PciBus: Discovered PCI @ [00|0F|01] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 PciBus: Discovered PCI @ [00|0F|02] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 PciBus: Discovered PCI @ [00|12|00] BAR[0]: Type = Mem32; Alignment = 0x1FFF; Length = 0x2000; Offset = 0x10 BAR[1]: Type = Mem32; Alignment = 0xFFF; Length = 0x100; Offset = 0x14 BAR[2]: Type = Io16; Alignment = 0x7; Length = 0x8; Offset = 0x18 BAR[3]: Type = Io16; Alignment = 0x3; Length = 0x4; Offset = 0x1C BAR[4]: Type = Io16; Alignment = 0x1F; Length = 0x20; Offset = 0x20 BAR[5]: Type = Mem32; Alignment = 0xFFF; Length = 0x800; Offset = 0x24 PciBus: Discovered PPB @ [00|13|00] PciBus: Discovered PPB @ [00|13|02] PciBus: Discovered PCI @ [02|00|00] BAR[0]: Type = Io32; Alignment = 0xFF; Length = 0x100; Offset = 0x10 BAR[2]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 BAR[3]: Type = PMem64; Alignment = 0x3FFF; Length = 0x4000; Offset = 0x20 PciBus: Discovered PPB @ [00|13|03] PciBus: Discovered PPB @ [00|14|00] PciBus: Discovered PPB @ [00|14|01] PciBus: Discovered PCI @ [00|15|00] BAR[0]: Type = Mem64; Alignment = 0xFFFF; Length = 0x10000; Offset = 0x10 PciBus: Discovered PCI @ [00|16|00] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 PciBus: Discovered PCI @ [00|16|01] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 PciBus: Discovered PCI @ [00|16|02] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 PciBus: Discovered PCI @ [00|16|03] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 PciBus: Discovered PCI @ [00|17|00] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 PciBus: Discovered PCI @ [00|17|01] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 PciBus: Discovered PCI @ [00|17|02] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 PciBus: Discovered PCI @ [00|17|03] BAR[0]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x10 BAR[1]: Type = Mem64; Alignment = 0xFFF; Length = 0x1000; Offset = 0x18 PciBus: Discovered PCI @ [00|18|00]
All of which makes sense!
Remember that I’m using SourcePoint to access the Apollo Lake target using Intel’s Direct Connect Interface (DCI) interface, and not native XDP. So, there’s no need for a dedicated hardware probe; just use the specialty USB cable, and you’re in.
This is lots of fun! I’ll definitely be investigating this more deeply using SourcePoint and writing about it again.
