windows-xp/Source/XPSP1/NT/com/ole32/common/lockperf.cxx

//+-----------------------------------------------------------------------------
//
//  File:       lockperf.cxx
//
//  Contents:   Implementation of lock monitoring for locks used by ole32.dll
//
//  Classes:    CLockPerfTracker
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
#if LOCK_PERF==1

#include <ole2int.h>
#include <lockperf.hxx>

// gbLockPerf == (Is lock monitoring ON?) 
// (It is possible to turn this on & off multiple times during a single test run.)
// Ideally, it would be good to turn it OFF after proc-attach, let the test
// run for a while and then turn it ON. This will get the startup skew out of
// the way.
BOOL gbLockPerf = TRUE;

// Lock perf tracker. Gathers perf measurements for all locks.
CLockPerfTracker gLockTracker;    

// static member table of the global tracker class.
CFileLineEntry CLockPerfTracker::_FileLineData[MAX_LOCKPERF_FILEENTRY];

// static member table of the global tracker: this keeps a track of shared time.
CLockEntry CLockPerfTracker::_LockData[MAX_LOCKS];

// counts of locks & {file,line} instances tracked.
ULONG CLockPerfTracker::_numLocks;
ULONG CLockPerfTracker::_numCritSecs;

// perf frequency on the system
LARGE_INTEGER CLockPerfTracker::_liFreq;

//Flagged if tables get full
BOOL    gbLockPerfOverflow=FALSE;

//Count of entries in the shared table (code critical sections)
LONG    glFileLine = 0;

//Strings to used to print report
LPSTR   gszLockPerfErr = "##### Error: LockPerfOverFlow!!";
char    gszLockPerfBuf[256];

//Used to debug the perf monitoring code.
#define perfPrint(x)
#if DBG==1
#define LockAssert(X)   if (!(X)) wsprintfA(gszLockPerfBuf,#X ## "\n"),OutputDebugStringA(gszLockPerfBuf);
#else
#define LockAssert(X)
#endif




// **** Functions to manage the Private TLS used by LockPerf *********

// Heap Handle (copied from tls.cxx)
extern  HANDLE    g_hHeap;
#define HEAP_SERIALIZE 0

DWORD gTlsLockPerfIndex = 0xFFFFFFFF;

//345678901234567890123456789012345678901234567890123456789012345678901234567890
//+-----------------------------------------------------------------------------
//
//  Function:   AllocLockPerfPvtTlsData
//
//  Synopsis:   Allocates the Tls data for a thread (at Thread_Attach)
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------

HRESULT AllocLockPerfPvtTlsData()
{
    void *pMem =  HeapAlloc(g_hHeap, 
                            HEAP_SERIALIZE, 
                            TLS_LOCKPERF_MAX*sizeof(CTlsLockPerf));
    if (!pMem)
    {
        LockAssert(!"Could not alloc private Tls data for LockPerf");
        return E_OUTOFMEMORY;
    }
    LockAssert(gTlsLockPerfIndex!=0xFFFFFFFF);
    memset(pMem, 0, TLS_LOCKPERF_MAX*sizeof(CTlsLockPerf));
    
    TlsSetValue(gTlsLockPerfIndex, pMem);
    return S_OK;
}

//+-----------------------------------------------------------------------------
//
//  Function:   FreeLockPerfPvtTlsData
//
//  Synopsis:   Frees the Tls data for a thread (at Thread_Detach)
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
//  REVIEW: What about cases when DllMain is not called with Thread_Detach?

void FreeLockPerfPvtTlsData()
{
    LockAssert(gTlsLockPerfIndex!=0xFFFFFFFF);
    void *pMem = TlsGetValue(gTlsLockPerfIndex); 
    if (pMem) 
    {
        HeapFree(g_hHeap, HEAP_SERIALIZE, pMem);
    }
}

//**** End: TLS functions ********************************************

//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::Init(), public
//
//  Synopsis:   Initializes lock perf data, marking entries as unused.
//              Called during Proc_Attach
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------

HRESULT CLockPerfTracker::Init()
{
    QueryPerformanceFrequency(&_liFreq);
    
    // We use lpLockPtr to tell if an entry in these tables is in-use.
    for (int i=0;i<MAX_LOCKPERF_FILEENTRY;i++)
    {
        _FileLineData[i].lpLockPtr = NULL;
    }
    for (i=0; i<MAX_LOCKS; i++)
    {
        _LockData[i].lpLockPtr = NULL;
    }
    _numLocks = 0;
    _numCritSecs = 0;
    return S_OK;
}


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::RegisterLock(), public
//
//  Synopsis:   Must be called by the lock creation function. 
//                  lpLockPtr   == this-ptr of the lock (or unique ptr)
//                  bReadWrite  == TRUE for Reader-Writer Locks.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------

void CLockPerfTracker::RegisterLock(void *lpLockPtr, BOOL bReadWrite)
{
    BOOL bDone = FALSE;
    int i=0;
    
    while (!bDone)
    {
        while (_LockData[i].lpLockPtr)
        {
            i++;
        }
        LockAssert(i < MAX_LOCKS);
        
        // REVIEW: 64-bit implications of this cast?
        bDone = !(InterlockedCompareExchange((LONG *)&_LockData[i].lpLockPtr, 
                                             (LONG)lpLockPtr, 
                                             NULL));
    }

    _LockData[i].dwTotalWriteWaitTime = 0;
    _LockData[i].dwTotalWriteEntrys = 0;       
    _LockData[i].dwTotalWriteLockTime = 0;
    _LockData[i].pszLockName = NULL;
    
    // REVIEW: These 5 could be skipped for non reader-writer locks?
   _LockData[i].dwSharedTime = 0;
   _LockData[i].dwNumReaders = 0;

   _LockData[i].dwTotalReadWaitTime = 0;
   _LockData[i].dwTotalReadLockTime = 0;
   _LockData[i].dwTotalReadEntrys = 0; 
        
}

//+-----------------------------------------------------------------------------
//
//  Function:   Hash
//
//  Synopsis:   Maps line #s to index in the perf data table.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
ULONG Hash (ULONG line)
{
    //  buckets of 256, 128, 64, 64 totaling to MAX_LOCKPERF_FILEENTRY
    //  this was based on a grep in Ole32 tree for LOCK macro (Sep98):
    //  Call counts: 
    //                              137 from   1 - 1024
    //                              92 from 1024 - 2048
    //                              45 from 2048 - 3072
    //                              28 from 3072 - 4096
    //                              10 from 4096 - 5120
    //                              11 from 5124 - 6144
    //                               8 from 6148 - 7168
    //  highest lineNum was 6872 in marshal.cxx
    //  The Hash function & array size may need updating if the highest lineNum
    //  goes beyond 7176 or if any bucket gets maxed out.

    ULONG base, offset;
    if (line < 1024)
    {
        base = 0;
        offset = line>>2;           //0 to 255
    }
    else if (line < 2048)
    {
        base = 256;
        offset = (line-1024)>>3;    //0 to 127
    }
    else if (line < 3072)
    {
        base = 384;
        offset = (line-2048)>>4;    //0 to 63
    }
    else
    {      //this covers lines from 3072 to 7168
        base = 448;
        offset = (line-3072)>>6;    //0 to 63
    }
    return base+offset;
}



//+-----------------------------------------------------------------------------
//
//  Function:   GetTlsLockPerfEntry
//
//  Synopsis:   Finds the entry in Tls for a lock or returns a free entry
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
CTlsLockPerf *GetTlsLockPerfEntry(void *lpLockPtr)
{
    CTlsLockPerf *lpEntry = NULL, *lpFree = NULL;
    
    CTlsLockPerf *lpCurrent = (CTlsLockPerf *)TlsGetValue(gTlsLockPerfIndex);
    for (int i=0; i<TLS_LOCKPERF_MAX; i++)
    {
        if (lpCurrent->_dwFlags & TLS_LOCKPERF_INUSE)
        {
            if (lpCurrent->_lpLockPtr == lpLockPtr)
            {
                lpEntry = lpCurrent;
                break;
            }
        }
        else if (!lpFree)
        {
            // Remember the first free entry in case we need it.
            lpFree = lpCurrent;
        }
        lpCurrent++;
    }
    return (lpEntry!=NULL) ? lpEntry : lpFree;
}


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::ReaderWaiting(), public
//
//  Synopsis:   Called by the lock code when a thread attempts to enter
//              a critical section for reading.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::ReaderWaiting(const char*pszFile, 
                                     DWORD dwLine, 
                                     const char* pszLockName, 
                                     void *lpLockPtr)
{
    if (gbLockPerf)
    {
        // Just call WriterWaiting till we need different semantics...
        WriterWaiting(pszFile, 
                      dwLine, 
                      pszLockName, 
                      lpLockPtr, FALSE /*bWriter*/);
    }
}


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::WriterWaiting(), public
//
//  Synopsis:   Called by the lock code when a thread attempts to enter
//              a critical section for writing.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::WriterWaiting(const char*pszFile, 
                                     DWORD dwLine, 
                                     const char* pszLockName, 
                                     void *lpLockPtr, 
                                     BOOL bWriter /*default TRUE*/)
{
    if (gbLockPerf)
    {  
        CTlsLockPerf *pTlsLP = GetTlsLockPerfEntry(lpLockPtr);

        // Will assert if we are getting more than TLS_LOCKPERF_MAX
        // locks one after another without releasing any.
        LockAssert(pTlsLP);    
    
        if (pTlsLP->_dwFlags & TLS_LOCKPERF_INUSE)         
        {   
            // Recursion on the lock. Request for the lock while holding it.
            // Can't be waiting recursively!
            LockAssert(pTlsLP->_dwFlags & TLS_LOCKPERF_ENTERED); 
        }
        else
        {
            ULONG idx;
            ULONG loc = FindOrCreateFileTableEntry(pszFile, 
                                                   dwLine, 
                                                   pszLockName, 
                                                   lpLockPtr, 
                                                   bWriter, 
                                                   &idx);

            LockAssert(loc <  MAX_LOCKPERF_FILEENTRY);
    
            //save table indices in TLS, for quick access later.
            pTlsLP->_loc = loc;
            pTlsLP->_idx = idx;
            pTlsLP->_lpLockPtr = lpLockPtr;
            pTlsLP->_dwFlags = TLS_LOCKPERF_WAITING | TLS_LOCKPERF_INUSE; //new Tls entry!
            pTlsLP->_dwRecursion = 0;   //we set this to 1 upon the first xxxEntered
    
            //store request time in TLS (last thing done to not skew lock wait/use times)
            QueryPerformanceCounter(&pTlsLP->_liRequest);
        }
    }
}


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::ReaderEntered(), public
//
//  Synopsis:   Called by lock code when a thread is granted access to 
//              a critical section for reading. 
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
//  REVIEW: Life will be easier for us if we enforce that the lock code 
//  must detect and inform if this is the first reader in the critical 
//  section. (Similarly for the last reader leaving.)
//------------------------------------------------------------------------------
void CLockPerfTracker::ReaderEntered(const char*pszFile, 
                                     DWORD dwLine, 
                                     const char* pszLockName, 
                                     void *lpLockPtr)
{  
    if (gbLockPerf)
    {
        ULONG idx = FindLockTableEntry(lpLockPtr);    
        if (InterlockedIncrement((LONG*)&_LockData[idx].dwNumReaders)==1)
        {
            QueryPerformanceCounter(&_LockData[idx].liEntered);
        }
        // rest of the work is done by WriterEntered
        WriterEntered(pszFile, dwLine, pszLockName, lpLockPtr, /*bWriter*/ FALSE);
    }
}


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::WriterEntered(), public
//
//  Synopsis:   Called by lock code when a thread is granted access to 
//              a critical section for writing.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::WriterEntered(const char*pszFile, 
                                     DWORD dwLine, 
                                     const char* pszLockName, 
                                     void *lpLockPtr, 
                                     BOOL bWriter /*default TRUE*/)
{
    if (gbLockPerf)
    {
        CTlsLockPerf *pTlsLP = GetTlsLockPerfEntry(lpLockPtr);
    
        /*
        // REVIEW: Should we force lock implementation to call ReaderWaiting/WriterWaiting
        // even if there is no reason to wait? In that case the following assertion is true.
        
        // There has to be an entry, either marked waiting or entered (recursive lock)
        LockAssert( pTlsLP && ((pTlsLP->_dwFlags & TLS_LOCKPERF_WAITING) ||  (pTlsLP->_dwFlags & TLS_LOCKPERF_ENTERED)) );
        */

        if (!(pTlsLP->_dwFlags & TLS_LOCKPERF_INUSE))
        {
            // Someone called xxxEntered directly (without calling xxxWaiting)
            ULONG idx;
            ULONG loc = FindOrCreateFileTableEntry(pszFile, 
                                                   dwLine, 
                                                   pszLockName, 
                                                   lpLockPtr, 
                                                   bWriter, 
                                                   &idx);
            LockAssert(loc <  MAX_LOCKPERF_FILEENTRY);
    
            // save the table indices in TLS, for quick access later.
            pTlsLP->_loc = loc;
            pTlsLP->_idx = idx;
            pTlsLP->_lpLockPtr = lpLockPtr;
            pTlsLP->_dwFlags = TLS_LOCKPERF_ENTERED | TLS_LOCKPERF_INUSE;
            pTlsLP->_dwRecursion = 0;
    
            QueryPerformanceCounter(&pTlsLP->_liEntered);
            pTlsLP->_liRequest = pTlsLP->_liEntered;
        }
        else if (pTlsLP->_dwFlags & TLS_LOCKPERF_WAITING)
        {
            QueryPerformanceCounter(&pTlsLP->_liEntered);
            // Not waiting any more.
            pTlsLP->_dwFlags |= TLS_LOCKPERF_ENTERED;
            pTlsLP->_dwFlags &= ~TLS_LOCKPERF_WAITING;
        }
        pTlsLP->_dwRecursion++; // 1 means first level entry (i.e. no recursion)
    }
}


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::ReaderLeaving(), public
//
//  Synopsis:   Called by the lock code when a reader is leaving a critical
//              section.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::ReaderLeaving(void *lpLockPtr)
{
    if (gbLockPerf)
    {
        ULONG idx = FindLockTableEntry(lpLockPtr);
    
        LARGE_INTEGER liEntered = _LockData[idx].liEntered;
        if (InterlockedDecrement((LONG*)&_LockData[idx].dwNumReaders) == 0)
        {   
            // Last reader leaving 
            LARGE_INTEGER liDelta, liRem;
            QueryPerformanceCounter(&liDelta);
        
            liDelta = RtlLargeIntegerSubtract(liDelta, liEntered);
            liDelta = RtlExtendedIntegerMultiply(liDelta,1000000);
            liDelta = RtlLargeIntegerDivide(liDelta, _liFreq, &liRem);
        
            LockAssert(liDelta.HighPart == 0); // no one must hold a lock for so long!
            
            // This must be done inter-locked in case someother thread does 
            // a 0->1, 1->0 transition while one thread is in this block.
            InterlockedExchangeAdd((LONG*)&_LockData[idx].dwSharedTime, 
                                   liDelta.LowPart);
        }
    
        //Call WriterLeaving to do the rest.
        WriterLeaving(lpLockPtr);
    }
}


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::WriterLeaving(), public
//
//  Synopsis:   Called by the lock code when a writer is leaving a critical
//              section.  
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::WriterLeaving(void *lpLockPtr)
{
    if (gbLockPerf)
    {    
        CTlsLockPerf *pTlsLP = GetTlsLockPerfEntry(lpLockPtr); 
    
        // There has be to an entry marked entered!
        LockAssert(pTlsLP && (pTlsLP->_dwFlags & TLS_LOCKPERF_ENTERED));
    
        pTlsLP->_dwRecursion--;
    
        if (pTlsLP->_dwRecursion == 0)
        {   
            // The thread is *really* leaving the lock. Do the math!
            LARGE_INTEGER liUnlockTime;
            QueryPerformanceCounter(&liUnlockTime);
            UpdateFileTableEntry(pTlsLP, &liUnlockTime);
            
            // Mark the Tls entry as free.
            pTlsLP->_dwFlags &= ~TLS_LOCKPERF_INUSE;
        }
        else
        {
            // The thread is still in the lock!
            LockAssert(pTlsLP->_dwFlags & TLS_LOCKPERF_ENTERED);
        }
    }
}


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::ReportContention(), public
//
//  Synopsis:   Must be called by the lock destroy/cleanup function.
//              This is single threaded by definition.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------

void CLockPerfTracker::ReportContention(void *lpLockPtr, 
                                        DWORD dwWriteEntrys, 
                                        DWORD dwWriterContention, 
                                        DWORD dwReadEntrys, 
                                        DWORD dwReaderContention)
{
    // This happens during DLL_PROCESS_DETACH hence single-threaded
    for (int i=0; i<MAX_LOCKS; i++)
    {
        if (_LockData[i].lpLockPtr == lpLockPtr)
        {
            _LockData[i].dwWriterContentionCount = dwWriterContention;
            _LockData[i].dwReaderContentionCount = dwReaderContention;

            // These asserts may not be very useful since some locks are entered 
            // before lock monitoring can be started! Also, monitoring can be
            // turned OFF and ON in windows.

            // LockAssert( _LockData[i].dwTotalWriteEntrys ==  dwWriteEntrys);
            // LockAssert( _LockData[i].dwTotalReadEntrys ==  dwReadEntrys);
            break;
        }
    }
    LockAssert( i<MAX_LOCKS );
}

//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::FindLockTableEntry(), private
//
//  Synopsis:   Finds the entry for a critical section in the lock table.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
ULONG CLockPerfTracker::FindLockTableEntry(void *lpLockPtr)
{
    for (int idx=0; idx<MAX_LOCKS; idx++)
    {
        if (_LockData[idx].lpLockPtr == lpLockPtr)
        {
            return idx;
        }
    }
    LockAssert(!"Lock not registered for monitoring!");
    return MAX_LOCKS-1; // just to avoid AVs
}

//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::FindOrCreateFileTableEntry(), private
//
//  Synopsis:   Finds the entry (or creates one) for a critical section guarded
//              by a lock at a {file, line}.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
ULONG CLockPerfTracker::FindOrCreateFileTableEntry(const char*pszFile, 
                                                   DWORD dwLine, 
                                                   const char* pszLockName, 
                                                   void *lpLockPtr, 
                                                   BOOL bWriter, 
                                                   DWORD *lpLockTableIndex)
{
    BOOL bFoundEntry = FALSE;
    CFileLineEntry *pNewTableEntry  = NULL;
    ULONG loc = Hash(dwLine);

    if (loc >= MAX_LOCKPERF_FILEENTRY)
    {
        LockAssert(!"Lock PerfTable full! Increase size.");
        gbLockPerfOverflow = TRUE;
        loc = MAX_LOCKPERF_FILEENTRY-1;
        goto errRet;
    }

    // If hashing works well this should not take too much time.

    while (!bFoundEntry)
    {
        while (_FileLineData[loc].lpLockPtr && loc<MAX_LOCKPERF_FILEENTRY)
        {
            if ( (_FileLineData[loc].dwLine==dwLine)
                 &&(_FileLineData[loc].pszFile==pszFile) )
            {
                bFoundEntry = TRUE;
                break;  //done
            }
            loc++;
        }
    
        if (loc >= MAX_LOCKPERF_FILEENTRY)
        {
            gbLockPerfOverflow = TRUE;
            loc = MAX_LOCKPERF_FILEENTRY-1;
            goto errRet;
        }
    
        if (!bFoundEntry && !( InterlockedCompareExchange(
                                    (LONG*)&_FileLineData[loc].lpLockPtr, 
                                    (LONG)lpLockPtr, 
                                    NULL) )
           )
        {
            // We are seeing a new critical section in the code base
            bFoundEntry = TRUE;
            pNewTableEntry = &_FileLineData[loc];
            InterlockedIncrement(&glFileLine); // Global count of code CritSec locations
        }
    }

    if (pNewTableEntry)
    {  // finish rest of initialization the entry is secured for this code location.
        // REVIEW: Ignoring races here.
        pNewTableEntry->bWriteCritSec   = bWriter;
        pNewTableEntry->dwNumEntrys     = 0;
        pNewTableEntry->pszLockName     = pszLockName;
        pNewTableEntry->pszFile         = pszFile;
        pNewTableEntry->dwLine          = dwLine;
        pNewTableEntry->dwWaitTime      = 0;
        pNewTableEntry->dwLockedTime    = 0;
        pNewTableEntry->ulLockTableIdx = FindLockTableEntry(lpLockPtr);
    }
errRet:
    *lpLockTableIndex = _FileLineData[loc].ulLockTableIdx;
    return loc;
}


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::UpdateFileTableEntry(), private
//
//  Synopsis:   Adds the waiting time and the locked time for this visit
//              to the cumulative data for the {file,line} entry.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::UpdateFileTableEntry(CTlsLockPerf *pTlsEntry, 
                                            LARGE_INTEGER *pliUnlockTime)
{
    LockAssert( (pTlsEntry->_dwFlags & TLS_LOCKPERF_INUSE)
                && (pTlsEntry->_dwFlags & TLS_LOCKPERF_ENTERED) );

    ULONG idx = pTlsEntry->_idx;
    ULONG loc = pTlsEntry->_loc;

    LockAssert(loc>=0 && loc < MAX_LOCKPERF_FILEENTRY);

    LARGE_INTEGER liRem;

    LARGE_INTEGER liWait = RtlLargeIntegerSubtract(pTlsEntry->_liEntered, 
                                                   pTlsEntry->_liRequest);
    liWait = RtlExtendedIntegerMultiply(liWait,1000000);        
    liWait = RtlLargeIntegerDivide(liWait,_liFreq,&liRem); // liWait is now in micro-seconds

    LockAssert(liWait.HighPart == 0);  // hopefully no one waits for so long!!

    LARGE_INTEGER liLocked = RtlLargeIntegerSubtract(*pliUnlockTime, 
                                                     pTlsEntry->_liEntered);
    liLocked = RtlExtendedIntegerMultiply(liLocked,1000000);
    liLocked = RtlLargeIntegerDivide(liLocked, _liFreq, &liRem);

    LockAssert(liLocked.HighPart == 0); // no one must hold a lock for so long!

    if (_FileLineData[loc].bWriteCritSec)
    {   // Since this is a write location, the lock itself guarantees exclusion
        _FileLineData[loc].dwNumEntrys++;
        _FileLineData[loc].dwWaitTime += liWait.LowPart;  
        _FileLineData[loc].dwLockedTime += liLocked.LowPart;

        /*
        This needs to be here if we wish to compare entry counts reported by
        the lock with our own. For now this is in ProcessPerfData
        _LockData[idx].dwTotalWriteEntrys++;
        _LockData[idx].dwTotalWriteWaitTime += liWait.LowPart;
        _LockData[idx].dwTotalWriteLockTime += liLocked.LowPart;
        */
    }
    else
    {   // This is a read location. 
        // Hence we have to exclude other readers from updating data 
        InterlockedIncrement( (LONG*) &_FileLineData[loc].dwNumEntrys );
        InterlockedExchangeAdd( (LONG*) &_FileLineData[loc].dwWaitTime, liWait.LowPart );  
        InterlockedExchangeAdd( (LONG*) &_FileLineData[loc].dwLockedTime, liLocked.LowPart );

        /*
        This needs to be here if we wish to compare entry counts reported by
        the lock with our own. For now this is in ProcessPerfData
        InterlockedIncrement( (LONG*) &_LockData[idx].dwTotalReadEntrys );
        InterlockedExchangeAdd( (LONG*) &_LockData[idx].dwTotalReadWaitTime, liWait.LowPart );
        InterlockedExchangeAdd( (LONG*) &_LockData[idx].dwTotalReadLockTime, liLocked.LowPart );
        */
    }

#if 0
    // Turn this ON, if you want a live log of every Update.
    wsprintfA(gszLockPerfBuf,"\n Lock at %-25s : line %u : Entry # %u",
                (pTableEntry->pszFile[1]==':') ? pTableEntry->pszFile+24
                                                : pTableEntry->pszFile,
                pTableEntry->dwLine,
                pTableEntry->dwNumEntrys);
    OutputDebugStringA(gszLockPerfBuf);

    wsprintfA(gszLockPerfBuf," Held for: %u mic-sec.",liLockHeld.LowPart);
    OutputDebugStringA(gszLockPerfBuf);
#endif
}

#define HOGLIST_TIME    0
#define HOGLIST_ENTRY   1
#define HOGLIST_AVGTIME 2


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::UpdateHoggers(), private
//
//  Synopsis:   Manages top ten lists. 
//                  This is done only during Proc_detach (hence thread safe!)
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::UpdateHoggers(ULONG* hogList, ULONG index, ULONG listType)
{
    int i,j;

    switch (listType)         
    {
    case HOGLIST_TIME:
        for (i=0; i<10; i++)
        {
            if (hogList[i]==-1)
            {
                break;
            }
            else if (_FileLineData[hogList[i]].dwLockedTime 
                        < _FileLineData[index].dwLockedTime)
            {
                break;
            }
        }
        break;

    case HOGLIST_ENTRY:
        for (i=0; i<10; i++)
        {
            if (hogList[i]==-1)
            {
                break;
            }
            else if (_FileLineData[hogList[i]].dwNumEntrys 
                        < _FileLineData[index].dwNumEntrys)
            {
                break;
            }
        }
        break;
    
    case HOGLIST_AVGTIME:
        for (i=0; i<10; i++)
        {
            if (hogList[i]==-1)
            {
                break;
            }
            else if (_FileLineData[hogList[i]].dwAvgTime 
                        < _FileLineData[index].dwAvgTime)
            {
                break;
            }
        }
        break;

    default:
        break;
    }

    if (i<10)
    {
        for (j=9; j>i;j--)
        {
            hogList[j] = hogList[j-1] ;
        }
        hogList[i] = index;
    }
}



//+-----------------------------------------------------------------------------
//
//  Function:   PercentToString
//
//  Synopsis:   Converts numbers like 74326 to "74.33".
//              We do not have float printing support in retail builds.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------

//  The percent argument is passed in 1000 times magnified.
char gPerc[7];
inline char *PercentToString(long percent)
{
    //round-off
    percent = percent/10 + ((percent%10 >= 5)?1:0);

    //set to fixed length
    percent+=10000;

    //create room for decimal point (4th char)
    percent = (percent/100)*1000 + (percent%100);

    _itoa(percent,gPerc,10);
    
    gPerc[0] = gPerc[0]-1;  //remove the 10000 we added.
    gPerc[3] = '.';

    return gPerc + (gPerc[0]=='0'? (gPerc[1]=='0'?2:1):0) ;
}



//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::OutputFileTableEntry, private
//
//  Synopsis:   Prints out cumulative data for a {file,line} entry
//              We are doing this during Process_Detach, hence thread-safe.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::OutputFileTableEntry(ULONG index, 
                                            ULONG bByName, 
                                            ULONG percent)
{
    ULONG trimFileName;
    CFileLineEntry *pTableEntry = &_FileLineData[index]; 

    if (pTableEntry->pszFile[1]==':')
    {
        trimFileName = 24;
    }
    else
    {
        trimFileName = 0;
    }
    if (bByName)
    {
        wsprintfA(gszLockPerfBuf,"\n %20s  %4d   %s %6d  %7u  %6s %% ",
                    pTableEntry->pszFile+trimFileName,
                    pTableEntry->dwLine,
                    pTableEntry->bWriteCritSec ? "Write" : " Read", 
                    pTableEntry->dwNumEntrys,
                    pTableEntry->dwLockedTime,
                    PercentToString(percent));

        OutputDebugStringA(gszLockPerfBuf);
    }
    else
    {
        wsprintfA(gszLockPerfBuf,"\n %20s  %4d   %-14.14s %s   %5d   %8u  %8u",
                    pTableEntry->pszFile+trimFileName,
                    pTableEntry->dwLine,
                    pTableEntry->pszLockName,
                    pTableEntry->bWriteCritSec?"Write":" Read", 
                    pTableEntry->dwNumEntrys,
                    pTableEntry->dwLockedTime,
                    pTableEntry->dwAvgTime);
        OutputDebugStringA(gszLockPerfBuf);
    }
}

#define TITLES_1      \
    wsprintfA(gszLockPerfBuf,"\n          File        Line    LockName       Type   Entrys  TotalTime  Avg/Entry"); OutputDebugStringA(gszLockPerfBuf)

#define TITLES_2      \
    wsprintfA(gszLockPerfBuf,"\n          File        Line    Type   Entrys TotalTime  %%-Time "); OutputDebugStringA(gszLockPerfBuf)

#define SEPARATOR_1   \
    wsprintfA(gszLockPerfBuf,"\n ==================== =====   ============   =====  ======  =========  ========="); OutputDebugStringA(gszLockPerfBuf)

#define SEPARATOR_2   \
    wsprintfA(gszLockPerfBuf,"\n ==================== =====   ====== ====== =========  ======"); OutputDebugStringA(gszLockPerfBuf)


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::OutputHoggers(), private
//
//  Synopsis:   Prints out a top ten list given an array of indices for the same.
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::OutputHoggers(ULONG *hogList)
{
    TITLES_1;
    SEPARATOR_1;

    for (int i=0; i<10; i++)
    {
        if (hogList[i]!=-1)
        {
            OutputFileTableEntry(hogList[i],0,0);
        }
    }
    SEPARATOR_1;
}


//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::ProcessPerfData(), public
//
//  Synopsis:   Organizes the perf table data by lockName. 
//              Prints lock summary data, top-ten lists.
//              This is done only during Proc_detach (hence thread safe!)
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::ProcessPerfData()
{
    // #### Begin : organize data
    CFileLineEntry  *pTableEntry;

    ULONG hogListTime[10];
    ULONG hogListEntry[10];
    ULONG hogListAvgTime[10];
    
    ULONG iName;
    DWORD totalLockTime = 0;        // lock sharing not reflected!
    DWORD totalRealLockTime = 0;    // takes lock sharing into account!
    DWORD totalLocksCreated = 0;    // some locks may never get used!


    for (int i=0; i<10; i++)
    {
        hogListTime[i] = -1;
        hogListEntry[i] = -1;
        hogListAvgTime[i] = -1;
    }
    
    for (i=0; i<MAX_LOCKPERF_FILEENTRY; i++)
    {
        if (_FileLineData[i].lpLockPtr)
        {
            pTableEntry = &_FileLineData[i];
            if (pTableEntry->dwNumEntrys)
            {
                pTableEntry->dwAvgTime = 
                        pTableEntry->dwLockedTime/pTableEntry->dwNumEntrys;
            }
            else
            {
                pTableEntry->dwAvgTime = 0;
            }
            UpdateHoggers(hogListTime,i, 0);
            UpdateHoggers(hogListEntry,i, 1);
            UpdateHoggers(hogListAvgTime,i, 2);
            _numCritSecs++;

            //REVIEW: how should we take shared time into account?
            totalLockTime = totalLockTime + pTableEntry->dwLockedTime;

            iName = FindLockTableEntry(_FileLineData[i].lpLockPtr);
            if (_LockData[iName].pszLockName==NULL)
            {   
                // First file table entry for this lock
                // We use pszLockName==NULL to tell if a lock got used!
                _LockData[iName].pszLockName = pTableEntry->pszLockName;
                _LockData[iName].dwHead = i;
                _LockData[iName].dwTail = i;

                _numLocks++;
            }
            else
            {   //CritSec is already in our list.
                _FileLineData[_LockData[iName].dwTail].dwNext = i;
                _LockData[iName].dwTail = i;
            }

            if (pTableEntry->bWriteCritSec)
            {
                _LockData[iName].dwTotalWriteLockTime += pTableEntry->dwLockedTime;
                _LockData[iName].dwTotalWriteEntrys += pTableEntry->dwNumEntrys;
                _LockData[iName].dwTotalWriteWaitTime += pTableEntry->dwWaitTime;
            }
            else
            {
                _LockData[iName].dwTotalReadLockTime += pTableEntry->dwLockedTime;
                _LockData[iName].dwTotalReadEntrys += pTableEntry->dwNumEntrys;
                _LockData[iName].dwTotalReadWaitTime += pTableEntry->dwWaitTime;
            }
        }   // if In Use
    }   // for each table entry
    // #### End : organize data

    wsprintfA(gszLockPerfBuf,
              "\n\n ============= LOCK_PERF: TOP TEN LISTS ===========\n");
    OutputDebugStringA(gszLockPerfBuf);

    wsprintfA(gszLockPerfBuf,
              "\n\n ============= Top Ten Hoggers by total time ===========\n");
    OutputDebugStringA(gszLockPerfBuf);
    OutputHoggers(hogListTime);

    wsprintfA(gszLockPerfBuf,
              "\n\n ============= Top Ten Hoggers by crit-sec Entrys ===========\n");
    OutputDebugStringA(gszLockPerfBuf);
    OutputHoggers(hogListEntry);

    wsprintfA(gszLockPerfBuf,
              "\n\n ============= Top Ten Hoggers by avg time per Entry ===========\n");
    OutputDebugStringA(gszLockPerfBuf);
    OutputHoggers(hogListAvgTime);

    SEPARATOR_1;
    wsprintfA(gszLockPerfBuf,
              "\n\n ============= LOCK_PERF: OVERALL LOCK STATS ===========\n");
    OutputDebugStringA(gszLockPerfBuf);

    for (i=0; i<MAX_LOCKS; i++)
    {
        if (_LockData[i].lpLockPtr)
        {
            totalLocksCreated++;
            if (_LockData[i].pszLockName)
            {
                // lock got used!
                totalRealLockTime += _LockData[i].dwTotalWriteLockTime;
                if (_LockData[i].dwTotalReadEntrys)
                {
                    totalRealLockTime += _LockData[i].dwSharedTime;
                }
            }
        }
    }

    wsprintfA(gszLockPerfBuf,
              "\n\n TOTAL locks created = %u",
              totalLocksCreated);
    OutputDebugStringA(gszLockPerfBuf);

    wsprintfA(gszLockPerfBuf,
              "\n TOTAL locks used    = %u",
              _numLocks);
    OutputDebugStringA(gszLockPerfBuf);
    wsprintfA(gszLockPerfBuf,
              "\n\n TOTAL code critSec areas covered = %u",
              _numCritSecs);
    OutputDebugStringA(gszLockPerfBuf);

    wsprintfA(gszLockPerfBuf,
              "\n\n\n TOTAL time spent in all critSecs = %u micro-sec\n\n",
              totalLockTime);
    OutputDebugStringA(gszLockPerfBuf);
    wsprintfA(gszLockPerfBuf,
              " [This is the sum of individual thread times.\n This does not take overlaps (shared work) into account.]");
    OutputDebugStringA(gszLockPerfBuf);
    
    wsprintfA(gszLockPerfBuf,
              "\n\n\n TOTAL real time spent in all critSecs = %u micro-sec\n\n",
              totalRealLockTime);
    OutputDebugStringA(gszLockPerfBuf);
    wsprintfA(gszLockPerfBuf," [This takes shared time into account.]");
    OutputDebugStringA(gszLockPerfBuf);
        
    wsprintfA(gszLockPerfBuf,
              "\n\n ## Warning ##: The total time counters overflow in about 70 minutes!\n\n");
    OutputDebugStringA(gszLockPerfBuf);
}

//+-----------------------------------------------------------------------------
//
//  Member:     CLockPerfTracker::OutputPerfData(), public
//
//  Synopsis:   Prints out the {file,line} table.
//              This is done only during Proc_detach (hence thread safe!)
//
//  History:    20-Dec-98   mprabhu     Created
//
//------------------------------------------------------------------------------
void CLockPerfTracker::OutputPerfData()
{
    if (glFileLine) //if monitoring was ON at any time!
    {
        if (gbLockPerfOverflow)
        {
            wsprintfA(gszLockPerfBuf,
                      "\n ### Warning: Overflow in lock perf data buffers!\n \
                      ### Increase array sizes and recompile!!\n");
            OutputDebugStringA(gszLockPerfBuf);
        }

        ULONG iStart, iNext, iEnd;
        const char *pszThisFile;
        
        ULONG iName;
        LARGE_INTEGER liPerc, liDiv, liRem ;


        //TITLES_1;
        //SEPARATOR_1;
        ProcessPerfData();


        // #### Begin: output by LockName:
        SEPARATOR_2;

        wsprintfA(gszLockPerfBuf,
                  "\n\n ============= LOCK_PERF: PER LOCK STATS ===========\n");
        OutputDebugStringA(gszLockPerfBuf);
        BOOL bShared;
        int iShared;
        for (iName=0; iName<_numLocks; iName++)
        {
            if (_LockData[iName].pszLockName) { //if the lock got used
            SEPARATOR_2;
            wsprintfA(gszLockPerfBuf,
                      "\n\n\n  #### ++++++++ Summary for %14s , this = %lx ++++++++ ####",
                      _LockData[iName].pszLockName, 
                      (DWORD)_LockData[iName].lpLockPtr);
            OutputDebugStringA(gszLockPerfBuf);

            wsprintfA(gszLockPerfBuf,
                      "\n\n      WrtLockTime:%12u      WrtEntrys:%14u\n      WrtWait:%16u      WrtContention:%10u \n",
                      _LockData[iName].dwTotalWriteLockTime,
                      _LockData[iName].dwTotalWriteEntrys,
                      _LockData[iName].dwTotalWriteWaitTime,
                      _LockData[iName].dwWriterContentionCount);
            OutputDebugStringA(gszLockPerfBuf);

            wsprintfA(gszLockPerfBuf,
                      "\n      RdLockTime:%13u      RdEntrys:%15u\n      RdWait:%17u      RdContention:%11u \n",
                      _LockData[iName].dwTotalReadLockTime,
                      _LockData[iName].dwTotalReadEntrys,
                      _LockData[iName].dwTotalReadWaitTime,
                      _LockData[iName].dwReaderContentionCount);
            OutputDebugStringA(gszLockPerfBuf);
            
            wsprintfA(gszLockPerfBuf,"\n      Shared Read Time:     %10u\n",
                      _LockData[iName].dwSharedTime);
            OutputDebugStringA(gszLockPerfBuf);
            

            TITLES_2;
            SEPARATOR_2;
            iNext = _LockData[iName].dwHead;
            iEnd = _LockData[iName].dwTail;
            while (1)
            {
                liPerc.HighPart = 0;
                liPerc.LowPart = _FileLineData[iNext].dwLockedTime;
                liPerc = RtlExtendedIntegerMultiply(liPerc,100000);
                liDiv.HighPart = 0;
                if (_FileLineData[iNext].bWriteCritSec)
                {
                    liDiv.LowPart = _LockData[iName].dwTotalWriteLockTime;
                }
                else
                {
                    liDiv.LowPart = _LockData[iName].dwTotalReadLockTime;
                }

                liPerc = RtlLargeIntegerDivide(liPerc, liDiv, &liRem);

                OutputFileTableEntry(iNext,1, liPerc.LowPart);
                if (iNext == iEnd)
                    break;
                iNext = _FileLineData[iNext].dwNext;
            }

            SEPARATOR_2;
            wsprintfA(gszLockPerfBuf,
                      "\n ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ \n");
            OutputDebugStringA(gszLockPerfBuf);
            }   //if the lock got used!
        }

        SEPARATOR_2;
        // #### End: output by LockName:

        SEPARATOR_1;


#if 0   //This lists lock data by fileNames
        // #### Begin: output by fileName : location:
        wsprintfA(gszLockPerfBuf,
                  "\n\n\n ======= CritSec data listed by FileName: =======\n");
        OutputDebugStringA(gszLockPerfBuf);

        TITLES_1;
        SEPARATOR_1;

        pszThisFile = NULL;
        i=0;
        while (!_FileLineData[i].bInUse)
            i++;
        iNext = i;

        while (iNext < MAX_LOCKPERF_FILEENTRY)
        {
            iStart = iNext;
            iNext = MAX_LOCKPERF_FILEENTRY;
            pszThisFile= _FileLineData[iStart].pszFile;
            for (i=iStart;i<MAX_LOCKPERF_FILEENTRY;i++)
            {
                if (_FileLineData[i].bInUse)
                {
                    if (pszThisFile==_FileLineData[i].pszFile)
                    {
                        OutputFileTableEntry(i,0,0);
                        _FileLineData[i].bInUse = FALSE;
                    }
                    else if (iNext==MAX_LOCKPERF_FILEENTRY)
                    {
                        iNext=i;
                    }
                }
            }
        }
        // #### End: output by fileName : location:
#endif  //0 This lists lock data by fileNames

    }   //if glFileLine  
}

#endif //LOCK_PERF==1