Windows NT 4.0 source code leak
You can not select more than 25 topics Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.
 
 
 
 
 
 

696 lines
18 KiB

//****************************************************************************
//
// Module: UNIMDM
// File: TRACING.C
//
// Copyright (c) 1992-1996, Microsoft Corporation, all rights reserved
//
// Revision History
//
//
// 3/29/96 JosephJ Created
//
//
// Description: Tracing (retail-mode diagnostics) functions
//
//****************************************************************************
#include "unimdm.h"
#include "umdmspi.h"
// Other modules use this via the TRACINGENABLED macro to determine if
// tracing is enabled in this session.
BOOL gfTracingEnabled;
#define fTRACING_INITED (0x1<<0)
#define fTRACING_EXTDLLBOUND (0x1<<1)
#define TRACINGINITED() (gTracing.dwFlags&fTRACING_INITED)
#define EXTDLLBOUND() (gTracing.dwFlags&fTRACING_EXTDLLBOUND)
typedef BOOL (WINAPI *PFNINIT) (DWORD, LPDWORD);
typedef void (WINAPI *PFNDEINIT) (void);
typedef void (WINAPI *PFNNOTIFY) (PNOTIFICATION_FRAME);
typedef void (WINAPI *PFNREGISTEROBJECT) (PVOID, PGUID, DWORD, DWORD, DWORD);
typedef void (WINAPI *PFNUNREGISTEROBJECT) (PVOID, DWORD, DWORD);
typedef void (WINAPI *PFNTRACE1) (DWORD);
typedef void (WINAPI *PFNTRACE2) (DWORD, DWORD);
typedef void (WINAPI *PFNTRACE3) (DWORD, DWORD, DWORD);
typedef void (WINAPI *PFNTRACE4) (DWORD, DWORD, DWORD, DWORD);
typedef void (WINAPI *PFNTRACE5) (DWORD, DWORD, DWORD, DWORD, DWORD);
typedef void (WINAPI *PFNTRACE8) (DWORD, DWORD, DWORD, DWORD, DWORD,
DWORD, DWORD, DWORD);
// Maintains info on the binding to the external MODEMDBG.DLL which contains
// extended tracing and diagnostic information.
// The ext field in gTracing is initialized after a successful call to
// itraceBindToExternalDll.
typedef struct
{
HANDLE hDll;
PFNINIT pfnInit;
PFNDEINIT pfnDeinit;
PFNREGISTEROBJECT pfnRegisterObject;
PFNUNREGISTEROBJECT pfnUnRegisterObject;
PFNNOTIFY pfnNotify;
PFNTRACE1 pfnTrace1;
PFNTRACE2 pfnTrace2;
PFNTRACE3 pfnTrace3;
PFNTRACE4 pfnTrace4;
PFNTRACE5 pfnTrace5;
PFNTRACE8 pfnTrace8;
} EXTERNAL_DLL;
// Global internal tracing state.
struct {
DWORD dwFlags;
CRITICAL_SECTION crit;
EXTERNAL_DLL ext;
LINEEVENT lineEventProc;
ASYNC_COMPLETION TapiCompletionProc;
} gTracing;
//---------- PRIVATE FUNCTIONS -------------------------------
BOOL itraceCheckIfEnabled(DWORD dwPermanentID);
BOOL itraceBindToExternalDll(void);
void itraceUnbindFromExternalDll(void);
void CALLBACK itraceEventProc(HTAPILINE htLine,
HTAPICALL htCall,
DWORD dwMsg,
DWORD dwParam1,
DWORD dwParam2,
DWORD dwParam3
);
void CALLBACK itraceTapiCompletionProc(
DRV_REQUESTID dwRequestID,
LONG lResult
);
//****************************************************************************
// Function: To be called on process attach
// History:
// 3/25/96 JosephJ Created
//****************************************************************************/
void traceOnProcessAttach(void)
{
InitializeCriticalSection(&gTracing.crit);
}
//****************************************************************************
// Function: To be called on process detach
// History:
// 3/25/96 JosephJ Created
//****************************************************************************/
void traceOnProcessDetach(void)
{
DeleteCriticalSection(&gTracing.crit);
}
//****************************************************************************
// Function: To be called on provider initialization
// History:
// 3/25/96 JosephJ Created
//****************************************************************************/
void traceInitialize(DWORD dwPermanentID)
{
TCHAR rgtchExternalDllName[MAX_PATH];
EnterCriticalSection(&gTracing.crit);
ASSERT(!gTracing.dwFlags);
// Determine if tracing is enabled, if so set the gTracingEnabled flag.
gfTracingEnabled = itraceCheckIfEnabled(dwPermanentID);
// If tracing enabled, try to load the external trace dll and get the
// entry points to that function.
if (TRACINGENABLED())
{
if (itraceBindToExternalDll())
{
ASSERT(EXTDLLBOUND());
}
}
gTracing.dwFlags |= fTRACING_INITED;
LeaveCriticalSection(&gTracing.crit);
}
//****************************************************************************
// Function: To be called on provider shutdown
// History:
// 3/25/96 JosephJ Created
//****************************************************************************/
void traceDeinitialize(void)
{
EnterCriticalSection(&gTracing.crit);
if (!TRACINGINITED()) goto end;
// Deinit external dll..
if (EXTDLLBOUND())
{
itraceUnbindFromExternalDll();
}
gTracing.dwFlags = 0;
end:
ASSERT(!gTracing.dwFlags);
LeaveCriticalSection(&gTracing.crit);
}
//****************************************************************************
// Function: Registers an arbitrary object with the external dll.
// History:
// 3/25/96 JosephJ Created
//****************************************************************************/
void traceRegisterObject(
PVOID pv, // Pointer to the object
PGUID pg, // GUID uniquely defining the object
DWORD dwVersion, // Implementation version of the object
DWORD dwFlags, // Unused, currently zero
DWORD dwParam // Unused, currently zero
)
{
DPRINTF2("traceRegisterObject: obj 0x%lx, type 0x%lx\n",
(DWORD) pv, (DWORD) pg);
if (!TRACINGENABLED()) goto end;
if (EXTDLLBOUND())
{
ASSERT(gTracing.ext.pfnRegisterObject);
gTracing.ext.pfnRegisterObject(pv, pg, dwVersion, dwFlags, dwParam);
}
end:
return;
}
//****************************************************************************
// Function: UnRegisters an arbitrary object with the external dll.
// History:
// 3/25/96 JosephJ Created
//****************************************************************************/
void traceUnRegisterObject(
PVOID pv, // Pointer to a previously-registered object.
DWORD dwFlags, // Unused, currently zero
DWORD dwParam // Unused, currently zero
)
{
DPRINTF1("traceUnRegiserObject: obj 0x%lx\n", (DWORD) pv);
if (!TRACINGENABLED()) goto end;
if (EXTDLLBOUND())
{
ASSERT(gTracing.ext.pfnUnRegisterObject);
gTracing.ext.pfnUnRegisterObject(pv, dwFlags, dwParam);
}
end:
return;
}
//****************************************************************************
// Function: Processes an external debug notification.
// History:
// 3/25/96 JosephJ Created
//****************************************************************************/
void traceProcessNotification(
PNOTIFICATION_FRAME pnf
)
{
if (!TRACINGENABLED()) goto end;
ASSERT(TSP_VALID_FRAME(pnf));
ASSERT(TSP_DEBUG_FRAME(pnf));
DPRINTF1("traceProcessNotification: type 0x%lx\n", pnf->dwType);
if (EXTDLLBOUND())
{
ASSERT(gTracing.ext.pfnNotify);
gTracing.ext.pfnNotify(pnf);
}
end:
return;
}
void traceTrace1(
DWORD dwWhat
)
{
ASSERT(TRACINGENABLED());
if (!EXTDLLBOUND()) goto end;
ASSERT(gTracing.ext.pfnTrace1);
gTracing.ext.pfnTrace1(dwWhat);
end:
return;
}
void traceTrace2(
DWORD dwWhat,
DWORD dw0
)
{
ASSERT(TRACINGENABLED());
if (!EXTDLLBOUND()) goto end;
ASSERT(gTracing.ext.pfnTrace2);
gTracing.ext.pfnTrace2(dwWhat, dw0);
end:
return;
}
void traceTrace3(
DWORD dwWhat,
DWORD dw0,
DWORD dw1
)
{
ASSERT(TRACINGENABLED());
if (!EXTDLLBOUND()) goto end;
ASSERT(gTracing.ext.pfnTrace3);
gTracing.ext.pfnTrace3(dwWhat, dw0, dw1);
end:
return;
}
void traceTrace4(
DWORD dwWhat,
DWORD dw0,
DWORD dw1,
DWORD dw2
)
{
ASSERT(TRACINGENABLED());
if (!EXTDLLBOUND()) goto end;
ASSERT(gTracing.ext.pfnTrace4);
gTracing.ext.pfnTrace4(dwWhat, dw0, dw1, dw2);
end:
return;
}
void traceTrace5(
DWORD dwWhat,
DWORD dw0,
DWORD dw1,
DWORD dw2,
DWORD dw3
)
{
ASSERT(TRACINGENABLED());
if (!EXTDLLBOUND()) goto end;
ASSERT(gTracing.ext.pfnTrace5);
gTracing.ext.pfnTrace5(dwWhat, dw0, dw1, dw2, dw3);
end:
return;
}
void traceTrace8(
DWORD dwWhat,
DWORD dw0,
DWORD dw1,
DWORD dw2,
DWORD dw3,
DWORD dw4,
DWORD dw5,
DWORD dw6
)
{
ASSERT(TRACINGENABLED());
if (!EXTDLLBOUND()) goto end;
ASSERT(gTracing.ext.pfnTrace8);
gTracing.ext.pfnTrace8(dwWhat, dw0, dw1, dw2, dw3, dw4, dw5, dw6);
end:
return;
}
LINEEVENT traceSetEventProc(LINEEVENT lineEventProc)
{
ASSERT(TRACINGENABLED());
gTracing.lineEventProc = lineEventProc;
return itraceEventProc;
}
ASYNC_COMPLETION traceSetCompletionProc(ASYNC_COMPLETION cbCompletionProc)
{
ASSERT(TRACINGENABLED());
gTracing.TapiCompletionProc = cbCompletionProc;
return itraceTapiCompletionProc;
}
#ifdef ENABLE_TRACE_CRITICAL_SECTION
//****************************************************************************
// void TRACEInitializeCriticalSection (
// TRACE_CRITICAL_SECTION * ptspcrit,
// DWORD dwID)
//
// Function: InitializeCriticalSection, with some perf monitoring
//****************************************************************************
void TRACEInitializeCriticalSection(TRACE_CRITICAL_SECTION * ptspcrit, DWORD dwID, DWORD dwWTime, DWORD dwCTime)
{
FillMemory(ptspcrit, sizeof(TRACE_CRITICAL_SECTION), 0);
InitializeCriticalSection(&(ptspcrit->crit));
ptspcrit->dwID = dwID;
ptspcrit->dwMaxWaitTime=dwWTime;
ptspcrit->dwMaxClaimTime=dwCTime;
}
//****************************************************************************
// void TRACEEnterCriticalSection (
// TRACE_CRITICAL_SECTION * ptspcrit,
// DWORD dwID)
//
// Function: EnterCriticalSection, with some perf monitoring
//****************************************************************************
void TRACEEnterCriticalSection(TRACE_CRITICAL_SECTION * ptspcrit, DWORD dwFrom)
{
DWORD tc0 = GetTickCount(), tc1;
DWORD dwDelta;
EnterCriticalSection(&(ptspcrit->crit));
ptspcrit->dwTotalHits++;
if (!ptspcrit->dwNested++)
{
tc1 = ptspcrit->tcEntered = GetTickCount();
ptspcrit->dwFromWhere = dwFrom;
dwDelta = GETTICKCOUNT_DELTA(tc0, tc1);
if (dwDelta>=CRIT_MIN_WAIT_DELTA)
{
if (dwDelta>=ptspcrit->dwMaxWaitTime)
{
// MONTSPEVENT(_id, _subid, ,,......)
DPRINTF3("WARNING: Took %lums to claim crit %lu from %lu",
dwDelta, ptspcrit->dwID, dwFrom);
}
ptspcrit->dwWaitHits++;
ptspcrit->dwTotalWaitTime+=dwDelta;
}
}
}
//****************************************************************************
// void TRACELeaveCriticalSection (
// TRACE_CRITICAL_SECTION * ptspcrit,
// DWORD dwFrom)
//
// Function: LeaveCriticalSection, with some perf monitoring
void TRACELeaveCriticalSection(TRACE_CRITICAL_SECTION * ptspcrit, DWORD dwFrom)
{
DWORD tc0 = ptspcrit->tcEntered, tc1=GetTickCount();
DWORD dwDelta = GETTICKCOUNT_DELTA(tc0, tc1);
if (!(--(ptspcrit->dwNested)))
{
if (dwDelta>=CRIT_MIN_CLAIM_DELTA)
{
ptspcrit->dwTotalClaimTime+=dwDelta;
ptspcrit->dwClaimHits++;
if (dwDelta>ptspcrit->dwMaxClaimTime)
{
// MONTSPEVENT(_id, _subid, ,,......)
DPRINTF4("WARNING: Took %lums inside crit %lu claimed from %lu;"
"released from %lu",
dwDelta, ptspcrit->dwID, ptspcrit->dwFromWhere, dwFrom);
}
}
}
LeaveCriticalSection(&(ptspcrit->crit));
}
//****************************************************************************
// void TRACEDeleteCriticalSection (
// TRACE_CRITICAL_SECTION * ptspcrit,
// DWORD dwID)
//
// Function: DeleteCriticalSection, with some perf monitoring
void TRACEDeleteCriticalSection(TRACE_CRITICAL_SECTION * ptspcrit)
{
EnterCriticalSection(&(ptspcrit->crit));
DPRINTF2("Deleteing TRACE crit %lu. TH=%lu",
ptspcrit->dwID,
ptspcrit->dwTotalHits);
DPRINTF4(" ... TWT=%lu TWH=%lu TCT=%lu TCH=%lu\n",
ptspcrit->dwTotalWaitTime,
ptspcrit->dwWaitHits,
ptspcrit->dwTotalClaimTime,
ptspcrit->dwClaimHits);
// +++ MON
DeleteCriticalSection(&(ptspcrit->crit));
}
//****************************************************************************
// void TRACESetMaxWaitAndClaimTime(
// TRACE_CRITICAL_SECTION * ptspcrit,
// DWORD dwWTime,
// DWORD dwCTime)
//
// Function: Sets the MaxWaitOrClaimTime of the crit -- if this time is
// exceeded, it results in a mon event being logged.
void TRACESetMaxWaitAndClaimTime(TRACE_CRITICAL_SECTION *ptspcrit, DWORD dwWTime, DWORD dwCTime)
{
DPRINTF2("TRACECRIT: setting (wait,claim) max time to (%lu,%lu)",
dwWTime, dwCTime);
EnterCriticalSection(&(ptspcrit->crit));
ptspcrit->dwMaxWaitTime = dwWTime;
ptspcrit->dwMaxClaimTime = dwCTime;
LeaveCriticalSection(&(ptspcrit->crit));
}
#endif // ENABLE_TRACE_CRITICAL_SECTION
//****************************************************************************
// Function: Reads the registry and determines if tracing is enabled in this
// session. Currently tracing is always enabled.
// History:
// 3/25/96 JosephJ Created
//****************************************************************************/
BOOL itraceCheckIfEnabled(DWORD dwPermanentID)
{
BOOL fRet=FALSE;
DWORD dwFlags=0;
DWORD dwType=0;
HKEY hKey=0;
LONG l;
DWORD dwSize=sizeof(dwFlags);
TCHAR rgtch[] = szUNIMODEM_REG_PATH TEXT("\\Diagnostics");
DPRINTF1("trace:Key=%s", rgtch);
l=RegOpenKeyEx(
HKEY_LOCAL_MACHINE, // handle of open key
rgtch, // address of name of subkey to open
0, // reserved
KEY_READ, // desired security access
&hKey // address of buffer for opened handle
);
if (l!=ERROR_SUCCESS) {hKey=0; goto end;}
DPRINTF("trace:RegOpen succeeded");
l=RegQueryValueEx(
hKey,
TEXT("TraceFlags"),
NULL,
&dwType,
(VOID *)&dwFlags,
&dwSize
);
if (l != ERROR_SUCCESS || dwType != REG_DWORD ||
dwSize != sizeof(dwFlags))
{
goto end;
}
DPRINTF1("RegQueryValue succeeds. Value=0x%lx", dwFlags);
fRet = !!dwFlags;
end:
if (hKey) RegCloseKey(hKey);
DPRINTF1("Tracing %s", (fRet)?TEXT("ENABLED"):TEXT("DISABLED"));
return fRet;
}
//****************************************************************************
// Function: Tries to bind to the external modem diagnostics dll.
// History:
// 3/31/96 JosephJ Created
//****************************************************************************/
BOOL itraceBindToExternalDll(void)
{
BOOL fRet=FALSE;
DWORD dwNegVer=0;
ASSERT(!EXTDLLBOUND());
FillMemory(&gTracing.ext, sizeof(gTracing.ext), 0);
gTracing.ext.hDll = LoadLibrary(TEXT("mdmdbg.dll"));
if (gTracing.ext.hDll)
{
(FARPROC) gTracing.ext.pfnInit =
GetProcAddress(gTracing.ext.hDll, "MdmDbgInit");
(FARPROC) gTracing.ext.pfnDeinit =
GetProcAddress(gTracing.ext.hDll, "MdmDbgDeinit");
(FARPROC) gTracing.ext.pfnNotify =
GetProcAddress(gTracing.ext.hDll, "MdmDbgNotify");
(FARPROC) gTracing.ext.pfnRegisterObject =
GetProcAddress(gTracing.ext.hDll, "MdmDbgRegisterObject");
(FARPROC) gTracing.ext.pfnUnRegisterObject =
GetProcAddress(gTracing.ext.hDll, "MdmDbgUnRegisterObject");
(FARPROC) gTracing.ext.pfnTrace1 =
GetProcAddress(gTracing.ext.hDll, "MdmDbgTrace1");
(FARPROC) gTracing.ext.pfnTrace2 =
GetProcAddress(gTracing.ext.hDll, "MdmDbgTrace2");
(FARPROC) gTracing.ext.pfnTrace3 =
GetProcAddress(gTracing.ext.hDll, "MdmDbgTrace3");
(FARPROC) gTracing.ext.pfnTrace4 =
GetProcAddress(gTracing.ext.hDll, "MdmDbgTrace4");
(FARPROC) gTracing.ext.pfnTrace5 =
GetProcAddress(gTracing.ext.hDll, "MdmDbgTrace5");
(FARPROC) gTracing.ext.pfnTrace8 =
GetProcAddress(gTracing.ext.hDll, "MdmDbgTrace8");
}
if ( gTracing.ext.pfnInit
&& gTracing.ext.pfnDeinit
&& gTracing.ext.pfnRegisterObject
&& gTracing.ext.pfnUnRegisterObject
&& gTracing.ext.pfnNotify
&& gTracing.ext.pfnTrace1
&& gTracing.ext.pfnTrace2
&& gTracing.ext.pfnTrace3
&& gTracing.ext.pfnTrace4
&& gTracing.ext.pfnTrace5
&& gTracing.ext.pfnTrace8)
{
fRet = gTracing.ext.pfnInit(dwMDMDBG_CURRENT_VERSION, &dwNegVer);
if (fRet && dwNegVer!=dwMDMDBG_CURRENT_VERSION)
{
fRet=FALSE;
gTracing.ext.pfnDeinit();
}
}
if (!fRet)
{
DPRINTF("trace: Did not bind to MDMDBG.DLL.\n");
if (gTracing.ext.hDll)
{
FreeLibrary(gTracing.ext.hDll);
}
FillMemory(&gTracing.ext, sizeof(gTracing.ext), 0);
}
else
{
DPRINTF("trace: BOUND TO MDMDBG.DLL.\n");
gTracing.dwFlags|=fTRACING_EXTDLLBOUND; // EXTDLLBOUND now returns TRUE
}
return fRet;
}
//****************************************************************************
// Function: Unbinds from the external modem diagnostics dll.
// History:
// 3/31/96 JosephJ Created
//****************************************************************************/
void itraceUnbindFromExternalDll(void)
{
ASSERT(EXTDLLBOUND());
ASSERT(gTracing.ext.hDll);
ASSERT(gTracing.ext.pfnDeinit);
gTracing.ext.pfnDeinit();
FreeLibrary(gTracing.ext.hDll);
FillMemory(&gTracing.ext, sizeof(gTracing.ext), 0);
gTracing.dwFlags&=~fTRACING_EXTDLLBOUND; // EXTDLLBOUND now returns FALSE
}
void CALLBACK itraceEventProc(HTAPILINE htLine,
HTAPICALL htCall,
DWORD dwMsg,
DWORD dwParam1,
DWORD dwParam2,
DWORD dwParam3)
{
TRACE8(IDEVENT_TSPFN_EVENTPROC, htLine, htCall, dwMsg,
dwParam1, dwParam2, dwParam3, 0);
if (gTracing.lineEventProc)
{
gTracing.lineEventProc(htLine, htCall, dwMsg,
dwParam1, dwParam2, dwParam3);
}
}
void CALLBACK itraceTapiCompletionProc(
DRV_REQUESTID dwRequestID,
LONG lResult
)
{
TRACE3(IDEVENT_TSPFN_COMPLETIONPROC, dwRequestID, lResult);
//DPRINTF2("TapiCompletionProc: dwReq = 0x%lx, dwResult=0x%lx\n",
// (DWORD) dwRequestID, (DWORD) lResult);
if (gTracing.TapiCompletionProc)
{
gTracing.TapiCompletionProc(dwRequestID, lResult);
}
}