/* -*- Mode: C++; tab-width: 4; indent-tabs-mode: nil; c-basic-offset: 2 -*- */ /* This Source Code Form is subject to the terms of the Mozilla Public * License, v. 2.0. If a copy of the MPL was not distributed with this * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ /* ** prtrace.c -- NSPR Trace Instrumentation ** ** Implement the API defined in prtrace.h ** ** ** */ #include #include "primpl.h" #define DEFAULT_TRACE_BUFSIZE ( 1024 * 1024 ) #define DEFAULT_BUFFER_SEGMENTS 2 /* ** Enumerate states in a RName structure */ typedef enum TraceState { Running = 1, Suspended = 2 } TraceState; /* ** Define QName structure */ typedef struct QName { PRCList link; PRCList rNameList; char name[PRTRACE_NAME_MAX+1]; } QName; /* ** Define RName structure */ typedef struct RName { PRCList link; PRLock *lock; QName *qName; TraceState state; char name[PRTRACE_NAME_MAX+1]; char desc[PRTRACE_DESC_MAX+1]; } RName; /* ** The Trace Facility database ** */ static PRLogModuleInfo *lm; static PRLock *traceLock; /* Facility Lock */ static PRCList qNameList; /* anchor to all QName structures */ static TraceState traceState = Running; /* ** in-memory trace buffer controls */ static PRTraceEntry *tBuf; /* pointer to buffer */ static PRInt32 bufSize; /* size of buffer, in bytes, rounded up to sizeof(PRTraceEntry) */ static volatile PRInt32 next; /* index to next PRTraceEntry */ static PRInt32 last; /* index of highest numbered trace entry */ /* ** Real-time buffer capture controls */ static PRInt32 fetchLastSeen = 0; static PRBool fetchLostData = PR_FALSE; /* ** Buffer write-to-file controls */ static PRLock *logLock; /* Sync lock */ static PRCondVar *logCVar; /* Sync Condidtion Variable */ /* ** Inter-thread state communication. ** Controling thread writes to logOrder under protection of logCVar ** the logging thread reads logOrder and sets logState on Notify. ** ** logSegments, logCount, logLostData must be read and written under ** protection of logLock, logCVar. ** */ static enum LogState { LogNotRunning, /* Initial state */ LogReset, /* Causes logger to re-calc controls */ LogActive, /* Logging in progress, set only by log thread */ LogSuspend, /* Suspend Logging */ LogResume, /* Resume Logging => LogActive */ LogStop /* Stop the log thread */ } logOrder, logState, localState; /* controlling state variables */ static PRInt32 logSegments; /* Number of buffer segments */ static PRInt32 logEntries; /* number of Trace Entries in the buffer */ static PRInt32 logEntriesPerSegment; /* number of PRTraceEntries per buffer segment */ static PRInt32 logSegSize; /* size of buffer segment */ static PRInt32 logCount; /* number of segments pending output */ static PRInt32 logLostData; /* number of lost log buffer segments */ /* ** end Trace Database ** */ /* ** _PR_InitializeTrace() -- Initialize the trace facility */ static void NewTraceBuffer( PRInt32 size ) { /* ** calculate the size of the buffer ** round down so that each segment has the same number of ** trace entries */ logSegments = DEFAULT_BUFFER_SEGMENTS; logEntries = size / sizeof(PRTraceEntry); logEntriesPerSegment = logEntries / logSegments; logEntries = logSegments * logEntriesPerSegment; bufSize = logEntries * sizeof(PRTraceEntry); logSegSize = logEntriesPerSegment * sizeof(PRTraceEntry); PR_ASSERT( bufSize != 0); PR_LOG( lm, PR_LOG_ERROR, ("NewTraceBuffer: logSegments: %ld, logEntries: %ld, logEntriesPerSegment: %ld, logSegSize: %ld", logSegments, logEntries, logEntriesPerSegment, logSegSize )); tBuf = PR_Malloc( bufSize ); if ( tBuf == NULL ) { PR_LOG( lm, PR_LOG_ERROR, ("PRTrace: Failed to get trace buffer")); PR_ASSERT( 0 ); } else { PR_LOG( lm, PR_LOG_NOTICE, ("PRTrace: Got trace buffer of size: %ld, at %p", bufSize, tBuf)); } next = 0; last = logEntries -1; logCount = 0; logLostData = PR_TRUE; /* not really on first call */ logOrder = LogReset; } /* end NewTraceBuffer() */ /* ** _PR_InitializeTrace() -- Initialize the trace facility */ static void _PR_InitializeTrace( void ) { /* The lock pointer better be null on this call */ PR_ASSERT( traceLock == NULL ); traceLock = PR_NewLock(); PR_ASSERT( traceLock != NULL ); PR_Lock( traceLock ); PR_INIT_CLIST( &qNameList ); lm = PR_NewLogModule("trace"); bufSize = DEFAULT_TRACE_BUFSIZE; NewTraceBuffer( bufSize ); /* Initialize logging controls */ logLock = PR_NewLock(); logCVar = PR_NewCondVar( logLock ); PR_Unlock( traceLock ); return; } /* end _PR_InitializeTrace() */ /* ** Create a Trace Handle */ PR_IMPLEMENT(PRTraceHandle) PR_CreateTrace( const char *qName, /* QName for this trace handle */ const char *rName, /* RName for this trace handle */ const char *description /* description for this trace handle */ ) { QName *qnp; RName *rnp; PRBool matchQname = PR_FALSE; /* Self initialize, if necessary */ if ( traceLock == NULL ) { _PR_InitializeTrace(); } /* Validate input arguments */ PR_ASSERT( strlen(qName) <= PRTRACE_NAME_MAX ); PR_ASSERT( strlen(rName) <= PRTRACE_NAME_MAX ); PR_ASSERT( strlen(description) <= PRTRACE_DESC_MAX ); PR_LOG( lm, PR_LOG_DEBUG, ("PRTRACE: CreateTrace: Qname: %s, RName: %s", qName, rName)); /* Lock the Facility */ PR_Lock( traceLock ); /* Do we already have a matching QName? */ if (!PR_CLIST_IS_EMPTY( &qNameList )) { qnp = (QName *) PR_LIST_HEAD( &qNameList ); do { if ( strcmp(qnp->name, qName) == 0) { matchQname = PR_TRUE; break; } qnp = (QName *)PR_NEXT_LINK( &qnp->link ); } while( qnp != (QName *)&qNameList ); } /* ** If we did not find a matching QName, ** allocate one and initialize it. ** link it onto the qNameList. ** */ if ( matchQname != PR_TRUE ) { qnp = PR_NEWZAP( QName ); PR_ASSERT( qnp != NULL ); PR_INIT_CLIST( &qnp->link ); PR_INIT_CLIST( &qnp->rNameList ); strcpy( qnp->name, qName ); PR_APPEND_LINK( &qnp->link, &qNameList ); } /* Do we already have a matching RName? */ if (!PR_CLIST_IS_EMPTY( &qnp->rNameList )) { rnp = (RName *) PR_LIST_HEAD( &qnp->rNameList ); do { /* ** No duplicate RNames are allowed within a QName ** */ PR_ASSERT( strcmp(rnp->name, rName)); rnp = (RName *)PR_NEXT_LINK( &rnp->link ); } while( rnp != (RName *)&qnp->rNameList ); } /* Get a new RName structure; initialize its members */ rnp = PR_NEWZAP( RName ); PR_ASSERT( rnp != NULL ); PR_INIT_CLIST( &rnp->link ); strcpy( rnp->name, rName ); strcpy( rnp->desc, description ); rnp->lock = PR_NewLock(); rnp->state = Running; if ( rnp->lock == NULL ) { PR_ASSERT(0); } PR_APPEND_LINK( &rnp->link, &qnp->rNameList ); /* add RName to QName's rnList */ rnp->qName = qnp; /* point the RName to the QName */ /* Unlock the Facility */ PR_Unlock( traceLock ); PR_LOG( lm, PR_LOG_DEBUG, ("PRTrace: Create: QName: %s %p, RName: %s %p\n\t", qName, qnp, rName, rnp )); return((PRTraceHandle)rnp); } /* end PR_CreateTrace() */ /* ** */ PR_IMPLEMENT(void) PR_DestroyTrace( PRTraceHandle handle /* Handle to be destroyed */ ) { RName *rnp = (RName *)handle; QName *qnp = rnp->qName; PR_LOG( lm, PR_LOG_DEBUG, ("PRTrace: Deleting: QName: %s, RName: %s", qnp->name, rnp->name)); /* Lock the Facility */ PR_Lock( traceLock ); /* ** Remove RName from the list of RNames in QName ** and free RName */ PR_LOG( lm, PR_LOG_DEBUG, ("PRTrace: Deleting RName: %s, %p", rnp->name, rnp)); PR_REMOVE_LINK( &rnp->link ); PR_Free( rnp->lock ); PR_DELETE( rnp ); /* ** If this is the last RName within QName ** remove QName from the qNameList and free it */ if ( PR_CLIST_IS_EMPTY( &qnp->rNameList ) ) { PR_LOG( lm, PR_LOG_DEBUG, ("PRTrace: Deleting unused QName: %s, %p", qnp->name, qnp)); PR_REMOVE_LINK( &qnp->link ); PR_DELETE( qnp ); } /* Unlock the Facility */ PR_Unlock( traceLock ); return; } /* end PR_DestroyTrace() */ /* ** Create a TraceEntry in the trace buffer */ PR_IMPLEMENT(void) PR_Trace( PRTraceHandle handle, /* use this trace handle */ PRUint32 userData0, /* User supplied data word 0 */ PRUint32 userData1, /* User supplied data word 1 */ PRUint32 userData2, /* User supplied data word 2 */ PRUint32 userData3, /* User supplied data word 3 */ PRUint32 userData4, /* User supplied data word 4 */ PRUint32 userData5, /* User supplied data word 5 */ PRUint32 userData6, /* User supplied data word 6 */ PRUint32 userData7 /* User supplied data word 7 */ ) { PRTraceEntry *tep; PRInt32 mark; if ( (traceState == Suspended ) || ( ((RName *)handle)->state == Suspended )) { return; } /* ** Get the next trace entry slot w/ minimum delay */ PR_Lock( traceLock ); tep = &tBuf[next++]; if ( next > last ) { next = 0; } if ( fetchLostData == PR_FALSE && next == fetchLastSeen ) { fetchLostData = PR_TRUE; } mark = next; PR_Unlock( traceLock ); /* ** We have a trace entry. Fill it in. */ tep->thread = PR_GetCurrentThread(); tep->handle = handle; tep->time = PR_Now(); tep->userData[0] = userData0; tep->userData[1] = userData1; tep->userData[2] = userData2; tep->userData[3] = userData3; tep->userData[4] = userData4; tep->userData[5] = userData5; tep->userData[6] = userData6; tep->userData[7] = userData7; /* When buffer segment is full, signal trace log thread to run */ if (( mark % logEntriesPerSegment) == 0 ) { PR_Lock( logLock ); logCount++; PR_NotifyCondVar( logCVar ); PR_Unlock( logLock ); /* ** Gh0D! This is awful! ** Anyway, to minimize lost trace data segments, ** I inserted the PR_Sleep(0) to cause a context switch ** so that the log thread could run. ** I know, it perturbs the universe and may cause ** funny things to happen in the optimized builds. ** Take it out, lose data; leave it in risk Heisenberg. */ /* PR_Sleep(0); */ } return; } /* end PR_Trace() */ /* ** */ PR_IMPLEMENT(void) PR_SetTraceOption( PRTraceOption command, /* One of the enumerated values */ void *value /* command value or NULL */ ) { RName * rnp; switch ( command ) { case PRTraceBufSize : PR_Lock( traceLock ); PR_Free( tBuf ); bufSize = *(PRInt32 *)value; NewTraceBuffer( bufSize ); PR_Unlock( traceLock ); PR_LOG( lm, PR_LOG_DEBUG, ("PRSetTraceOption: PRTraceBufSize: %ld", bufSize)); break; case PRTraceEnable : rnp = *(RName **)value; rnp->state = Running; PR_LOG( lm, PR_LOG_DEBUG, ("PRSetTraceOption: PRTraceEnable: %p", rnp)); break; case PRTraceDisable : rnp = *(RName **)value; rnp->state = Suspended; PR_LOG( lm, PR_LOG_DEBUG, ("PRSetTraceOption: PRTraceDisable: %p", rnp)); break; case PRTraceSuspend : traceState = Suspended; PR_LOG( lm, PR_LOG_DEBUG, ("PRSetTraceOption: PRTraceSuspend")); break; case PRTraceResume : traceState = Running; PR_LOG( lm, PR_LOG_DEBUG, ("PRSetTraceOption: PRTraceResume")); break; case PRTraceSuspendRecording : PR_Lock( logLock ); logOrder = LogSuspend; PR_NotifyCondVar( logCVar ); PR_Unlock( logLock ); PR_LOG( lm, PR_LOG_DEBUG, ("PRSetTraceOption: PRTraceSuspendRecording")); break; case PRTraceResumeRecording : PR_LOG( lm, PR_LOG_DEBUG, ("PRSetTraceOption: PRTraceResumeRecording")); if ( logState != LogSuspend ) { break; } PR_Lock( logLock ); logOrder = LogResume; PR_NotifyCondVar( logCVar ); PR_Unlock( logLock ); break; case PRTraceStopRecording : PR_Lock( logLock ); logOrder = LogStop; PR_NotifyCondVar( logCVar ); PR_Unlock( logLock ); PR_LOG( lm, PR_LOG_DEBUG, ("PRSetTraceOption: PRTraceStopRecording")); break; case PRTraceLockHandles : PR_LOG( lm, PR_LOG_DEBUG, ("PRSetTraceOption: PRTraceLockTraceHandles")); PR_Lock( traceLock ); break; case PRTraceUnLockHandles : PR_LOG( lm, PR_LOG_DEBUG, ("PRSetTraceOption: PRTraceUnLockHandles")); PR_Unlock( traceLock ); break; default: PR_LOG( lm, PR_LOG_ERROR, ("PRSetTraceOption: Invalid command %ld", command )); PR_ASSERT( 0 ); break; } /* end switch() */ return; } /* end PR_SetTraceOption() */ /* ** */ PR_IMPLEMENT(void) PR_GetTraceOption( PRTraceOption command, /* One of the enumerated values */ void *value /* command value or NULL */ ) { switch ( command ) { case PRTraceBufSize : *((PRInt32 *)value) = bufSize; PR_LOG( lm, PR_LOG_DEBUG, ("PRGetTraceOption: PRTraceBufSize: %ld", bufSize )); break; default: PR_LOG( lm, PR_LOG_ERROR, ("PRGetTraceOption: Invalid command %ld", command )); PR_ASSERT( 0 ); break; } /* end switch() */ return; } /* end PR_GetTraceOption() */ /* ** */ PR_IMPLEMENT(PRTraceHandle) PR_GetTraceHandleFromName( const char *qName, /* QName search argument */ const char *rName /* RName search argument */ ) { const char *qn, *rn, *desc; PRTraceHandle qh, rh = NULL; RName *rnp = NULL; PR_LOG( lm, PR_LOG_DEBUG, ("PRTrace: GetTraceHandleFromName:\n\t" "QName: %s, RName: %s", qName, rName )); qh = PR_FindNextTraceQname( NULL ); while (qh != NULL) { rh = PR_FindNextTraceRname( NULL, qh ); while ( rh != NULL ) { PR_GetTraceNameFromHandle( rh, &qn, &rn, &desc ); if ( (strcmp( qName, qn ) == 0) && (strcmp( rName, rn ) == 0 )) { rnp = (RName *)rh; goto foundIt; } rh = PR_FindNextTraceRname( rh, qh ); } qh = PR_FindNextTraceQname( NULL ); } foundIt: PR_LOG( lm, PR_LOG_DEBUG, ("PR_Counter: GetConterHandleFromName: %p", rnp )); return(rh); } /* end PR_GetTraceHandleFromName() */ /* ** */ PR_IMPLEMENT(void) PR_GetTraceNameFromHandle( PRTraceHandle handle, /* handle as search argument */ const char **qName, /* pointer to associated QName */ const char **rName, /* pointer to associated RName */ const char **description /* pointer to associated description */ ) { RName *rnp = (RName *)handle; QName *qnp = rnp->qName; *qName = qnp->name; *rName = rnp->name; *description = rnp->desc; PR_LOG( lm, PR_LOG_DEBUG, ("PRTrace: GetConterNameFromHandle: " "QNp: %p, RNp: %p,\n\tQName: %s, RName: %s, Desc: %s", qnp, rnp, qnp->name, rnp->name, rnp->desc )); return; } /* end PR_GetTraceNameFromHandle() */ /* ** */ PR_IMPLEMENT(PRTraceHandle) PR_FindNextTraceQname( PRTraceHandle handle ) { QName *qnp = (QName *)handle; if ( PR_CLIST_IS_EMPTY( &qNameList )) { qnp = NULL; } else if ( qnp == NULL ) { qnp = (QName *)PR_LIST_HEAD( &qNameList ); } else if ( PR_NEXT_LINK( &qnp->link ) == &qNameList ) { qnp = NULL; } else { qnp = (QName *)PR_NEXT_LINK( &qnp->link ); } PR_LOG( lm, PR_LOG_DEBUG, ("PRTrace: FindNextQname: Handle: %p, Returns: %p", handle, qnp )); return((PRTraceHandle)qnp); } /* end PR_FindNextTraceQname() */ /* ** */ PR_IMPLEMENT(PRTraceHandle) PR_FindNextTraceRname( PRTraceHandle rhandle, PRTraceHandle qhandle ) { RName *rnp = (RName *)rhandle; QName *qnp = (QName *)qhandle; if ( PR_CLIST_IS_EMPTY( &qnp->rNameList )) { rnp = NULL; } else if ( rnp == NULL ) { rnp = (RName *)PR_LIST_HEAD( &qnp->rNameList ); } else if ( PR_NEXT_LINK( &rnp->link ) == &qnp->rNameList ) { rnp = NULL; } else { rnp = (RName *)PR_NEXT_LINK( &rnp->link ); } PR_LOG( lm, PR_LOG_DEBUG, ("PRTrace: FindNextRname: Rhandle: %p, QHandle: %p, Returns: %p", rhandle, qhandle, rnp )); return((PRTraceHandle)rnp); } /* end PR_FindNextTraceRname() */ /* ** */ static PRFileDesc * InitializeRecording( void ) { char *logFileName; PRFileDesc *logFile; /* Self initialize, if necessary */ if ( traceLock == NULL ) { _PR_InitializeTrace(); } PR_LOG( lm, PR_LOG_DEBUG, ("PR_RecordTraceEntries: begins")); logLostData = 0; /* reset at entry */ logState = LogReset; /* Get the filename for the logfile from the environment */ logFileName = PR_GetEnvSecure( "NSPR_TRACE_LOG" ); if ( logFileName == NULL ) { PR_LOG( lm, PR_LOG_ERROR, ("RecordTraceEntries: Environment variable not defined. Exiting")); return NULL; } /* Open the logfile */ logFile = PR_Open( logFileName, PR_WRONLY | PR_CREATE_FILE, 0666 ); if ( logFile == NULL ) { PR_LOG( lm, PR_LOG_ERROR, ("RecordTraceEntries: Cannot open %s as trace log file. OS error: %ld", logFileName, PR_GetOSError())); return NULL; } return logFile; } /* end InitializeRecording() */ /* ** */ static void ProcessOrders( void ) { switch ( logOrder ) { case LogReset : logOrder = logState = localState; PR_LOG( lm, PR_LOG_DEBUG, ("RecordTraceEntries: LogReset")); break; case LogSuspend : localState = logOrder = logState = LogSuspend; PR_LOG( lm, PR_LOG_DEBUG, ("RecordTraceEntries: LogSuspend")); break; case LogResume : localState = logOrder = logState = LogActive; PR_LOG( lm, PR_LOG_DEBUG, ("RecordTraceEntries: LogResume")); break; case LogStop : logOrder = logState = LogStop; PR_LOG( lm, PR_LOG_DEBUG, ("RecordTraceEntries: LogStop")); break; default : PR_LOG( lm, PR_LOG_ERROR, ("RecordTraceEntries: Invalid logOrder: %ld", logOrder )); PR_ASSERT( 0 ); break; } /* end switch() */ return ; } /* end ProcessOrders() */ /* ** */ static void WriteTraceSegment( PRFileDesc *logFile, void *buf, PRInt32 amount ) { PRInt32 rc; PR_LOG( lm, PR_LOG_ERROR, ("WriteTraceSegment: Buffer: %p, Amount: %ld", buf, amount)); rc = PR_Write( logFile, buf, amount ); if ( rc == -1 ) PR_LOG( lm, PR_LOG_ERROR, ("RecordTraceEntries: PR_Write() failed. Error: %ld", PR_GetError() )); else if ( rc != amount ) PR_LOG( lm, PR_LOG_ERROR, ("RecordTraceEntries: PR_Write() Tried to write: %ld, Wrote: %ld", amount, rc)); else PR_LOG( lm, PR_LOG_DEBUG, ("RecordTraceEntries: PR_Write(): Buffer: %p, bytes: %ld", buf, amount)); return; } /* end WriteTraceSegment() */ /* ** */ PR_IMPLEMENT(void) PR_RecordTraceEntries( void ) { PRFileDesc *logFile; PRInt32 lostSegments; PRInt32 currentSegment = 0; void *buf; PRBool doWrite; logFile = InitializeRecording(); if ( logFile == NULL ) { PR_LOG( lm, PR_LOG_DEBUG, ("PR_RecordTraceEntries: Failed to initialize")); return; } /* Do this until told to stop */ while ( logState != LogStop ) { PR_Lock( logLock ); while ( (logCount == 0) && ( logOrder == logState ) ) { PR_WaitCondVar( logCVar, PR_INTERVAL_NO_TIMEOUT ); } /* Handle state transitions */ if ( logOrder != logState ) { ProcessOrders(); } /* recalculate local controls */ if ( logCount ) { lostSegments = logCount - logSegments; if ( lostSegments > 0 ) { logLostData += ( logCount - logSegments ); logCount = (logCount % logSegments); currentSegment = logCount; PR_LOG( lm, PR_LOG_DEBUG, ("PR_RecordTraceEntries: LostData segments: %ld", logLostData)); } else { logCount--; } buf = tBuf + ( logEntriesPerSegment * currentSegment ); if (++currentSegment >= logSegments ) { currentSegment = 0; } doWrite = PR_TRUE; } else { doWrite = PR_FALSE; } PR_Unlock( logLock ); if ( doWrite == PR_TRUE ) { if ( localState != LogSuspend ) { WriteTraceSegment( logFile, buf, logSegSize ); } else PR_LOG( lm, PR_LOG_DEBUG, ("RecordTraceEntries: PR_Write(): is suspended" )); } } /* end while(logState...) */ PR_Close( logFile ); PR_LOG( lm, PR_LOG_DEBUG, ("RecordTraceEntries: exiting")); return; } /* end PR_RecordTraceEntries() */ /* ** */ PR_IMPLEMENT(PRIntn) PR_GetTraceEntries( PRTraceEntry *buffer, /* where to write output */ PRInt32 count, /* number to get */ PRInt32 *found /* number you got */ ) { PRInt32 rc; PRInt32 copied = 0; PR_Lock( traceLock ); /* ** Depending on where the LastSeen and Next indices are, ** copy the trace buffer in one or two pieces. */ PR_LOG( lm, PR_LOG_ERROR, ("PR_GetTraceEntries: Next: %ld, LastSeen: %ld", next, fetchLastSeen)); if ( fetchLastSeen <= next ) { while (( count-- > 0 ) && (fetchLastSeen < next )) { *(buffer + copied++) = *(tBuf + fetchLastSeen++); } PR_LOG( lm, PR_LOG_ERROR, ("PR_GetTraceEntries: Copied: %ld, LastSeen: %ld", copied, fetchLastSeen)); } else /* copy in 2 parts */ { while ( count-- > 0 && fetchLastSeen <= last ) { *(buffer + copied++) = *(tBuf + fetchLastSeen++); } fetchLastSeen = 0; PR_LOG( lm, PR_LOG_ERROR, ("PR_GetTraceEntries: Copied: %ld, LastSeen: %ld", copied, fetchLastSeen)); while ( count-- > 0 && fetchLastSeen < next ) { *(buffer + copied++) = *(tBuf + fetchLastSeen++); } PR_LOG( lm, PR_LOG_ERROR, ("PR_GetTraceEntries: Copied: %ld, LastSeen: %ld", copied, fetchLastSeen)); } *found = copied; rc = ( fetchLostData == PR_TRUE )? 1 : 0; fetchLostData = PR_FALSE; PR_Unlock( traceLock ); return rc; } /* end PR_GetTraceEntries() */ /* end prtrace.c */