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   process_creation_time_ = base::CurrentProcessInfo::CreationTime();
 128   InitHistograms();
 129 }
 130
 131 void FirstWebContentsProfiler::DidFirstVisuallyNonEmptyPaint() {
 132   if (collected_paint_metric_)
 133     return;
 134   if (startup_metric_utils::WasNonBrowserUIDisplayed()) {
 135     FinishedCollectingMetrics();
 136     return;
 137   }
 138
 139   collected_paint_metric_ = true;
 140   if (!process_creation_time_.is_null()) {
 141     base::TimeDelta elapsed = base::Time::Now() - process_creation_time_;
 142
 143     UMA_HISTOGRAM_LONG_TIMES_100("Startup.FirstWebContents.NonEmptyPaint",
 144                                  elapsed);
 145   }
 146
 147   metrics::TrackingSynchronizer::OnProfilingPhaseCompleted(
 148       metrics::ProfilerEventProto::EVENT_FIRST_NONEMPTY_PAINT);
 149
 150   // Measures responsiveness now.
 151   MeasureUIResponsiveness(responsiveness_histogram_,
 152                           unresponsiveness_histogram_);
 153
 154   // As it was observed that sometimes the task queue can be free immediately
 155   // after the first paint but get overloaded shortly thereafter, here we
 156   // measures responsiveness after 1 second and 10 seconds to observe the
 157   // possible effect of those late tasks.
 158   base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
 159       FROM_HERE,
 160       base::Bind(&MeasureUIResponsiveness, responsiveness_1sec_histogram_,
 161                  unresponsiveness_1sec_histogram_),
 162       base::TimeDelta::FromSeconds(1));
 163
 164   base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
 165       FROM_HERE,
 166       base::Bind(&MeasureUIResponsiveness, responsiveness_10sec_histogram_,
 167                  unresponsiveness_10sec_histogram_),
 168       base::TimeDelta::FromSeconds(10));
 169
 170   if (IsFinishedCollectingMetrics())
 171     FinishedCollectingMetrics();
 172 }
 173
 174 void FirstWebContentsProfiler::DocumentOnLoadCompletedInMainFrame() {
 175   if (collected_load_metric_)
 176     return;
 177   if (startup_metric_utils::WasNonBrowserUIDisplayed()) {
 178     FinishedCollectingMetrics();
 179     return;
 180   }
 181
 182   collected_load_metric_ = true;
 183   if (!process_creation_time_.is_null()) {
 184     base::TimeDelta elapsed = base::Time::Now() - process_creation_time_;
 185
 186     UMA_HISTOGRAM_LONG_TIMES_100("Startup.FirstWebContents.MainFrameLoad",
 187                                  elapsed);
 188   }
 189
 190   if (IsFinishedCollectingMetrics())
 191     FinishedCollectingMetrics();
 192 }
 193
 194 void FirstWebContentsProfiler::WebContentsDestroyed() {
 195   FinishedCollectingMetrics();
 196 }
 197
 198 bool FirstWebContentsProfiler::IsFinishedCollectingMetrics() {
 199   return collected_paint_metric_ && collected_load_metric_;
 200 }
 201
 202 void FirstWebContentsProfiler::FinishedCollectingMetrics() {
 203   delegate_->ProfilerFinishedCollectingMetrics();
 204 }
 205
 206 void FirstWebContentsProfiler::InitHistograms() {
 207   const std::string responsiveness_histogram_name =
 208       "Startup.FirstWebContents.UIResponsive";
 209   responsiveness_histogram_ = base::Histogram::FactoryTimeGet(
 210       responsiveness_histogram_name, base::TimeDelta::FromMilliseconds(1),
 211       base::TimeDelta::FromSeconds(60), 100,
 212       base::Histogram::kUmaTargetedHistogramFlag);
 213
 214   const std::string responsiveness_1sec_histogram_name =
 215       "Startup.FirstWebContents.UIResponsive_1sec";
 216   responsiveness_1sec_histogram_ = base::Histogram::FactoryTimeGet(
 217       responsiveness_1sec_histogram_name, base::TimeDelta::FromMilliseconds(1),
 218       base::TimeDelta::FromSeconds(60), 100,
 219       base::Histogram::kUmaTargetedHistogramFlag);
 220
 221   const std::string responsiveness_10sec_histogram_name =
 222       "Startup.FirstWebContents.UIResponsive_10sec";
 223   responsiveness_10sec_histogram_ = base::Histogram::FactoryTimeGet(
 224       responsiveness_10sec_histogram_name, base::TimeDelta::FromMilliseconds(1),
 225       base::TimeDelta::FromSeconds(60), 100,
 226       base::Histogram::kUmaTargetedHistogramFlag);
 227
 228   const std::string unresponsiveness_histogram_name =
 229       "Startup.FirstWebContents.UINotResponsive";
 230   unresponsiveness_histogram_ = base::Histogram::FactoryTimeGet(
 231       unresponsiveness_histogram_name, base::TimeDelta::FromMilliseconds(1),
 232       base::TimeDelta::FromSeconds(60), 100,
 233       base::Histogram::kUmaTargetedHistogramFlag);
 234
 235   const std::string unresponsiveness_1sec_histogram_name =
 236       "Startup.FirstWebContents.UINotResponsive_1sec";
 237   unresponsiveness_1sec_histogram_ = base::Histogram::FactoryTimeGet(
 238       unresponsiveness_1sec_histogram_name,
 239       base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60),
 240       100, base::Histogram::kUmaTargetedHistogramFlag);
 241
 242   const std::string unresponsiveness_10sec_histogram_name =
 243       "Startup.FirstWebContents.UINotResponsive_10sec";
 244   unresponsiveness_10sec_histogram_ = base::Histogram::FactoryTimeGet(
 245       unresponsiveness_10sec_histogram_name,
 246       base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60),
 247       100, base::Histogram::kUmaTargetedHistogramFlag);
 248 }
 249 #endif  // !defined(OS_ANDROID)