From ea812b8f47c0b2424b32a07b760a2d871303a9bc Mon Sep 17 00:00:00 2001 From: "jar@chromium.org" Date: Wed, 3 Nov 2010 23:36:34 +0000 Subject: Reduce Jankometer measurements by only periodically sampling The Jankometer is monitoring durations for each task, but most of the time, this work is not used. I changed the system to only sample the durations, unless someone turns on a watchdog, and then we monitor every event. The sampling is deterministic, (every N events is sampled) but should be fine when we aggregate across thousands of users in a histogram. r=brettw Review URL: http://codereview.chromium.org/4279003 git-svn-id: svn://svn.chromium.org/chrome/trunk/src@64991 0039d316-1c4b-4281-b951-d872f2087c98 --- chrome/browser/jankometer.cc | 50 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 50 insertions(+) diff --git a/chrome/browser/jankometer.cc b/chrome/browser/jankometer.cc index e58b71a..c7f6184 100644 --- a/chrome/browser/jankometer.cc +++ b/chrome/browser/jankometer.cc @@ -91,9 +91,24 @@ class JankObserverHelper { void StartProcessingTimers(const TimeDelta& queueing_time); void EndProcessingTimers(); + // Indicate if we will bother to measuer this message. + bool MessageWillBeMeasured(); + + static void SetDefaultMessagesToSkip(int count) { discard_count_ = count; } + private: const TimeDelta max_message_delay_; + // Indicate if we'll bother measuring this message. + bool measure_current_message_; + + // Down counter which will periodically hit 0, and only then bother to measure + // the corresponding message. + int events_till_measurement_; + + // The value to re-initialize events_till_measurement_ after it reaches 0. + static int discard_count_; + // Time at which the current message processing began. TimeTicks begin_process_message_; @@ -116,6 +131,8 @@ JankObserverHelper::JankObserverHelper( const TimeDelta& excessive_duration, bool watchdog_enable) : max_message_delay_(excessive_duration), + measure_current_message_(true), + events_till_measurement_(0), slow_processing_counter_(std::string("Chrome.SlowMsg") + thread_name), queueing_delay_counter_(std::string("Chrome.DelayMsg") + thread_name), total_time_watchdog_(excessive_duration, thread_name, watchdog_enable) { @@ -125,6 +142,11 @@ JankObserverHelper::JankObserverHelper( total_times_ = base::Histogram::FactoryGet( std::string("Chrome.TotalMsgL ") + thread_name, 1, 3600000, 50, base::Histogram::kUmaTargetedHistogramFlag); + if (discard_count_ > 0) { + // Select a vaguely random sample-start-point. + events_till_measurement_ = + (TimeTicks::Now() - TimeTicks()).InSeconds() % (discard_count_ + 1); + } } JankObserverHelper::~JankObserverHelper() {} @@ -132,6 +154,7 @@ JankObserverHelper::~JankObserverHelper() {} // Called when a message has just begun processing, initializes // per-message variables and timers. void JankObserverHelper::StartProcessingTimers(const TimeDelta& queueing_time) { + DCHECK(measure_current_message_); begin_process_message_ = TimeTicks::Now(); queueing_time_ = queueing_time; @@ -150,6 +173,8 @@ void JankObserverHelper::StartProcessingTimers(const TimeDelta& queueing_time) { // Called when a message has just finished processing, finalizes // per-message variables and timers. void JankObserverHelper::EndProcessingTimers() { + if (!measure_current_message_) + return; total_time_watchdog_.Disarm(); TimeTicks now = TimeTicks::Now(); if (begin_process_message_ != TimeTicks()) { @@ -172,6 +197,18 @@ void JankObserverHelper::EndProcessingTimers() { queueing_time_ = base::TimeDelta(); } +bool JankObserverHelper::MessageWillBeMeasured() { + measure_current_message_ = events_till_measurement_ <= 0; + if (!measure_current_message_) + --events_till_measurement_; + else + events_till_measurement_ = discard_count_; + return measure_current_message_; +} + +// static +int JankObserverHelper::discard_count_ = 99; // Measure only 1 in 100. + //------------------------------------------------------------------------------ class IOJankObserver : public base::RefCountedThreadSafe, public MessageLoopForIO::IOObserver, @@ -199,6 +236,8 @@ class IOJankObserver : public base::RefCountedThreadSafe, } virtual void WillProcessIOEvent() { + if (!helper_.MessageWillBeMeasured()) + return; helper_.StartProcessingTimers(base::TimeDelta()); } @@ -207,6 +246,8 @@ class IOJankObserver : public base::RefCountedThreadSafe, } virtual void WillProcessTask(const Task* task) { + if (!helper_.MessageWillBeMeasured()) + return; base::TimeTicks now = base::TimeTicks::Now(); const base::TimeDelta queueing_time = now - task->tracked_birth_time(); helper_.StartProcessingTimers(queueing_time); @@ -251,6 +292,8 @@ class UIJankObserver : public base::RefCountedThreadSafe, } virtual void WillProcessTask(const Task* task) { + if (!helper_.MessageWillBeMeasured()) + return; base::TimeTicks now = base::TimeTicks::Now(); const base::TimeDelta queueing_time = now - task->tracked_birth_time(); helper_.StartProcessingTimers(queueing_time); @@ -262,6 +305,8 @@ class UIJankObserver : public base::RefCountedThreadSafe, #if defined(OS_WIN) virtual void WillProcessMessage(const MSG& msg) { + if (!helper_.MessageWillBeMeasured()) + return; // GetMessageTime returns a LONG (signed 32-bit) and GetTickCount returns // a DWORD (unsigned 32-bit). They both wrap around when the time is longer // than they can hold. I'm not sure if GetMessageTime wraps around to 0, @@ -284,6 +329,8 @@ class UIJankObserver : public base::RefCountedThreadSafe, } #elif defined(TOOLKIT_USES_GTK) virtual void WillProcessEvent(GdkEvent* event) { + if (!helper_.MessageWillBeMeasured()) + return; // TODO(evanm): we want to set queueing_time_ using // gdk_event_get_time, but how do you convert that info // into a delta? @@ -330,6 +377,9 @@ void InstallJankometer(const CommandLine& parsed_command_line) { io_watchdog_enabled = true; } + if (ui_watchdog_enabled || io_watchdog_enabled) + JankObserverHelper::SetDefaultMessagesToSkip(0); // Watch everything. + // Install on the UI thread. ui_observer = new scoped_refptr( new UIJankObserver( -- cgit v1.1