trace_event support for thread names

base/debug/trace_event.cc

 // Copyright (c) 2011 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/debug/trace_event.h"
 
 #if defined(OS_WIN)
 #include "base/debug/trace_event_win.h"
 #endif
 #include "base/format_macros.h"
 #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"
 
 #define USE_UNRELIABLE_NOW
 
 namespace base {
 namespace debug {
 
 // Controls the number of trace events we will buffer in-memory
 // before throwing them away.
 const size_t kTraceEventBufferSize = 500000;
 const size_t kTraceEventBatchSize = 1000;
 
 #define TRACE_EVENT_MAX_CATEGORIES 42
 
 static TraceCategory g_categories[TRACE_EVENT_MAX_CATEGORIES] = {
   { "tracing already shutdown", false },
   { "tracing categories exhausted; must increase TRACE_EVENT_MAX_CATEGORIES",
     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
 
+// Flag to indicate whether we captured the current thread name
+static ThreadLocalBoolean g_current_thread_name_captured;
+
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceValue
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 void TraceValue::AppendAsJSON(std::string* out) const {
   char temp_string[128];
   std::string::size_type start_pos;
   switch (type_) {
@@ skipping 46 matching lines @@
 namespace {
 
 const char* GetPhaseStr(TraceEventPhase phase) {
   switch(phase) {
     case TRACE_EVENT_PHASE_BEGIN:
       return "B";
     case TRACE_EVENT_PHASE_INSTANT:
       return "I";
     case TRACE_EVENT_PHASE_END:
       return "E";
+    case TRACE_EVENT_PHASE_METADATA:
+      return "M";
     default:
       NOTREACHED() << "Invalid phase argument";
       return "?";
   }
 }
 
 size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; }
 
 // Copies |*member| into |*buffer|, sets |*member| to point to this new
 // location, and then advances |*buffer| by the amount written.
@@ skipping 170 matching lines @@
     AutoLock lock(lock_);
     if (enabled == enabled_)
       return;
     logged_events_.reserve(1024);
     enabled_ = enabled;
     for (int i = 0; i < g_category_index; i++) {
       //TODO(scheib): If changed to enable specific categories instead of all
       // 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 {
   return (float)((double)logged_events_.size()/(double)kTraceEventBufferSize);
 }
 
 void TraceLog::SetOutputCallback(const TraceLog::OutputCallback& cb) {
   AutoLock lock(lock_);
   output_callback_ = cb;
   logged_events_.clear();
@@ skipping 44 matching lines @@
   TimeTicks now = TimeTicks::Now();
 #endif
   BufferFullCallback buffer_full_callback_copy;
   int ret_begin_id = -1;
   {
     AutoLock lock(lock_);
     if (!enabled_ || !category->enabled)
       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

[Sigurður Ásgeirsson, 2011/08/04 20:07:05]

so, you want to keep all names you've seen?

+        // new name.
+        std::vector<std::string> existing_names;
+        Tokenize(existing_name->second, std::string(","), &existing_names);
+        bool found = false;
+        for (size_t i = 0; i < existing_names.size(); ++i) {

[Sigurður Ásgeirsson, 2011/08/04 20:07:05]

nit: to the naked eye this looks equivalent to

bool found = std::find(existing_names.begin(),
                       existing_names.end(),
                       cur_name) != existing_names.end();

with a shorter variable name, it might even fit a single line :).

+          if(existing_names[i] == cur_name) {
+            found = true;
+            break;
+          }
+        }
+        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);
       // Return now if there has been a flush since the begin event was posted.
       if (begin_i >= logged_events_.size())
         return -1;
       // Determine whether to drop the begin/end pair.
       TimeDelta elapsed = now - logged_events_[begin_i].timestamp();
       if (elapsed < TimeDelta::FromMicroseconds(threshold)) {
         // Remove begin event and do not add end event.
         // This will be expensive if there have been other events in the
         // mean time (should be rare).
         logged_events_.erase(logged_events_.begin() + begin_i);
         return -1;
       }
     }
     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,
                    copy));
 
     if (logged_events_.size() == kTraceEventBufferSize) {
       buffer_full_callback_copy = buffer_full_callback_;
     }
   } // release lock
 
@@ skipping 18 matching lines @@
     TraceLog* tracelog = TraceLog::GetInstance();
     if (!tracelog)
       return;
     tracelog->AddTraceEvent(phase, category, name,
                             "id", id,
                             "extra", extra ? extra : "",
                             -1, 0, false);
   }
 }
 
+void TraceLog::AddCurrentMetadataEvents() {
+  lock_.AssertAcquired();
+  static const TraceCategory* metadata_category =
+      GetCategoryInternal("__metadata");
+  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,
+                     metadata_category, "thread_name",
+                     "name", it->second.c_str(),
+                     NULL, 0,
+                     false));
+  }
+}
+
 void TraceLog::Resurrect() {
   StaticMemorySingletonTraits<TraceLog>::Resurrect();
 }
 
 namespace internal {
 
 void TraceEndOnScopeClose::Initialize(const TraceCategory* category,
                                       const char* name) {
   data_.category = category;
   data_.name = name;
@@ skipping 32 matching lines @@
         p_data_->name,
         NULL, 0, NULL, 0,
         p_data_->threshold_begin_id, p_data_->threshold, false);
   }
 }
 
 } // namespace internal
 
 }  // namespace debug
 }  // namespace base