Sampling profiler for chrome://tracing

Allows using TRACE_EVENT_STATE to set a current state. This state is encoded as a static const string pointer. Using the macro stores the static string pointer to a global.

While tracing is active, a background thread is spun up and samples this global at a regular interval.

The motivation (as compared with other TRACE_EVENT_* macros) is that the runtime cost is lower (in both the disabled and enabled state), at a cost of lower accuracy and less information gathered.

A "normal" sampling profiler would try to sample the program counter instead, however, this induces the cost of suspending the target thread(s), whereas this approach only adds the constant overhead of storing to a global.

Currently, in chrome://tracing the data shows up as a fake thread containing only one event which contains the sampling data as an "instant" event. This UI will be improved in future patches.


BUG=

Review URL: https://chromiumcodereview.appspot.com/12224011

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@184542 0039d316-1c4b-4281-b951-d872f2087c98

5 files changed, 244 insertions, 5 deletions

diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index 3459a94..0636180 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -69,6 +69,13 @@
 // Defines visibility for classes in trace_event_internal.h
 #define TRACE_EVENT_API_CLASS_EXPORT BASE_EXPORT
 
+// The thread buckets for the sampling profiler.
+TRACE_EVENT_API_CLASS_EXPORT extern TRACE_EVENT_API_ATOMIC_WORD g_trace_state0;
+TRACE_EVENT_API_CLASS_EXPORT extern TRACE_EVENT_API_ATOMIC_WORD g_trace_state1;
+TRACE_EVENT_API_CLASS_EXPORT extern TRACE_EVENT_API_ATOMIC_WORD g_trace_state2;
+#define TRACE_EVENT_API_THREAD_BUCKET(thread_bucket)                           \
+  g_trace_state##thread_bucket
+
 ////////////////////////////////////////////////////////////////////////////////
 
 #include "base/debug/trace_event_internal.h"
diff --git a/base/debug/trace_event_impl.cc b/base/debug/trace_event_impl.cc
index 5eafd52..81687ab 100644
--- a/base/debug/trace_event_impl.cc
+++ b/base/debug/trace_event_impl.cc
@@ -18,6 +18,8 @@
 #include "base/string_util.h"
 #include "base/stringprintf.h"
 #include "base/strings/string_tokenizer.h"
+#include "base/synchronization/cancellation_flag.h"
+#include "base/synchronization/waitable_event.h"
 #include "base/sys_info.h"
 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
 #include "base/threading/platform_thread.h"
@@ -38,6 +40,11 @@ class DeleteTraceLogForTesting {
   }
 };
 
+// The thread buckets for the sampling profiler.
+BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state0;
+BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state1;
+BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state2;
+
 namespace base {
 namespace debug {
 
@@ -320,6 +327,147 @@ void TraceResultBuffer::Finish() {
 
 ////////////////////////////////////////////////////////////////////////////////
 //
+// TraceSamplingThread
+//
+////////////////////////////////////////////////////////////////////////////////
+class TraceBucketData;
+typedef base::Callback<void(TraceBucketData*)> TraceSampleCallback;
+
+class TraceBucketData {
+ public:
+  TraceBucketData(base::subtle::AtomicWord* bucket,
+                  const char* name,
+                  TraceSampleCallback callback);
+  ~TraceBucketData();
+
+  TRACE_EVENT_API_ATOMIC_WORD* bucket;
+  const char* bucket_name;
+  TraceSampleCallback callback;
+};
+
+// This object must be created on the IO thread.
+class TraceSamplingThread : public PlatformThread::Delegate {
+ public:
+  TraceSamplingThread();
+  virtual ~TraceSamplingThread();
+
+  // Implementation of PlatformThread::Delegate:
+  virtual void ThreadMain() OVERRIDE;
+
+  static void DefaultSampleCallback(TraceBucketData* bucekt_data);
+
+  void Stop();
+  void InstallWaitableEventForSamplingTesting(WaitableEvent* waitable_event);
+
+ private:
+  friend class TraceLog;
+
+  void GetSamples();
+  // Not thread-safe. Once the ThreadMain has been called, this can no longer
+  // be called.
+  void RegisterSampleBucket(TRACE_EVENT_API_ATOMIC_WORD* bucket,
+                            const char* const name,
+                            TraceSampleCallback callback);
+  // Splits a combined "category\0name" into the two component parts.
+  static void ExtractCategoryAndName(const char* combined,
+                                     const char** category,
+                                     const char** name);
+  std::vector<TraceBucketData> sample_buckets_;
+  bool thread_running_;
+  scoped_ptr<CancellationFlag> cancellation_flag_;
+  scoped_ptr<WaitableEvent> waitable_event_for_testing_;
+};
+
+
+TraceSamplingThread::TraceSamplingThread()
+    : thread_running_(false) {
+  cancellation_flag_.reset(new CancellationFlag);
+}
+
+TraceSamplingThread::~TraceSamplingThread() {
+}
+
+void TraceSamplingThread::ThreadMain() {
+  PlatformThread::SetName("Sampling Thread");
+  thread_running_ = true;
+  const int kSamplingFrequencyMicroseconds = 1000;
+  while (!cancellation_flag_->IsSet()) {
+    PlatformThread::Sleep(
+        TimeDelta::FromMicroseconds(kSamplingFrequencyMicroseconds));
+    GetSamples();
+    if (waitable_event_for_testing_.get())
+      waitable_event_for_testing_->Signal();
+  }
+}
+
+// static
+void TraceSamplingThread::DefaultSampleCallback(TraceBucketData* bucket_data) {
+  TRACE_EVENT_API_ATOMIC_WORD category_and_name =
+      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;
+  const char* name;
+  ExtractCategoryAndName(combined, &category, &name);
+  TRACE_EVENT_API_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_SAMPLE,
+                                  TraceLog::GetCategoryEnabled(category),
+                                  name,
+                                  0,
+                                  0,
+                                  NULL,
+                                  NULL,
+                                  NULL,
+                                  0);
+}
+
+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(
+    TRACE_EVENT_API_ATOMIC_WORD* bucket,
+    const char* const name,
+    TraceSampleCallback callback) {
+  DCHECK(!thread_running_);
+  sample_buckets_.push_back(TraceBucketData(bucket, name, callback));
+}
+
+// static
+void TraceSamplingThread::ExtractCategoryAndName(const char* combined,
+                                                 const char** category,
+                                                 const char** name) {
+  *category = combined;
+  *name = &combined[strlen(combined) + 1];
+}
+
+void TraceSamplingThread::Stop() {
+  cancellation_flag_->Set();
+}
+
+void TraceSamplingThread::InstallWaitableEventForSamplingTesting(
+    WaitableEvent* waitable_event) {
+  waitable_event_for_testing_.reset(waitable_event);
+}
+
+
+TraceBucketData::TraceBucketData(base::subtle::AtomicWord* bucket,
+                                 const char* name,
+                                 TraceSampleCallback callback)
+    : bucket(bucket),
+      bucket_name(name),
+      callback(callback) {
+}
+
+TraceBucketData::~TraceBucketData() {
+}
+
+////////////////////////////////////////////////////////////////////////////////
+//
 // TraceLog
 //
 ////////////////////////////////////////////////////////////////////////////////
@@ -381,7 +529,8 @@ TraceLog::TraceLog()
     : enable_count_(0),
       dispatching_to_observer_list_(false),
       watch_category_(NULL),
-      trace_options_(RECORD_UNTIL_FULL) {
+      trace_options_(RECORD_UNTIL_FULL),
+      sampling_thread_handle_(0) {
   // Trace is enabled or disabled on one thread while other threads are
   // accessing the enabled flag. We don't care whether edge-case events are
   // traced or not, so we allow races on the enabled flag to keep the trace
@@ -555,6 +704,26 @@ void TraceLog::SetEnabled(const std::vector<std::string>& included_categories,
     EnableMatchingCategories(included_categories_, CATEGORY_ENABLED, 0);
   else
     EnableMatchingCategories(excluded_categories_, 0, CATEGORY_ENABLED);
+
+  if (options & ENABLE_SAMPLING) {
+    sampling_thread_.reset(new TraceSamplingThread);
+    sampling_thread_->RegisterSampleBucket(
+        &g_trace_state0,
+        "bucket0",
+        Bind(&TraceSamplingThread::DefaultSampleCallback));
+    sampling_thread_->RegisterSampleBucket(
+        &g_trace_state1,
+        "bucket1",
+        Bind(&TraceSamplingThread::DefaultSampleCallback));
+    sampling_thread_->RegisterSampleBucket(
+        &g_trace_state2,
+        "bucket2",
+        Bind(&TraceSamplingThread::DefaultSampleCallback));
+    if (!PlatformThread::Create(
+          0, sampling_thread_.get(), &sampling_thread_handle_)) {
+      DCHECK(false) << "failed to create thread";
+    }
+  }
 }
 
 void TraceLog::SetEnabled(const std::string& categories, Options options) {
@@ -600,8 +769,19 @@ void TraceLog::SetDisabled() {
     return;
   }
 
+  if (sampling_thread_.get()) {
+    // Stop the sampling thread.
+    sampling_thread_->Stop();
+    lock_.Release();
+    PlatformThread::Join(sampling_thread_handle_);
+    lock_.Acquire();
+    sampling_thread_handle_ = 0;
+    sampling_thread_.reset();
+  }
+
   dispatching_to_observer_list_ = true;
-  FOR_EACH_OBSERVER(EnabledStateChangedObserver, enabled_state_observer_list_,
+  FOR_EACH_OBSERVER(EnabledStateChangedObserver,
+                    enabled_state_observer_list_,
                     OnTraceLogWillDisable());
   dispatching_to_observer_list_ = false;
 
@@ -834,6 +1014,11 @@ void TraceLog::AddThreadNameMetadataEvents() {
   }
 }
 
+void TraceLog::InstallWaitableEventForSamplingTesting(
+    WaitableEvent* waitable_event) {
+  sampling_thread_->InstallWaitableEventForSamplingTesting(waitable_event);
+}
+
 void TraceLog::DeleteForTesting() {
   DeleteTraceLogForTesting::Delete();
 }
diff --git a/base/debug/trace_event_impl.h b/base/debug/trace_event_impl.h
index c73fbcb..193e6b4 100644
--- a/base/debug/trace_event_impl.h
+++ b/base/debug/trace_event_impl.h
@@ -6,8 +6,6 @@
 #ifndef BASE_DEBUG_TRACE_EVENT_IMPL_H_
 #define BASE_DEBUG_TRACE_EVENT_IMPL_H_
 
-#include "build/build_config.h"
-
 #include <string>
 #include <vector>
 
@@ -18,6 +16,7 @@
 #include "base/string_util.h"
 #include "base/synchronization/condition_variable.h"
 #include "base/synchronization/lock.h"
+#include "base/threading/thread.h"
 #include "base/timer.h"
 
 // Older style trace macros with explicit id and extra data
@@ -42,6 +41,8 @@ struct StaticMemorySingletonTraits;
 
 namespace base {
 
+class WaitableEvent;
+
 namespace debug {
 
 const int kTraceMaxNumArgs = 2;
@@ -157,6 +158,8 @@ class BASE_EXPORT TraceResultBuffer {
   bool append_comma_;
 };
 
+class TraceSamplingThread;
+
 class BASE_EXPORT TraceLog {
  public:
   // Notification is a mask of one or more of the following events.
@@ -171,7 +174,9 @@ class BASE_EXPORT TraceLog {
 
   // Options determines how the trace buffer stores data.
   enum Options {
-    RECORD_UNTIL_FULL = 1 << 0
+    RECORD_UNTIL_FULL = 1 << 0,
+    // Enable the sampling profiler.
+    ENABLE_SAMPLING = 1 << 1,
   };
 
   static TraceLog* GetInstance();
@@ -312,6 +317,8 @@ class BASE_EXPORT TraceLog {
 
   // Exposed for unittesting:
 
+  void InstallWaitableEventForSamplingTesting(WaitableEvent* waitable_event);
+
   // Allows deleting our singleton instance.
   static void DeleteForTesting();
 
@@ -413,6 +420,10 @@ class BASE_EXPORT TraceLog {
 
   Options trace_options_;
 
+  // Sampling thread handles.
+  scoped_ptr<TraceSamplingThread> sampling_thread_;
+  PlatformThreadHandle sampling_thread_handle_;
+
   DISALLOW_COPY_AND_ASSIGN(TraceLog);
 };
 
diff --git a/base/debug/trace_event_internal.h b/base/debug/trace_event_internal.h
index b10210e..65fe34a 100644
--- a/base/debug/trace_event_internal.h
+++ b/base/debug/trace_event_internal.h
@@ -233,6 +233,17 @@
         category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val, \
         arg2_name, arg2_val)
 
+// Sets the current sample state to the given category and name (both must be
+// constant strings). These states are intended for a sampling profiler.
+// Implementation note: we store category and name together because we don't
+// want the inconsistency/expense of storing two pointers.
+// |thread_bucket| is [0..2] and is used to statically isolate samples in one
+// thread from others.
+#define TRACE_EVENT_SAMPLE_STATE(thread_bucket, category, name)                \
+  TRACE_EVENT_API_ATOMIC_STORE(                                                \
+      TRACE_EVENT_API_THREAD_BUCKET(thread_bucket),                            \
+      reinterpret_cast<TRACE_EVENT_API_ATOMIC_WORD>(category "\0" name));
+
 // Records a single BEGIN event called "name" immediately, with 0, 1 or 2
 // associated arguments. If the category is not enabled, then this
 // does nothing.
@@ -682,6 +693,7 @@
 #define TRACE_EVENT_PHASE_FLOW_END   ('f')
 #define TRACE_EVENT_PHASE_METADATA ('M')
 #define TRACE_EVENT_PHASE_COUNTER  ('C')
+#define TRACE_EVENT_PHASE_SAMPLE  ('P')
 
 // Flags for changing the behavior of TRACE_EVENT_API_ADD_TRACE_EVENT.
 #define TRACE_EVENT_FLAG_NONE        (static_cast<unsigned char>(0))
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index fd6bbd2..e8e6c8a 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -1494,5 +1494,29 @@ TEST_F(TraceEventTestFixture, TraceOptionsParsing) {
             TraceLog::TraceOptionsFromString("record-until-full"));
 }
 
+TEST_F(TraceEventTestFixture, TraceSampling) {
+  ManualTestSetUp();
+
+  event_watch_notification_ = 0;
+  TraceLog::GetInstance()->SetEnabled(
+      std::string("*"),
+      TraceLog::Options(TraceLog::RECORD_UNTIL_FULL |
+                        TraceLog::ENABLE_SAMPLING));
+
+  WaitableEvent* sampled = new WaitableEvent(false, false);
+  TraceLog::GetInstance()->InstallWaitableEventForSamplingTesting(sampled);
+
+  TRACE_EVENT_SAMPLE_STATE(1, "cc", "Stuff");
+  sampled->Wait();
+  TRACE_EVENT_SAMPLE_STATE(1, "cc", "Things");
+  sampled->Wait();
+
+  EndTraceAndFlush();
+
+  // Make sure we hit at least once.
+  EXPECT_TRUE(FindNamePhase("Stuff", "P"));
+  EXPECT_TRUE(FindNamePhase("Things", "P"));
+}
+
 }  // namespace debug
 }  // namespace base