/** @file Default instance of MemLogLib library for simple log services to memory buffer. **/ #include #include #include #include #include #include #include #include #include #include #include #include #include "GenericIch.h" #include // // 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; #ifdef JIEF_DEBUG if (0) { #else if (Timing) { #endif // // 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; // // Write to standard debug device also // // Jief : use SerialPortWrite instead of DebugPrint to avoid 256 chars message length limitation. // Jief : do this before CallBack to preserve order of messages sent from inside callback. SerialPortWrite((UINT8*)LastMessage, mMemLog->Cursor - LastMessage); // DebugPrint(DEBUG_INFO, "%a", LastMessage); // // Pass this last message to callback if defined // if (mMemLog->Callback != NULL) { mMemLog->Callback(DebugMode, 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; } /** Sets callback that will be called when message is added to mem log. **/ MEM_LOG_CALLBACK EFIAPI GetMemLogCallback () { return mMemLog->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; #ifdef JIEF_DEBUG vprintf_with_callback_timestamp_emitcr(Format, Marker, transmitS8Printf, NULL, &printfNewline, 0, 1); #else vprintf_with_callback_timestamp_emitcr(Format, Marker, transmitS8Printf, NULL, &printfNewline, Timing, 1); #endif size_t DataWritten = mMemLog->Cursor - 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. // Jief : do this before CallBack to preserve order of messages sent from inside callback. SerialPortWrite((UINT8*)(mMemLog->Buffer + LastMessage), DataWritten); // DebugPrint(DEBUG_INFO, "%a", LastMessage); // // Pass this last message to callback if defined // if (mMemLog->Callback != NULL) { mMemLog->Callback(DebugMode, mMemLog->Buffer + 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); }