Creating infrastructure for profiler instrumentation only in developer build and Canary channel.

This introduces TrackingProfile class that is equivalent to ScopedProfile what tracking is enabled and does nothing otherwise.

There is an idea to remove the single-parametered ScopedProfile constructor, but for this CL, I’m leaving it. Otherwise, I’d have to replace ~100 ScopedProfile instantiations throughout the code with TrackingProfile, and the substantial changes would be lost in these changes. I’ll do this in a separate CL. I replaced one ScopedProfile just to make sure this will compile.

BUG=401560
TBR=asanka@chromium.org

Review URL: https://codereview.chromium.org/663093005

Cr-Commit-Position: refs/heads/master@{#301695}

17 files changed, 183 insertions, 35 deletions

diff --git a/base/BUILD.gn b/base/BUILD.gn
index e5e4aa4..84beb15 100644
--- a/base/BUILD.gn
+++ b/base/BUILD.gn
@@ -508,10 +508,12 @@ component("base") {
     "process/process_metrics_win.cc",
     "process/process_posix.cc",
     "process/process_win.cc",
-    "profiler/scoped_profile.cc",
-    "profiler/scoped_profile.h",
     "profiler/alternate_timer.cc",
     "profiler/alternate_timer.h",
+    "profiler/scoped_profile.cc",
+    "profiler/scoped_profile.h",
+    "profiler/scoped_tracker.cc",
+    "profiler/scoped_tracker.h",
     "profiler/tracked_time.cc",
     "profiler/tracked_time.h",
     "rand_util.cc",
diff --git a/base/base.gypi b/base/base.gypi
index 935314b..416a7e5 100644
--- a/base/base.gypi
+++ b/base/base.gypi
@@ -497,10 +497,12 @@
           'process/process_metrics_win.cc',
           'process/process_posix.cc',
           'process/process_win.cc',
-          'profiler/scoped_profile.cc',
-          'profiler/scoped_profile.h',
           'profiler/alternate_timer.cc',
           'profiler/alternate_timer.h',
+          'profiler/scoped_profile.cc',
+          'profiler/scoped_profile.h',
+          'profiler/scoped_tracker.cc',
+          'profiler/scoped_tracker.h',
           'profiler/tracked_time.cc',
           'profiler/tracked_time.h',
           'rand_util.cc',
diff --git a/base/debug/task_annotator.cc b/base/debug/task_annotator.cc
index f2e4b73..ae2d797 100644
--- a/base/debug/task_annotator.cc
+++ b/base/debug/task_annotator.cc
@@ -30,6 +30,7 @@ void TaskAnnotator::RunTask(const char* queue_function,
                             const PendingTask& pending_task) {
   tracked_objects::ThreadData::PrepareForStartOfRun(pending_task.birth_tally);
   tracked_objects::TaskStopwatch stopwatch;
+  stopwatch.Start();
   tracked_objects::Duration queue_duration =
       stopwatch.StartTime() - pending_task.EffectiveTimePosted();
 
diff --git a/base/profiler/scoped_profile.cc b/base/profiler/scoped_profile.cc
index e1edc97..8b0ae59 100644
--- a/base/profiler/scoped_profile.cc
+++ b/base/profiler/scoped_profile.cc
@@ -13,20 +13,32 @@ namespace tracked_objects {
 
 ScopedProfile::ScopedProfile(const Location& location)
     : birth_(ThreadData::TallyABirthIfActive(location)) {
+  if (!birth_)
+    return;
+
   ThreadData::PrepareForStartOfRun(birth_);
+  stopwatch_.Start();
 }
 
-ScopedProfile::~ScopedProfile() {
-  StopClockAndTally();
-}
+ScopedProfile::ScopedProfile(const Location& location, Mode mode)
+    : birth_(NULL) {
+  if (mode == DISABLED)
+    return;
 
-void ScopedProfile::StopClockAndTally() {
-  stopwatch_.Stop();
+  birth_ = ThreadData::TallyABirthIfActive(location);
+  if (!birth_)
+    return;
+
+  ThreadData::PrepareForStartOfRun(birth_);
+  stopwatch_.Start();
+}
 
+ScopedProfile::~ScopedProfile() {
   if (!birth_)
     return;
+
+  stopwatch_.Stop();
   ThreadData::TallyRunInAScopedRegionIfTracking(birth_, stopwatch_);
-  birth_ = NULL;
 }
 
 }  // namespace tracked_objects
diff --git a/base/profiler/scoped_profile.h b/base/profiler/scoped_profile.h
index 7290908..6a76486 100644
--- a/base/profiler/scoped_profile.h
+++ b/base/profiler/scoped_profile.h
@@ -35,12 +35,18 @@ class Births;
 
 class BASE_EXPORT ScopedProfile {
  public:
+  // Mode of operation. Specifies whether ScopedProfile should be a no-op or
+  // needs to create and tally a task.
+  enum Mode {
+    DISABLED,  // Do nothing.
+    ENABLED    // Create and tally a task.
+  };
+
+  // TODO(vadimt): Remove this constructor.
   explicit ScopedProfile(const Location& location);
+  ScopedProfile(const Location& location, Mode mode);
   ~ScopedProfile();
 
-  // Stop tracing prior to the end destruction of the instance.
-  void StopClockAndTally();
-
  private:
   Births* birth_;  // Place in code where tracking started.
   TaskStopwatch stopwatch_;
diff --git a/base/profiler/scoped_tracker.cc b/base/profiler/scoped_tracker.cc
new file mode 100644
index 0000000..5cd0bca
--- /dev/null
+++ b/base/profiler/scoped_tracker.cc
@@ -0,0 +1,24 @@
+// Copyright 2014 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/profiler/scoped_tracker.h"
+
+namespace tracked_objects {
+
+namespace {
+
+ScopedProfile::Mode g_scoped_profile_mode = ScopedProfile::DISABLED;
+
+}  // namespace
+
+// static
+void ScopedTracker::Enable() {
+  g_scoped_profile_mode = ScopedProfile::ENABLED;
+}
+
+ScopedTracker::ScopedTracker(const Location& location)
+    : scoped_profile_(location, g_scoped_profile_mode) {
+}
+
+}  // namespace tracked_objects
diff --git a/base/profiler/scoped_tracker.h b/base/profiler/scoped_tracker.h
new file mode 100644
index 0000000..fbd7309
--- /dev/null
+++ b/base/profiler/scoped_tracker.h
@@ -0,0 +1,37 @@
+// Copyright 2014 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.
+
+#ifndef BASE_PROFILER_SCOPED_TRACKER_H_
+#define BASE_PROFILER_SCOPED_TRACKER_H_
+
+//------------------------------------------------------------------------------
+// Utilities for temporarily instrumenting code to dig into issues that were
+// found using profiler data.
+
+#include "base/base_export.h"
+#include "base/location.h"
+#include "base/profiler/scoped_profile.h"
+
+namespace tracked_objects {
+
+// ScopedTracker instruments a region within the code if the instrumentation is
+// enabled. It can be used, for example, to find out if a source of jankiness is
+// inside the instrumented code region.
+class BASE_EXPORT ScopedTracker {
+ public:
+  ScopedTracker(const Location& location);
+
+  // Enables instrumentation for the remainder of the current process' life. If
+  // this function is not called, all profiler instrumentations are no-ops.
+  static void Enable();
+
+ private:
+  const ScopedProfile scoped_profile_;
+
+  DISALLOW_COPY_AND_ASSIGN(ScopedTracker);
+};
+
+}  // namespace tracked_objects
+
+#endif  // BASE_PROFILER_SCOPED_TRACKER_H_
diff --git a/base/run_loop.cc b/base/run_loop.cc
index e92e110..2aa4def 100644
--- a/base/run_loop.cc
+++ b/base/run_loop.cc
@@ -51,6 +51,7 @@ void RunLoop::Run() {
   // Use task stopwatch to exclude the loop run time from the current task, if
   // any.
   tracked_objects::TaskStopwatch stopwatch;
+  stopwatch.Start();
   loop_->RunHandler();
   stopwatch.Stop();
 
diff --git a/base/threading/sequenced_worker_pool.cc b/base/threading/sequenced_worker_pool.cc
index 08ef5f0..4c37320 100644
--- a/base/threading/sequenced_worker_pool.cc
+++ b/base/threading/sequenced_worker_pool.cc
@@ -756,6 +756,7 @@ void SequencedWorkerPool::Inner::ThreadLoop(Worker* this_worker) {
 
           tracked_objects::ThreadData::PrepareForStartOfRun(task.birth_tally);
           tracked_objects::TaskStopwatch stopwatch;
+          stopwatch.Start();
           task.task.Run();
           stopwatch.Stop();
 
diff --git a/base/threading/worker_pool_posix.cc b/base/threading/worker_pool_posix.cc
index f54b7ec..cd3c9dc 100644
--- a/base/threading/worker_pool_posix.cc
+++ b/base/threading/worker_pool_posix.cc
@@ -97,6 +97,7 @@ void WorkerThread::ThreadMain() {
 
     tracked_objects::ThreadData::PrepareForStartOfRun(pending_task.birth_tally);
     tracked_objects::TaskStopwatch stopwatch;
+    stopwatch.Start();
     pending_task.task.Run();
     stopwatch.Stop();
 
diff --git a/base/threading/worker_pool_win.cc b/base/threading/worker_pool_win.cc
index 8fc7324..ff3cc83 100644
--- a/base/threading/worker_pool_win.cc
+++ b/base/threading/worker_pool_win.cc
@@ -30,6 +30,7 @@ DWORD CALLBACK WorkItemCallback(void* param) {
   g_worker_pool_running_on_this_thread.Get().Set(true);
 
   tracked_objects::TaskStopwatch stopwatch;
+  stopwatch.Start();
   pending_task->task.Run();
   stopwatch.Stop();
 
diff --git a/base/tracked_objects.cc b/base/tracked_objects.cc
index 659d421..4fe88512 100644
--- a/base/tracked_objects.cc
+++ b/base/tracked_objects.cc
@@ -854,16 +854,32 @@ void ThreadData::ShutdownSingleThreadedCleanup(bool leak) {
 
 //------------------------------------------------------------------------------
 TaskStopwatch::TaskStopwatch()
-    : start_time_(ThreadData::Now()),
-      current_thread_data_(ThreadData::Get()),
+    : wallclock_duration_ms_(0),
+      current_thread_data_(NULL),
       excluded_duration_ms_(0),
       parent_(NULL) {
 #if DCHECK_IS_ON
-  state_ = RUNNING;
+  state_ = CREATED;
   child_ = NULL;
 #endif
+}
+
+TaskStopwatch::~TaskStopwatch() {
+#if DCHECK_IS_ON
+  DCHECK(state_ != RUNNING);
+  DCHECK(child_ == NULL);
+#endif
+}
+
+void TaskStopwatch::Start() {
+#if DCHECK_IS_ON
+  DCHECK(state_ == CREATED);
+  state_ = RUNNING;
+#endif
+
+  start_time_ = ThreadData::Now();
 
-  wallclock_duration_ms_ = 0;
+  current_thread_data_ = ThreadData::Get();
   if (!current_thread_data_)
     return;
 
@@ -878,13 +894,6 @@ TaskStopwatch::TaskStopwatch()
   current_thread_data_->current_stopwatch_ = this;
 }
 
-TaskStopwatch::~TaskStopwatch() {
-#if DCHECK_IS_ON
-  DCHECK(state_ != RUNNING);
-  DCHECK(child_ == NULL);
-#endif
-}
-
 void TaskStopwatch::Stop() {
   const TrackedTime end_time = ThreadData::Now();
 #if DCHECK_IS_ON
@@ -910,12 +919,15 @@ void TaskStopwatch::Stop() {
   DCHECK(parent_->child_ == this);
   parent_->child_ = NULL;
 #endif
-  parent_->excluded_duration_ms_ +=
-      wallclock_duration_ms_;
+  parent_->excluded_duration_ms_ += wallclock_duration_ms_;
   parent_ = NULL;
 }
 
 TrackedTime TaskStopwatch::StartTime() const {
+#if DCHECK_IS_ON
+  DCHECK(state_ != CREATED);
+#endif
+
   return start_time_;
 }
 
@@ -928,6 +940,10 @@ int32 TaskStopwatch::RunDurationMs() const {
 }
 
 ThreadData* TaskStopwatch::GetThreadData() const {
+#if DCHECK_IS_ON
+  DCHECK(state_ != CREATED);
+#endif
+
   return current_thread_data_;
 }
 
diff --git a/base/tracked_objects.h b/base/tracked_objects.h
index 055cf19..222f581 100644
--- a/base/tracked_objects.h
+++ b/base/tracked_objects.h
@@ -709,6 +709,9 @@ class BASE_EXPORT TaskStopwatch {
   TaskStopwatch();
   ~TaskStopwatch();
 
+  // Starts stopwatch.
+  void Start();
+
   // Stops stopwatch.
   void Stop();
 
@@ -744,12 +747,9 @@ class BASE_EXPORT TaskStopwatch {
   TaskStopwatch* parent_;
 
 #if DCHECK_IS_ON
-  // State of the stopwatch. Stopwatch is first constructed in a running state,
-  // then stopped, then destructed.
-  enum {
-    RUNNING,
-    STOPPED
-  } state_;
+  // State of the stopwatch. Stopwatch is first constructed in a created state
+  // state, then is optionally started/stopped, then destructed.
+  enum { CREATED, RUNNING, STOPPED } state_;
 
   // Currently running stopwatch that is directly nested in this one, if such
   // stopwatch exists. NULL otherwise.
diff --git a/base/tracked_objects_unittest.cc b/base/tracked_objects_unittest.cc
index 3ca7d74..f19ba7b 100644
--- a/base/tracked_objects_unittest.cc
+++ b/base/tracked_objects_unittest.cc
@@ -111,6 +111,16 @@ class TrackedObjectsTest : public testing::Test {
 // static
 unsigned int TrackedObjectsTest::test_time_;
 
+TEST_F(TrackedObjectsTest, TaskStopwatchNoStartStop) {
+  if (!ThreadData::InitializeAndSetTrackingStatus(
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
+    return;
+  }
+
+  // Check that creating and destroying a stopwatch without starting it doesn't
+  // crash.
+  TaskStopwatch stopwatch;
+}
 
 TEST_F(TrackedObjectsTest, MinimalStartupShutdown) {
   // Minimal test doesn't even create any tasks.
@@ -190,6 +200,7 @@ TEST_F(TrackedObjectsTest, TinyStartupShutdown) {
   base::TrackingInfo pending_task(location, kBogusBirthTime);
   SetTestTime(1);
   TaskStopwatch stopwatch;
+  stopwatch.Start();
   // Finally conclude the outer run.
   const int32 time_elapsed = 1000;
   SetTestTime(start_time + time_elapsed);
@@ -382,6 +393,7 @@ TEST_F(TrackedObjectsTest, LifeCycleToSnapshotMainThread) {
   const unsigned int kEndOfRun = 7;
   SetTestTime(kStartOfRun);
   TaskStopwatch stopwatch;
+  stopwatch.Start();
   SetTestTime(kEndOfRun);
   stopwatch.Stop();
 
@@ -422,6 +434,7 @@ TEST_F(TrackedObjectsTest, LifeCycleMidDeactivatedToSnapshotMainThread) {
   const unsigned int kEndOfRun = 7;
   SetTestTime(kStartOfRun);
   TaskStopwatch stopwatch;
+  stopwatch.Start();
   SetTestTime(kEndOfRun);
   stopwatch.Stop();
 
@@ -456,6 +469,7 @@ TEST_F(TrackedObjectsTest, LifeCyclePreDeactivatedToSnapshotMainThread) {
   const unsigned int kEndOfRun = 7;
   SetTestTime(kStartOfRun);
   TaskStopwatch stopwatch;
+  stopwatch.Start();
   SetTestTime(kEndOfRun);
   stopwatch.Stop();
 
@@ -485,6 +499,7 @@ TEST_F(TrackedObjectsTest, LifeCycleToSnapshotWorkerThread) {
   const unsigned int kEndOfRun = 7;
   SetTestTime(kStartOfRun);
   TaskStopwatch stopwatch;
+  stopwatch.Start();
   SetTestTime(kEndOfRun);
   stopwatch.Stop();
 
@@ -552,6 +567,7 @@ TEST_F(TrackedObjectsTest, TwoLives) {
   const unsigned int kEndOfRun = 7;
   SetTestTime(kStartOfRun);
   TaskStopwatch stopwatch;
+  stopwatch.Start();
   SetTestTime(kEndOfRun);
   stopwatch.Stop();
 
@@ -562,6 +578,7 @@ TEST_F(TrackedObjectsTest, TwoLives) {
   pending_task2.time_posted = kTimePosted;  // Overwrite implied Now().
   SetTestTime(kStartOfRun);
   TaskStopwatch stopwatch2;
+  stopwatch2.Start();
   SetTestTime(kEndOfRun);
   stopwatch2.Stop();
 
@@ -595,6 +612,7 @@ TEST_F(TrackedObjectsTest, DifferentLives) {
   const unsigned int kEndOfRun = 7;
   SetTestTime(kStartOfRun);
   TaskStopwatch stopwatch;
+  stopwatch.Start();
   SetTestTime(kEndOfRun);
   stopwatch.Stop();
 
@@ -659,9 +677,11 @@ TEST_F(TrackedObjectsTest, TaskWithNestedExclusion) {
 
   SetTestTime(5);
   TaskStopwatch task_stopwatch;
+  task_stopwatch.Start();
   {
     SetTestTime(8);
     TaskStopwatch exclusion_stopwatch;
+    exclusion_stopwatch.Start();
     SetTestTime(12);
     exclusion_stopwatch.Stop();
   }
@@ -695,14 +715,17 @@ TEST_F(TrackedObjectsTest, TaskWith2NestedExclusions) {
 
   SetTestTime(5);
   TaskStopwatch task_stopwatch;
+  task_stopwatch.Start();
   {
     SetTestTime(8);
     TaskStopwatch exclusion_stopwatch;
+    exclusion_stopwatch.Start();
     SetTestTime(12);
     exclusion_stopwatch.Stop();
 
     SetTestTime(15);
     TaskStopwatch exclusion_stopwatch2;
+    exclusion_stopwatch2.Start();
     SetTestTime(18);
     exclusion_stopwatch2.Stop();
   }
@@ -739,9 +762,11 @@ TEST_F(TrackedObjectsTest, TaskWithNestedExclusionWithNestedTask) {
 
   SetTestTime(5);
   TaskStopwatch task_stopwatch;
+  task_stopwatch.Start();
   {
     SetTestTime(8);
     TaskStopwatch exclusion_stopwatch;
+    exclusion_stopwatch.Start();
     {
       Location second_location(kFunction, kFile, kSecondFakeLineNumber, NULL);
       base::TrackingInfo nested_task(second_location, kDelayedStartTime);
@@ -750,6 +775,7 @@ TEST_F(TrackedObjectsTest, TaskWithNestedExclusionWithNestedTask) {
           base::TimeTicks() + base::TimeDelta::FromMilliseconds(8);
       SetTestTime(9);
       TaskStopwatch nested_task_stopwatch;
+      nested_task_stopwatch.Start();
       SetTestTime(11);
       nested_task_stopwatch.Stop();
       ThreadData::TallyRunOnNamedThreadIfTracking(
diff --git a/chrome/browser/chrome_browser_main.cc b/chrome/browser/chrome_browser_main.cc
index a58813f..b11e83f 100644
--- a/chrome/browser/chrome_browser_main.cc
+++ b/chrome/browser/chrome_browser_main.cc
@@ -25,6 +25,7 @@
 #include "base/prefs/pref_value_store.h"
 #include "base/prefs/scoped_user_pref_update.h"
 #include "base/process/process_info.h"
+#include "base/profiler/scoped_tracker.h"
 #include "base/run_loop.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_piece.h"
@@ -91,6 +92,7 @@
 #include "chrome/common/chrome_paths.h"
 #include "chrome/common/chrome_result_codes.h"
 #include "chrome/common/chrome_switches.h"
+#include "chrome/common/chrome_version_info.h"
 #include "chrome/common/crash_keys.h"
 #include "chrome/common/env_vars.h"
 #include "chrome/common/logging_chrome.h"
@@ -639,6 +641,20 @@ void ChromeBrowserMainParts::SetupMetricsAndFieldTrials() {
 
   // Now that field trials have been created, initializes metrics recording.
   metrics->InitializeMetricsRecordingState();
+
+  // Enable profiler instrumentation depending on the channel.
+  switch (chrome::VersionInfo::GetChannel()) {
+    case chrome::VersionInfo::CHANNEL_UNKNOWN:
+    case chrome::VersionInfo::CHANNEL_CANARY:
+      tracked_objects::ScopedTracker::Enable();
+      break;
+
+    case chrome::VersionInfo::CHANNEL_DEV:
+    case chrome::VersionInfo::CHANNEL_BETA:
+    case chrome::VersionInfo::CHANNEL_STABLE:
+      // Don't enable instrumentation.
+      break;
+  }
 }
 
 // ChromeBrowserMainParts: |SetupMetricsAndFieldTrials()| related --------------
diff --git a/content/browser/gpu/browser_gpu_channel_host_factory.cc b/content/browser/gpu/browser_gpu_channel_host_factory.cc
index f4fb185..032c597 100644
--- a/content/browser/gpu/browser_gpu_channel_host_factory.cc
+++ b/content/browser/gpu/browser_gpu_channel_host_factory.cc
@@ -180,6 +180,8 @@ void BrowserGpuChannelHostFactory::EstablishRequest::Wait() {
     // to do with its efficiency. Using task stopwatch to exclude the waiting
     // time from the current task run time.
     tracked_objects::TaskStopwatch stopwatch;
+    stopwatch.Start();
+
     // We're blocking the UI thread, which is generally undesirable.
     // In this case we need to wait for this before we can show any UI
     // /anyway/, so it won't cause additional jank.
diff --git a/net/proxy/proxy_config_service_win.cc b/net/proxy/proxy_config_service_win.cc
index dba1d9b..6547659 100644
--- a/net/proxy/proxy_config_service_win.cc
+++ b/net/proxy/proxy_config_service_win.cc
@@ -11,7 +11,7 @@
 #include "base/bind_helpers.h"
 #include "base/logging.h"
 #include "base/memory/scoped_ptr.h"
-#include "base/profiler/scoped_profile.h"
+#include "base/profiler/scoped_tracker.h"
 #include "base/stl_util.h"
 #include "base/strings/string_util.h"
 #include "base/strings/string_tokenizer.h"
@@ -113,8 +113,8 @@ bool ProxyConfigServiceWin::AddKeyToWatchList(HKEY rootkey,
 }
 
 void ProxyConfigServiceWin::OnObjectSignaled(base::win::RegKey* key) {
-  // TODO(vadimt): Remove ScopedProfile below once crbug.com/418183 is fixed.
-  tracked_objects::ScopedProfile tracking_profile(
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/418183 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION(
           "ProxyConfigServiceWin_OnObjectSignaled"));