Bug 846942 - Add thread names to log messages
authorAdam Roach [:abr] <adam@nostrum.com>
Tue, 05 Mar 2013 17:23:26 -0600
changeset 123876 db2af0e84527a85607b7fe03c364441ccfaad516
parent 123875 23a1dd29471f8336e18677141667de4625052ab0
child 123877 edcb3f098cceee6263e4fec3a9b3c327dc65951b
push id1401
push userpastithas@mozilla.com
push dateThu, 07 Mar 2013 07:26:45 +0000
treeherderfx-team@ee4879719f78 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
bugs846942
milestone22.0a1
Bug 846942 - Add thread names to log messages
media/webrtc/signaling/src/common/browser_logging/CSFLog.cpp
media/webrtc/signaling/src/sipcc/cpr/android/cpr_android_threads.c
media/webrtc/signaling/src/sipcc/cpr/darwin/cpr_darwin_threads.c
media/webrtc/signaling/src/sipcc/cpr/include/cpr_debug.h
media/webrtc/signaling/src/sipcc/cpr/include/cpr_threads.h
media/webrtc/signaling/src/sipcc/cpr/linux/cpr_linux_threads.c
media/webrtc/signaling/src/sipcc/cpr/win32/cpr_win_threads.c
media/webrtc/signaling/test/signaling_unittests.cpp
--- a/media/webrtc/signaling/src/common/browser_logging/CSFLog.cpp
+++ b/media/webrtc/signaling/src/common/browser_logging/CSFLog.cpp
@@ -5,16 +5,31 @@
 #include <stdio.h>
 #include <string.h>
 #include <stdarg.h>
 
 #include "CSFLog.h"
 #include "base/basictypes.h"
 #include "prtypes.h"
 
+#include <map>
+#include "cpr_threads.h"
+#include "prrwlock.h"
+#include "prthread.h"
+#include "nsThreadUtils.h"
+#ifndef WIN32
+#include <pthread.h>
+#endif
+#ifdef OS_MACOSX
+#include <dlfcn.h>
+#endif
+#ifdef OS_LINUX
+#include <sys/prctl.h>
+#endif
+
 static PRLogModuleInfo *gLogModuleInfo = NULL;
 
 PRLogModuleInfo *GetSignalingLogInfo()
 {
   if (gLogModuleInfo == NULL)
     gLogModuleInfo = PR_NewLogModule("signaling");
 
   return gLogModuleInfo;
@@ -26,47 +41,164 @@ int gWebrtcTraceLoggingOn = 0;
 PRLogModuleInfo *GetWebRTCLogInfo()
 {
   if (gWebRTCLogModuleInfo == NULL)
     gWebRTCLogModuleInfo = PR_NewLogModule("webrtc_trace");
 
   return gWebRTCLogModuleInfo;
 }
 
+extern "C" {
+  void CSFLogRegisterThread(const cprThread_t thread);
+  void CSFLogUnregisterThread(const cprThread_t thread);
+#ifndef WIN32
+  pthread_t cprGetThreadId(cprThread_t thread);
+#endif
+}
+
+#ifdef WIN32
+typedef unsigned int thread_key_t;
+#else
+typedef pthread_t thread_key_t;
+#endif
+static PRRWLock *maplock = PR_NewRWLock(0,"thread map");
+typedef std::map<thread_key_t,const cpr_thread_t*> threadMap_t;
+static threadMap_t threadMap;
+
+void CSFLogRegisterThread(const cprThread_t thread) {
+  const cpr_thread_t *t = reinterpret_cast<cpr_thread_t *>(thread);
+  thread_key_t key;
+#ifdef WIN32
+  key = t->threadId;
+#else
+  key = cprGetThreadId(thread);
+#endif
+
+  CSFLog(CSF_LOG_DEBUG, __FILE__, __LINE__, "log",
+         "Registering new thread with logging system: %s", t->name);
+  PR_RWLock_Wlock(maplock);
+  threadMap[key] = t;
+  PR_RWLock_Unlock(maplock);
+}
+
+void CSFLogUnregisterThread(const cprThread_t thread) {
+  const cpr_thread_t *t = reinterpret_cast<cpr_thread_t *>(thread);
+  thread_key_t key;
+#ifdef WIN32
+  key = t->threadId;
+#else
+  key = cprGetThreadId(thread);
+#endif
+  CSFLog(CSF_LOG_DEBUG, __FILE__, __LINE__, "log",
+         "Unregistering thread from logging system: %s", t->name);
+  PR_RWLock_Wlock(maplock);
+  threadMap.erase(key);
+  PR_RWLock_Unlock(maplock);
+}
+
+const char *CSFCurrentThreadName() {
+  const char *name = nullptr;
+#ifdef WIN32
+  thread_key_t key = GetCurrentThreadId();
+#else
+  thread_key_t key = pthread_self();
+#endif
+  PR_RWLock_Rlock(maplock);
+  threadMap_t::iterator i = threadMap.find(key);
+  if (i != threadMap.end()) {
+    name = i->second->name;
+  }
+  PR_RWLock_Unlock(maplock);
+  return name;
+}
+
+#ifdef OS_MACOSX
+// pthread_getname_np isn't available on all versions of OS X, so
+// we need to load it in dynamically and check for its presence
+static int (*dynamic_pthread_getname_np)(pthread_t,char*,size_t);
+bool init_pthread_getname() {
+  *reinterpret_cast<void**>(&dynamic_pthread_getname_np) =
+      dlsym(RTLD_DEFAULT, "pthread_getname_np");
+  return dynamic_pthread_getname_np;
+}
+static bool have_pthread_getname_np = init_pthread_getname();
+#endif
 
 void CSFLogV(CSFLogLevel priority, const char* sourceFile, int sourceLine, const char* tag , const char* format, va_list args)
 {
 #ifdef STDOUT_LOGGING
   printf("%s\n:",tag);
   vprintf(format, args);
 #else
 
 #define MAX_MESSAGE_LENGTH 1024
   char message[MAX_MESSAGE_LENGTH];
+  char buffer[64] = "";
+
+  const char *threadName = CSFCurrentThreadName();
+
+  // Check if we're the main thread...
+  if (!threadName && NS_IsMainThread()) {
+    threadName = "main";
+  }
+
+  // If null, the name wasn't set up by CPR -- try NSPR
+  if (!threadName) {
+    threadName = PR_GetThreadName(PR_GetCurrentThread());
+  }
+
+  // If not NSPR, it might be from some other imported library that uses
+  // one of the variety of non-portable means of naming threads.
+#ifdef OS_LINUX
+  if (!threadName &&
+    !prctl(PR_GET_NAME,reinterpret_cast<uintptr_t>(buffer),0,0,0)) {
+    buffer[16]='\0';
+    if (buffer[0] != '\0') {
+      threadName = buffer;
+    }
+  }
+#endif
+#ifdef OS_MACOSX
+  if (!threadName && have_pthread_getname_np) {
+    dynamic_pthread_getname_np(pthread_self(), buffer, sizeof(buffer));
+    if (buffer[0] != '\0') {
+      threadName = buffer;
+    }
+  }
+#endif
+
+  // If we can't find it anywhere, use a blank string
+  if (!threadName) {
+    threadName = "";
+  }
 
   vsnprintf(message, MAX_MESSAGE_LENGTH, format, args);
 
   GetSignalingLogInfo();
 
   switch(priority)
   {
     case CSF_LOG_CRITICAL:
     case CSF_LOG_ERROR:
-      PR_LOG(gLogModuleInfo, PR_LOG_ERROR, ("%s %s", tag, message));
+      PR_LOG(gLogModuleInfo, PR_LOG_ERROR, ("[%s] %s %s",
+                                            threadName, tag, message));
       break;
     case CSF_LOG_WARNING:
     case CSF_LOG_INFO:
     case CSF_LOG_NOTICE:
-      PR_LOG(gLogModuleInfo, PR_LOG_WARNING, ("%s %s", tag, message));
+      PR_LOG(gLogModuleInfo, PR_LOG_WARNING, ("[%s] %s %s",
+                                            threadName, tag, message));
       break;
     case CSF_LOG_DEBUG:
-      PR_LOG(gLogModuleInfo, PR_LOG_DEBUG, ("%s %s", tag, message));
+      PR_LOG(gLogModuleInfo, PR_LOG_DEBUG, ("[%s] %s %s",
+                                            threadName, tag, message));
       break;
     default:
-      PR_LOG(gLogModuleInfo, PR_LOG_ALWAYS, ("%s %s", tag, message));
+      PR_LOG(gLogModuleInfo, PR_LOG_ALWAYS, ("[%s] %s %s",
+                                            threadName, tag, message));
   }
 
 #endif
 
 }
 
 void CSFLog( CSFLogLevel priority, const char* sourceFile, int sourceLine, const char* tag , const char* format, ...)
 {
--- a/media/webrtc/signaling/src/sipcc/cpr/android/cpr_android_threads.c
+++ b/media/webrtc/signaling/src/sipcc/cpr/android/cpr_android_threads.c
@@ -11,16 +11,17 @@
 #include <sys/resource.h>
 #include "thread_monitor.h"
 #include "prtypes.h"
 #include "mozilla/Assertions.h"
 
 #define ANDROID_MIN_THREAD_PRIORITY (-20)	/* tbd: check MV linux: current val from Larry port */
 #define ANDROID_MAX_THREAD_PRIORITY (+19)	/* tbd: check MV linux. current val from Larry port */
 
+void CSFLogRegisterThread(const cprThread_t thread);
 
 /**
  * cprCreateThread
  *
  * @brief Create a thread
  *
  *  The cprCreateThread function creates another execution thread within the
  *  current process. If the input parameter "name" is present, then this is used
@@ -88,16 +89,17 @@ cprCreateThread (const char *name,
          * TODO - It would be nice for CPR to keep a linked
          * list of running threads for debugging purposes
          * such as a show command or walking the list to ensure
          * that an application does not attempt to create
          * the same thread twice.
          */
         threadPtr->u.handleInt = threadId;
         threadPtr->threadId = ++id;
+        CSFLogRegisterThread(threadPtr);
         return (cprThread_t)threadPtr;
     }
 
     /* Malloc failed */
     CPR_ERROR("%s - Malloc for thread %s failed.\n", fname, name);
     errno = ENOMEM;
     return (cprThread_t)NULL;
 }
@@ -207,12 +209,11 @@ cprAdjustRelativeThreadPriority (int rel
 pthread_t
 cprGetThreadId (cprThread_t thread)
 {
     if (thread) {
         return ((cpr_thread_t *)thread)->u.handleInt;
     }
     return 0;
 }
-
 /**
   * @}
   */
--- a/media/webrtc/signaling/src/sipcc/cpr/darwin/cpr_darwin_threads.c
+++ b/media/webrtc/signaling/src/sipcc/cpr/darwin/cpr_darwin_threads.c
@@ -12,16 +12,17 @@
 #include "thread_monitor.h"
 #include "prtypes.h"
 #include "mozilla/Assertions.h"
 
 
 #define LINUX_MIN_THREAD_PRIORITY (-20)	/* tbd: check MV linux: current val from Larry port */
 #define LINUX_MAX_THREAD_PRIORITY (+19)	/* tbd: check MV linux. current val from Larry port */
 
+void CSFLogRegisterThread(const cprThread_t thread);
 
 /**
  * cprCreateThread
  *
  * @brief Create a thread
  *
  *  The cprCreateThread function creates another execution thread within the
  *  current process. If the input parameter "name" is present, then this is used
@@ -87,16 +88,17 @@ cprCreateThread (const char *name,
          * TODO - It would be nice for CPR to keep a linked
          * list of running threads for debugging purposes
          * such as a show command or walking the list to ensure
          * that an application does not attempt to create
          * the same thread twice.
          */
         threadPtr->u.handlePtr = threadId;
         threadPtr->threadId = ++id;
+        CSFLogRegisterThread(threadPtr);
         return threadPtr;
     }
 
     /* Malloc failed */
     CPR_ERROR("%s - Malloc for thread %s failed.\n", fname, name);
     errno = ENOMEM;
     return NULL;
 }
@@ -206,9 +208,8 @@ cprAdjustRelativeThreadPriority (int rel
 pthread_t
 cprGetThreadId (cprThread_t thread)
 {
     if (thread) {
         return ((cpr_thread_t *)thread)->u.handlePtr;
     }
     return 0;
 }
-
--- a/media/webrtc/signaling/src/sipcc/cpr/include/cpr_debug.h
+++ b/media/webrtc/signaling/src/sipcc/cpr/include/cpr_debug.h
@@ -11,14 +11,14 @@
 __BEGIN_DECLS
 
 /**
  * CPR debugging flag - MUST be defined at some place in CPR code so that
  * debugging/logging is possible.
  */
 extern int32_t cprInfo;
 
-#define CPR_INFO if (cprInfo) buginf
+#define CPR_INFO if (cprInfo) notice_msg
 #define CPR_ERROR err_msg
 
 __END_DECLS
 
 #endif
--- a/media/webrtc/signaling/src/sipcc/cpr/include/cpr_threads.h
+++ b/media/webrtc/signaling/src/sipcc/cpr/include/cpr_threads.h
@@ -122,12 +122,11 @@ cprRC_t cprDestroyThread(cprThread_t thr
  * media or timer processing on your system.
  *
  * @param[in] relPri - normalized relative Priority of the thread [-20,+19]
  *
  * @return CPR_SUCCESS or CPR_FAILURE
  */
 cprRC_t cprAdjustRelativeThreadPriority(int relPri);
 
-
 __END_DECLS
 
 #endif
--- a/media/webrtc/signaling/src/sipcc/cpr/linux/cpr_linux_threads.c
+++ b/media/webrtc/signaling/src/sipcc/cpr/linux/cpr_linux_threads.c
@@ -11,16 +11,17 @@
 #include <pthread.h>
 #include <errno.h>
 #include <unistd.h>
 #include <sys/resource.h>
 
 #define LINUX_MIN_THREAD_PRIORITY (-20)	/* tbd: check MV linux: current val from Larry port */
 #define LINUX_MAX_THREAD_PRIORITY (+19)	/* tbd: check MV linux. current val from Larry port */
 
+void CSFLogRegisterThread(const cprThread_t thread);
 
 /**
  * cprCreateThread
  *
  * @brief Create a thread
  *
  *  The cprCreateThread function creates another execution thread within the
  *  current process. If the input parameter "name" is present, then this is used
@@ -88,16 +89,17 @@ cprCreateThread (const char *name,
          * TODO - It would be nice for CPR to keep a linked
          * list of running threads for debugging purposes
          * such as a show command or walking the list to ensure
          * that an application does not attempt to create
          * the same thread twice.
          */
         threadPtr->u.handleInt = threadId;
         threadPtr->threadId = ++id;
+        CSFLogRegisterThread(threadPtr);
         return (cprThread_t)threadPtr;
     }
 
     /* Malloc failed */
     CPR_ERROR("%s - Malloc for thread %s failed.\n", fname, name);
     errno = ENOMEM;
     return (cprThread_t)NULL;
 }
@@ -207,12 +209,11 @@ cprAdjustRelativeThreadPriority (int rel
 pthread_t
 cprGetThreadId (cprThread_t thread)
 {
     if (thread) {
         return ((cpr_thread_t *)thread)->u.handleInt;
     }
     return 0;
 }
-
 /**
   * @}
   */
--- a/media/webrtc/signaling/src/sipcc/cpr/win32/cpr_win_threads.c
+++ b/media/webrtc/signaling/src/sipcc/cpr/win32/cpr_win_threads.c
@@ -13,16 +13,18 @@
 
 #ifndef WIN32_LEAN_AND_MEAN
 #define WIN32_LEAN_AND_MEAN
 #endif
 
 #include <windows.h>
 #include <process.h>
 
+void CSFLogRegisterThread(const cprThread_t thread);
+
 typedef struct {
     cprThreadStartRoutine startRoutine;
 	void *data;
 	HANDLE event;
 } startThreadData;
 
 unsigned __stdcall
 cprStartThread (void *arg)
@@ -200,16 +202,18 @@ cprCreateThread(const char* name,
 			}
 			CloseHandle( serialize_lock );
 		}
     } else {
         /* Malloc failed */
         CPR_ERROR("%s - Malloc for new thread failed.\n", fname);
     }
 
+    CSFLogRegisterThread(threadPtr);
+
     return(threadPtr);
 };
 
 
 /*
  * cprJoinThread
  *
  * wait for thread termination
--- a/media/webrtc/signaling/test/signaling_unittests.cpp
+++ b/media/webrtc/signaling/test/signaling_unittests.cpp
@@ -119,17 +119,17 @@ enum offerAnswerFlags
   OFFER_AV = OFFER_AUDIO | OFFER_VIDEO,
   ANSWER_AV = ANSWER_AUDIO | ANSWER_VIDEO
 };
 
 static bool SetupGlobalThread() {
   if (!gThread) {
     nsIThread *thread;
 
-    nsresult rv = NS_NewThread(&thread);
+    nsresult rv = NS_NewNamedThread("pseudo-main",&thread);
     if (NS_FAILED(rv))
       return false;
 
     gThread = thread;
   }
   return true;
 }