From c06ad33ed2fbbacdba42baf07f5d3fd41b36781d Mon Sep 17 00:00:00 2001 From: darylm503 Date: Fri, 23 Apr 2010 17:00:32 +0000 Subject: Libraries and utilities for instrumenting regions of code and measuring their performance. git-svn-id: https://edk2.svn.sourceforge.net/svnroot/edk2/trunk/edk2@10417 6f19259b-4bc3-4df7-8a09-765794883524 --- PerformancePkg/Dp_App/DpTrace.c | 681 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 681 insertions(+) create mode 100644 PerformancePkg/Dp_App/DpTrace.c (limited to 'PerformancePkg/Dp_App/DpTrace.c') diff --git a/PerformancePkg/Dp_App/DpTrace.c b/PerformancePkg/Dp_App/DpTrace.c new file mode 100644 index 0000000000..fdbd860d43 --- /dev/null +++ b/PerformancePkg/Dp_App/DpTrace.c @@ -0,0 +1,681 @@ +/** @file + * Trace reporting for the Dp utility. + * + * Copyright (c) 2009-2010, Intel Corporation. All rights reserved.
+ * 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 +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include + +#include "Dp.h" +#include "Literals.h" +#include "DpInternal.h" + +/** Collect verbose statistics about the logged performance measurements. + * + * General Summary information for all Trace measurements is gathered and + * stored within the SummaryData structure. This information is both + * used internally by subsequent reporting functions, and displayed + * at the end of verbose reports. + * + * @pre The SummaryData and CumData structures must be initialized + * prior to calling this function. + * + * @post The SummaryData and CumData structures contain statistics for the + * current performance logs. +**/ +VOID +GatherStatistics( + VOID +) +{ + MEASUREMENT_RECORD Measurement; + UINT64 Duration; + UINTN LogEntryKey; + UINTN TIndex; + + LogEntryKey = 0; + while ((LogEntryKey = GetPerformanceMeasurement ( + LogEntryKey, + &Measurement.Handle, + &Measurement.Token, + &Measurement.Module, + &Measurement.StartTimeStamp, + &Measurement.EndTimeStamp)) != 0) + { + ++SummaryData.NumTrace; // Count the number of TRACE Measurement records + if (Measurement.EndTimeStamp == 0) { + ++SummaryData.NumIncomplete; // Count the incomplete records + continue; + } + + if (Measurement.Handle != NULL) { + ++SummaryData.NumHandles; // Count the number of measurements with non-NULL handles + } + + if (IsPhase( &Measurement)) { + ++SummaryData.NumSummary; // Count the number of major phases + } + else { // !IsPhase(... + if(Measurement.Handle == NULL) { + ++SummaryData.NumGlobal; + } + } + + if (AsciiStrnCmp (Measurement.Token, ALit_PEIM, PERF_TOKEN_LENGTH) == 0) { + ++SummaryData.NumPEIMs; // Count PEIM measurements + } + + Duration = GetDuration (&Measurement); + TIndex = GetCumulativeItem (&Measurement); + if (TIndex >= 0) { + CumData[TIndex].Duration += Duration; + CumData[TIndex].Count++; + if ( Duration < CumData[TIndex].MinDur ) { + CumData[TIndex].MinDur = Duration; + } + if ( Duration > CumData[TIndex].MaxDur ) { + CumData[TIndex].MaxDur = Duration; + } + } + } +} + +/** Gather and print ALL Trace Records. + * + * Displays all "interesting" Trace measurements in order.
+ * The number of records displayed is controlled by: + * - records with a duration less than mInterestThreshold microseconds are not displayed. + * - No more than Limit records are displayed. A Limit of zero will not limit the output. + * - If the ExcludeFlag is TRUE, records matching entries in the CumData array are not + * displayed. + * + * @pre The mInterestThreshold global variable is set to the shortest duration to be printed. + * The mGaugeString and mUnicodeToken global arrays are used for temporary string storage. + * They must not be in use by a calling function. + * + * @param[in] Limit The number of records to print. Zero is ALL. + * @param[in] ExcludeFlag TRUE to exclude individual Cumulative items from display. + * +**/ +VOID +DumpAllTrace( + IN UINTN Limit, + IN BOOLEAN ExcludeFlag + ) +{ + MEASUREMENT_RECORD Measurement; + UINT64 ElapsedTime; + UINT64 Duration; + const CHAR16 *IncFlag; + UINTN LogEntryKey; + UINTN Count; + UINTN Index; + UINTN TIndex; + + EFI_HANDLE *HandleBuffer; + UINTN Size; + EFI_HANDLE TempHandle; + EFI_STATUS Status; + + IncFlag = HiiGetString (gHiiHandle, STRING_TOKEN (STR_DP_SECTION_ALL), NULL); + PrintToken( STRING_TOKEN (STR_DP_SECTION_HEADER), + (IncFlag == NULL) ? ALit_UNKNOWN: IncFlag); + + // Get Handle information + // + Size = 0; + HandleBuffer = NULL; + Status = gBS->LocateHandle (AllHandles, NULL, NULL, &Size, &TempHandle); + if (Status == EFI_BUFFER_TOO_SMALL) { + HandleBuffer = AllocatePool (Size); + ASSERT (HandleBuffer != NULL); + Status = gBS->LocateHandle (AllHandles, NULL, NULL, &Size, HandleBuffer); + } + if (EFI_ERROR (Status)) { + PrintToken (STRING_TOKEN (STR_DP_HANDLES_ERROR), Status); + } + else { + // We have successfully populated the HandleBuffer + // Display ALL Measurement Records + // Up to Limit lines displayed + // Display only records with Elapsed times >= mInterestThreshold + // Display driver names in Module field for records with Handles. + // + PrintToken (STRING_TOKEN (STR_DP_ALL_HEADR) ); + PrintToken (STRING_TOKEN (STR_DP_DASHES) ); + + LogEntryKey = 0; + Count = 0; + Index = 0; + while ( WITHIN_LIMIT(Count, Limit) && + ((LogEntryKey = GetPerformanceMeasurement ( + LogEntryKey, + &Measurement.Handle, + &Measurement.Token, + &Measurement.Module, + &Measurement.StartTimeStamp, + &Measurement.EndTimeStamp)) != 0) + ) + { + ++Index; // Count every record. First record is 1. + ElapsedTime = 0; + if (Measurement.EndTimeStamp != 0) { + Duration = GetDuration (&Measurement); + ElapsedTime = DurationInMicroSeconds ( Duration ); + IncFlag = STR_DP_COMPLETE; + } + else { + IncFlag = STR_DP_INCOMPLETE; // Mark incomplete records + } + if ((ElapsedTime < mInterestThreshold) || + ((ExcludeFlag) && (GetCumulativeItem(&Measurement) >= 0)) + ) { // Ignore "uninteresting" or excluded records + continue; + } + if (Measurement.EndTimeStamp == 0) { + ElapsedTime = Measurement.StartTimeStamp; + } + ++Count; // Count the number of records printed + + // If Handle is non-zero, see if we can determine a name for the driver + AsciiStrToUnicodeStr (Measurement.Module, mGaugeString); // Use Module by default + AsciiStrToUnicodeStr (Measurement.Token, mUnicodeToken); + if (Measurement.Handle != NULL) { + // See if the Handle is in the HandleBuffer + for (TIndex = 0; TIndex < (Size / sizeof(HandleBuffer[0])); TIndex++) { + if (Measurement.Handle == HandleBuffer[TIndex]) { + GetNameFromHandle (HandleBuffer[TIndex]); + break; + } + } + } + // Ensure that the argument strings are not too long. + mGaugeString[31] = 0; + mUnicodeToken[18] = 0; + + PrintToken( STRING_TOKEN (STR_DP_ALL_STATS), + Index, // 1 based, Which measurement record is being printed + IncFlag, + Measurement.Handle, + mGaugeString, + mUnicodeToken, + ElapsedTime + ); + } + } + FreePool (HandleBuffer); +} + +/** Gather and print Raw Trace Records. + * + * All Trace measurements with a duration greater than or equal to + * mInterestThreshold are printed without interpretation. + * + * The number of records displayed is controlled by: + * - records with a duration less than mInterestThreshold microseconds are not displayed. + * - No more than Limit records are displayed. A Limit of zero will not limit the output. + * - If the ExcludeFlag is TRUE, records matching entries in the CumData array are not + * displayed. + * + * @pre The mInterestThreshold global variable is set to the shortest duration to be printed. + * + * @param[in] Limit The number of records to print. Zero is ALL. + * @param[in] ExcludeFlag TRUE to exclude individual Cumulative items from display. + * +**/ +VOID +DumpRawTrace( + IN UINTN Limit, + IN BOOLEAN ExcludeFlag + ) +{ + MEASUREMENT_RECORD Measurement; + UINT64 ElapsedTime; + UINT64 Duration; + UINTN LogEntryKey; + UINTN Count; + UINTN Index; + + EFI_STRING StringPtr; + + StringPtr = HiiGetString (gHiiHandle, STRING_TOKEN (STR_DP_SECTION_RAWTRACE), NULL); + PrintToken( STRING_TOKEN (STR_DP_SECTION_HEADER), + (StringPtr == NULL) ? ALit_UNKNOWN: StringPtr); + + PrintToken (STRING_TOKEN (STR_DP_RAW_HEADR) ); + PrintToken (STRING_TOKEN (STR_DP_RAW_DASHES) ); + + LogEntryKey = 0; + Count = 0; + Index = 0; + while ( WITHIN_LIMIT(Count, Limit) && + ((LogEntryKey = GetPerformanceMeasurement ( + LogEntryKey, + &Measurement.Handle, + &Measurement.Token, + &Measurement.Module, + &Measurement.StartTimeStamp, + &Measurement.EndTimeStamp)) != 0) + ) + { + ++Index; // Count every record. First record is 1. + ElapsedTime = 0; + if (Measurement.EndTimeStamp != 0) { + Duration = GetDuration (&Measurement); + ElapsedTime = DurationInMicroSeconds ( Duration ); + } + if ((ElapsedTime < mInterestThreshold) || + ((ExcludeFlag) && (GetCumulativeItem(&Measurement) >= 0)) + ) { // Ignore "uninteresting" or Excluded records + continue; + } + ++Count; // Count the number of records printed + PrintToken (STRING_TOKEN (STR_DP_RAW_VARS), + Index, // 1 based, Which measurement record is being printed + Measurement.Handle, + Measurement.StartTimeStamp, + Measurement.EndTimeStamp, + Measurement.Token, + Measurement.Module + ); + } +} + +/** Gather and print Major Phase metrics. + * + * @param[in] Ticker The timer value for the END of Shell phase + * +**/ +VOID +ProcessPhases( + UINT64 Ticker + ) +{ + MEASUREMENT_RECORD Measurement; + UINT64 BdsTimeoutValue = 0; + UINT64 SecTime = 0; + UINT64 PeiTime = 0; + UINT64 DxeTime = 0; + UINT64 BdsTime = 0; + UINT64 ShellTime = 0; + UINT64 ElapsedTime; + UINT64 Duration; + UINT64 Total; + EFI_STRING StringPtr; + UINTN LogEntryKey; + + // + // Get Execution Phase Statistics + // + StringPtr = HiiGetString (gHiiHandle, STRING_TOKEN (STR_DP_SECTION_PHASES), NULL); + PrintToken( STRING_TOKEN (STR_DP_SECTION_HEADER), + (StringPtr == NULL) ? ALit_UNKNOWN: StringPtr); + + LogEntryKey = 0; + while ((LogEntryKey = GetPerformanceMeasurement ( + LogEntryKey, + &Measurement.Handle, + &Measurement.Token, + &Measurement.Module, + &Measurement.StartTimeStamp, + &Measurement.EndTimeStamp)) != 0) + { + if (AsciiStrnCmp (Measurement.Token, ALit_SHELL, PERF_TOKEN_LENGTH) == 0) { + Measurement.EndTimeStamp = Ticker; + } + if (Measurement.EndTimeStamp == 0) { // Skip "incomplete" records + continue; + } + Duration = GetDuration (&Measurement); + if ( Measurement.Handle != NULL + && (AsciiStrnCmp (Measurement.Token, ALit_BdsTO, PERF_TOKEN_LENGTH) == 0) + ) + { + BdsTimeoutValue = Duration; + } else if (AsciiStrnCmp (Measurement.Token, ALit_SEC, PERF_TOKEN_LENGTH) == 0) { + SecTime = Duration; + } else if (AsciiStrnCmp (Measurement.Token, ALit_PEI, PERF_TOKEN_LENGTH) == 0) { + PeiTime = Duration; + } else if (AsciiStrnCmp (Measurement.Token, ALit_DXE, PERF_TOKEN_LENGTH) == 0) { + DxeTime = Duration; + } else if (AsciiStrnCmp (Measurement.Token, ALit_BDS, PERF_TOKEN_LENGTH) == 0) { + BdsTime = Duration; + } else if (AsciiStrnCmp (Measurement.Token, ALit_SHELL, PERF_TOKEN_LENGTH) == 0) { + ShellTime = Duration; + } + } + + Total = 0; + + // print SEC phase duration time + // + if (SecTime > 0) { + ElapsedTime = DurationInMicroSeconds ( SecTime ); // Calculate elapsed time in microseconds + Total += DivU64x32 (ElapsedTime, 1000); // Accumulate time in milliseconds + PrintToken (STRING_TOKEN (STR_DP_SEC_PHASE), ElapsedTime); + } + + // print PEI phase duration time + // + if (PeiTime > 0) { + ElapsedTime = DivU64x32 ( + PeiTime, + (UINT32)TimerInfo.Frequency + ); + Total += ElapsedTime; + PrintToken (STRING_TOKEN (STR_DP_PHASE_DURATION), ALit_PEI, ElapsedTime); + } + + // print DXE phase duration time + // + if (DxeTime > 0) { + ElapsedTime = DivU64x32 ( + DxeTime, + (UINT32)TimerInfo.Frequency + ); + Total += ElapsedTime; + PrintToken (STRING_TOKEN (STR_DP_PHASE_DURATION), ALit_DXE, ElapsedTime); + } + + // print BDS phase duration time + // + if (BdsTime > 0) { + ElapsedTime = DivU64x32 ( + BdsTime, + (UINT32)TimerInfo.Frequency + ); + Total += ElapsedTime; + PrintToken (STRING_TOKEN (STR_DP_PHASE_DURATION), ALit_BDS, ElapsedTime); + } + + if (BdsTimeoutValue > 0) { + ElapsedTime = DivU64x32 ( + BdsTimeoutValue, + (UINT32)TimerInfo.Frequency + ); + PrintToken (STRING_TOKEN (STR_DP_PHASE_BDSTO), ALit_BdsTO, ElapsedTime); + } + + // print SHELL phase duration time + // + if (ShellTime > 0) { + ElapsedTime = DivU64x32 ( + ShellTime, + (UINT32)TimerInfo.Frequency + ); + Total += ElapsedTime; + PrintToken (STRING_TOKEN (STR_DP_PHASE_DURATION), ALit_SHELL, ElapsedTime); + } + + PrintToken (STRING_TOKEN (STR_DP_TOTAL_DURATION), Total); +} + +/** Gather and print Handle data. + * + * @param[in] ExcludeFlag TRUE to exclude individual Cumulative items from display. + * + * @return Status from a call to gBS->LocateHandle(). +**/ +EFI_STATUS +ProcessHandles( + IN BOOLEAN ExcludeFlag + ) +{ + MEASUREMENT_RECORD Measurement; + UINT64 ElapsedTime; + UINT64 Duration; + EFI_HANDLE *HandleBuffer; + EFI_STRING StringPtr; + UINTN Index; + UINTN LogEntryKey; + UINTN Count; + UINTN Size; + EFI_HANDLE TempHandle; + EFI_STATUS Status; + + StringPtr = HiiGetString (gHiiHandle, STRING_TOKEN (STR_DP_SECTION_DRIVERS), NULL); + PrintToken( STRING_TOKEN (STR_DP_SECTION_HEADER), + (StringPtr == NULL) ? ALit_UNKNOWN: StringPtr); + + Size = 0; + HandleBuffer = NULL; + Status = gBS->LocateHandle (AllHandles, NULL, NULL, &Size, &TempHandle); + if (Status == EFI_BUFFER_TOO_SMALL) { + HandleBuffer = AllocatePool (Size); + ASSERT (HandleBuffer != NULL); + Status = gBS->LocateHandle (AllHandles, NULL, NULL, &Size, HandleBuffer); + } + if (EFI_ERROR (Status)) { + PrintToken (STRING_TOKEN (STR_DP_HANDLES_ERROR), Status); + } + else { +#if DP_DEBUG == 2 + Print (L"There are %,d Handles defined.\n", (Size / sizeof(HandleBuffer[0]))); +#endif + + PrintToken (STRING_TOKEN (STR_DP_HANDLE_GUID) ); + PrintToken (STRING_TOKEN (STR_DP_DASHES) ); + + LogEntryKey = 0; + Count = 0; + while ((LogEntryKey = GetPerformanceMeasurement ( + LogEntryKey, + &Measurement.Handle, + &Measurement.Token, + &Measurement.Module, + &Measurement.StartTimeStamp, + &Measurement.EndTimeStamp)) != 0) + { + Count++; + Duration = GetDuration (&Measurement); + ElapsedTime = DurationInMicroSeconds ( Duration ); + if ((ElapsedTime < mInterestThreshold) || + (Measurement.EndTimeStamp == 0) || + (Measurement.Handle == NULL) || + ((ExcludeFlag) && (GetCumulativeItem(&Measurement) >= 0)) + ) { // Ignore "uninteresting" or excluded records + continue; + } + mGaugeString[0] = 0; // Empty driver name by default + AsciiStrToUnicodeStr (Measurement.Token, mUnicodeToken); + // See if the Handle is in the HandleBuffer + for (Index = 0; Index < (Size / sizeof(HandleBuffer[0])); Index++) { + if (Measurement.Handle == HandleBuffer[Index]) { + GetNameFromHandle (HandleBuffer[Index]); // Name is put into mGaugeString + break; + } + } + // Ensure that the argument strings are not too long. + mGaugeString[31] = 0; + mUnicodeToken[18] = 0; + if (mGaugeString[0] != 0) { + // Display the record if it has a valid handle. + PrintToken ( + STRING_TOKEN (STR_DP_HANDLE_VARS), + Count, // 1 based, Which measurement record is being printed + Index + 1, // 1 based, Which handle is being printed + mGaugeString, + mUnicodeToken, + ElapsedTime + ); + } + } + } + FreePool (HandleBuffer); + return Status; +} + +/** Gather and print PEIM data. + * + * Only prints complete PEIM records + * +**/ +VOID +ProcessPeims( + VOID +) +{ + MEASUREMENT_RECORD Measurement; + UINT64 Duration; + UINT64 ElapsedTime; + EFI_STRING StringPtr; + UINTN LogEntryKey; + UINTN TIndex; + + + StringPtr = HiiGetString (gHiiHandle, STRING_TOKEN (STR_DP_SECTION_PEIMS), NULL); + PrintToken( STRING_TOKEN (STR_DP_SECTION_HEADER), + (StringPtr == NULL) ? ALit_UNKNOWN: StringPtr); + + PrintToken (STRING_TOKEN (STR_DP_PEIM_SECTION)); + PrintToken (STRING_TOKEN (STR_DP_DASHES)); + TIndex = 0; + LogEntryKey = 0; + while ((LogEntryKey = GetPerformanceMeasurement ( + LogEntryKey, + &Measurement.Handle, + &Measurement.Token, + &Measurement.Module, + &Measurement.StartTimeStamp, + &Measurement.EndTimeStamp)) != 0) + { + TIndex++; + if ((Measurement.EndTimeStamp == 0) || + (AsciiStrnCmp (Measurement.Token, ALit_PEIM, PERF_TOKEN_LENGTH) != 0) + ) { + continue; + } + + Duration = GetDuration (&Measurement); + ElapsedTime = DurationInMicroSeconds ( Duration ); // Calculate elapsed time in microseconds + if (ElapsedTime >= mInterestThreshold) { + GetNameFromHandle (Measurement.Handle); // Name placed in mGaugeString + PrintToken (STRING_TOKEN (STR_DP_PEIM_STAT2), + TIndex, // 1 based, Which measurement record is being printed + Measurement.Handle, + mGaugeString, + ElapsedTime + ); + } + } +} + +/** Gather and print global data. + * + * Strips out incomplete or "Execution Phase" records + * Only prints records where Handle is NULL + * Increment TIndex for every record, even skipped ones, so that we have an + * indication of every measurement record taken. + * + * +**/ +VOID +ProcessGlobal( + VOID +) +{ + MEASUREMENT_RECORD Measurement; + UINT64 Duration; + UINT64 ElapsedTime; + EFI_STRING StringPtr; + UINTN LogEntryKey; + UINTN Index; // Index, or number, of the measurement record being processed + + StringPtr = HiiGetString (gHiiHandle, STRING_TOKEN (STR_DP_SECTION_GENERAL), NULL); + PrintToken( STRING_TOKEN (STR_DP_SECTION_HEADER), + (StringPtr == NULL) ? ALit_UNKNOWN: StringPtr); + + PrintToken (STRING_TOKEN (STR_DP_GLOBAL_SECTION)); + PrintToken (STRING_TOKEN (STR_DP_DASHES)); + + Index = 1; + LogEntryKey = 0; + + while ((LogEntryKey = GetPerformanceMeasurement ( + LogEntryKey, + &Measurement.Handle, + &Measurement.Token, + &Measurement.Module, + &Measurement.StartTimeStamp, + &Measurement.EndTimeStamp)) != 0) + { + AsciiStrToUnicodeStr (Measurement.Module, mGaugeString); + AsciiStrToUnicodeStr (Measurement.Token, mUnicodeToken); + if ( ! ( IsPhase( &Measurement) || + (Measurement.Handle != NULL) || + (Measurement.EndTimeStamp == 0) + )) + { + Duration = GetDuration (&Measurement); + ElapsedTime = DurationInMicroSeconds ( Duration ); + if (ElapsedTime >= mInterestThreshold) { + PrintToken ( + STRING_TOKEN (STR_DP_FOUR_VARS_2), + Index, + mGaugeString, + mUnicodeToken, + ElapsedTime + ); + } + } + Index++; + } +} + +/** Gather and print cumulative data. + * + * Traverse the measurement records and:
+ * For each record with a Token listed in the CumData array:
+ * - Update the instance count and the total, minimum, and maximum durations. + * Finally, print the gathered cumulative statistics. + * +**/ +VOID +ProcessCumulative( + VOID +) +{ + UINT64 avgval; // the computed average duration + EFI_STRING StringPtr; + UINTN TIndex; + + + StringPtr = HiiGetString (gHiiHandle, STRING_TOKEN (STR_DP_SECTION_CUMULATIVE), NULL); + PrintToken( STRING_TOKEN (STR_DP_SECTION_HEADER), + (StringPtr == NULL) ? ALit_UNKNOWN: StringPtr); + + PrintToken (STRING_TOKEN (STR_DP_CUMULATIVE_SECT_1)); + PrintToken (STRING_TOKEN (STR_DP_CUMULATIVE_SECT_2)); + PrintToken (STRING_TOKEN (STR_DP_DASHES)); + + for ( TIndex = 0; TIndex < NumCum; ++TIndex) { + avgval = DivU64x32 (CumData[TIndex].Duration, CumData[TIndex].Count); + PrintToken (STRING_TOKEN (STR_DP_CUMULATIVE_STATS), + CumData[TIndex].Name, + CumData[TIndex].Count, + DurationInMicroSeconds(CumData[TIndex].Duration), + DurationInMicroSeconds(avgval), + DurationInMicroSeconds(CumData[TIndex].MinDur), + DurationInMicroSeconds(CumData[TIndex].MaxDur) + ); + } +} -- cgit v1.2.3