trace_event: distinguish between scoped begin/end and global start/finish events

base/debug/trace_event.cc

Index: base/debug/trace_event.cc
diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc
index dbddeb39fbcc8b0eed91875741c98c3f821d2f29..44a439a8c7eda8a90c14ac83a0c906d61858b0ca 100644
--- a/base/debug/trace_event.cc
+++ b/base/debug/trace_event.cc
@@ -72,32 +72,26 @@ LazyInstance<ThreadLocalPointer<char>,
 ////////////////////////////////////////////////////////////////////////////////
 
 void TraceValue::AppendAsJSON(std::string* out) const {
-  char temp_string[128];
   std::string::size_type start_pos;
   switch (type_) {
     case TRACE_TYPE_BOOL:
       *out += as_bool() ? "true" : "false";
       break;
     case TRACE_TYPE_UINT:
-      base::snprintf(temp_string, arraysize(temp_string), "%llu",
-                     static_cast<unsigned long long>(as_uint()));
-      *out += temp_string;
+      StringAppendF(out, "%llu", static_cast<unsigned long long>(as_uint()));

[jar (doing other things), 2011/12/01 01:47:49]

Have you looked at using the "portable" definitions described in
http://src.chromium.org/svn/trunk/src/base/format_macros.h

[jbates, 2011/12/01 23:07:50]

Done.

       break;
     case TRACE_TYPE_INT:
-      base::snprintf(temp_string, arraysize(temp_string), "%lld",
-                     static_cast<long long>(as_int()));
-      *out += temp_string;
+      StringAppendF(out, "%lld", static_cast<long long>(as_int()));
       break;
     case TRACE_TYPE_DOUBLE:
-      base::snprintf(temp_string, arraysize(temp_string), "%f", as_double());
-      *out += temp_string;
+      StringAppendF(out, "%f", as_double());
       break;
     case TRACE_TYPE_POINTER:
-      base::snprintf(temp_string, arraysize(temp_string), "%llu",
-                     static_cast<unsigned long long>(
-                       reinterpret_cast<intptr_t>(
-                         as_pointer())));
-      *out += temp_string;
+      // JSON only supports double and int numbers.
+      // So as not to lose bits from a 64-bit pointer, output as a hex string.
+      StringAppendF(out, "\"%llx\"", static_cast<unsigned long long>(
+                                     reinterpret_cast<intptr_t>(
+                                     as_pointer())));
       break;
     case TRACE_TYPE_STRING:
     case TRACE_TYPE_STATIC_STRING:
@@ -121,6 +115,17 @@ void TraceValue::AppendAsJSON(std::string* out) const {
 
 ////////////////////////////////////////////////////////////////////////////////
 //
+// TraceID
+//
+////////////////////////////////////////////////////////////////////////////////
+
+TraceID::TraceID(void* rhs) {
+  data_ = base::debug::TraceLog::GetInstance()->GetIntraProcessID(
+      static_cast<uint64>(reinterpret_cast<uintptr_t>(rhs)));
+}
+
+////////////////////////////////////////////////////////////////////////////////
+//
 // TraceEvent
 //
 ////////////////////////////////////////////////////////////////////////////////
@@ -145,36 +150,39 @@ void CopyTraceEventParameter(char** buffer,
 }  // namespace
 
 TraceEvent::TraceEvent()
-    : process_id_(0),
+    : id_(0u),
+      category_(NULL),
+      name_(NULL),
       thread_id_(0),
       phase_(TRACE_EVENT_PHASE_BEGIN),
-      category_(NULL),
-      name_(NULL) {
+      flags_(0) {
   arg_names_[0] = NULL;
   arg_names_[1] = NULL;
 }
 
-TraceEvent::TraceEvent(unsigned long process_id,
-                       unsigned long thread_id,
+TraceEvent::TraceEvent(int thread_id,
                        TimeTicks timestamp,
                        TraceEventPhase phase,
                        const TraceCategory* category,
                        const char* name,
+                       TraceID id,
                        const char* arg1_name, const TraceValue& arg1_val,
                        const char* arg2_name, const TraceValue& arg2_val,
-                       bool copy)
-    : process_id_(process_id),
+                       TraceEventFlags flags)
+    : timestamp_(timestamp),
+      id_(id),
+      category_(category),
+      name_(name),
       thread_id_(thread_id),
-      timestamp_(timestamp),
       phase_(phase),
-      category_(category),
-      name_(name) {
+      flags_(flags) {
   COMPILE_ASSERT(kTraceMaxNumArgs == 2, TraceEvent_arg_count_out_of_sync);
   arg_names_[0] = arg1_name;
   arg_names_[1] = arg2_name;
   arg_values_[0] = arg1_val;
   arg_values_[1] = arg2_val;
 
+  bool copy = !!(flags & TRACE_EVENT_FLAG_COPY);
   size_t alloc_size = 0;
   if (copy) {
     alloc_size += GetAllocLength(name);
@@ -213,42 +221,6 @@ TraceEvent::TraceEvent(unsigned long process_id,
 TraceEvent::~TraceEvent() {
 }
 
-const char* TraceEvent::GetPhaseString(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";
-    case TRACE_EVENT_PHASE_COUNTER:
-      return "C";
-    default:
-      NOTREACHED() << "Invalid phase argument";
-      return "?";
-  }
-}
-
-TraceEventPhase TraceEvent::GetPhase(const char* phase) {
-  switch(*phase) {
-    case 'B':
-      return TRACE_EVENT_PHASE_BEGIN;
-    case 'I':
-      return TRACE_EVENT_PHASE_INSTANT;
-    case 'E':
-      return TRACE_EVENT_PHASE_END;
-    case 'M':
-      return TRACE_EVENT_PHASE_METADATA;
-    case 'C':
-      return TRACE_EVENT_PHASE_COUNTER;
-    default:
-      NOTREACHED() << "Invalid phase name";
-      return TRACE_EVENT_PHASE_METADATA;
-  }
-}
-
 void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events,
                                     size_t start,
                                     size_t count,
@@ -261,18 +233,19 @@ void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events,
 }
 
 void TraceEvent::AppendAsJSON(std::string* out) const {
-  const char* phase_str = GetPhaseString(phase_);
+  const char phase_char = GetPhaseChar(phase_);
   int64 time_int64 = timestamp_.ToInternalValue();
+  int process_id = TraceLog::GetInstance()->process_id();
   // Category name checked at category creation time.
   DCHECK(!strchr(name_, '"'));
   StringAppendF(out,
       "{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%lld,"
-      "\"ph\":\"%s\",\"name\":\"%s\",\"args\":{",
+      "\"ph\":\"%c\",\"name\":\"%s\",\"args\":{",
       category_->name,
-      static_cast<int>(process_id_),
-      static_cast<int>(thread_id_),
+      process_id,
+      thread_id_,
       static_cast<long long>(time_int64),
-      phase_str,
+      phase_char,
       name_);
 
   // Output argument names and values, stop at first NULL argument name.
@@ -284,7 +257,14 @@ void TraceEvent::AppendAsJSON(std::string* out) const {
     *out += "\":";
     arg_values_[i].AppendAsJSON(out);
   }
-  *out += "}}";
+  *out += "}";
+
+  // If id_ is set, print it out as a hex string so we don't loose any
+  // bits (it might be a 64-bit pointer).
+  if (flags_ & TRACE_EVENT_FLAG_HAS_ID)
+    StringAppendF(out, ",\"id\":\"%llx\"",
+                  static_cast<unsigned long long>(id_.data()));
+  *out += "}";
 }
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -342,6 +322,7 @@ TraceLog* TraceLog::GetInstance() {
 
 TraceLog::TraceLog()
     : enabled_(false) {
+  SetProcessID(static_cast<int>(base::GetCurrentProcId()));
 }
 
 TraceLog::~TraceLog() {
@@ -533,11 +514,12 @@ void TraceLog::Flush() {
 int TraceLog::AddTraceEvent(TraceEventPhase phase,
                             const TraceCategory* category,
                             const char* name,
+                            TraceID id,
                             const char* arg1_name, TraceValue arg1_val,
                             const char* arg2_name, TraceValue arg2_val,
                             int threshold_begin_id,
                             int64 threshold,
-                            EventFlags flags) {
+                            TraceEventFlags flags) {
   DCHECK(name);
   TimeTicks now = TimeTicks::HighResNow();
   BufferFullCallback buffer_full_callback_copy;
@@ -549,7 +531,7 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase,
     if (logged_events_.size() >= kTraceEventBufferSize)
       return -1;
 
-    PlatformThreadId thread_id = PlatformThread::CurrentId();
+    int thread_id = static_cast<int>(PlatformThread::CurrentId());
 
     const char* new_name = PlatformThread::GetName();
     // Check if the thread name has been set or changed since the previous
@@ -560,7 +542,7 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase,
         new_name && *new_name) {
       // Benign const cast.
       g_current_thread_name.Get().Set(const_cast<char*>(new_name));
-      base::hash_map<PlatformThreadId, std::string>::iterator existing_name =
+      base::hash_map<int, 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.
@@ -581,7 +563,7 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase,
     }
 
     if (threshold_begin_id > -1) {
-      DCHECK(phase == base::debug::TRACE_EVENT_PHASE_END);
+      DCHECK(phase == 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())
@@ -598,12 +580,11 @@ 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()),
-                   thread_id,
-                   now, phase, category, name,
+        TraceEvent(thread_id,
+                   now, phase, category, name, id,
                    arg1_name, arg1_val,
                    arg2_name, arg2_val,
-                   flags & EVENT_FLAG_COPY));
+                   flags));
 
     if (logged_events_.size() == kTraceEventBufferSize) {
       buffer_full_callback_copy = buffer_full_callback_;
@@ -625,7 +606,7 @@ void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
 #endif
   INTERNAL_TRACE_EVENT_ADD(phase,
       "ETW Trace Event", name, "id", id, "extra", TRACE_STR_COPY(extra),
-      base::debug::TraceLog::EVENT_FLAG_COPY);
+      TRACE_EVENT_FLAG_COPY);
 }
 
 void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
@@ -638,17 +619,18 @@ void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
 #endif
   INTERNAL_TRACE_EVENT_ADD(phase,
       "ETW Trace Event", name, "id", id, "extra", extra,
-      base::debug::TraceLog::EVENT_FLAG_COPY);
+      TRACE_EVENT_FLAG_COPY);
 }
 
 int TraceLog::AddCounterEvent(const TraceCategory* category,
                               const char* name,
                               const char* value1_name, int32 value1_val,
                               const char* value2_name, int32 value2_val,
-                              EventFlags flags) {
+                              TraceEventFlags flags) {
   return AddTraceEvent(TRACE_EVENT_PHASE_COUNTER,
                        category,
                        name,
+                       0,
                        value1_name, value1_val,
                        value2_name, value2_val,
                        -1, 0,
@@ -657,19 +639,17 @@ int TraceLog::AddCounterEvent(const TraceCategory* category,
 
 void TraceLog::AddCurrentMetadataEvents() {
   lock_.AssertAcquired();
-  for(base::hash_map<PlatformThreadId, std::string>::iterator it =
-          thread_names_.begin();
+  for(base::hash_map<int, 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",
+          TraceEvent(it->first,
+                     TimeTicks(), TRACE_EVENT_PHASE_METADATA,
+                     g_category_metadata, "thread_name", 0,
                      "name", it->second,
                      NULL, 0,
-                     false));
+                     TRACE_EVENT_FLAG_NONE));
   }
 }
 
@@ -681,6 +661,13 @@ void TraceLog::Resurrect() {
   StaticMemorySingletonTraits<TraceLog>::Resurrect();
 }
 
+void TraceLog::SetProcessID(int process_id) {
+  process_id_ = process_id;
+  // Create a hash from the process ID for XORing.
+  unsigned long long pid = static_cast<unsigned long long>(process_id_);
+  process_id_hash_ = (14695981039346656037ull ^ pid) * 1099511628211ull;

[jar (doing other things), 2011/12/01 01:47:49]

nit: Add a comment (url?) as a reference, or mention this is an FNV hash?  It
would also help to name the variables, rather than using raw constants inline.

[jbates, 2011/12/01 23:07:50]

Done.

+}
+
 namespace internal {
 
 void TraceEndOnScopeClose::Initialize(const TraceCategory* category,
@@ -694,11 +681,11 @@ void TraceEndOnScopeClose::AddEventIfEnabled() {
   // Only called when p_data_ is non-null.
   if (p_data_->category->enabled) {
     base::debug::TraceLog::GetInstance()->AddTraceEvent(
-        base::debug::TRACE_EVENT_PHASE_END,
+        TRACE_EVENT_PHASE_END,
         p_data_->category,
-        p_data_->name,
+        p_data_->name, 0,

[jar (doing other things), 2011/12/01 01:47:49]

It would really help readability if you assigned these constants to well named
variables.  I still wouldn't be sure that you got the order right (there are a
lot of args... probably enough that you should use a struct), but at least I'd
know the intent.

For instance, when you put the 0 here, what did you mean to pass in as zero??

[jbates, 2011/12/01 23:07:50]

Done.

         NULL, 0, NULL, 0,
-        -1, 0, TraceLog::EVENT_FLAG_NONE);
+        -1, 0, TRACE_EVENT_FLAG_NONE);
   }
 }
 
@@ -717,12 +704,12 @@ void TraceEndOnScopeCloseThreshold::AddEventIfEnabled() {
   // Only called when p_data_ is non-null.
   if (p_data_->category->enabled) {
     base::debug::TraceLog::GetInstance()->AddTraceEvent(
-        base::debug::TRACE_EVENT_PHASE_END,
+        TRACE_EVENT_PHASE_END,
         p_data_->category,
-        p_data_->name,
+        p_data_->name, 0,
         NULL, 0, NULL, 0,
         p_data_->threshold_begin_id, p_data_->threshold,
-        TraceLog::EVENT_FLAG_NONE);
+        TRACE_EVENT_FLAG_NONE);
   }
 }