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()));

[jbates, 2011/11/17 01:15:28]

Cleanup to match other instances of StringAppendF in this file.

       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>(

[jbates, 2011/11/17 01:15:28]

Storing the pointer as a string instead of an int, because JSON doesn't support
64-bit ints. The string will prevent data loss when the pointer value is
extracted from json.

+                                     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, '\\');
@@ skipping 27 matching lines @@
     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),
+    : extra_(0u),
+      category_(NULL),
+      name_(NULL),
       thread_id_(0),
-      phase_(TRACE_EVENT_PHASE_BEGIN),
-      category_(NULL),
-      name_(NULL) {
+      phase_(TRACE_EVENT_PHASE_BEGIN) {
   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,
+                       uint64 extra,
                        const char* arg1_name, const TraceValue& arg1_val,
                        const char* arg2_name, const TraceValue& arg2_val,
                        bool copy)
-    : process_id_(process_id),
+    : timestamp_(timestamp),
+      extra_(extra),
+      category_(category),
+      name_(name),
       thread_id_(thread_id),
-      timestamp_(timestamp),
-      phase_(phase),
-      category_(category),
-      name_(name) {
+      phase_(phase) {
   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;
 
   size_t alloc_size = 0;
   if (copy) {
     alloc_size += GetAllocLength(name);
     alloc_size += GetAllocLength(arg1_name);
@@ skipping 28 matching lines @@
   }
 }
 
 TraceEvent::~TraceEvent() {
 }
 
 const char* TraceEvent::GetPhaseString(TraceEventPhase phase) {
   switch(phase) {
     case TRACE_EVENT_PHASE_BEGIN:
       return "B";
+    case TRACE_EVENT_PHASE_END:

[jbates, 2011/11/17 01:15:28]

Reordered these to match the order in the enum.

+      return "E";
     case TRACE_EVENT_PHASE_INSTANT:
       return "I";
-    case TRACE_EVENT_PHASE_END:
-      return "E";
+    case TRACE_EVENT_PHASE_START:
+      return "S";
+    case TRACE_EVENT_PHASE_FINISH:
+      return "F";
     case TRACE_EVENT_PHASE_METADATA:
       return "M";
     default:
       NOTREACHED() << "Invalid phase argument";
       return "?";
   }
 }
 
 TraceEventPhase TraceEvent::GetPhase(const char* phase) {
   switch(*phase) {
     case 'B':
       return TRACE_EVENT_PHASE_BEGIN;
+    case 'E':
+      return TRACE_EVENT_PHASE_END;
     case 'I':
       return TRACE_EVENT_PHASE_INSTANT;
-    case 'E':
-      return TRACE_EVENT_PHASE_END;
+    case 'S':
+      return TRACE_EVENT_PHASE_START;
+    case 'F':
+      return TRACE_EVENT_PHASE_FINISH;
     case 'M':
       return TRACE_EVENT_PHASE_METADATA;
     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_);
   int64 time_int64 = timestamp_.ToInternalValue();
+  int process_id = static_cast<int>(base::GetCurrentProcId());
   // 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\":{",
       category_->name,
-      static_cast<int>(process_id_),
-      static_cast<int>(thread_id_),
+      process_id,
+      thread_id_,
       static_cast<long long>(time_int64),
       phase_str,
       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 extra_ is non-zero, print it out as a hex string so we don't loose any
+  // bits (it might be a 64-bit pointer).
+  if (extra_ != 0ull)
+    StringAppendF(out, ",\"ext\":\"%llx\"",
+                  static_cast<unsigned long long>(extra_));
+  *out += "}";
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceResultBuffer
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 TraceResultBuffer::OutputCallback
     TraceResultBuffer::SimpleOutput::GetCallback() {
@@ skipping 228 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,
+                            uint64 extra,
                             const char* arg1_name, TraceValue arg1_val,
                             const char* arg2_name, TraceValue arg2_val,
                             int threshold_begin_id,
                             int64 threshold,
                             EventFlags 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));
@@ skipping 28 matching lines @@
       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, extra,
                    arg1_name, arg1_val,
                    arg2_name, arg2_val,
                    flags & EVENT_FLAG_COPY));
 
     if (logged_events_.size() == kTraceEventBufferSize) {
       buffer_full_callback_copy = buffer_full_callback_;
     }
   }  // release lock
 
   if (!buffer_full_callback_copy.is_null())
@@ skipping 28 matching lines @@
 }
 
 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,
+          TraceEvent(it->first,
                      TimeTicks(), base::debug::TRACE_EVENT_PHASE_METADATA,
-                     g_category_metadata, "thread_name",
+                     g_category_metadata, "thread_name", 0,
                      "name", it->second,
                      NULL, 0,
                      false));
   }
 }
 
 void TraceLog::DeleteForTesting() {
   DeleteTraceLogForTesting::Delete();
 }
 
 void TraceLog::Resurrect() {
   StaticMemorySingletonTraits<TraceLog>::Resurrect();
 }
 
 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,
         p_data_->category,
-        p_data_->name,
+        p_data_->name, 0,
         NULL, 0, NULL, 0,
         -1, 0, TraceLog::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,
         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);
   }
 }
 
 }  // namespace internal
 
 }  // namespace debug
 }  // namespace base