Add a command line flag for dumping trace events to VLOG

base/debug/trace_event_impl.cc

 // Copyright (c) 2012 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_impl.h"
 
 #include <algorithm>
 
 #include "base/bind.h"
 #include "base/debug/leak_annotations.h"
@@ skipping 210 matching lines @@
     return logged_events_.size();
   }
 
  private:
   size_t current_iteration_index_;
   std::vector<TraceEvent> logged_events_;
 
   DISALLOW_COPY_AND_ASSIGN(TraceBufferVector);
 };
 
+class TraceBufferDiscardsEvents : public TraceBuffer {
+ public:
+  virtual ~TraceBufferDiscardsEvents() { }
+
+  virtual void AddEvent(const TraceEvent& event) { }
+  virtual bool HasMoreEvents() const { return false; }
+
+  virtual const TraceEvent& NextEvent() {
+    NOTREACHED();
+    return *static_cast<TraceEvent*>(NULL);
+  }
+
+  virtual bool IsFull() const { return false; }
+
+  virtual size_t CountEnabledByName(const unsigned char* category,
+                                    const std::string& event_name) const {
+    return 0;
+  }
+
+  virtual size_t Size() const { return 0; }
+
+  virtual const TraceEvent& GetEventAt(size_t index) const {
+    NOTREACHED();
+    return *static_cast<TraceEvent*>(NULL);
+  }
+};
+
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceEvent
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 namespace {
 
 size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; }
 
@@ skipping 674 matching lines @@
 
 void TraceLog::SetNotificationCallback(
     const TraceLog::NotificationCallback& cb) {
   AutoLock lock(lock_);
   notification_callback_ = cb;
 }
 
 TraceBuffer* TraceLog::GetTraceBuffer() {
   if (trace_options_ & RECORD_CONTINUOUSLY)
     return new TraceBufferRingBuffer();
+  else if (trace_options_ & ECHO_TO_VLOG)
+    return new TraceBufferDiscardsEvents();
   return new TraceBufferVector();
 }
 
 void TraceLog::SetEventCallback(EventCallback cb) {
   AutoLock lock(lock_);
   event_callback_ = cb;
 };
 
 void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
   scoped_ptr<TraceBuffer> previous_logged_events;
@@ skipping 45 matching lines @@
     unsigned long long id,
     int thread_id,
     const TimeTicks& timestamp,
     int num_args,
     const char** arg_names,
     const unsigned char* arg_types,
     const unsigned long long* arg_values,
     unsigned char flags) {
   DCHECK(name);
 
+  TimeDelta duration;
+  if (phase == TRACE_EVENT_PHASE_END && trace_options_ & ECHO_TO_VLOG) {
+    duration = timestamp - thread_event_start_times_[thread_id].top();
+    thread_event_start_times_[thread_id].pop();
+  }
+
   if (flags & TRACE_EVENT_FLAG_MANGLE_ID)
     id ^= process_id_hash_;
 
 #if defined(OS_ANDROID)
   SendToATrace(phase, GetCategoryGroupName(category_group_enabled), name, id,
                num_args, arg_names, arg_types, arg_values, flags);
 #endif
 
   TimeTicks now = timestamp - time_offset_;
   EventCallback event_callback_copy;
@@ skipping 30 matching lines @@
         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 (trace_options_ & ECHO_TO_VLOG) {
+      std::string thread_name = thread_names_[thread_id];
+      if (thread_colors_.find(thread_name) == thread_colors_.end())
+        thread_colors_[thread_name] = (thread_colors_.size() % 6) + 1;
+
+      std::ostringstream log;
+      log << base::StringPrintf("%s: \e[0;3%dm",
+                                thread_name.c_str(),
+                                thread_colors_[thread_name]);
+
+      size_t depth = 0;
+      if (thread_event_start_times_.find(thread_id) !=
+          thread_event_start_times_.end())
+        depth = thread_event_start_times_[thread_id].size();
+
+      for (size_t i = 0; i < depth; ++i)
+        log << "| ";
+
+      log << base::StringPrintf("'%c', %s", phase, name);
+
+      if (phase == TRACE_EVENT_PHASE_END)
+        log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF());
+
+      VLOG(0) << log.str() << "\e[0;m";
+    }
+
     logged_events_->AddEvent(TraceEvent(thread_id,
         now, phase, category_group_enabled, name, id,
         num_args, arg_names, arg_types, arg_values,
         flags));
 
     if (logged_events_->IsFull())
       notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL);
 
     if (watch_category_ == category_group_enabled && watch_event_name_ == name)
       notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION);
 
     event_callback_copy = event_callback_;
   }  // release lock
 
+  if (phase == TRACE_EVENT_PHASE_BEGIN && trace_options_ & ECHO_TO_VLOG)
+    thread_event_start_times_[thread_id].push(timestamp);
+
   notifier.SendNotificationIfAny();
   if (event_callback_copy != NULL) {
     event_callback_copy(phase, category_group_enabled, name, id,
         num_args, arg_names, arg_types, arg_values,
         flags);
   }
 }
 
 void TraceLog::AddTraceEventEtw(char phase,
                                 const char* name,
@@ skipping 279 matching lines @@
         0,                       // num_args
         NULL,                    // arg_names
         NULL,                    // arg_types
         NULL,                    // arg_values
         TRACE_EVENT_FLAG_NONE);  // flags
   }
 }
 
 }  // namespace trace_event_internal