chrome/browser/metrics/first_web_contents_profiler.cc

   1 // Copyright 2014 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #if !defined(OS_ANDROID)
   6
   7 #include "chrome/browser/metrics/first_web_contents_profiler.h"
   8
   9 #include <string>
  10
  11 #include "base/location.h"
  12 #include "base/metrics/histogram_macros.h"
  13 #include "base/process/process_info.h"
  14 #include "base/single_thread_task_runner.h"
  15 #include "base/thread_task_runner_handle.h"
  16 #include "base/time/time.h"
  17 #include "chrome/browser/ui/browser.h"
  18 #include "chrome/browser/ui/browser_iterator.h"
  19 #include "chrome/browser/ui/tabs/tab_strip_model.h"
  20 #include "components/metrics/profiler/tracking_synchronizer.h"
  21 #include "components/metrics/proto/profiler_event.pb.h"
  22 #include "components/startup_metric_utils/startup_metric_utils.h"
  23 #include "content/public/browser/browser_thread.h"
  24
  25 namespace {
  26 // The initial delay for responsiveness prober in milliseconds.
  27 const int kInitialDelayMs = 20;
  28
  29 // The following is the multiplier is used to delay the probe for
  30 // responsiveness.
  31 const double kBackoffMultiplier = 1.5;
  32
  33 // The maximum backoff delay in milliseconds.
  34 const int kMaxDelayMs = 250;
  35
  36 void DelayedRecordUIResponsiveness(
  37     base::HistogramBase* responsiveness_histogram,
  38     base::HistogramBase* unresponsiveness_histogram,
  39     base::Time start_recording_time,
  40     base::TimeDelta next_task_delay);
  41
  42 // Records the elapsed time for a task to execute a UI task under 1/60s after
  43 // the first WebContent was painted at least once. If after few tries it is
  44 // unable to execute under 1/60s it records the execution time of a task.
  45 void RecordUIResponsiveness(base::HistogramBase* responsiveness_histogram,
  46                             base::HistogramBase* unresponsiveness_histogram,
  47                             base::Time start_recording_time,
  48                             base::Time task_posted_time,
  49                             base::TimeDelta next_task_delay) {
  50   DCHECK(!start_recording_time.is_null());
  51   DCHECK(!task_posted_time.is_null());
  52   base::Time now = base::Time::Now();
  53   base::TimeDelta elapsed = now - task_posted_time;
  54
  55   // Task executed in less then 1/60s.
  56   if (elapsed.InMilliseconds() <= (1000 / 60)) {
  57     responsiveness_histogram->AddTime(now - start_recording_time);
  58   } else if (next_task_delay.InMilliseconds() > kMaxDelayMs) {
  59     // Records elapsed time to execute last task.
  60     unresponsiveness_histogram->AddTime(elapsed);
  61   } else {
  62     base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
  63         FROM_HERE,
  64         base::Bind(&DelayedRecordUIResponsiveness, responsiveness_histogram,
  65                    unresponsiveness_histogram, start_recording_time,
  66                    next_task_delay * kBackoffMultiplier),
  67         next_task_delay);
  68   }
  69 }
  70
  71 // Used for posting |RecordUIResponsiveness| without delay, so that
  72 // |RecordUIResponsiveness| can do more accurate time calculation for elapsed
  73 // time of the task to complete.
  74 void DelayedRecordUIResponsiveness(
  75     base::HistogramBase* responsiveness_histogram,
  76     base::HistogramBase* unresponsiveness_histogram,
  77     base::Time start_recording_time,
  78     base::TimeDelta next_task_delay) {
  79   base::ThreadTaskRunnerHandle::Get()->PostTask(
  80       FROM_HERE, base::Bind(&RecordUIResponsiveness, responsiveness_histogram,
  81                             unresponsiveness_histogram, start_recording_time,
  82                             base::Time::Now(), next_task_delay));
  83 }
  84
  85 // Sends the first task for measuring UI Responsiveness.
  86 void MeasureUIResponsiveness(base::HistogramBase* responsiveness_histogram,
  87                              base::HistogramBase* unresponsiveness_histogram) {
  88   base::ThreadTaskRunnerHandle::Get()->PostTask(
  89       FROM_HERE,
  90       base::Bind(&RecordUIResponsiveness, responsiveness_histogram,
  91                  unresponsiveness_histogram, base::Time::Now(),
  92                  base::Time::Now(),
  93                  base::TimeDelta::FromMilliseconds(kInitialDelayMs)));
  94 }
  95
  96 }  // namespace
  97
  98 scoped_ptr<FirstWebContentsProfiler>
  99 FirstWebContentsProfiler::CreateProfilerForFirstWebContents(
 100     Delegate* delegate) {
 101   DCHECK(delegate);
 102   for (chrome::BrowserIterator iterator; !iterator.done(); iterator.Next()) {
 103     Browser* browser = *iterator;
 104     content::WebContents* web_contents =
 105         browser->tab_strip_model()->GetActiveWebContents();
 106     if (web_contents) {
 107       return scoped_ptr<FirstWebContentsProfiler>(
 108           new FirstWebContentsProfiler(web_contents, delegate));
 109     }
 110   }
 111   return nullptr;
 112 }
 113
 114 FirstWebContentsProfiler::FirstWebContentsProfiler(
 115     content::WebContents* web_contents,
 116     Delegate* delegate)
 117     : content::WebContentsObserver(web_contents),
 118       collected_paint_metric_(false),
 119       collected_load_metric_(false),
 120       delegate_(delegate),
 121       responsiveness_histogram_(NULL),
 122       responsiveness_1sec_histogram_(NULL),
 123       responsiveness_10sec_histogram_(NULL),
 124       unresponsiveness_histogram_(NULL),
 125       unresponsiveness_1sec_histogram_(NULL),
 126       unresponsiveness_10sec_histogram_(NULL) {
 127   InitHistograms();
 128 }
 129
 130 void FirstWebContentsProfiler::DidFirstVisuallyNonEmptyPaint() {
 131   if (collected_paint_metric_)
 132     return;
 133   if (startup_metric_utils::WasNonBrowserUIDisplayed()) {
 134     FinishedCollectingMetrics();
 135     return;
 136   }
 137
 138   collected_paint_metric_ = true;
 139   startup_metric_utils::RecordFirstWebContentsNonEmptyPaint(base::Time::Now());
 140
 141   metrics::TrackingSynchronizer::OnProfilingPhaseCompleted(
 142       metrics::ProfilerEventProto::EVENT_FIRST_NONEMPTY_PAINT);
 143
 144   // Measures responsiveness now.
 145   MeasureUIResponsiveness(responsiveness_histogram_,
 146                           unresponsiveness_histogram_);
 147
 148   // As it was observed that sometimes the task queue can be free immediately
 149   // after the first paint but get overloaded shortly thereafter, here we
 150   // measures responsiveness after 1 second and 10 seconds to observe the
 151   // possible effect of those late tasks.
 152   base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
 153       FROM_HERE,
 154       base::Bind(&MeasureUIResponsiveness, responsiveness_1sec_histogram_,
 155                  unresponsiveness_1sec_histogram_),
 156       base::TimeDelta::FromSeconds(1));
 157
 158   base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
 159       FROM_HERE,
 160       base::Bind(&MeasureUIResponsiveness, responsiveness_10sec_histogram_,
 161                  unresponsiveness_10sec_histogram_),
 162       base::TimeDelta::FromSeconds(10));
 163
 164   if (IsFinishedCollectingMetrics())
 165     FinishedCollectingMetrics();
 166 }
 167
 168 void FirstWebContentsProfiler::DocumentOnLoadCompletedInMainFrame() {
 169   if (collected_load_metric_)
 170     return;
 171   if (startup_metric_utils::WasNonBrowserUIDisplayed()) {
 172     FinishedCollectingMetrics();
 173     return;
 174   }
 175
 176   collected_load_metric_ = true;
 177   startup_metric_utils::RecordFirstWebContentsMainFrameLoad(base::Time::Now());
 178
 179   if (IsFinishedCollectingMetrics())
 180     FinishedCollectingMetrics();
 181 }
 182
 183 void FirstWebContentsProfiler::WebContentsDestroyed() {
 184   FinishedCollectingMetrics();
 185 }
 186
 187 bool FirstWebContentsProfiler::IsFinishedCollectingMetrics() {
 188   return collected_paint_metric_ && collected_load_metric_;
 189 }
 190
 191 void FirstWebContentsProfiler::FinishedCollectingMetrics() {
 192   delegate_->ProfilerFinishedCollectingMetrics();
 193 }
 194
 195 void FirstWebContentsProfiler::InitHistograms() {
 196   const std::string responsiveness_histogram_name =
 197       "Startup.FirstWebContents.UIResponsive";
 198   responsiveness_histogram_ = base::Histogram::FactoryTimeGet(
 199       responsiveness_histogram_name, base::TimeDelta::FromMilliseconds(1),
 200       base::TimeDelta::FromSeconds(60), 100,
 201       base::Histogram::kUmaTargetedHistogramFlag);
 202
 203   const std::string responsiveness_1sec_histogram_name =
 204       "Startup.FirstWebContents.UIResponsive_1sec";
 205   responsiveness_1sec_histogram_ = base::Histogram::FactoryTimeGet(
 206       responsiveness_1sec_histogram_name, base::TimeDelta::FromMilliseconds(1),
 207       base::TimeDelta::FromSeconds(60), 100,
 208       base::Histogram::kUmaTargetedHistogramFlag);
 209
 210   const std::string responsiveness_10sec_histogram_name =
 211       "Startup.FirstWebContents.UIResponsive_10sec";
 212   responsiveness_10sec_histogram_ = base::Histogram::FactoryTimeGet(
 213       responsiveness_10sec_histogram_name, base::TimeDelta::FromMilliseconds(1),
 214       base::TimeDelta::FromSeconds(60), 100,
 215       base::Histogram::kUmaTargetedHistogramFlag);
 216
 217   const std::string unresponsiveness_histogram_name =
 218       "Startup.FirstWebContents.UINotResponsive";
 219   unresponsiveness_histogram_ = base::Histogram::FactoryTimeGet(
 220       unresponsiveness_histogram_name, base::TimeDelta::FromMilliseconds(1),
 221       base::TimeDelta::FromSeconds(60), 100,
 222       base::Histogram::kUmaTargetedHistogramFlag);
 223
 224   const std::string unresponsiveness_1sec_histogram_name =
 225       "Startup.FirstWebContents.UINotResponsive_1sec";
 226   unresponsiveness_1sec_histogram_ = base::Histogram::FactoryTimeGet(
 227       unresponsiveness_1sec_histogram_name,
 228       base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60),
 229       100, base::Histogram::kUmaTargetedHistogramFlag);
 230
 231   const std::string unresponsiveness_10sec_histogram_name =
 232       "Startup.FirstWebContents.UINotResponsive_10sec";
 233   unresponsiveness_10sec_histogram_ = base::Histogram::FactoryTimeGet(
 234       unresponsiveness_10sec_histogram_name,
 235       base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60),
 236       100, base::Histogram::kUmaTargetedHistogramFlag);
 237 }
 238 #endif  // !defined(OS_ANDROID)