//+------------------------------------------------------------------- // // File: tracelog.cxx // // Contents: trace log implementation // // Classes: CTraceLog - class for logging traces // CTraceCall - class for logging one function call // // Functions: none // // History: 23-Aug-93 Rickhi Created // // Notes: The trace log is used to record call information in a // process global ring buffer. The information can be used // to assist debugging, by allowing you to see what events // have taken place that lead up to some problem, and also // to provide profiling the CairOLE subsystem. // // CODEWORK: add call nesting depth // add logical thread id // get input parms from ini file // //-------------------------------------------------------------------- #include #ifdef TRACELOG #include #include // these prototypes must be here because the cairo headers and Nt headers // conflict with each other, so i cant include the latter. extern "C" { #define NTAPI __stdcall // winnt LONG NTAPI NtQueryPerformanceCounter ( LARGE_INTEGER *PerformanceCounter, LARGE_INTEGER *PerformanceFrequency ); LARGE_INTEGER NTAPI RtlLargeIntegerSubtract ( LARGE_INTEGER Minuend, LARGE_INTEGER Subtrahend ); LARGE_INTEGER NTAPI RtlLargeIntegerDivide ( LARGE_INTEGER Dividend, LARGE_INTEGER Divisor, LARGE_INTEGER *Remainder ); LARGE_INTEGER NTAPI RtlExtendedIntegerMultiply ( LARGE_INTEGER Multiplicand, LONG Multiplier ); } // extern "C" // globals DWORD sg_dwTraceFlag = 0x0; // what to trace CTraceLog *sg_pTraceLog = NULL; // ptr to log LARGE_INTEGER sg_liFreq; // counter frequency //------------------------------------------------------------------------ // // function: MapFlagToName // // synopsis: returns an ascii name equivalent for the trace flag value // //------------------------------------------------------------------------ CHAR * MapFlagToName(DWORD dwFlag) { if (dwFlag & TRACE_RPC) return "RPC"; else if (dwFlag & TRACE_MARSHAL) return "MSH"; else if (dwFlag & TRACE_ACTIVATION) return "ACT"; else if (dwFlag & TRACE_REGISTRY) return "REG"; else if (dwFlag & TRACE_DLL) return "DLL"; else if (dwFlag & TRACE_INITIALIZE) return "INI"; else if (dwFlag & TRACE_CALLCONT) return "CCT"; else if (dwFlag & TRACE_APP) return "APP"; else return "???"; } //------------------------------------------------------------------------ // // member: CTraceCall::CTraceCall // // synopsis: constructor is called on entry to each function that we wish // to trace. the constructor matches the trace flag passed in // against the global trace mask, and if a match is made then // an entry is made in the trace log for this function call. // //------------------------------------------------------------------------ CTraceCall::CTraceCall(DWORD dwFlags, CHAR *pszMsg) : _dwFlags(dwFlags), _pszMsg(pszMsg) { // compare the flag value with the global mask to determine if this // call should be traced or not. if ((_dwFlags & sg_dwTraceFlag) && sg_pTraceLog) { // trace the call _dwThreadId = GetCurrentThreadId(); LARGE_INTEGER liEndTime, liFreq; liEndTime.LowPart = 0; liEndTime.HighPart = 0; NtQueryPerformanceCounter(&_liStartTime, &liFreq); sg_pTraceLog->TraceEntry(_dwFlags, _pszMsg, _dwThreadId, _liStartTime, liEndTime); } } //------------------------------------------------------------------------ // // member: CTraceCall::~CTraceCall // // synopsis: destructor is called class placed on the stack in each function that we wish to // trace. the constructor matches the trace flag passed in // against the global trace mask, and if a match is made then // an entry is made in the trace log for this function call. // //------------------------------------------------------------------------ CTraceCall::~CTraceCall(void) { // if we traced the entry, then we'll trace the exit too. if ((_dwFlags & sg_dwTraceFlag) && sg_pTraceLog) { LARGE_INTEGER liEndTime, liFreq; NtQueryPerformanceCounter(&liEndTime, &liFreq); sg_pTraceLog->TraceEntry(_dwFlags, _pszMsg, _dwThreadId, liEndTime, _liStartTime); } } //------------------------------------------------------------------------ // // member: CTraceLog // // synopsis: constructor called at process entry time. // //------------------------------------------------------------------------ CTraceLog::CTraceLog(void) : _dwTraceFlag(0), _pLogStart(NULL), _pLogCurr(NULL), _pLogEnd(NULL), _fDump(TRUE), _ulLevel(0) { ULONG ulLogSize = 0; // init the mutex semaphore _mxs.Init(); // read the execution parameters from win.ini, or use defaults. CHAR szRead[20]; GetProfileStringA("CairOLE", "LogFlags", "0", szRead, sizeof(szRead)); sscanf(szRead, "%li", &_dwTraceFlag); if (_dwTraceFlag != 0) { GetProfileStringA("CairOLE", "LogSize", "1000", szRead, sizeof(szRead)); sscanf(szRead, "%li", &ulLogSize); GetProfileStringA("CairOLE", "LogDump", "Y", szRead, sizeof(szRead)); _fDump = (_stricmp(szRead, "Y")) ? FALSE : TRUE; if (ulLogSize > 0) { // allocate the logfile and set the pointers appropriately. _pLogStart = (STraceEntry *) VirtualAlloc(NULL, sizeof(STraceEntry)*ulLogSize, MEM_COMMIT, PAGE_READWRITE); Win4Assert(_pLogStart); _pLogCurr = _pLogStart; _pLogEnd = _pLogStart + ulLogSize; // clear the trace log memset((BYTE *)_pLogStart, 0, ulLogSize*sizeof(STraceEntry)); // get the startup time NtQueryPerformanceCounter(&_liStartTime, &sg_liFreq); GetProfileStringA("CairOLE", "WaitForStart", "N", szRead, sizeof(szRead)); if (!_stricmp(szRead, "N")) { // start logging right away otherwise wait for // start signal. StartTrace("Auto Tracing Started"); } } } CairoleDebugOut((DEB_ITRACE, "TraceLog: LogFlags=%ld LogSize=%ld LogDump=%ld\n", sg_dwTraceFlag, ulLogSize, _fDump)); } //------------------------------------------------------------------------ // // member: ~CTraceLog // // synopsis: destructor called at process exit time. // //------------------------------------------------------------------------ CTraceLog::~CTraceLog(void) { // if the user requested logging to a file, do it now if (_pLogStart) { if (_fDump) { LogToFile(); } // delete the log file VirtualFree(_pLogStart,0,MEM_RELEASE); } } //------------------------------------------------------------------------ // // member: TraceEntry // // synopsis: adds a function call entry to the log file // //------------------------------------------------------------------------ void CTraceLog::TraceEntry(DWORD dwFlags, CHAR *pszMsg, DWORD dwThreadId, LARGE_INTEGER liCurrTime, LARGE_INTEGER liStartTime) { if (!_pLogStart) return; CLock lck(_mxs); // lock the log file while we play // record an entry in the logfile to designate function entry _pLogCurr->dwThreadId = dwThreadId; _pLogCurr->dwFlags = dwFlags; _pLogCurr->pszMsg = pszMsg; _pLogCurr->liCurrTime = liCurrTime; _pLogCurr->liStartTime = liStartTime; if (liStartTime.HighPart == 0 && liStartTime.LowPart == 0) { _pLogCurr->fExit = FALSE; _pLogCurr->ulLevel = _ulLevel++; } else { _pLogCurr->fExit = TRUE; _pLogCurr->ulLevel = --_ulLevel; } // update logfile ptr to next entry if (++_pLogCurr == _pLogEnd) _pLogCurr = _pLogStart; } //------------------------------------------------------------------------ // // member: LogToFile // // synopsis: Dumps the tracelog to a file. // //------------------------------------------------------------------------ void CTraceLog::LogToFile(void) { CairoleDebugOut((DEB_ITRACE, "Dumping TraceLog to file.\n")); CLock lck(_mxs); // lock just for safety // extract the program name from the command line and use it // to generate a file name for the log file. CHAR szFileName[MAX_PATH]; CHAR *pszNameStart = GetCommandLineA(); CHAR *pszNameEnd = pszNameStart; while (*pszNameEnd && *pszNameEnd != ' ' && *pszNameEnd != '\t' && *pszNameEnd != '.') pszNameEnd++; ULONG ulLen = pszNameEnd-pszNameStart; strncpy(szFileName, pszNameStart, ulLen); szFileName[ulLen] = '\0'; strcat(szFileName, ".log"); // open the logging file FILE *fpLog = fopen(szFileName, "at"); Win4Assert(fpLog && "Can't Open TraceLog File"); if (!fpLog) return; // print the title and column header fprintf(fpLog, "\t\t%s\n\n", szFileName); fprintf(fpLog, "Thread Elapsed Delta Call Flg D Function\n"); // loop, writing the entries. we start at the current pointer (which // is currently the oldest entry in the logfile) and write each one. // in case we have not yet wrapped the log, we skip any blank entries. CHAR szBlank[MAX_PATH]; memset(szBlank, ' ', sizeof(szBlank)); STraceEntry *pEntry = _pLogCurr; BOOL fFirst = TRUE; LARGE_INTEGER liPrev; do { // write the entry if (pEntry->pszMsg) { // we want the first time delta to be zero, so liPrev gets set // to the value of the first entry that we write. if (fFirst) liPrev = pEntry->liCurrTime; // compute the time deltas LARGE_INTEGER liElapsed = PerfDelta(pEntry->liCurrTime, _liStartTime); LARGE_INTEGER liDeltaPrev = PerfDelta(pEntry->liCurrTime, liPrev); LARGE_INTEGER liDeltaCall; if (pEntry->fExit) { liDeltaCall = PerfDelta(pEntry->liCurrTime, pEntry->liStartTime); } else { liDeltaCall.LowPart = 0; liDeltaCall.HighPart = 0; } // get the ascii name for the flag CHAR *pszFlagName = MapFlagToName(pEntry->dwFlags); // null terminate the blank padding string that prefixes the // pszMsg. this gives the illusion of call nesting level in // the output, by shifting the output right ulLevel characters. szBlank[pEntry->ulLevel] = '\0'; fprintf(fpLog, "%6ld %10lu %10lu %10lu %s %c %s%s\n", pEntry->dwThreadId, liElapsed.LowPart, liDeltaPrev.LowPart, liDeltaCall.LowPart, pszFlagName, (pEntry->fExit) ? '<' : '>', szBlank, pEntry->pszMsg); // restore the padding string szBlank[pEntry->ulLevel] = ' '; fFirst = FALSE; liPrev = pEntry->liCurrTime; } // update the current pointer if (++pEntry == _pLogEnd) pEntry = _pLogStart; } while (pEntry != _pLogCurr); // close the logging file fclose(fpLog); } //------------------------------------------------------------------------ // // member: LogToDebug // // synopsis: dumps the trace log to the debugger // //------------------------------------------------------------------------ void CTraceLog::LogToDebug(void) { CairoleDebugOut((DEB_ITRACE, "Dumping TraceLog to Debugger.\n")); } //------------------------------------------------------------------------ // // function: PerfDelta // // synopsis: computes the different between two Performace Counter values // //------------------------------------------------------------------------ LARGE_INTEGER CTraceLog::PerfDelta(LARGE_INTEGER liNow, LARGE_INTEGER liStart) { LARGE_INTEGER liDelta, liRemainder; liDelta = RtlLargeIntegerSubtract (liNow, liStart); liDelta = RtlExtendedIntegerMultiply (liDelta, 1000000); liDelta = RtlLargeIntegerDivide (liDelta, sg_liFreq, &liRemainder); return liDelta; } void CTraceLog::StartTrace(LPSTR pszMsg) // start log tracing { CHAR szMsg[260]; strcpy(szMsg, "\n*** Start Trace\n"); strcat(szMsg, pszMsg); sg_dwTraceFlag = _dwTraceFlag; CTraceCall trc(0xffffffff, szMsg); } void CTraceLog::StopTrace(LPSTR pszMsg) // stop tracing { CHAR szMsg[260]; strcpy(szMsg, "\n*** Stop Trace\n"); strcat(szMsg, pszMsg); CTraceCall trc(0xffffffff, szMsg); sg_dwTraceFlag = 0; } STDAPI StartTrace(LPSTR pszMsg) { sg_pTraceLog->StartTrace(pszMsg); return 0; } STDAPI StopTrace(LPSTR pszMsg) { sg_pTraceLog->StopTrace(pszMsg); return 0; } #endif // TRACELOG