Implement sampling profiler (chromium side change)

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/base_switches.h"
 #include "base/bind.h"
@@ skipping 1076 matching lines @@
 void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() {
   delete this;
 }
 
 void TraceLog::ThreadLocalEventBuffer::FlushWhileLocked() {
   if (!chunk_)
     return;
 
   trace_log_->lock_.AssertAcquired();
   if (trace_log_->CheckGeneration(generation_)) {
-    // Return the chunk to the buffer only if the generation matches,
+    // Return the chunk to the buffer only if the generation matches.
     trace_log_->logged_events_->ReturnChunk(chunk_index_, chunk_.Pass());
   }
   // Otherwise this method may be called from the destructor, or TraceLog will
   // find the generation mismatch and delete this buffer soon.
 }
 
 // static
 TraceLog* TraceLog::GetInstance() {
   return Singleton<TraceLog, LeakySingletonTraits<TraceLog> >::get();
 }
 
 TraceLog::TraceLog()
-    : enabled_(false),
+    : mode_(DISABLED),
       num_traces_recorded_(0),
       event_callback_(0),
       dispatching_to_observer_list_(false),
       process_sort_index_(0),
       process_id_hash_(0),
       process_id_(0),
       watch_category_(0),
       trace_options_(RECORD_UNTIL_FULL),
       sampling_thread_handle_(0),
       category_filter_(CategoryFilter::kDefaultCategoryFilterString),
@@ skipping 25 matching lines @@
         switches::kTraceToConsole);
     if (filter.empty()) {
       filter = kEchoToConsoleCategoryFilter;
     } else {
       filter.append(",");
       filter.append(kEchoToConsoleCategoryFilter);
     }
 
     LOG(ERROR) << "Start " << switches::kTraceToConsole
                << " with CategoryFilter '" << filter << "'.";
-    SetEnabled(CategoryFilter(filter), ECHO_TO_CONSOLE);
+    SetEnabled(CategoryFilter(filter), RECORDING_MODE, ECHO_TO_CONSOLE);
   }
 #endif
 
   logged_events_.reset(CreateTraceBuffer());
 }
 
 TraceLog::~TraceLog() {
 }
 
 const unsigned char* TraceLog::GetCategoryGroupEnabled(
@@ skipping 18 matching lines @@
              g_category_group_enabled + MAX_CATEGORY_GROUPS)) <<
       "out of bounds category pointer";
   uintptr_t category_index =
       (category_ptr - category_begin) / sizeof(g_category_group_enabled[0]);
   return g_category_groups[category_index];
 }
 
 void TraceLog::UpdateCategoryGroupEnabledFlag(int category_index) {
   unsigned char enabled_flag = 0;
   const char* category_group = g_category_groups[category_index];
-  if (enabled_ && category_filter_.IsCategoryGroupEnabled(category_group))
+  if (mode_ == RECORDING_MODE &&
+      category_filter_.IsCategoryGroupEnabled(category_group))
     enabled_flag |= ENABLED_FOR_RECORDING;
+  if (mode_ == MONITORING_MODE &&
+      category_filter_.IsCategoryGroupEnabled(category_group))
+    enabled_flag |= ENABLED_FOR_MONITORING;
   if (event_callback_ &&
       event_callback_category_filter_.IsCategoryGroupEnabled(category_group))
     enabled_flag |= ENABLED_FOR_EVENT_CALLBACK;
   g_category_group_enabled[category_index] = enabled_flag;
 }
 
 void TraceLog::UpdateCategoryGroupEnabledFlags() {
   for (int i = 0; i < g_category_index; i++)
     UpdateCategoryGroupEnabledFlag(i);
 }
@@ skipping 42 matching lines @@
 void TraceLog::GetKnownCategoryGroups(
     std::vector<std::string>* category_groups) {
   AutoLock lock(lock_);
   category_groups->push_back(
       g_category_groups[g_category_trace_event_overhead]);
   for (int i = g_num_builtin_categories; i < g_category_index; i++)
     category_groups->push_back(g_category_groups[i]);
 }
 
 void TraceLog::SetEnabled(const CategoryFilter& category_filter,
+                          Mode mode,
                           Options options) {
   std::vector<EnabledStateObserver*> observer_list;
   {
     AutoLock lock(lock_);
 
     // Can't enable tracing when Flush() is in progress.
     DCHECK(!flush_message_loop_proxy_.get());
 
     Options old_options = trace_options();
 
-    if (enabled_) {
+    if (IsEnabled()) {
       if (options != old_options) {
         DLOG(ERROR) << "Attemting to re-enable tracing with a different "
                     << "set of options.";
       }
 
       category_filter_.Merge(category_filter);
       UpdateCategoryGroupEnabledFlags();
       return;
     }
 
     if (dispatching_to_observer_list_) {
       DLOG(ERROR) <<
           "Cannot manipulate TraceLog::Enabled state from an observer.";
       return;
     }
 
-    enabled_ = true;
+    mode_ = mode;
 
     if (options != old_options) {
       subtle::NoBarrier_Store(&trace_options_, options);
       UseNextTraceBuffer();
     }
 
     num_traces_recorded_++;
 
     category_filter_ = CategoryFilter(category_filter);
     UpdateCategoryGroupEnabledFlags();
 
-    if ((options & ENABLE_SAMPLING) || (options & MONITOR_SAMPLING)) {
+    if (options & ENABLE_SAMPLING) {
       sampling_thread_.reset(new TraceSamplingThread);
       sampling_thread_->RegisterSampleBucket(
           &g_trace_state[0],
           "bucket0",
           Bind(&TraceSamplingThread::DefaultSamplingCallback));
       sampling_thread_->RegisterSampleBucket(
           &g_trace_state[1],
           "bucket1",
           Bind(&TraceSamplingThread::DefaultSamplingCallback));
       sampling_thread_->RegisterSampleBucket(
@@ skipping 25 matching lines @@
 }
 
 void TraceLog::SetDisabled() {
   AutoLock lock(lock_);
   SetDisabledWhileLocked();
 }
 
 void TraceLog::SetDisabledWhileLocked() {
   lock_.AssertAcquired();
 
-  if (!enabled_)
+  if (!IsEnabled())
     return;
 
   if (dispatching_to_observer_list_) {
     DLOG(ERROR)
         << "Cannot manipulate TraceLog::Enabled state from an observer.";
     return;
   }
 
-  enabled_ = false;
+  mode_ = DISABLED;
 
   if (sampling_thread_.get()) {
     // Stop the sampling thread.
     sampling_thread_->Stop();
     lock_.Release();
     PlatformThread::Join(sampling_thread_handle_);
     lock_.Acquire();
     sampling_thread_handle_ = PlatformThreadHandle();
     sampling_thread_.reset();
   }
@@ skipping 13 matching lines @@
     // trace event.
     AutoUnlock unlock(lock_);
     for (size_t i = 0; i < observer_list.size(); ++i)
       observer_list[i]->OnTraceLogDisabled();
   }
   dispatching_to_observer_list_ = false;
 }
 
 int TraceLog::GetNumTracesRecorded() {
   AutoLock lock(lock_);
-  if (!enabled_)
+  if (!IsEnabled())
     return -1;
   return num_traces_recorded_;
 }
 
 void TraceLog::AddEnabledStateObserver(EnabledStateObserver* listener) {
   enabled_state_observer_list_.push_back(listener);
 }
 
 void TraceLog::RemoveEnabledStateObserver(EnabledStateObserver* listener) {
   std::vector<EnabledStateObserver*>::iterator it =
@@ skipping 20 matching lines @@
 
 bool TraceLog::BufferIsFull() const {
   AutoLock lock(lock_);
   return logged_events_->IsFull();
 }
 
 TraceBuffer* TraceLog::CreateTraceBuffer() {
   Options options = trace_options();
   if (options & RECORD_CONTINUOUSLY)
     return new TraceBufferRingBuffer(kTraceEventRingBufferChunks);
-  else if (options & MONITOR_SAMPLING)
+  else if ((options & ENABLE_SAMPLING) && mode_ == MONITORING_MODE)
     return new TraceBufferRingBuffer(kMonitorTraceEventBufferChunks);
   else if (options & ECHO_TO_CONSOLE)
     return new TraceBufferRingBuffer(kEchoToConsoleTraceEventBufferChunks);
   return new TraceBufferVector();
 }
 
 TraceEvent* TraceLog::AddEventToThreadSharedChunkWhileLocked(
     TraceEventHandle* handle, bool check_buffer_is_full) {
   lock_.AssertAcquired();
 
   if (thread_shared_chunk_ && thread_shared_chunk_->IsFull()) {
+    // Return the chunk to the buffer only if the generation matches.
     logged_events_->ReturnChunk(thread_shared_chunk_index_,
                                 thread_shared_chunk_.Pass());
   }
 
   if (!thread_shared_chunk_) {
     thread_shared_chunk_ = logged_events_->GetChunk(
         &thread_shared_chunk_index_);
     if (check_buffer_is_full)
       CheckIfBufferIsFullWhileLocked();
   }
@@ skipping 236 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,
     const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
     unsigned char flags) {
   TraceEventHandle handle = { 0, 0, 0 };
+
   if (!*category_group_enabled)
     return handle;
 
   // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
   // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
   // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
   if (thread_is_in_trace_event_.Get())
     return handle;
 
   AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);
@@ skipping 56 matching lines @@
         if (!found) {
           if (existing_names.size())
             existing_name->second.push_back(',');
           existing_name->second.append(new_name);
         }
       }
     }
   }
 
   std::string console_message;
-  if ((*category_group_enabled & ENABLED_FOR_RECORDING)) {
+  if ((mode_ == RECORDING_MODE &&
+       *category_group_enabled & ENABLED_FOR_RECORDING) ||
+      (mode_ == MONITORING_MODE &&
+       *category_group_enabled & ENABLED_FOR_MONITORING) &&
+       phase == TRACE_EVENT_PHASE_SAMPLE) {

[haraken, 2013/12/18 21:48:10]

Concern 1: There is a threading race in mode_. mode_ is set by the FILE thread
and accessed by the UI thread. We don't want to use a lock to access mode_,
because AddTraceEvent() is always called by TRACE_EVENT macros and thus
performance-sensitive.

Concern 2: This implementation will slow down TRACE_EVENT macros. Imagine that
the monitoring mode is enabled for all categories. In this case, all TRACE_EVENT
macros (for the recording mode) start calling AddTraceEvent() and then reach
this check. Since this check returns false, AddTraceEvent() returns without
doing nothing. However, it would be heavy to execute AddTraceEvent() for all
TRACE_EVENT macros. (We want to enable the sampling profiler always on in the
future.)

[Xianzhu, 2013/12/18 22:26:54]

I think we can omit checking mode_ here because we should trust
*category_group_enabled which has been updated according to mode_ in
UpdateCategoryEnabledFlags().
This doesn't look good. Currently the extra cost is less than 3~4 machine
instructions for each TRACE_EVENT macro when it doesn't actually generate
traces.

I think we should also add the check in the macros:
- in sampling macros, change "if (*category_group_enabled)" to "if
(*category_group_enabled & ENABLED_FOR_MONITORING)"
- in other macros, change to "if (*category_group_enabled &
(ENABLED_FOR_RECORDING | ENABLED_FOR_EVENT_CALLBACK))"
so that for recording macros, the extra cost is still near zero when recording
and event_callback are not enabled.

[haraken, 2013/12/18 22:40:21]

Would you elaborate on how to do that?

(1) TRACE_EVENT macros are just checking *category_group_enabled. They are not
checking *category_group_enabled & ENABLED_FOR_XXX. We want to keep the current
check for performance.

(2) If we want to enable some categories in the monitoring mode, we need to
enable *category_group_enabled for the categories.

(3) Then TRACE_EVENT macros start falling back to AddTraceEvent().

Are you suggesting using two category_group_enabled, one for the recording mode
and the other for the monitoring mode?
Actually I tried this at first but found that it won't make sense to distinguish
ENABLED_FOR_RECORDING from ENABLED_FOR_MONITORING. Because the recording mode
and the monitoring mode are mutually exclusive, we can just use
category_group_enabled for a category filter of the mode that is currently
enabled.

     OptionalAutoLock lock(lock_);
 
     TraceEvent* trace_event = NULL;
     if (thread_local_event_buffer) {
       trace_event = thread_local_event_buffer->AddTraceEvent(&handle);
     } else {
       lock.EnsureAcquired();
       trace_event = AddEventToThreadSharedChunkWhileLocked(&handle, true);
     }
 
@@ skipping 529 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