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

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"
 
 #include <algorithm>
 
 #include "base/bind.h"
 #include "base/format_macros.h"
@@ skipping 54 matching lines @@
 
 }  // namespace
 
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceValue
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 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:
       *out += "\"";
       start_pos = out->size();
       *out += as_string() ? as_string() : "NULL";
       // insert backslash before special characters for proper json format.
       while ((start_pos = out->find_first_of("\\\"", start_pos)) !=
              std::string::npos) {
         out->insert(start_pos, 1, '\\');
         // skip inserted escape character and following character.
         start_pos += 2;
       }
       *out += "\"";
       break;
     default:
       NOTREACHED() << "Don't know how to print this value";
       break;
   }
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 //
+// TraceID
+//
+////////////////////////////////////////////////////////////////////////////////
+
+TraceID::TraceID(void* rhs) {
+  data_ = base::debug::TraceLog::GetInstance()->GetIntraProcessID(
+      static_cast<uint64>(reinterpret_cast<uintptr_t>(rhs)));
+}
+
+////////////////////////////////////////////////////////////////////////////////
+//
 // TraceEvent
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 namespace {
 
 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.
 void CopyTraceEventParameter(char** buffer,
                              const char** member,
                              const char* end) {
   if (*member) {
     size_t written = strlcpy(*buffer, *member, end - *buffer) + 1;
     DCHECK_LE(static_cast<int>(written), end - *buffer);
     *member = *buffer;
     *buffer += written;
   }
 }
 
 }  // 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);
     alloc_size += GetAllocLength(arg1_name);
     alloc_size += GetAllocLength(arg2_name);
   }
 
   bool arg1_is_copy = (arg1_val.type() == TraceValue::TRACE_TYPE_STRING);
   bool arg2_is_copy = (arg2_val.type() == TraceValue::TRACE_TYPE_STRING);
 
@@ skipping 18 matching lines @@
       CopyTraceEventParameter(&ptr, arg_values_[0].as_assignable_string(), end);
     if (arg2_is_copy)
       CopyTraceEventParameter(&ptr, arg_values_[1].as_assignable_string(), end);
     DCHECK_EQ(end, ptr) << "Overrun by " << ptr - end;
   }
 }
 
 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,
                                     std::string* out) {
   for (size_t i = 0; i < count && start + i < events.size(); ++i) {
     if (i > 0)
       *out += ",";
     events[i + start].AppendAsJSON(out);
   }
 }
 
 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.
   for (size_t i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
     if (i > 0)
       *out += ",";
     *out += "\"";
     *out += arg_names_[i];
     *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 += "}";
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceResultBuffer
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 TraceResultBuffer::OutputCallback
     TraceResultBuffer::SimpleOutput::GetCallback() {
@@ skipping 37 matching lines @@
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 // static
 TraceLog* TraceLog::GetInstance() {
   return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get();
 }
 
 TraceLog::TraceLog()
     : enabled_(false) {
+  SetProcessID(static_cast<int>(base::GetCurrentProcId()));
 }
 
 TraceLog::~TraceLog() {
 }
 
 const TraceCategory* TraceLog::GetCategory(const char* name) {
   TraceLog* tracelog = GetInstance();
   if (!tracelog){
     DCHECK(!g_category_already_shutdown->enabled);
     return g_category_already_shutdown;
@@ skipping 171 matching lines @@
                                    i,
                                    kTraceEventBatchSize,
                                    &(json_events_str_ptr->data));
     output_callback_copy.Run(json_events_str_ptr);
   }
 }
 
 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;
   int ret_begin_id = -1;
   {
     AutoLock lock(lock_);
     if (!category->enabled)
       return -1;
     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
     // call (if any), but don't bother if the new name is empty. Note this will
     // not detect a thread name change within the same char* buffer address: we
     // favor common case performance over corner case correctness.
     if (new_name != g_current_thread_name.Get().Get() &&
         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.
         thread_names_[thread_id] = new_name;
       } else {
         // This is a thread id that we've seen before, but potentially with a
         // new name.
         std::vector<base::StringPiece> existing_names;
         Tokenize(existing_name->second, ",", &existing_names);
         bool found = std::find(existing_names.begin(),
                                existing_names.end(),
                                new_name) != existing_names.end();
         if (!found) {
           existing_name->second.push_back(',');
           existing_name->second.append(new_name);
         }
       }
     }
 
     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())
         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()),
-                   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_;
     }
   }  // release lock
 
   if (!buffer_full_callback_copy.is_null())
     buffer_full_callback_copy.Run();
 
   return ret_begin_id;
 }
 
 void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
                                 const char* name,
                                 const void* id,
                                 const char* extra) {
 #if defined(OS_WIN)
   TraceEventETWProvider::Trace(name, phase, id, extra);
 #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,
                                 const char* name,
                                 const void* id,
                                 const std::string& extra)
 {
 #if defined(OS_WIN)
   TraceEventETWProvider::Trace(name, phase, id, extra);
 #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,
                        flags);
 }
 
 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));
   }
 }
 
 void TraceLog::DeleteForTesting() {
   DeleteTraceLogForTesting::Delete();
 }
 
 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,
                                       const char* name) {
   data_.category = category;
   data_.name = name;
   p_data_ = &data_;
 }
 
 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);
   }
 }
 
 void TraceEndOnScopeCloseThreshold::Initialize(const TraceCategory* category,
                                                const char* name,
                                                int threshold_begin_id,
                                                int64 threshold) {
   data_.category = category;
   data_.name = name;
   data_.threshold_begin_id = threshold_begin_id;
   data_.threshold = threshold;
   p_data_ = &data_;
 }
 
 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);
   }
 }
 
 }  // namespace internal
 
 }  // namespace debug
 }  // namespace base