// 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. #if !defined(OS_ANDROID) #include "chrome/browser/metrics/first_web_contents_profiler.h" #include #include "base/location.h" #include "base/metrics/histogram_macros.h" #include "base/process/process_info.h" #include "base/single_thread_task_runner.h" #include "base/thread_task_runner_handle.h" #include "base/time/time.h" #include "chrome/browser/ui/browser.h" #include "chrome/browser/ui/browser_iterator.h" #include "chrome/browser/ui/tabs/tab_strip_model.h" #include "components/metrics/profiler/tracking_synchronizer.h" #include "components/metrics/proto/profiler_event.pb.h" #include "components/startup_metric_utils/startup_metric_utils.h" #include "content/public/browser/browser_thread.h" namespace { // The initial delay for responsiveness prober in milliseconds. const int kInitialDelayMs = 20; // The following is the multiplier is used to delay the probe for // responsiveness. const double kBackoffMultiplier = 1.5; // The maximum backoff delay in milliseconds. const int kMaxDelayMs = 250; void DelayedRecordUIResponsiveness( base::HistogramBase* responsiveness_histogram, base::HistogramBase* unresponsiveness_histogram, base::Time start_recording_time, base::TimeDelta next_task_delay); // Records the elapsed time for a task to execute a UI task under 1/60s after // the first WebContent was painted at least once. If after few tries it is // unable to execute under 1/60s it records the execution time of a task. void RecordUIResponsiveness(base::HistogramBase* responsiveness_histogram, base::HistogramBase* unresponsiveness_histogram, base::Time start_recording_time, base::Time task_posted_time, base::TimeDelta next_task_delay) { DCHECK(!start_recording_time.is_null()); DCHECK(!task_posted_time.is_null()); base::Time now = base::Time::Now(); base::TimeDelta elapsed = now - task_posted_time; // Task executed in less then 1/60s. if (elapsed.InMilliseconds() <= (1000 / 60)) { responsiveness_histogram->AddTime(now - start_recording_time); } else if (next_task_delay.InMilliseconds() > kMaxDelayMs) { // Records elapsed time to execute last task. unresponsiveness_histogram->AddTime(elapsed); } else { base::ThreadTaskRunnerHandle::Get()->PostDelayedTask( FROM_HERE, base::Bind(&DelayedRecordUIResponsiveness, responsiveness_histogram, unresponsiveness_histogram, start_recording_time, next_task_delay * kBackoffMultiplier), next_task_delay); } } // Used for posting |RecordUIResponsiveness| without delay, so that // |RecordUIResponsiveness| can do more accurate time calculation for elapsed // time of the task to complete. void DelayedRecordUIResponsiveness( base::HistogramBase* responsiveness_histogram, base::HistogramBase* unresponsiveness_histogram, base::Time start_recording_time, base::TimeDelta next_task_delay) { base::ThreadTaskRunnerHandle::Get()->PostTask( FROM_HERE, base::Bind(&RecordUIResponsiveness, responsiveness_histogram, unresponsiveness_histogram, start_recording_time, base::Time::Now(), next_task_delay)); } // Sends the first task for measuring UI Responsiveness. void MeasureUIResponsiveness(base::HistogramBase* responsiveness_histogram, base::HistogramBase* unresponsiveness_histogram) { base::ThreadTaskRunnerHandle::Get()->PostTask( FROM_HERE, base::Bind(&RecordUIResponsiveness, responsiveness_histogram, unresponsiveness_histogram, base::Time::Now(), base::Time::Now(), base::TimeDelta::FromMilliseconds(kInitialDelayMs))); } } // namespace scoped_ptr FirstWebContentsProfiler::CreateProfilerForFirstWebContents( Delegate* delegate) { DCHECK(delegate); for (chrome::BrowserIterator iterator; !iterator.done(); iterator.Next()) { Browser* browser = *iterator; content::WebContents* web_contents = browser->tab_strip_model()->GetActiveWebContents(); if (web_contents) { return scoped_ptr( new FirstWebContentsProfiler(web_contents, delegate)); } } return nullptr; } FirstWebContentsProfiler::FirstWebContentsProfiler( content::WebContents* web_contents, Delegate* delegate) : content::WebContentsObserver(web_contents), collected_paint_metric_(false), collected_load_metric_(false), delegate_(delegate), responsiveness_histogram_(NULL), responsiveness_1sec_histogram_(NULL), responsiveness_10sec_histogram_(NULL), unresponsiveness_histogram_(NULL), unresponsiveness_1sec_histogram_(NULL), unresponsiveness_10sec_histogram_(NULL) { process_creation_time_ = base::CurrentProcessInfo::CreationTime(); InitHistograms(); } void FirstWebContentsProfiler::DidFirstVisuallyNonEmptyPaint() { if (collected_paint_metric_) return; if (startup_metric_utils::WasNonBrowserUIDisplayed()) { FinishedCollectingMetrics(); return; } collected_paint_metric_ = true; if (!process_creation_time_.is_null()) { base::TimeDelta elapsed = base::Time::Now() - process_creation_time_; UMA_HISTOGRAM_LONG_TIMES_100("Startup.FirstWebContents.NonEmptyPaint", elapsed); } metrics::TrackingSynchronizer::OnProfilingPhaseCompleted( metrics::ProfilerEventProto::EVENT_FIRST_NONEMPTY_PAINT); // Measures responsiveness now. MeasureUIResponsiveness(responsiveness_histogram_, unresponsiveness_histogram_); // As it was observed that sometimes the task queue can be free immediately // after the first paint but get overloaded shortly thereafter, here we // measures responsiveness after 1 second and 10 seconds to observe the // possible effect of those late tasks. base::ThreadTaskRunnerHandle::Get()->PostDelayedTask( FROM_HERE, base::Bind(&MeasureUIResponsiveness, responsiveness_1sec_histogram_, unresponsiveness_1sec_histogram_), base::TimeDelta::FromSeconds(1)); base::ThreadTaskRunnerHandle::Get()->PostDelayedTask( FROM_HERE, base::Bind(&MeasureUIResponsiveness, responsiveness_10sec_histogram_, unresponsiveness_10sec_histogram_), base::TimeDelta::FromSeconds(10)); if (IsFinishedCollectingMetrics()) FinishedCollectingMetrics(); } void FirstWebContentsProfiler::DocumentOnLoadCompletedInMainFrame() { if (collected_load_metric_) return; if (startup_metric_utils::WasNonBrowserUIDisplayed()) { FinishedCollectingMetrics(); return; } collected_load_metric_ = true; if (!process_creation_time_.is_null()) { base::TimeDelta elapsed = base::Time::Now() - process_creation_time_; UMA_HISTOGRAM_LONG_TIMES_100("Startup.FirstWebContents.MainFrameLoad", elapsed); } if (IsFinishedCollectingMetrics()) FinishedCollectingMetrics(); } void FirstWebContentsProfiler::WebContentsDestroyed() { FinishedCollectingMetrics(); } bool FirstWebContentsProfiler::IsFinishedCollectingMetrics() { return collected_paint_metric_ && collected_load_metric_; } void FirstWebContentsProfiler::FinishedCollectingMetrics() { delegate_->ProfilerFinishedCollectingMetrics(); } void FirstWebContentsProfiler::InitHistograms() { const std::string responsiveness_histogram_name = "Startup.FirstWebContents.UIResponsive"; responsiveness_histogram_ = base::Histogram::FactoryTimeGet( responsiveness_histogram_name, base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60), 100, base::Histogram::kUmaTargetedHistogramFlag); const std::string responsiveness_1sec_histogram_name = "Startup.FirstWebContents.UIResponsive_1sec"; responsiveness_1sec_histogram_ = base::Histogram::FactoryTimeGet( responsiveness_1sec_histogram_name, base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60), 100, base::Histogram::kUmaTargetedHistogramFlag); const std::string responsiveness_10sec_histogram_name = "Startup.FirstWebContents.UIResponsive_10sec"; responsiveness_10sec_histogram_ = base::Histogram::FactoryTimeGet( responsiveness_10sec_histogram_name, base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60), 100, base::Histogram::kUmaTargetedHistogramFlag); const std::string unresponsiveness_histogram_name = "Startup.FirstWebContents.UINotResponsive"; unresponsiveness_histogram_ = base::Histogram::FactoryTimeGet( unresponsiveness_histogram_name, base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60), 100, base::Histogram::kUmaTargetedHistogramFlag); const std::string unresponsiveness_1sec_histogram_name = "Startup.FirstWebContents.UINotResponsive_1sec"; unresponsiveness_1sec_histogram_ = base::Histogram::FactoryTimeGet( unresponsiveness_1sec_histogram_name, base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60), 100, base::Histogram::kUmaTargetedHistogramFlag); const std::string unresponsiveness_10sec_histogram_name = "Startup.FirstWebContents.UINotResponsive_10sec"; unresponsiveness_10sec_histogram_ = base::Histogram::FactoryTimeGet( unresponsiveness_10sec_histogram_name, base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60), 100, base::Histogram::kUmaTargetedHistogramFlag); } #endif // !defined(OS_ANDROID)