Remove trace event overhead reporting feature

base/trace_event/trace_log.cc

 // Copyright 2015 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/trace_event/trace_log.h"
 
 #include <algorithm>
 #include <cmath>
 
 #include "base/base_switches.h"
@@ skipping 61 matching lines @@
 static_assert(
     kTraceEventVectorBufferChunks <= TraceBufferChunk::kMaxChunkIndex,
     "Too many vector buffer chunks");
 const size_t kTraceEventRingBufferChunks = kTraceEventVectorBufferChunks / 4;
 
 // Can store results for 30 seconds with 1 ms sampling interval.
 const size_t kMonitorTraceEventBufferChunks = 30000 / kTraceBufferChunkSize;
 // ECHO_TO_CONSOLE needs a small buffer to hold the unfinished COMPLETE events.
 const size_t kEchoToConsoleTraceEventBufferChunks = 256;
 
-// The overhead of TraceEvent above this threshold will be reported in the
-// trace.
-const int kOverheadReportThresholdInMicroseconds = 50;
 const size_t kTraceEventBufferSizeInBytes = 100 * 1024;
 const int kThreadFlushTimeoutMs = 3000;
 
 #if !defined(OS_NACL)
 // These categories will cause deadlock when ECHO_TO_CONSOLE. crbug.com/325575.
 const char kEchoToConsoleCategoryFilter[] = "-ipc,-task";
 #endif
 
 #define MAX_CATEGORY_GROUPS 100
 
 // Parallel arrays g_category_groups and g_category_group_enabled are separate
 // so that a pointer to a member of g_category_group_enabled can be easily
 // converted to an index into g_category_groups. This allows macros to deal
 // only with char enabled pointers from g_category_group_enabled, and we can
 // convert internally to determine the category name from the char enabled
 // pointer.
 const char* g_category_groups[MAX_CATEGORY_GROUPS] = {
     "toplevel",
     "tracing already shutdown",
     "tracing categories exhausted; must increase MAX_CATEGORY_GROUPS",
-    "__metadata",
-    // For reporting trace_event overhead. For thread local event buffers only.
-    "trace_event_overhead"};
+    "__metadata"};
 
 // The enabled flag is char instead of bool so that the API can be used from C.
 unsigned char g_category_group_enabled[MAX_CATEGORY_GROUPS] = {0};
 // Indexes here have to match the g_category_groups array indexes above.
 const int g_category_already_shutdown = 1;
 const int g_category_categories_exhausted = 2;
 const int g_category_metadata = 3;
-const int g_category_trace_event_overhead = 4;
-const int g_num_builtin_categories = 5;
+const int g_num_builtin_categories = 4;
 // Skip default categories.
 base::subtle::AtomicWord g_category_index = g_num_builtin_categories;
 
 // The name of the current thread. This is used to decide if the current
 // thread name has changed. We combine all the seen thread names into the
 // output name for the thread.
 LazyInstance<ThreadLocalPointer<const char>>::Leaky g_current_thread_name =
     LAZY_INSTANCE_INITIALIZER;
 
 ThreadTicks ThreadNow() {
@@ skipping 87 matching lines @@
 
 class TraceLog::ThreadLocalEventBuffer
     : public MessageLoop::DestructionObserver,
       public MemoryDumpProvider {
  public:
   ThreadLocalEventBuffer(TraceLog* trace_log);
   ~ThreadLocalEventBuffer() override;
 
   TraceEvent* AddTraceEvent(TraceEventHandle* handle);
 
-  void ReportOverhead(const TraceTicks& event_timestamp,
-                      const ThreadTicks& event_thread_timestamp);
-
   TraceEvent* GetEventByHandle(TraceEventHandle handle) {
     if (!chunk_ || handle.chunk_seq != chunk_->seq() ||
         handle.chunk_index != chunk_index_)
       return NULL;
 
     return chunk_->GetEventAt(handle.event_index);
   }
 
   int generation() const { return generation_; }
 
  private:
   // MessageLoop::DestructionObserver
   void WillDestroyCurrentMessageLoop() override;
 
   // MemoryDumpProvider implementation.
   bool OnMemoryDump(const MemoryDumpArgs& args,
                     ProcessMemoryDump* pmd) override;
 
   void FlushWhileLocked();
 
   void CheckThisIsCurrentBuffer() const {
     DCHECK(trace_log_->thread_local_event_buffer_.Get() == this);
   }
 
   // Since TraceLog is a leaky singleton, trace_log_ will always be valid
   // as long as the thread exists.
   TraceLog* trace_log_;
   scoped_ptr<TraceBufferChunk> chunk_;
   size_t chunk_index_;
   int event_count_;

[dsinclair, 2015/09/17 13:12:28]

Can we also remove event_count_?

[Xianzhu, 2015/09/17 16:01:49]

Done.

-  TimeDelta overhead_;
   int generation_;
 
   DISALLOW_COPY_AND_ASSIGN(ThreadLocalEventBuffer);
 };
 
 TraceLog::ThreadLocalEventBuffer::ThreadLocalEventBuffer(TraceLog* trace_log)
     : trace_log_(trace_log),
       chunk_index_(0),
       event_count_(0),
       generation_(trace_log->generation()) {
   // ThreadLocalEventBuffer is created only if the thread has a message loop, so
   // the following message_loop won't be NULL.
   MessageLoop* message_loop = MessageLoop::current();
   message_loop->AddDestructionObserver(this);
 
   // This is to report the local memory usage when memory-infra is enabled.
   MemoryDumpManager::GetInstance()->RegisterDumpProvider(
       this, ThreadTaskRunnerHandle::Get());
 
   AutoLock lock(trace_log->lock_);
   trace_log->thread_message_loops_.insert(message_loop);
 }
 
 TraceLog::ThreadLocalEventBuffer::~ThreadLocalEventBuffer() {
   CheckThisIsCurrentBuffer();
   MessageLoop::current()->RemoveDestructionObserver(this);
   MemoryDumpManager::GetInstance()->UnregisterDumpProvider(this);
 
-  // Zero event_count_ happens in either of the following cases:
-  // - no event generated for the thread;
-  // - the thread has no message loop;
-  // - trace_event_overhead is disabled.
-  if (event_count_) {
-    InitializeMetadataEvent(AddTraceEvent(NULL),
-                            static_cast<int>(base::PlatformThread::CurrentId()),
-                            "overhead", "average_overhead",
-                            overhead_.InMillisecondsF() / event_count_);
-  }
-
   {
     AutoLock lock(trace_log_->lock_);
     FlushWhileLocked();
     trace_log_->thread_message_loops_.erase(MessageLoop::current());
   }
   trace_log_->thread_local_event_buffer_.Set(NULL);
 }
 
 TraceEvent* TraceLog::ThreadLocalEventBuffer::AddTraceEvent(
     TraceEventHandle* handle) {
@@ skipping 13 matching lines @@
     return NULL;
 
   size_t event_index;
   TraceEvent* trace_event = chunk_->AddTraceEvent(&event_index);
   if (trace_event && handle)
     MakeHandle(chunk_->seq(), chunk_index_, event_index, handle);
 
   return trace_event;
 }
 
-void TraceLog::ThreadLocalEventBuffer::ReportOverhead(
-    const TraceTicks& event_timestamp,
-    const ThreadTicks& event_thread_timestamp) {
-  if (!g_category_group_enabled[g_category_trace_event_overhead])
-    return;
-
-  CheckThisIsCurrentBuffer();
-
-  event_count_++;
-  ThreadTicks thread_now = ThreadNow();
-  TraceTicks now = trace_log_->OffsetNow();
-  TimeDelta overhead = now - event_timestamp;
-  if (overhead.InMicroseconds() >= kOverheadReportThresholdInMicroseconds) {
-    TraceEvent* trace_event = AddTraceEvent(NULL);
-    if (trace_event) {
-      trace_event->Initialize(
-          static_cast<int>(PlatformThread::CurrentId()),
-          event_timestamp,
-          event_thread_timestamp,
-          TRACE_EVENT_PHASE_COMPLETE,
-          &g_category_group_enabled[g_category_trace_event_overhead],
-          "overhead",
-          trace_event_internal::kNoId,  // id
-          trace_event_internal::kNoId,  // context_id
-          trace_event_internal::kNoId,  // bind_id
-          ::trace_event_internal::kZeroNumArgs,
-          nullptr,
-          nullptr,
-          nullptr,
-          nullptr,
-          TRACE_EVENT_FLAG_NONE);
-      trace_event->UpdateDuration(now, thread_now);
-    }
-  }
-  overhead_ += overhead;
-}
-
 void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() {
   delete this;
 }
 
 bool TraceLog::ThreadLocalEventBuffer::OnMemoryDump(const MemoryDumpArgs& args,
                                                     ProcessMemoryDump* pmd) {
   if (!chunk_)
     return true;
   std::string dump_base_name = StringPrintf(
       "tracing/thread_%d", static_cast<int>(PlatformThread::CurrentId()));
@@ skipping 250 matching lines @@
   } else {
     category_group_enabled =
         &g_category_group_enabled[g_category_categories_exhausted];
   }
   return category_group_enabled;
 }
 
 void TraceLog::GetKnownCategoryGroups(
     std::vector<std::string>* category_groups) {
   AutoLock lock(lock_);
-  category_groups->push_back(
-      g_category_groups[g_category_trace_event_overhead]);
   size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
   for (size_t i = g_num_builtin_categories; i < category_index; i++)
     category_groups->push_back(g_category_groups[i]);
 }
 
 void TraceLog::SetEnabled(const TraceConfig& trace_config, Mode mode) {
   std::vector<EnabledStateObserver*> observer_list;
   {
     AutoLock lock(lock_);
 
@@ skipping 598 matching lines @@
   DCHECK(!timestamp.is_null());
 
   if (flags & TRACE_EVENT_FLAG_MANGLE_ID) {
     if ((flags & TRACE_EVENT_FLAG_FLOW_IN) ||
         (flags & TRACE_EVENT_FLAG_FLOW_OUT))
       bind_id = MangleEventId(bind_id);
     id = MangleEventId(id);
   }
 
   TraceTicks offset_event_timestamp = OffsetTimestamp(timestamp);
-  TraceTicks now = flags & TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP
-                       ? OffsetNow()
-                       : offset_event_timestamp;
   ThreadTicks thread_now = ThreadNow();
 
   // |thread_local_event_buffer_| can be null if the current thread doesn't have
   // a message loop or the message loop is blocked.
   InitializeThreadLocalEventBufferIfSupported();
   auto thread_local_event_buffer = thread_local_event_buffer_.Get();
 
   // Check and update the current thread name only if the event is for the
   // current thread to avoid locks in most cases.
   if (thread_id == static_cast<int>(PlatformThread::CurrentId())) {
@@ skipping 105 matching lines @@
         subtle::NoBarrier_Load(&event_callback_));
     if (event_callback) {
       event_callback(
           offset_event_timestamp,
           phase == TRACE_EVENT_PHASE_COMPLETE ? TRACE_EVENT_PHASE_BEGIN : phase,
           category_group_enabled, name, id, num_args, arg_names, arg_types,
           arg_values, flags);
     }
   }
 
-  if (thread_local_event_buffer)
-    thread_local_event_buffer->ReportOverhead(now, thread_now);
-
   return handle;
 }
 
 // May be called when a COMPELETE event ends and the unfinished event has been
 // recycled (phase == TRACE_EVENT_PHASE_END and trace_event == NULL).
 std::string TraceLog::EventToConsoleMessage(unsigned char phase,
                                             const TraceTicks& timestamp,
                                             TraceEvent* trace_event) {
   AutoLock thread_info_lock(thread_info_lock_);
 
@@ skipping 371 matching lines @@
 }
 
 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
   if (*category_group_enabled_) {
     TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_, name_,
                                                 event_handle_);
   }
 }
 
 }  // namespace trace_event_internal