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 880 matching lines @@
       TRACE_EVENT_API_ATOMIC_LOAD(*bucket_data->bucket);
   if (!category_and_name)
     return;
   const char* const combined =
       reinterpret_cast<const char* const>(category_and_name);
   const char* category_group;
   const char* name;
   ExtractCategoryAndName(combined, &category_group, &name);
   TRACE_EVENT_API_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_SAMPLE,
       TraceLog::GetCategoryGroupEnabled(category_group),
-      name, 0, 0, NULL, NULL, NULL, NULL, 0);
+      name, 0, 0, NULL, NULL, NULL, NULL, TRACE_EVENT_FLAG_SAMPLING);

[nduca, 2013/12/12 07:02:41]

i'm a little confused on this side. what is the category_group typically? i
think maybe there's something im misunderstanding in the way the sampling thread
is implemented :$

[haraken, 2013/12/12 07:34:28]

(1) The sampling thread gets the current category group.
(2) The sampling thread checks if the category group is enabled or not. The
check is done in TraceLog::AddTraceEvent() (See the diff below).
(3) If it's not enabled, the sampling thread doesn't log the event.

Thus, if we specify "-*" for a category group, the sampling thread logs nothing.
The TRACE_EVENT_FALG_SAMPLING is necessary to tell that "this is a sampling
thread, so I want to log everything".

[dsinclair, 2013/12/12 15:19:31]

If we really want everything then why not set hte category flag to "*" instead
of "-*" and then we don't need the TRACE_EVENT_FLAG_SAMPLING magic? Seems like
we're just building a path around the category flags that's special cased to
sampling?

[haraken, 2013/12/12 15:32:17]

Then there arises another problem: If we use "*", then normal tracing like
TRACE_EVENT0 starts logging :(

[dsinclair, 2013/12/13 15:55:57]

Isn't adding the TRACE_EVENT_FLAG_SAMPLING the same as checking for phase ==
TRACE_EVENT_PHASE_SAMPLE? The flag seems redundant.

 }
 
 void TraceSamplingThread::GetSamples() {
   for (size_t i = 0; i < sample_buckets_.size(); ++i) {
     TraceBucketData* bucket_data = &sample_buckets_[i];
     bucket_data->callback.Run(bucket_data);
   }
 }
 
 void TraceSamplingThread::RegisterSampleBucket(
@@ skipping 175 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();
 }
@@ skipping 234 matching lines @@
 
   if (dispatching_to_observer_list_) {
     DLOG(ERROR)
         << "Cannot manipulate TraceLog::Enabled state from an observer.";
     return;
   }
 
   enabled_ = false;
 
   if (sampling_thread_.get()) {
+    // TODO(haraken): Don't call Platform::Join from the UI thread.

[dsinclair, 2013/12/11 15:55:04]

Is this todo to be done before commit? Or for later?

[haraken, 2013/12/12 00:48:47]

Sure, I'll fix before commit.

[haraken, 2013/12/12 01:54:52]

Question: Would the right fix for this be to change TracingControllerImpl so
that it calls SetDisabled() from the FILE thread? Or should we allow
TracingControllerImpl to call SetDisabled() from the UI thread but execute only
Platform::Join() from the FILE thread?

[dsinclair, 2013/12/13 15:55:57]

I believe this was handled in a separate CL correct?

+    base::ThreadRestrictions::SetIOAllowed(true);
+
     // Stop the sampling thread.
     sampling_thread_->Stop();
     lock_.Release();
     PlatformThread::Join(sampling_thread_handle_);
     lock_.Acquire();
     sampling_thread_handle_ = PlatformThreadHandle();
     sampling_thread_.reset();
+
+    base::ThreadRestrictions::SetIOAllowed(false);
   }
 
   category_filter_.Clear();
   subtle::NoBarrier_Store(&watch_category_, 0);
   watch_event_name_ = "";
   UpdateCategoryGroupEnabledFlags();
   AddMetadataEventsWhileLocked();
 
   dispatching_to_observer_list_ = true;
   std::vector<EnabledStateObserver*> observer_list =
@@ skipping 57 matching lines @@
   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 196 matching lines @@
       logged_events_->ReturnChunk(thread_shared_chunk_index_,
                                   thread_shared_chunk_.Pass());
     }
     previous_logged_events = logged_events_->CloneForIteration().Pass();
   }  // release lock
 
   ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
                                   flush_output_callback);
 }
 
+int TraceLog::NextGeneration()
+{
+  thread_shared_chunk_.reset();
+  thread_shared_chunk_index_ = 0;
+  return static_cast<int>(subtle::NoBarrier_AtomicIncrement(&generation_, 1));

[Xianzhu, 2013/12/11 17:53:42]

Thanks for fixing this!

Would it be even better to
- move logged_events_.reset(CreateTraceBuffer()) from the callsites - into this
function
- rename it (UseNextTraceBuffer?)
- remove the return value

[haraken, 2013/12/12 00:48:47]

Sure, will do!

+}
+
 TraceEventHandle TraceLog::AddTraceEvent(
     char phase,
     const unsigned char* category_group_enabled,
     const char* name,
     unsigned long long id,
     int num_args,
     const char** arg_names,
     const unsigned char* arg_types,
     const unsigned long long* arg_values,
     const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
@@ skipping 14 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)
+
+  // We enable all categories in sampling tracing, since it doesn't make sense

[dsinclair, 2013/12/11 15:55:04]

Does this include disabled-by-default- categories? Do we really want those on
with the sampling profiler?

[haraken, 2013/12/12 00:48:47]

I think the answer is yes. Given that the sampling profiler is a thing that
tells us a percentage distribution of all sampled events, it wouldn't make much
sense to filter out some sampled events. (i.e., technically it's possible to
filter out sampled events by categories, but I cannot come up with practical use
cases for the filtering.) WDYT?

[dsinclair, 2013/12/12 15:19:31]

The problem with having disabled-by-default- is they can have a lot more
overhead then regular trace events. There is, potentially, a bunch of work to
convert from the current format into a base::Value object which will be
converted later. So, my fear is that we'd end up throwing off the samping
information due to these events.

[haraken, 2013/12/12 15:32:17]

Now I agree that we shouldn't enable all categories by default (See my comment
below), but I'm curious why it affects performance. The sampling thread is just
peeking global variables  with 1 ms intervals. So the number of samples is
always up to 1000 per 1 second.

[dsinclair, 2013/12/13 15:55:57]

I think this was my own confusion with how sampling worked. I'd forgotten that
sampling has it's own macros that are separate. So, as long as the non-sampling
macros aren't being forced to evaluate their arguments it should be fine.

+  // to filter sample events by categories.
+  if (!(flags & TRACE_EVENT_FLAG_SAMPLING) && !*category_group_enabled)

[dsinclair, 2013/12/11 15:55:04]

If we always enable all categories then why does the EnableMonitoring call take
a category filter?

[haraken, 2013/12/12 00:48:47]

I think that's because the monitoring mode is going to be used for other
purposes than sampling profiler in the future (system tracing, tcmalloc
monitoring, etc).

[dsinclair, 2013/12/12 15:19:31]

Why can't I use monitoring mode to say, tell me the relative percentage of time
we spend in cc. functions? If I'm just interested in optimizing cc I may want to
filter out everything else.

[haraken, 2013/12/12 15:32:17]

Sounds reasonable. We want to have category filters for sampling tracing as
well.

However, what's the cleanest way to realize it? Currently a category group is
shared between normal tracing and sampling tracing. So we cannot say that "We
want to enable these categories only in sampling tracing". Probably do we want
to prepare a separate category group for sampling tracing?

[dsinclair, 2013/12/13 15:55:57]

I think I'm getting confused on how this works. Please correct me if I'm
mistaken.

The sampling mode is separate from the tracing mode. They are mutually exclusive
so you can't turn them both on at the same time.

If that's the case, then we should be able to use the category_filter as it will
only apply to the current mode (sampling or tracing) that is enabled.

Is the problem that both use AddTraceEvent and we don't want to log
non-PHASE_SAMPLE events when in sampling mode?

What am I missing?

     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 55 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 ((flags & TRACE_EVENT_FLAG_SAMPLING) ||
+      (*category_group_enabled & ENABLED_FOR_RECORDING)) {
     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