Implement backend for thread names and process names.

Added a new trace event phase 'M'/TRACE_EVENT_PHASE_METADATA,
which can become a general mechanism for adding metadata to traces.

The two M-type events that we then add are:
	{ph=M pid=<pid> name="process_name" args={ name="name of pid" }}
	{ph=M pid=<pid> tid=<tid> name="thread_name" args={ name="name of tid" }}

base::thread is instrumented to set names automatically. I will do a followon
changelist to add instrumentation to Chrome for its various processes and
threads.

Review URL: http://codereview.chromium.org/7495031

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@95997 0039d316-1c4b-4281-b951-d872f2087c98

base/debug/trace_event.cc

@@ -4,6 +4,8 @@
 
 #include "base/debug/trace_event.h"
 
+#include <algorithm>
+
 #if defined(OS_WIN)
 #include "base/debug/trace_event_win.h"
 #endif
@@ -11,6 +13,7 @@
 #include "base/memory/ref_counted_memory.h"
 #include "base/process_util.h"
 #include "base/stringprintf.h"
+#include "base/threading/thread_local.h"
 #include "base/utf_string_conversions.h"
 #include "base/stl_util.h"
 #include "base/time.h"
@@ -30,13 +33,20 @@ const size_t kTraceEventBatchSize = 1000;
 static TraceCategory g_categories[TRACE_EVENT_MAX_CATEGORIES] = {
   { "tracing already shutdown", false },
   { "tracing categories exhausted; must increase TRACE_EVENT_MAX_CATEGORIES",
+    false },
+  { "__metadata",
     false }
 };
 static const TraceCategory* const g_category_already_shutdown =
     &g_categories[0];
 static const TraceCategory* const g_category_categories_exhausted =
     &g_categories[1];
-static int g_category_index = 2; // skip initial 2 error categories
+static const TraceCategory* const g_category_metadata =
+    &g_categories[2];
+static int g_category_index = 3; // skip initial 3 categories
+
+// Flag to indicate whether we captured the current thread name
+static ThreadLocalBoolean g_current_thread_name_captured;
 
 ////////////////////////////////////////////////////////////////////////////////
 //
@@ -104,6 +114,8 @@ const char* GetPhaseStr(TraceEventPhase phase) {
       return "I";
     case TRACE_EVENT_PHASE_END:
       return "E";
+    case TRACE_EVENT_PHASE_METADATA:
+      return "M";
     default:
       NOTREACHED() << "Invalid phase argument";
       return "?";
@@ -294,9 +306,13 @@ void TraceLog::SetEnabled(bool enabled) {
       // check GetCategoryInternal creation code that users TraceLog::enabled_
       g_categories[i].enabled = enabled;
     }
+
+    if (!enabled)
+      AddCurrentMetadataEvents();
   } // release lock
-  if (!enabled)
+  if (!enabled) {
     Flush();
+  }
 }
 
 float TraceLog::GetBufferPercentFull() const {
@@ -361,6 +377,33 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase,
       return -1;
     if (logged_events_.size() >= kTraceEventBufferSize)
       return -1;
+
+    PlatformThreadId thread_id = PlatformThread::CurrentId();
+
+    // Record the name of the calling thread, if not done already.
+    if (!g_current_thread_name_captured.Get()) {
+      const char* cur_name = PlatformThread::GetName();
+      base::hash_map<PlatformThreadId, std::string>::iterator existing_name =
+          thread_names_.find(thread_id);
+      if (existing_name == thread_names_.end()) {
+        // This is a new thread id, and a new name.
+        thread_names_[thread_id] = cur_name ? cur_name : "";
+      } else if(cur_name != NULL) {
+        // This is a thread id that we've seen before, but potentially with a
+        // new name.
+        std::vector<std::string> existing_names;
+        Tokenize(existing_name->second, std::string(","), &existing_names);
+        bool found = std::find(existing_names.begin(),
+                               existing_names.end(),
+                               cur_name) != existing_names.end();
+        if (!found) {
+          existing_names.push_back(cur_name);
+          thread_names_[thread_id] =
+              JoinString(existing_names, ',');
+        }
+      }
+    }
+
     if (threshold_begin_id > -1) {
       DCHECK(phase == base::debug::TRACE_EVENT_PHASE_END);
       size_t begin_i = static_cast<size_t>(threshold_begin_id);
@@ -380,7 +423,7 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase,
     ret_begin_id = static_cast<int>(logged_events_.size());
     logged_events_.push_back(
         TraceEvent(static_cast<unsigned long>(base::GetCurrentProcId()),
-                   PlatformThread::CurrentId(),
+                   thread_id,
                    now, phase, category, name,
                    arg1_name, arg1_val,
                    arg2_name, arg2_val,
@@ -419,6 +462,24 @@ void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
   }
 }
 
+void TraceLog::AddCurrentMetadataEvents() {
+  lock_.AssertAcquired();
+  for(base::hash_map<PlatformThreadId, std::string>::iterator it =
+          thread_names_.begin();
+      it != thread_names_.end();
+      it++) {
+    if (!it->second.empty())
+      logged_events_.push_back(
+          TraceEvent(static_cast<unsigned long>(base::GetCurrentProcId()),
+                     it->first,
+                     TimeTicks(), base::debug::TRACE_EVENT_PHASE_METADATA,
+                     g_category_metadata, "thread_name",
+                     "name", it->second.c_str(),
+                     NULL, 0,
+                     false));
+  }
+}
+
 void TraceLog::Resurrect() {
   StaticMemorySingletonTraits<TraceLog>::Resurrect();
 }

base/debug/trace_event.h

@@ -90,6 +90,7 @@
 #include <vector>
 
 #include "base/callback.h"
+#include "base/hash_tables.h"
 #include "base/memory/singleton.h"
 #include "base/string_util.h"
 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
@@ -296,7 +297,8 @@ const size_t kTraceMaxNumArgs = 2;
 enum TraceEventPhase {
   TRACE_EVENT_PHASE_BEGIN,
   TRACE_EVENT_PHASE_END,
-  TRACE_EVENT_PHASE_INSTANT
+  TRACE_EVENT_PHASE_INSTANT,
+  TRACE_EVENT_PHASE_METADATA
 };
 
 // Simple union of values. This is much lighter weight than base::Value, which
@@ -512,6 +514,7 @@ class BASE_EXPORT TraceLog {
   TraceLog();
   ~TraceLog();
   const TraceCategory* GetCategoryInternal(const char* name);
+  void AddCurrentMetadataEvents();
 
   // TODO(nduca): switch to per-thread trace buffers to reduce thread
   // synchronization.
@@ -521,6 +524,8 @@ class BASE_EXPORT TraceLog {
   BufferFullCallback buffer_full_callback_;
   std::vector<TraceEvent> logged_events_;
 
+  base::hash_map<PlatformThreadId, std::string> thread_names_;
+
   DISALLOW_COPY_AND_ASSIGN(TraceLog);
 };
 

base/debug/trace_event_unittest.cc

@@ -9,6 +9,7 @@
 #include "base/json/json_reader.h"
 #include "base/json/json_writer.h"
 #include "base/memory/scoped_ptr.h"
+#include "base/process_util.h"
 #include "base/stringprintf.h"
 #include "base/synchronization/waitable_event.h"
 #include "base/threading/thread.h"
@@ -154,7 +155,7 @@ bool IsStringInDict(const char* string_to_match, DictionaryValue* dict) {
 }
 
 DictionaryValue* FindTraceEntry(const ListValue& trace_parsed,
-                                const char *string_to_match,
+                                const char* string_to_match,
                                 DictionaryValue* match_after_this_item = NULL) {
   // Scan all items
   size_t trace_parsed_count = trace_parsed.GetSize();
@@ -176,7 +177,25 @@ DictionaryValue* FindTraceEntry(const ListValue& trace_parsed,
   return NULL;
 }
 
-void DataCapturedCallTraces(WaitableEvent* task_complete_event) {
+std::vector<DictionaryValue*> FindTraceEntries(
+    const ListValue& trace_parsed,
+    const char* string_to_match) {
+  std::vector<DictionaryValue*> hits;
+  size_t trace_parsed_count = trace_parsed.GetSize();
+  for (size_t i = 0; i < trace_parsed_count; i++) {
+    Value* value = NULL;
+    trace_parsed.Get(i, &value);
+    if (!value || value->GetType() != Value::TYPE_DICTIONARY)
+      continue;
+    DictionaryValue* dict = static_cast<DictionaryValue*>(value);
+
+    if (IsStringInDict(string_to_match, dict))
+      hits.push_back(dict);
+  }
+  return hits;
+}
+
+void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
   {
     TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 1122, "extrastring1");
     TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 3344, "extrastring2");
@@ -212,7 +231,7 @@ void DataCapturedCallTraces(WaitableEvent* task_complete_event) {
     task_complete_event->Signal();
 }
 
-void DataCapturedValidateTraces(const ListValue& trace_parsed,
+void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed,
                                  const std::string& trace_string) {
   DictionaryValue* item = NULL;
 
@@ -275,6 +294,57 @@ void DataCapturedValidateTraces(const ListValue& trace_parsed,
   EXPECT_SUB_FIND_("value2");
 }
 
+void TraceManyInstantEvents(int thread_id, int num_events,
+                                 WaitableEvent* task_complete_event) {
+  for (int i = 0; i < num_events; i++) {
+    TRACE_EVENT_INSTANT2("all", "multi thread event",
+                         "thread", thread_id,
+                         "event", i);
+  }
+
+  if (task_complete_event)
+    task_complete_event->Signal();
+}
+
+void ValidateInstantEventPresentOnEveryThread(const ListValue& trace_parsed,
+                                     const std::string& trace_string,
+                                     int num_threads, int num_events) {
+  std::map<int, std::map<int, bool> > results;
+
+  size_t trace_parsed_count = trace_parsed.GetSize();
+  for (size_t i = 0; i < trace_parsed_count; i++) {
+    Value* value = NULL;
+    trace_parsed.Get(i, &value);
+    if (!value || value->GetType() != Value::TYPE_DICTIONARY)
+      continue;
+    DictionaryValue* dict = static_cast<DictionaryValue*>(value);
+    std::string name;
+    dict->GetString("name", &name);
+    if (name != "multi thread event")
+      continue;
+
+    int thread = 0;
+    int event = 0;
+    EXPECT_TRUE(dict->GetInteger("args.thread", &thread));
+    EXPECT_TRUE(dict->GetInteger("args.event", &event));
+    results[thread][event] = true;
+  }
+
+  EXPECT_FALSE(results[-1][-1]);
+  for (int thread = 0; thread < num_threads; thread++) {
+    for (int event = 0; event < num_events; event++) {
+      EXPECT_TRUE(results[thread][event]);
+    }
+  }
+}
+
+void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) {
+  TRACE_EVENT0("category name1", name_str);
+  TRACE_EVENT_INSTANT0("category name2", name_str);
+  TRACE_EVENT_BEGIN0("category name3", name_str);
+  TRACE_EVENT_END0("category name4", name_str);
+}
+
 }  // namespace
 
 // Simple Test for emitting data and validating it was received.
@@ -282,11 +352,11 @@ TEST_F(TraceEventTestFixture, DataCaptured) {
   ManualTestSetUp();
   TraceLog::GetInstance()->SetEnabled(true);
 
-  DataCapturedCallTraces(NULL);
+  TraceWithAllMacroVariants(NULL);
 
   TraceLog::GetInstance()->SetEnabled(false);
 
-  DataCapturedValidateTraces(trace_parsed_, trace_string_);
+  ValidateAllTraceMacrosCreatedData(trace_parsed_, trace_string_);
 }
 
 // Simple Test for time threshold events.
@@ -402,103 +472,116 @@ TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
   thread.Start();
 
   thread.message_loop()->PostTask(
-    FROM_HERE, NewRunnableFunction(&DataCapturedCallTraces,
+    FROM_HERE, NewRunnableFunction(&TraceWithAllMacroVariants,
                                    &task_complete_event));
   task_complete_event.Wait();
 
   TraceLog::GetInstance()->SetEnabled(false);
   thread.Stop();
-  DataCapturedValidateTraces(trace_parsed_, trace_string_);
+  ValidateAllTraceMacrosCreatedData(trace_parsed_, trace_string_);
 }
 
-namespace {
+// Test that data sent from multiple threads is gathered
+TEST_F(TraceEventTestFixture, DataCapturedManyThreads) {
+  ManualTestSetUp();
+  TraceLog::GetInstance()->SetEnabled(true);
 
-void DataCapturedCallManyTraces(int thread_id, int num_events,
-                                 WaitableEvent* task_complete_event) {
-  for (int i = 0; i < num_events; i++) {
-    TRACE_EVENT_INSTANT2("all", "multi thread event",
-                         "thread", thread_id,
-                         "event", i);
+  const int num_threads = 4;
+  const int num_events = 4000;
+  Thread* threads[num_threads];
+  WaitableEvent* task_complete_events[num_threads];
+  for (int i = 0; i < num_threads; i++) {
+    threads[i] = new Thread(StringPrintf("Thread %d", i).c_str());
+    task_complete_events[i] = new WaitableEvent(false, false);
+    threads[i]->Start();
+    threads[i]->message_loop()->PostTask(
+      FROM_HERE, NewRunnableFunction(&TraceManyInstantEvents,
+                                     i, num_events, task_complete_events[i]));
   }
 
-  if (task_complete_event)
-    task_complete_event->Signal();
-}
-
-void DataCapturedValidateManyTraces(const ListValue& trace_parsed,
-                                     const std::string& trace_string,
-                                     int num_threads, int num_events) {
-  std::map<int, std::map<int, bool> > results;
+  for (int i = 0; i < num_threads; i++) {
+    task_complete_events[i]->Wait();
+  }
 
-  size_t trace_parsed_count = trace_parsed.GetSize();
-  for (size_t i = 0; i < trace_parsed_count; i++) {
-    Value* value = NULL;
-    trace_parsed.Get(i, &value);
-    if (!value || value->GetType() != Value::TYPE_DICTIONARY)
-      continue;
-    DictionaryValue* dict = static_cast<DictionaryValue*>(value);
-    std::string name;
-    dict->GetString("name", &name);
-    if (name != "multi thread event")
-      continue;
+  TraceLog::GetInstance()->SetEnabled(false);
 
-    int thread = 0;
-    int event = 0;
-    EXPECT_TRUE(dict->GetInteger("args.thread", &thread));
-    EXPECT_TRUE(dict->GetInteger("args.event", &event));
-    results[thread][event] = true;
+  for (int i = 0; i < num_threads; i++) {
+    threads[i]->Stop();
+    delete threads[i];
+    delete task_complete_events[i];
   }
 
-  EXPECT_FALSE(results[-1][-1]);
-  for (int thread = 0; thread < num_threads; thread++) {
-    for (int event = 0; event < num_events; event++) {
-      EXPECT_TRUE(results[thread][event]);
-    }
-  }
+  ValidateInstantEventPresentOnEveryThread(trace_parsed_, trace_string_,
+                                           num_threads, num_events);
 }
 
-}  // namespace
-
-// Test that data sent from multiple threads is gathered
-TEST_F(TraceEventTestFixture, DataCapturedManyThreads) {
+// Test that thread and process names show up in the trace
+TEST_F(TraceEventTestFixture, ThreadNames) {
   ManualTestSetUp();
-  TraceLog::GetInstance()->SetEnabled(true);
 
+  // Create threads before we enable tracing to make sure
+  // that tracelog still captures them.
   const int num_threads = 4;
-  const int num_events = 4000;
+  const int num_events = 10;
   Thread* threads[num_threads];
+  PlatformThreadId thread_ids[num_threads];
+  for (int i = 0; i < num_threads; i++)
+    threads[i] = new Thread(StringPrintf("Thread %d", i).c_str());
+
+  // Enable tracing.
+  TraceLog::GetInstance()->SetEnabled(true);
+
+  // Now run some trace code on these threads.
   WaitableEvent* task_complete_events[num_threads];
   for (int i = 0; i < num_threads; i++) {
-    threads[i] = new Thread(StringPrintf("Thread %d", i).c_str());
     task_complete_events[i] = new WaitableEvent(false, false);
     threads[i]->Start();
+    thread_ids[i] = threads[i]->thread_id();
     threads[i]->message_loop()->PostTask(
-      FROM_HERE, NewRunnableFunction(&DataCapturedCallManyTraces,
+      FROM_HERE, NewRunnableFunction(&TraceManyInstantEvents,
                                      i, num_events, task_complete_events[i]));
   }
-
   for (int i = 0; i < num_threads; i++) {
     task_complete_events[i]->Wait();
   }
 
+  // Shut things down.
   TraceLog::GetInstance()->SetEnabled(false);
-
   for (int i = 0; i < num_threads; i++) {
     threads[i]->Stop();
     delete threads[i];
     delete task_complete_events[i];
   }
 
-  DataCapturedValidateManyTraces(trace_parsed_, trace_string_,
-                                  num_threads, num_events);
+  std::string tmp;
+  int tmp_int;
+  DictionaryValue* item;
+
+  // Make sure we get thread name metadata.
+  // Note, the test suite may have created a ton of threads.
+  // So, we'll have thread names for threads we didn't create.
+  std::vector<DictionaryValue*> items =
+      FindTraceEntries(trace_parsed_, "thread_name");
+  for (int i = 0; i < static_cast<int>(items.size()); i++) {
+    item = items[i];
+    EXPECT_TRUE(item);
+    EXPECT_TRUE(item->GetInteger("tid", &tmp_int));
+
+    // See if this thread name is one of the threads we just created
+    for (int j = 0; j < num_threads; j++) {
+      if(static_cast<int>(thread_ids[j]) != tmp_int)
+        continue;
+
+      std::string expected_name = StringPrintf("Thread %d", j).c_str();
+      EXPECT_TRUE(item->GetString("ph", &tmp) && tmp == "M");
+      EXPECT_TRUE(item->GetInteger("pid", &tmp_int) &&
+                  tmp_int == static_cast<int>(base::GetCurrentProcId()));
+      EXPECT_TRUE(item->GetString("args.name", &tmp) &&
+                  tmp == expected_name);
+    }
+  }
 }
 
-void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) {
-  TRACE_EVENT0("category name1", name_str);
-  TRACE_EVENT_INSTANT0("category name2", name_str);
-  TRACE_EVENT_BEGIN0("category name3", name_str);
-  TRACE_EVENT_END0("category name4", name_str);
-}
 
 // Test trace calls made after tracing singleton shut down.
 //

base/threading/platform_thread.h

@@ -74,9 +74,14 @@ class BASE_EXPORT PlatformThread {
   // Sleeps for the specified duration (units are milliseconds).
   static void Sleep(int duration_ms);
 
-  // Sets the thread name visible to a debugger.  This has no effect otherwise.
+  // Sets the thread name visible to debuggers/tools. This has no effect
+  // otherwise. This name pointer is not copied internally. Thus, it must stay
+  // valid until the thread ends.
   static void SetName(const char* name);
 
+  // Gets the thread name, if previously set by SetName.
+  static const char* GetName();
+
   // Creates a new thread.  The |stack_size| parameter can be 0 to indicate
   // that the default stack size should be used.  Upon success,
   // |*thread_handle| will be assigned a handle to the newly created thread,

base/threading/platform_thread_mac.mm

@@ -11,9 +11,12 @@
 #include <mach/thread_policy.h>
 
 #include "base/logging.h"
+#include "base/threading/thread_local.h"
 
 namespace base {
 
+static ThreadLocalPointer<char> current_thread_name;
+
 // If Cocoa is to be used on more than one thread, it must know that the
 // application is multithreaded.  Since it's possible to enter Cocoa code
 // from threads created by pthread_thread_create, Cocoa won't necessarily
@@ -37,6 +40,8 @@ void InitThreading() {
 
 // static
 void PlatformThread::SetName(const char* name) {
+  current_thread_name.Set(const_cast<char*>(name));
+
   // pthread_setname_np is only available in 10.6 or later, so test
   // for it at runtime.
   int (*dynamic_pthread_setname_np)(const char*);
@@ -54,6 +59,11 @@ void PlatformThread::SetName(const char* name) {
   dynamic_pthread_setname_np(shortened_name.c_str());
 }
 
+// static
+const char* PlatformThread::GetName() {
+  return current_thread_name.Get();
+}
+
 namespace {
 
 void SetPriorityNormal(mach_port_t mach_thread_id) {

base/threading/platform_thread_posix.cc

@@ -10,6 +10,7 @@
 #include "base/logging.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/safe_strerror_posix.h"
+#include "base/threading/thread_local.h"
 #include "base/threading/thread_restrictions.h"
 
 #if defined(OS_MACOSX)
@@ -41,6 +42,8 @@ void InitThreading();
 
 namespace {
 
+static ThreadLocalPointer<char> current_thread_name;
+
 struct ThreadParams {
   PlatformThread::Delegate* delegate;
   bool joinable;
@@ -168,6 +171,10 @@ void PlatformThread::Sleep(int duration_ms) {
 #if 0 && defined(OS_LINUX)
 // static
 void PlatformThread::SetName(const char* name) {
+  // have to cast away const because ThreadLocalPointer does not support const
+  // void*
+  current_thread_name.Set(const_cast<char*>(name));
+
   // http://0pointer.de/blog/projects/name-your-threads.html
 
   // glibc recently added support for pthread_setname_np, but it's not
@@ -198,14 +205,25 @@ void PlatformThread::SetName(const char* name) {
 // Mac is implemented in platform_thread_mac.mm.
 #else
 // static
-void PlatformThread::SetName(const char* /*name*/) {
-  // Leave it unimplemented.
+void PlatformThread::SetName(const char* name) {
+  // have to cast away const because ThreadLocalPointer does not support const
+  // void*
+  current_thread_name.Set(const_cast<char*>(name));
 
   // (This should be relatively simple to implement for the BSDs; I
   // just don't have one handy to test the code on.)
 }
 #endif  // defined(OS_LINUX)
 
+
+#if !defined(OS_MACOSX)
+// Mac is implemented in platform_thread_mac.mm.
+// static
+const char* PlatformThread::GetName() {
+  return current_thread_name.Get();
+}
+#endif
+
 // static
 bool PlatformThread::Create(size_t stack_size, Delegate* delegate,
                             PlatformThreadHandle* thread_handle) {

base/threading/platform_thread_win.cc

@@ -5,13 +5,17 @@
 #include "base/threading/platform_thread.h"
 
 #include "base/logging.h"
+#include "base/threading/thread_local.h"
 #include "base/threading/thread_restrictions.h"
+
 #include "base/win/windows_version.h"
 
 namespace base {
 
 namespace {
 
+static ThreadLocalPointer<char> current_thread_name;
+
 // The information on how to set the thread name comes from
 // a MSDN article: http://msdn2.microsoft.com/en-us/library/xcb2z8hs.aspx
 const DWORD kVCThreadNameException = 0x406D1388;
@@ -94,6 +98,8 @@ void PlatformThread::Sleep(int duration_ms) {
 
 // static
 void PlatformThread::SetName(const char* name) {
+  current_thread_name.Set(const_cast<char*>(name));
+
   // The debugger needs to be around to catch the name in the exception.  If
   // there isn't a debugger, we are just needlessly throwing an exception.
   if (!::IsDebuggerPresent())
@@ -112,6 +118,11 @@ void PlatformThread::SetName(const char* name) {
   }
 }
 
+// static
+const char* PlatformThread::GetName() {
+  return current_thread_name.Get();
+}
+
 // static
 bool PlatformThread::Create(size_t stack_size, Delegate* delegate,
                             PlatformThreadHandle* thread_handle) {