/* print a single mutex log entry */
static void dbgMutLogPrintOne(dbgMutLog_t *pLog)
{
char *strmutop;
char buf[64];
char pszThrdName[64];
assert(pLog != NULL);
switch(pLog->mutexOp) {
case MUTOP_LOCKWAIT:
strmutop = "waited on";
break;
case MUTOP_LOCK:
strmutop = "owned";
break;
default:
snprintf(buf, sizeof(buf)/sizeof(char), "unknown state %d - should not happen!", pLog->mutexOp);
strmutop = buf;
break;
}
dbgGetThrdName(pszThrdName, sizeof(pszThrdName), pLog->thrd, 1);
dbgprintf("mutex 0x%lx is being %s by code at %s:%d, thread %s\n", (unsigned long) pLog->mut,
strmutop, pLog->pFuncDB->file,
(pLog->mutexOp == MUTOP_LOCK) ? pLog->lockLn : pLog->pFuncDB->line,
pszThrdName);
}
/* print any mutex that can be found in the FuncDB. Custom header is provided.
* "thrd" is the thread that is searched. If it is 0, mutexes for all threads
* shall be printed.
*/
static inline void
dbgFuncDBPrintActiveMutexes(dbgFuncDB_t *pFuncDB, char *pszHdrText, pthread_t thrd)
{
int i;
char pszThrdName[64];
for(i = 0 ; i < SIZE_FUNCDB_MUTEX_TABLE(pFuncDB) ; ++i) {
if(pFuncDB->mutInfo[i].lockLn != -1 && (thrd == 0 || thrd == pFuncDB->mutInfo[i].thrd)) {
dbgGetThrdName(pszThrdName, sizeof(pszThrdName), pFuncDB->mutInfo[i].thrd, 1);
dbgprintf("%s:%d:%s:invocation %ld: %s %p[%d/%s]\n", pFuncDB->file, pFuncDB->line, pFuncDB->func,
pFuncDB->mutInfo[i].lInvocation, pszHdrText, (void*)pFuncDB->mutInfo[i].pmut, i,
pszThrdName);
}
}
}
/* print a thread's call stack
*/
static void dbgCallStackPrint(dbgThrdInfo_t *pThrd)
{
int i;
char pszThrdName[64];
pthread_mutex_lock(&mutCallStack);
dbgGetThrdName(pszThrdName, sizeof(pszThrdName), pThrd->thrd, 1);
dbgprintf("\n");
dbgprintf("Recorded Call Order for Thread '%s':\n", pszThrdName);
for(i = 0 ; i < pThrd->stackPtr ; i++) {
dbgprintf("%d: %s:%d:%s:\n", i, pThrd->callStack[i]->file, pThrd->lastLine[i], pThrd->callStack[i]->func);
}
dbgprintf("maximum number of nested calls for this thread: %d.\n", pThrd->stackPtrMax);
dbgprintf("NOTE: not all calls may have been recorded, code does not currently guarantee that!\n");
pthread_mutex_unlock(&mutCallStack);
}
/* report trylock on a mutex and add it to the mutex log */
static inline void dbgMutexPreTryLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln)
{
dbgMutLog_t *pHolder;
char pszBuf[128];
char pszHolderThrdName[64];
char *pszHolder;
pthread_mutex_lock(&mutMutLog);
pHolder = dbgMutLogFindHolder(pmut);
dbgMutLogAddEntry(pmut, MUTOP_TRYLOCK, pFuncDB, ln);
if(pHolder == NULL)
pszHolder = "[NONE]";
else {
dbgGetThrdName(pszHolderThrdName, sizeof(pszHolderThrdName), pHolder->thrd, 1);
snprintf(pszBuf, sizeof(pszBuf), "%s:%d [%s]", pHolder->pFuncDB->file, pHolder->lockLn, pszHolderThrdName);
pszHolder = pszBuf;
}
if(bPrintMutexAction)
dbgprintf("%s:%d:%s: mutex %p trying to get lock, held by %s\n", pFuncDB->file, ln, pFuncDB->func, (void*)pmut, pszHolder);
pthread_mutex_unlock(&mutMutLog);
}
/* actually write the debug message. This is a separate fuction because the cleanup_push/_pop
* interface otherwise is unsafe to use (generates compiler warnings at least).
* 2009-05-20 rgerhards
*/
static inline void
do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg)
{
static pthread_t ptLastThrdID = 0;
static int bWasNL = 0;
char pszThrdName[64]; /* 64 is to be on the safe side, anything over 20 is bad... */
char pszWriteBuf[32*1024];
size_t lenWriteBuf;
struct timespec t;
# if _POSIX_TIMERS <= 0
struct timeval tv;
# endif
/* The bWasNL handler does not really work. It works if no thread
* switching occurs during non-NL messages. Else, things are messed
* up. Anyhow, it works well enough to provide useful help during
* getting this up and running. It is questionable if the extra effort
* is worth fixing it, giving the limited appliability. -- rgerhards, 2005-10-25
* I have decided that it is not worth fixing it - especially as it works
* pretty well. -- rgerhards, 2007-06-15
*/
if(ptLastThrdID != pthread_self()) {
if(!bWasNL) {
if(stddbg != -1) write(stddbg, "\n", 1);
if(altdbg != -1) write(altdbg, "\n", 1);
bWasNL = 1;
}
ptLastThrdID = pthread_self();
}
/* do not cache the thread name, as the caller might have changed it
* TODO: optimized, invalidate cache when new name is set
*/
dbgGetThrdName(pszThrdName, sizeof(pszThrdName), ptLastThrdID, 0);
if(bWasNL) {
if(bPrintTime) {
# if _POSIX_TIMERS > 0
/* this is the "regular" code */
clock_gettime(CLOCK_REALTIME, &t);
# else
gettimeofday(&tv, NULL);
t.tv_sec = tv.tv_sec;
t.tv_nsec = tv.tv_usec * 1000;
# endif
lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf),
"%4.4ld.%9.9ld:", (long) (t.tv_sec % 10000), t.tv_nsec);
if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf);
if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf);
}
lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%s: ", pszThrdName);
// use for testing: lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "{%ld}%s: ", (long) syscall(SYS_gettid), pszThrdName);
if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf);
if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf);
/* print object name header if we have an object */
if(pszObjName != NULL) {
lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%s: ", pszObjName);
if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf);
if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf);
}
}
if(stddbg != -1) write(stddbg, pszMsg, lenMsg);
if(altdbg != -1) write(altdbg, pszMsg, lenMsg);
bWasNL = (pszMsg[lenMsg - 1] == '\n') ? 1 : 0;
}
/* write the debug message. This is a helper to dbgprintf and dbgoprint which
* contains common code. added 2008-09-26 rgerhards
*/
static void
dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg)
{
static pthread_t ptLastThrdID = 0;
static int bWasNL = 0;
char pszThrdName[64]; /* 64 is to be on the safe side, anything over 20 is bad... */
char pszWriteBuf[32*1024];
size_t lenWriteBuf;
struct timespec t;
uchar *pszObjName = NULL;
/* we must get the object name before we lock the mutex, because the object
* potentially calls back into us. If we locked the mutex, we would deadlock
* ourselfs. On the other hand, the GetName call needs not to be protected, as
* this thread has a valid reference. If such an object is deleted by another
* thread, we are in much more trouble than just for dbgprint(). -- rgerhards, 2008-09-26
*/
if(pObj != NULL) {
pszObjName = obj.GetName(pObj);
}
pthread_mutex_lock(&mutdbgprint);
pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgprint);
/* The bWasNL handler does not really work. It works if no thread
* switching occurs during non-NL messages. Else, things are messed
* up. Anyhow, it works well enough to provide useful help during
* getting this up and running. It is questionable if the extra effort
* is worth fixing it, giving the limited appliability. -- rgerhards, 2005-10-25
* I have decided that it is not worth fixing it - especially as it works
* pretty well. -- rgerhards, 2007-06-15
*/
if(ptLastThrdID != pthread_self()) {
if(!bWasNL) {
if(stddbg != -1) write(stddbg, "\n", 1);
if(altdbg != -1) write(altdbg, "\n", 1);
bWasNL = 1;
}
ptLastThrdID = pthread_self();
}
/* do not cache the thread name, as the caller might have changed it
* TODO: optimized, invalidate cache when new name is set
*/
dbgGetThrdName(pszThrdName, sizeof(pszThrdName), ptLastThrdID, 0);
if(bWasNL) {
if(bPrintTime) {
clock_gettime(CLOCK_REALTIME, &t);
lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf),
"%4.4ld.%9.9ld:", (long) (t.tv_sec % 10000), t.tv_nsec);
if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf);
if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf);
}
lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%s: ", pszThrdName);
// use for testing: lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "{%ld}%s: ", (long) syscall(SYS_gettid), pszThrdName);
if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf);
if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf);
/* print object name header if we have an object */
if(pszObjName != NULL) {
lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%s: ", pszObjName);
if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf);
if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf);
}
}
if(stddbg != -1) write(stddbg, pszMsg, lenMsg);
if(altdbg != -1) write(altdbg, pszMsg, lenMsg);
bWasNL = (pszMsg[lenMsg - 1] == '\n') ? 1 : 0;
pthread_cleanup_pop(1);
}
/* actually write the debug message. This is a separate fuction because the cleanup_push/_pop
* interface otherwise is unsafe to use (generates compiler warnings at least).
* 2009-05-20 rgerhards
*/
static inline void
do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg)
{
static pthread_t ptLastThrdID = 0;
static int bWasNL = 0;
char pszThrdName[64]; /* 64 is to be on the safe side, anything over 20 is bad... */
char pszWriteBuf[32*1024];
size_t lenCopy;
size_t offsWriteBuf = 0;
size_t lenWriteBuf;
struct timespec t;
# if _POSIX_TIMERS <= 0
struct timeval tv;
# endif
#if 1
/* The bWasNL handler does not really work. It works if no thread
* switching occurs during non-NL messages. Else, things are messed
* up. Anyhow, it works well enough to provide useful help during
* getting this up and running. It is questionable if the extra effort
* is worth fixing it, giving the limited appliability. -- rgerhards, 2005-10-25
* I have decided that it is not worth fixing it - especially as it works
* pretty well. -- rgerhards, 2007-06-15
*/
if(ptLastThrdID != pthread_self()) {
if(!bWasNL) {
pszWriteBuf[0] = '\n';
offsWriteBuf = 1;
bWasNL = 1;
}
ptLastThrdID = pthread_self();
}
/* do not cache the thread name, as the caller might have changed it
* TODO: optimized, invalidate cache when new name is set
*/
dbgGetThrdName(pszThrdName, sizeof(pszThrdName), ptLastThrdID, 0);
if(bWasNL) {
if(bPrintTime) {
# if _POSIX_TIMERS > 0
/* this is the "regular" code */
clock_gettime(CLOCK_REALTIME, &t);
# else
gettimeofday(&tv, NULL);
t.tv_sec = tv.tv_sec;
t.tv_nsec = tv.tv_usec * 1000;
# endif
lenWriteBuf = snprintf(pszWriteBuf+offsWriteBuf, sizeof(pszWriteBuf) - offsWriteBuf,
"%4.4ld.%9.9ld:", (long) (t.tv_sec % 10000), t.tv_nsec);
offsWriteBuf += lenWriteBuf;
}
lenWriteBuf = snprintf(pszWriteBuf + offsWriteBuf, sizeof(pszWriteBuf) - offsWriteBuf, "%s: ", pszThrdName);
offsWriteBuf += lenWriteBuf;
/* print object name header if we have an object */
if(pszObjName != NULL) {
lenWriteBuf = snprintf(pszWriteBuf + offsWriteBuf, sizeof(pszWriteBuf) - offsWriteBuf, "%s: ", pszObjName);
offsWriteBuf += lenWriteBuf;
}
}
#endif
if(lenMsg > sizeof(pszWriteBuf) - offsWriteBuf)
lenCopy = sizeof(pszWriteBuf) - offsWriteBuf;
else
lenCopy = lenMsg;
memcpy(pszWriteBuf + offsWriteBuf, pszMsg, lenCopy);
offsWriteBuf += lenCopy;
/* the write is included in an "if" just to silence compiler
* warnings. Here, we really don't care if the write fails, we
* have no good response to that in any case... -- rgerhards, 2012-11-28
*/
if(stddbg != -1) if(write(stddbg, pszWriteBuf, offsWriteBuf)){};
if(altdbg != -1) if(write(altdbg, pszWriteBuf, offsWriteBuf)){};
bWasNL = (pszMsg[lenMsg - 1] == '\n') ? 1 : 0;
}
