profiler.c

WinCE5.0部分核心源码

        if (fRet == FALSE) {
            RETAILMSG(1, (TEXT("ProfLockPages : Failed to lock @ 0x%08X\r\n"), lpvAddress));
            return FALSE;
        }
        cbSize -= SECTION_SIZE;
        lpvAddress = (LPVOID) ((DWORD) lpvAddress + SECTION_SIZE);
        pPFNs += PAGES_PER_SECTION;
    }
    return fRet;
}



//------------------------------------------------------------------------------
//------------------------------------------------------------------------------
BOOL
ProfilerAllocBuffer(void)
{
    DWORD dwMemRequest = 0;
    BOOL  fRet;
    DWORD i;
    CALLBACKINFO cbi;

    if (dwProfileBufferMax) {
        //
        // Buffer max was specified in BIB file via FIXUP_VAR
        //
        if (dwProfileBufferMax > PROFILE_BUFFER_MAX) {
            DEBUGMSG(1, (TEXT("dwProfileBufferMax = 0x%08X exceeds limit 0x%08X, fixing.\r\n"), 
                         dwProfileBufferMax, PROFILE_BUFFER_MAX));
            dwMemRequest = PROFILE_BUFFER_MAX;
        } else {
            dwMemRequest = dwProfileBufferMax;
        }
        
        if (dwMemRequest >= (DWORD) (UserKInfo[KINX_PAGEFREE] * PAGE_SIZE)) {
            // Try 3/4 of available RAM
            dwMemRequest = ((UserKInfo[KINX_PAGEFREE] * PAGE_SIZE * 3) / 4) & ~(PAGE_SIZE-1);
            DEBUGMSG(1, (TEXT("dwProfileBufferMax = 0x%08X, but only 0x%08X available, using 0x%08x instead.\r\n"), 
                         dwProfileBufferMax, (UserKInfo[KINX_PAGEFREE] * PAGE_SIZE),
                         dwMemRequest));
        }
    }
    
    if (dwMemRequest == 0) {
        //
        // Default to half the free RAM.
        //
        dwMemRequest = (UserKInfo[KINX_PAGEFREE] * PAGE_SIZE) / 2;
        //
        // Make an upper limit.
        //
        if (dwMemRequest > PROFILE_BUFFER_MAX) {
            dwMemRequest = PROFILE_BUFFER_MAX;
        }
    }
    g_dwProfileBufNumPages   = dwMemRequest / PAGE_SIZE;
    g_dwProfileBufNumEntries = g_dwProfileBufNumPages * ENTRIES_PER_PAGE;

    //
    // Create a shared memory-mapped object
    //
    
    // Need to use callbacks so that the kernel owns the map instead of the app
    
    // CreateFileMapping(INVALID_HANDLE_VALUE, ...);
    cbi.hProc = ProcArray[0].hProc;
    cbi.pfn = (FARPROC)CreateFileMapping;
    cbi.pvArg0 = INVALID_HANDLE_VALUE;
    g_hProfileBuf = (HANDLE)PerformCallBack(&cbi, NULL,
                                            PAGE_READWRITE | SEC_COMMIT, 0,
                                            dwMemRequest, NULL);
    if (!g_hProfileBuf) {
        goto EXIT_FALSE;
    }

    // MapViewOfFile(g_hProfileBuf, ...);
    cbi.pfn = (FARPROC)MapViewOfFile;
    cbi.pvArg0 = g_hProfileBuf;
    g_pdwProfileBufStart = (PDWORD)PerformCallBack(&cbi, FILE_MAP_ALL_ACCESS,
                                                   0, 0, 0);
    if (!g_pdwProfileBufStart) {
        DoFreeBuffer();
        goto EXIT_FALSE;
    }

    //
    // Lock the pages and get the physical addresses.
    //
    fRet = ProfLockPages(g_pdwProfileBufStart, dwMemRequest, (PDWORD) g_pPBE, LOCKFLAG_READ | LOCKFLAG_WRITE);

    if (fRet == FALSE) {
        DoFreeBuffer();
        goto EXIT_FALSE;
    }

    //
    // Convert the physical addresses to statically-mapped virtual addresses
    //
    for (i = 0; i < g_dwProfileBufNumPages; i++) {
        g_pPBE[i] = Phys2Virt((DWORD) g_pPBE[i]);
    }

    PROFILEMSG(1, (TEXT("ProfileStart() : Allocated %d kB for Profiler Buffer (0x%08X)\r\n"), dwMemRequest >> 10, g_pdwProfileBufStart));
    return TRUE;

EXIT_FALSE:
    PROFILEMSG(1, (TEXT("ProfileStart() : Error allocating buffer... defaulting to symbol lookup in ISR.\r\n")));
    return FALSE;
}


//------------------------------------------------------------------------------
//
// Takes a raw index and looks up the tiered entry pointer.
//
//------------------------------------------------------------------------------
static _inline PPROFBUFENTRY
GetEntryPointer(
    DWORD dwIndex
    )
{
    DWORD dwPage, dwEntry;

    dwPage  = dwIndex >> PROF_PAGE_SHIFT;
    dwEntry = dwIndex & PROF_ENTRY_MASK;

    return (&(g_pPBE[dwPage][dwEntry]));
}


/*
 *  ClearProfileHits - zero all profiler counters
 *
 */
void ClearProfileHits(void)
{
    unsigned int iMod;
    PROFentry   *profptr;
    SYMentry    *symptr;
    unsigned int iSym;

    g_ProfilerState_dwSamplesRecorded = 0;
    g_ProfilerState_dwSamplesDropped  = 0;
    g_ProfilerState_dwSamplesInIdle   = 0;

    // If no profile section just return
    if (!pTOC->ulProfileLen)
        return;
    
    profptr = (PROFentry *)pTOC->ulProfileOffset; // profptr-> first profile entry
    for (iMod = 0; iMod < g_dwNumROMModules; iMod++) {
        profptr->ulHits = 0;            // clear module hit count
        if (profptr->ulNumSym) {        // if there are symbols for this module
            // clear symbol hits
            iSym = profptr->ulNumSym;
            symptr = (SYMentry*)profptr->ulHitAddress;
            while (iSym) {
                symptr->ulFuncHits = 0;
                iSym--;
                symptr++;
            }
        }
        profptr++;
    }
}


//------------------------------------------------------------------------------
//  GetSymbol - searches symbol table for passed symbol number
//
//  Input:  lpSym - pointer to start of symbol buffer
//          dwSymNum - symbol number to lookup
//
//  Output: returns pointer to symbol
//------------------------------------------------------------------------------
static LPBYTE GetSymbol(LPBYTE lpSym, DWORD dwSymNum)
{
    while (dwSymNum > 0) {
        while (*lpSym++);
        dwSymNum--;
    }
    return lpSym;
}


// Used to sort symbol hits, copied from SYMentry but ulModuleIndex allows us to
// print faster
typedef struct SortSYMentry {
    ULONG   ulFuncAddress;          // function starting address
    ULONG   ulFuncHits;             // function hit counter
    ULONG   ulModuleIndex;          // index (wrt XIP 1) of module
} SortSYMentry;


//------------------------------------------------------------------------------
//  ProfilerReportHeader - display header for hit report
//------------------------------------------------------------------------------
void ProfilerReportHeader(void)
{
    DWORD dwTotalSamples, dwRecordedSamples, dwNonIdleSamples;
    ULONG ulPercent;

    // Simplify some logic by adding up the totals
    dwTotalSamples    = g_ProfilerState_dwSamplesRecorded + g_ProfilerState_dwSamplesDropped + g_ProfilerState_dwSamplesInIdle;
    dwRecordedSamples = g_ProfilerState_dwSamplesRecorded + g_ProfilerState_dwSamplesInIdle;
    dwNonIdleSamples  = g_ProfilerState_dwSamplesRecorded + g_ProfilerState_dwSamplesDropped;

    if (g_dwProfilerFlags & PROFILE_OBJCALL) {
        PROFILEMSG(1, (TEXT("=================== SYSTEM CALL HIT REPORT ===================\r\n")));
    } else {
        PROFILEMSG(1, (TEXT("=================== MONTE CARLO HIT REPORT ===================\r\n")));
    }

    PROFILEMSG(1, (TEXT("Total samples recorded = %8lu\r\n"), dwRecordedSamples));
    PROFILEMSG(1, (TEXT("Total samples dropped  = %8lu\r\n"), g_ProfilerState_dwSamplesDropped));
    PROFILEMSG(1, (TEXT("Ticks elapsed          = %8lu\r\n"), g_ProfilerState_dwTickCount));
    
    // Object call profiling has no other header info
    if (g_dwProfilerFlags & PROFILE_OBJCALL) {
        return;
    }

    // MONTE CARLO REPORT

    // Print idle report
    PROFILEMSG(1, (TEXT("IDLE TIME:\r\n")));
    PROFILEMSG(1, (TEXT("  * Total non-idle samples (recorded+dropped)        = %8lu\r\n"),
                   dwNonIdleSamples));
    PROFILEMSG(1, (TEXT("  * Total idle samples (recorded+dropped)            = %8lu\r\n"),
                   g_ProfilerState_dwSamplesInIdle));
    if (dwTotalSamples) {  // sanity check for division safety
        ulPercent = g_ProfilerState_dwSamplesInIdle;
        ulPercent *= 1000;
        ulPercent /= dwTotalSamples;
        PROFILEMSG(1, (TEXT("  * Percentage of samples in idle                    = %6lu.%1d\r\n"),
                       ulPercent / 10, ulPercent % 10));
    }

    // Print interrupt report if we have data
    if (g_ProfilerState_dwInterrupts) {
        PROFILEMSG(1, (TEXT("INTERRUPTS:\r\n")));
        PROFILEMSG(1, (TEXT("  * Total interrupts during sample period            = %8lu\r\n"),
                       g_ProfilerState_dwInterrupts));
        PROFILEMSG(1, (TEXT("  * Non-profiler interrupts                          = %8lu\r\n"),
                       g_ProfilerState_dwInterrupts - dwTotalSamples));
        if (g_ProfilerState_dwTickCount) {  // sanity check for division safety
            ulPercent = g_ProfilerState_dwInterrupts - dwTotalSamples;
            ulPercent *= 10;
            ulPercent /= g_ProfilerState_dwTickCount;
            PROFILEMSG(1, (TEXT("  * Non-profiler interrupts per tick                 = %6lu.%1d\r\n"),
                           ulPercent / 10, ulPercent % 10));
        }
    }

    // Print TLB report if we have data.  Only SH and MIPS software TLB miss 
    // handlers produce this data right now, but CPU perf counters could be
    // used for other architectures in the future.
    if ((g_ProfilerState_dwTLBCount) || (g_ProfilerState_dwProfilerIntsInTLB)) {
        PROFILEMSG(1, (TEXT("TLB MISSES:\r\n")));
        
        PROFILEMSG(1, (TEXT("  * Total TLB misses during sample period            = %8lu\r\n"),
                       g_ProfilerState_dwTLBCount));
        if (g_ProfilerState_dwTickCount) {  // sanity check for division safety
            ulPercent = g_ProfilerState_dwTLBCount;
            ulPercent *= 10;
            ulPercent /= g_ProfilerState_dwTickCount;
            PROFILEMSG(1, (TEXT("  * TLB misses per tick                              = %6lu.%1d\r\n"),
                           ulPercent / 10, ulPercent % 10));
        }

        // Only display profiler hits in TLB miss handler if we got any.  If
        // this data can't be gathered on this processor, we shouldn't
        // erroneously report that there were no hits during TLB miss handling.
        if (g_ProfilerState_dwProfilerIntsInTLB) {
            PROFILEMSG(1, (TEXT("  * Profiler samples during TLB miss handler         = %8lu\r\n"),
                           g_ProfilerState_dwProfilerIntsInTLB));
            if (dwTotalSamples) {  // sanity check for division safety
                ulPercent = g_ProfilerState_dwProfilerIntsInTLB;
                ulPercent *= 1000;
                ulPercent /= dwTotalSamples;
                PROFILEMSG(1, (TEXT("  * Percentage of samples in TLB miss handler        = %6lu.%1d\r\n"),
                               ulPercent / 10, ulPercent % 10));
            }
        }
    }
}


//------------------------------------------------------------------------------
//  ProfilerReport - display hit report
//------------------------------------------------------------------------------
void ProfilerReport(void)
{
    ROMChain_t *pROM;                    // Chain of ROM XIP regions
    DWORD      loop, loop2;              // index
    PROFentry *pProf;                    // profile section pointer
    DWORD      dwModCount, dwSymCount, dwCount;  // number of symbols hit
    ULONG      ulPercent;                // hit percentage
    DWORD      dwModIndex, dwNumModules; // number of modules in ROM
    SYMentry  *pSym;                     // symbol address/hit pointer
    SortSYMentry *pHits = NULL;          // Sorted list of function hits
    SortSYMentry  symTemp;               // sorting temp
    TOCentry  *tocptr;
    DWORD      dwHits[NUM_MODULES], dwMods[NUM_MODULES], dwTemp;  // Sorted list of module hits
    PPROFBUFENTRY pEntry;
    DWORD      dwTotalSamples, dwRecordedSamples;

    #define IDLE_SIGNATURE ((DWORD)-1)
    
    // Simplify some logic by adding up the totals
    dwTotalSamples    = g_ProfilerState_dwSamplesRecorded + g_ProfilerState_dwSamplesDropped + g_ProfilerState_dwSamplesInIdle;
    dwRecordedSamples = g_ProfilerState_dwSamplesRecorded + g_ProfilerState_dwSamplesInIdle;
    
    if (!dwTotalSamples) {
        PROFILEMSG(1, (TEXT("Kernel Profiler: No hits recorded.  Make sure profiling\r\n")));
        PROFILEMSG(1, (TEXT("is implemented in the OAL, and the profiler was started.\r\n")));
        goto profile_exit;
    }

    // If profiling to buffer, lookup symbols now
    if (g_dwProfilerFlags & PROFILE_BUFFER) {
        PROFILEMSG(1, (TEXT("Kernel Profiler: Looking up symbols for %u hits.\r\n"), g_ProfilerState_dwSamplesRecorded));
        for (loop = 0; loop < g_ProfilerState_dwSamplesRecorded; loop++) {
            if (loop % 10000 == 0)    // display a . every 10000 hits, so user knows we are working
                PROFILEMSG(1, (TEXT(".")));

            pEntry = GetEntryPointer(loop);