CloverBootloader/Library/MemLogLibDefault/MemLogLib.c
jief666 5779130ea5 MemLogfVA now use only printf_lite which has better handling of
timestamp at the beginning of lines.
2020-08-26 21:49:49 +03:00

577 lines
16 KiB
C

/** @file
Default instance of MemLogLib library for simple log services to memory buffer.
**/
#include <Uefi.h>
#include <Library/BaseLib.h>
#include <Library/PrintLib.h>
#include <Library/BaseMemoryLib.h>
#include <Library/MemoryAllocationLib.h>
#include <Library/UefiBootServicesTableLib.h>
#include <Library/MemLogLib.h>
#include <Library/DebugLib.h>
#include <Library/SerialPortLib.h>
#include <Library/DebugPrintErrorLevelLib.h>
#include <Library/IoLib.h>
#include <Library/PciLib.h>
#include "GenericIch.h"
#include <Library/printf_lite.h>
//
// Struct for holding mem buffer.
//
typedef struct {
CHAR8 *Buffer;
CHAR8 *Cursor;
UINTN BufferSize;
MEM_LOG_CALLBACK Callback;
/// Start debug ticks.
UINT64 TscStart;
/// Last debug ticks.
UINT64 TscLast;
/// TSC ticks per second.
UINT64 TscFreqSec;
} MEM_LOG;
//
// Guid for internal protocol for publishing mem log buffer.
//
EFI_GUID mMemLogProtocolGuid = { 0x74B91DA4, 0x2B4C, 0x11E2, {0x99, 0x03, 0x22, 0xF0, 0x61, 0x88, 0x70, 0x9B } };
//
// Pointer to mem log buffer.
//
MEM_LOG *mMemLog = NULL;
//
// Buffer for debug time.
//
CHAR8 mTimingTxt[32];
/**
Inits mem log.
@retval EFI_SUCCESS The constructor always returns EFI_SUCCESS.
**/
CHAR8*
GetTiming(VOID)
{
UINT64 dTStartSec;
UINT64 dTStartMs;
UINT64 dTLastSec;
UINT64 dTLastMs;
UINT64 CurrentTsc;
mTimingTxt[0] = '\0';
if (mMemLog != NULL && mMemLog->TscFreqSec != 0) {
CurrentTsc = AsmReadTsc();
dTStartMs = DivU64x64Remainder(MultU64x32(CurrentTsc - mMemLog->TscStart, 1000), mMemLog->TscFreqSec, NULL);
dTStartSec = DivU64x64Remainder(dTStartMs, 1000, &dTStartMs);
dTLastMs = DivU64x64Remainder(MultU64x32(CurrentTsc - mMemLog->TscLast, 1000), mMemLog->TscFreqSec, NULL);
dTLastSec = DivU64x64Remainder(dTLastMs, 1000, &dTLastMs);
AsciiSPrint(mTimingTxt, sizeof(mTimingTxt),
"%ld:%03ld %ld:%03ld", dTStartSec, dTStartMs, dTLastSec, dTLastMs);
mMemLog->TscLast = CurrentTsc;
}
return mTimingTxt;
}
/**
Inits mem log.
@retval EFI_SUCCESS The constructor always returns EFI_SUCCESS.
**/
EFI_STATUS
EFIAPI
MemLogInit (
VOID
)
{
EFI_STATUS Status;
UINT32 TimerAddr = 0;
UINT64 Tsc0, Tsc1;
UINT32 AcpiTick0, AcpiTick1, AcpiTicksDelta, AcpiTicksTarget;
CHAR8 InitError[50];
if (mMemLog != NULL) {
return EFI_SUCCESS;
}
//
// Try to use existing MEM_LOG
//
Status = gBS->LocateProtocol (&mMemLogProtocolGuid, NULL, (VOID **) &mMemLog);
if (Status == EFI_SUCCESS && mMemLog != NULL) {
//
// We are inited with existing MEM_LOG
//
return EFI_SUCCESS;
}
//
// Set up and publish new MEM_LOG
//
mMemLog = AllocateZeroPool( sizeof (MEM_LOG) );
if (mMemLog == NULL) {
return EFI_OUT_OF_RESOURCES;
}
mMemLog->BufferSize = MEM_LOG_INITIAL_SIZE;
mMemLog->Buffer = AllocateZeroPool(MEM_LOG_INITIAL_SIZE);
mMemLog->Cursor = mMemLog->Buffer;
mMemLog->Callback = NULL;
//
// Calibrate TSC for timings
//
InitError[0]='\0';
// We will try to calibrate TSC frequency according to the ACPI Power Management Timer.
// The ACPI PM Timer is running at a universal known frequency of 3579545Hz.
// So, we wait 357954 clocks of the ACPI timer (100ms), and compare with how much TSC advanced.
// This seems to provide a much more accurate calibration than using gBS->Stall(), especially on UEFI machines, and is important as this value is used later to calculate FSBFrequency.
// Check if we can use the timer - we need to be on Intel ICH, get ACPI PM Timer Address from PCI, and check that it's sane
if ((PciRead16 (PCI_ICH_LPC_ADDRESS (0))) != 0x8086) { // Intel ICH device was not found
AsciiSPrint(InitError, sizeof(InitError), "Intel ICH device was not found.");
} else if ((PciRead8 (PCI_ICH_LPC_ADDRESS (R_ICH_LPC_ACPI_CNT)) & B_ICH_LPC_ACPI_CNT_ACPI_EN) == 0) { // Check for TSC at LPC (default location)
/* if ((PciRead8 (PCI_ICH_SMBUS_ADDRESS (R_ICH_SMBUS_ACPI_CNT)) & B_ICH_SMBUS_ACPI_CNT_ACPI_EN) != 0) { // Check for TSC at SMBUS (Skylake specific)
TimerAddr = (PciRead16 (PCI_ICH_SMBUS_ADDRESS (R_ICH_SMBUS_ACPI_BASE)) & B_ICH_SMBUS_ACPI_BASE_BAR) + R_ACPI_PM1_TMR;
} else { */
AsciiSPrint(InitError, sizeof(InitError), "ACPI I/O space is not enabled.");
// }
} else if ((TimerAddr = ((PciRead16 (PCI_ICH_LPC_ADDRESS (R_ICH_LPC_ACPI_BASE))) & B_ICH_LPC_ACPI_BASE_BAR) + R_ACPI_PM1_TMR) == 0) { // Timer address can't be obtained
AsciiSPrint(InitError, sizeof(InitError), "Timer address can't be obtained.");
} else {
// Check that Timer is advancing
AcpiTick0 = IoRead32 (TimerAddr);
gBS->Stall(1000); // 1ms
AcpiTick1 = IoRead32(TimerAddr);
if (AcpiTick0 == AcpiTick1) { // Timer is not advancing
TimerAddr = 0; // Flag it as not working
AsciiSPrint(InitError, sizeof(InitError), "Timer is not advancing.");
}
}
// We prefer to use the ACPI PM Timer when possible. If it is not available we fallback to old method.
if (TimerAddr != 0) { // ACPI PM Timer seems to be working
// ACPI PM timers are usually of 24-bit length, but there are some less common cases of 32-bit length also. When the maximal number is reached, it overflows.
// The code below can handle overflow with AcpiTicksTarget of up to 24-bit size, on both available sizes of ACPI PM Timers (24-bit and 32-bit).
AcpiTicksTarget = V_ACPI_TMR_FREQUENCY/10; // 357954 clocks of ACPI timer (100ms)
AcpiTick0 = IoRead32 (TimerAddr); // read ACPI tick
Tsc0 = AsmReadTsc(); // read TSC
do {
CpuPause();
// check how many AcpiTicks passed since we started
AcpiTick1 = IoRead32 (TimerAddr);
if (AcpiTick0 <= AcpiTick1) { // no overflow
AcpiTicksDelta = AcpiTick1 - AcpiTick0;
} else if (AcpiTick0 - AcpiTick1 <= 0x00FFFFFF) { // overflow, 24-bit timer
AcpiTicksDelta = (0x00FFFFFF - AcpiTick0) + AcpiTick1;
} else { // overflow, 32-bit timer
AcpiTicksDelta = (0xFFFFFFFF - AcpiTick0) + AcpiTick1;
}
} while (AcpiTicksDelta < AcpiTicksTarget); // keep checking Acpi ticks until target is reached
Tsc1 = AsmReadTsc(); // we're done, get another TSC
mMemLog->TscFreqSec = DivU64x32(MultU64x32((Tsc1 - Tsc0), V_ACPI_TMR_FREQUENCY), AcpiTicksDelta);
} else {
// ACPI PM Timer is not working, fallback to old method
Tsc0 = AsmReadTsc();
gBS->Stall(100000); // 100ms
Tsc1 = AsmReadTsc();
mMemLog->TscFreqSec = MultU64x32((Tsc1 - Tsc0), 10);
}
mMemLog->TscStart = Tsc0;
mMemLog->TscLast = Tsc0;
//
// Install (publish) MEM_LOG
//
Status = gBS->InstallMultipleProtocolInterfaces (
&gImageHandle,
&mMemLogProtocolGuid,
mMemLog,
NULL
);
MemLogf(TRUE, 1, "MemLog inited, TSC freq: %lld\n", mMemLog->TscFreqSec);
if (InitError[0] != '\0') {
MemLogf(TRUE, 1, "CPU was calibrated with RTC\n");
} else {
MemLogf(TRUE, 1, "CPU was calibrated with ACPI PM Timer\n");
}
return Status;
}
/**
Prints a log message to memory buffer.
@param Timing TRUE to prepend timing to log.
@param DebugMode DebugMode will be passed to Callback function if it is set.
@param Format The format string for the debug message to print.
@param Marker VA_LIST with variable arguments for Format.
**/
VOID
EFIAPI
MemLogVA (
IN CONST BOOLEAN Timing,
IN CONST INTN DebugMode,
IN CONST CHAR8 *Format,
IN VA_LIST Marker
)
{
EFI_STATUS Status;
UINTN DataWritten;
CHAR8 *LastMessage;
if (Format == NULL) {
return;
}
if (mMemLog == NULL) {
Status = MemLogInit ();
if (EFI_ERROR(Status)) {
return;
}
}
//
// Check if buffer can accept MEM_LOG_MAX_LINE_SIZE chars.
// Increase buffer if not.
//
if ((UINTN)(mMemLog->Cursor - mMemLog->Buffer) + MEM_LOG_MAX_LINE_SIZE > mMemLog->BufferSize) {
UINTN Offset;
// not enough place for max line - make buffer bigger
// but not too big (if something gets out of controll)
if (mMemLog->BufferSize + MEM_LOG_INITIAL_SIZE > MEM_LOG_MAX_SIZE) {
// Out of resources!
return;
}
Offset = mMemLog->Cursor - mMemLog->Buffer;
mMemLog->Buffer = ReallocatePool(mMemLog->BufferSize, mMemLog->BufferSize + MEM_LOG_INITIAL_SIZE, mMemLog->Buffer);
mMemLog->BufferSize += MEM_LOG_INITIAL_SIZE;
mMemLog->Cursor = mMemLog->Buffer + Offset;
}
//
// Add log to buffer
//
LastMessage = mMemLog->Cursor;
if (Timing) {
//
// Write timing only at the beginning of a new line
//
if ((mMemLog->Buffer[0] == '\0') || (mMemLog->Cursor[-1] == '\n')) {
DataWritten = AsciiSPrint(
mMemLog->Cursor,
mMemLog->BufferSize - (mMemLog->Cursor - mMemLog->Buffer),
"%a ",
GetTiming ());
mMemLog->Cursor += DataWritten;
}
}
DataWritten = AsciiVSPrint(
mMemLog->Cursor,
mMemLog->BufferSize - (mMemLog->Cursor - mMemLog->Buffer),
Format,
Marker);
mMemLog->Cursor += DataWritten;
//
// Pass this last message to callback if defined
//
if (mMemLog->Callback != NULL) {
mMemLog->Callback(DebugMode, LastMessage);
}
//
// Write to standard debug device also
//
DebugPrint(DEBUG_INFO, "%a", LastMessage);
}
/**
Prints a log to message memory buffer.
If Format is NULL, then does nothing.
@param Timing TRUE to prepend timing to log.
@param DebugMode DebugMode will be passed to Callback function if it is set.
@param Format The format string for the debug message to print.
@param ... The variable argument list whose contents are accessed
based on the format string specified by Format.
**/
VOID
EFIAPI
MemLog (
IN CONST BOOLEAN Timing,
IN CONST INTN DebugMode,
IN CONST CHAR8 *Format,
...
)
{
VA_LIST Marker;
if (Format == NULL) {
return;
}
VA_START (Marker, Format);
MemLogVA (Timing, DebugMode, Format, Marker);
VA_END (Marker);
}
/**
Returns pointer to MemLog buffer.
**/
CHAR8*
EFIAPI
GetMemLogBuffer (
VOID
)
{
EFI_STATUS Status;
if (mMemLog == NULL) {
Status = MemLogInit ();
if (EFI_ERROR(Status)) {
return NULL;
}
}
return mMemLog != NULL ? mMemLog->Buffer : NULL;
}
/**
Returns the length of log (number of chars written) in mem buffer.
**/
UINTN
EFIAPI
GetMemLogLen (
VOID
)
{
EFI_STATUS Status;
if (mMemLog == NULL) {
Status = MemLogInit ();
if (EFI_ERROR(Status)) {
return 0;
}
}
return mMemLog != NULL ? mMemLog->Cursor - mMemLog->Buffer : 0;
}
/**
Sets callback that will be called when message is added to mem log.
**/
VOID
EFIAPI
SetMemLogCallback (
MEM_LOG_CALLBACK Callback
)
{
EFI_STATUS Status;
if (mMemLog == NULL) {
Status = MemLogInit ();
if (EFI_ERROR(Status)) {
return;
}
}
mMemLog->Callback = Callback;
}
/**
Returns TSC ticks per second.
**/
UINT64
EFIAPI
GetMemLogTscTicksPerSecond (VOID)
{
EFI_STATUS Status;
if (mMemLog == NULL) {
Status = MemLogInit ();
if (EFI_ERROR(Status)) {
return 0;
}
}
return mMemLog->TscFreqSec;
}
// Microsoft wants _fltused
#ifdef _MSC_VER
#ifdef __cplusplus
extern "C" {
#endif
int _fltused=0; // it should be a single underscore since the double one is the mangled name
#ifdef __cplusplus
}
#endif
#endif
static int printfNewline = 1;
static void transmitS8Printf(const char* buf, unsigned int nbchar, void* context)
{
//
// Check if buffer can accept nbchar chars.
// Increase buffer if not.
//
if ( mMemLog->BufferSize - (UINTN)(mMemLog->Cursor - mMemLog->Buffer) <= nbchar )
{
UINTN Offset;
// not enough place for max line - make buffer bigger
// but not too big (if something gets out of controll)
if (mMemLog->BufferSize + MEM_LOG_INITIAL_SIZE > MEM_LOG_MAX_SIZE) {
// Out of resources!
return;
}
Offset = mMemLog->Cursor - mMemLog->Buffer;
mMemLog->Buffer = ReallocatePool(mMemLog->BufferSize, mMemLog->BufferSize + MEM_LOG_INITIAL_SIZE, mMemLog->Buffer);
mMemLog->BufferSize += MEM_LOG_INITIAL_SIZE;
mMemLog->Cursor = mMemLog->Buffer + Offset;
}
CopyMem(mMemLog->Cursor, buf, nbchar);
mMemLog->Cursor += nbchar;
}
const char* printf_lite_get_timestamp()
{
UINT64 dTStartSec;
UINT64 dTStartMs;
UINT64 dTLastSec;
UINT64 dTLastMs;
UINT64 CurrentTsc;
mTimingTxt[0] = '\0';
if (mMemLog != NULL && mMemLog->TscFreqSec != 0) {
CurrentTsc = AsmReadTsc();
dTStartMs = DivU64x64Remainder(MultU64x32(CurrentTsc - mMemLog->TscStart, 1000), mMemLog->TscFreqSec, NULL);
dTStartSec = DivU64x64Remainder(dTStartMs, 1000, &dTStartMs);
dTLastMs = DivU64x64Remainder(MultU64x32(CurrentTsc - mMemLog->TscLast, 1000), mMemLog->TscFreqSec, NULL);
dTLastSec = DivU64x64Remainder(dTLastMs, 1000, &dTLastMs);
snprintf(mTimingTxt, sizeof(mTimingTxt), "%lld:%03lld %lld:%03lld ", dTStartSec, dTStartMs, dTLastSec, dTLastMs);
mMemLog->TscLast = CurrentTsc;
}
return mTimingTxt;
}
/**
Prints a log message to memory buffer.
@param Timing TRUE to prepend timing to log.
@param DebugMode DebugMode will be passed to Callback function if it is set.
@param Format The format string for the debug message to print.
@param Marker VA_LIST with variable arguments for Format.
**/
VOID
EFIAPI
MemLogfVA (
IN CONST BOOLEAN Timing,
IN CONST INTN DebugMode,
IN CONST CHAR8 *Format,
IN VA_LIST Marker
)
{
EFI_STATUS Status;
if (Format == NULL) {
return;
}
if (mMemLog == NULL) {
Status = MemLogInit ();
if (EFI_ERROR(Status)) {
return;
}
}
//
// Add log to buffer
//
UINTN LastMessage = mMemLog->Cursor - mMemLog->Buffer;
vprintf_with_callback_timestamp_emitcr(Format, Marker, transmitS8Printf, NULL, &printfNewline, 1, 1);
size_t DataWritten = mMemLog->Cursor - mMemLog->Buffer - LastMessage;
//
// Pass this last message to callback if defined
//
if (mMemLog->Callback != NULL) {
mMemLog->Callback(DebugMode, mMemLog->Buffer + LastMessage);
}
//
// Check driver debug mask value and global mask
//
if ((DebugMode & GetDebugPrintErrorLevel ()) == 0) {
return;
}
//
// Write to standard debug device also
//
// Jief : use SerialPortWrite instead of DebugPrint to avoid 256 chars message length limitation.
SerialPortWrite((UINT8*)(mMemLog->Buffer + LastMessage), DataWritten);
// DebugPrint(DEBUG_INFO, "%a", LastMessage);
}
/**
Prints a log to message memory buffer.
If Format is NULL, then does nothing.
@param Timing TRUE to prepend timing to log.
@param DebugMode DebugMode will be passed to Callback function if it is set.
@param Format The format string for the debug message to print.
@param ... The variable argument list whose contents are accessed
based on the format string specified by Format.
**/
VOID
EFIAPI
MemLogf (
IN CONST BOOLEAN Timing,
IN CONST INTN DebugMode,
IN CONST CHAR8 *Format,
...
)
{
VA_LIST Marker;
if (Format == NULL) {
return;
}
VA_START (Marker, Format);
MemLogfVA (Timing, DebugMode, Format, Marker);
VA_END (Marker);
}