| OLD | NEW |
|---|
| (Empty) |
| 1 // Copyright (c) 2012 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 #include "chrome/browser/jankometer.h" | |
| 6 | |
| 7 #include <limits> | |
| 8 | |
| 9 #include "base/basictypes.h" | |
| 10 #include "base/bind.h" | |
| 11 #include "base/command_line.h" | |
| 12 #include "base/memory/ref_counted.h" | |
| 13 #include "base/message_loop/message_loop.h" | |
| 14 #include "base/metrics/histogram.h" | |
| 15 #include "base/metrics/stats_counters.h" | |
| 16 #include "base/pending_task.h" | |
| 17 #include "base/strings/string_util.h" | |
| 18 #include "base/threading/thread.h" | |
| 19 #include "base/threading/watchdog.h" | |
| 20 #include "base/time/time.h" | |
| 21 #include "build/build_config.h" | |
| 22 #include "chrome/browser/browser_process.h" | |
| 23 #include "chrome/common/chrome_switches.h" | |
| 24 #include "content/public/browser/browser_thread.h" | |
| 25 | |
| 26 using base::TimeDelta; | |
| 27 using base::TimeTicks; | |
| 28 using content::BrowserThread; | |
| 29 | |
| 30 namespace { | |
| 31 | |
| 32 // The maximum threshold of delay of the message before considering it a delay. | |
| 33 // For a debug build, you may want to set IO delay around 500ms. | |
| 34 // For a release build, setting it around 350ms is sensible. | |
| 35 // Visit about:histograms to see what the distribution is on your system, with | |
| 36 // your build. Be sure to do some work to get interesting stats. | |
| 37 // The numbers below came from a warm start (you'll get about 5-10 alarms with | |
| 38 // a cold start), and running the page-cycler for 5 rounds. | |
| 39 #ifdef NDEBUG | |
| 40 const int kMaxUIMessageDelayMs = 350; | |
| 41 const int kMaxIOMessageDelayMs = 200; | |
| 42 #else | |
| 43 const int kMaxUIMessageDelayMs = 500; | |
| 44 const int kMaxIOMessageDelayMs = 400; | |
| 45 #endif | |
| 46 | |
| 47 // Maximum processing time (excluding queueing delay) for a message before | |
| 48 // considering it delayed. | |
| 49 const int kMaxMessageProcessingMs = 100; | |
| 50 | |
| 51 // TODO(brettw) Consider making this a pref. | |
| 52 const bool kPlaySounds = false; | |
| 53 | |
| 54 //------------------------------------------------------------------------------ | |
| 55 // Provide a special watchdog to make it easy to set the breakpoint on this | |
| 56 // class only. | |
| 57 class JankWatchdog : public base::Watchdog { | |
| 58 public: | |
| 59 JankWatchdog(const TimeDelta& duration, | |
| 60 const std::string& thread_watched_name, | |
| 61 bool enabled) | |
| 62 : Watchdog(duration, thread_watched_name, enabled), | |
| 63 thread_name_watched_(thread_watched_name), | |
| 64 alarm_count_(0) { | |
| 65 } | |
| 66 | |
| 67 virtual ~JankWatchdog() {} | |
| 68 | |
| 69 virtual void Alarm() OVERRIDE { | |
| 70 // Put break point here if you want to stop threads and look at what caused | |
| 71 // the jankiness. | |
| 72 alarm_count_++; | |
| 73 Watchdog::Alarm(); | |
| 74 } | |
| 75 | |
| 76 private: | |
| 77 std::string thread_name_watched_; | |
| 78 int alarm_count_; | |
| 79 | |
| 80 DISALLOW_COPY_AND_ASSIGN(JankWatchdog); | |
| 81 }; | |
| 82 | |
| 83 class JankObserverHelper { | |
| 84 public: | |
| 85 JankObserverHelper(const std::string& thread_name, | |
| 86 const TimeDelta& excessive_duration, | |
| 87 bool watchdog_enable); | |
| 88 ~JankObserverHelper(); | |
| 89 | |
| 90 void StartProcessingTimers(const TimeDelta& queueing_time); | |
| 91 void EndProcessingTimers(); | |
| 92 | |
| 93 // Indicate if we will bother to measuer this message. | |
| 94 bool MessageWillBeMeasured(); | |
| 95 | |
| 96 static void SetDefaultMessagesToSkip(int count) { discard_count_ = count; } | |
| 97 | |
| 98 private: | |
| 99 const TimeDelta max_message_delay_; | |
| 100 | |
| 101 // Indicate if we'll bother measuring this message. | |
| 102 bool measure_current_message_; | |
| 103 | |
| 104 // Down counter which will periodically hit 0, and only then bother to measure | |
| 105 // the corresponding message. | |
| 106 int events_till_measurement_; | |
| 107 | |
| 108 // The value to re-initialize events_till_measurement_ after it reaches 0. | |
| 109 static int discard_count_; | |
| 110 | |
| 111 // Time at which the current message processing began. | |
| 112 TimeTicks begin_process_message_; | |
| 113 | |
| 114 // Time the current message spent in the queue -- delta between message | |
| 115 // construction time and message processing time. | |
| 116 TimeDelta queueing_time_; | |
| 117 | |
| 118 // Counters for the two types of jank we measure. | |
| 119 base::StatsCounter slow_processing_counter_; // Msgs w/ long proc time. | |
| 120 base::StatsCounter queueing_delay_counter_; // Msgs w/ long queueing delay. | |
| 121 base::HistogramBase* const process_times_; // Time spent proc. task. | |
| 122 base::HistogramBase* const total_times_; // Total queueing plus proc. | |
| 123 JankWatchdog total_time_watchdog_; // Watching for excessive total_time. | |
| 124 | |
| 125 DISALLOW_COPY_AND_ASSIGN(JankObserverHelper); | |
| 126 }; | |
| 127 | |
| 128 JankObserverHelper::JankObserverHelper( | |
| 129 const std::string& thread_name, | |
| 130 const TimeDelta& excessive_duration, | |
| 131 bool watchdog_enable) | |
| 132 : max_message_delay_(excessive_duration), | |
| 133 measure_current_message_(true), | |
| 134 events_till_measurement_(0), | |
| 135 slow_processing_counter_(std::string("Chrome.SlowMsg") + thread_name), | |
| 136 queueing_delay_counter_(std::string("Chrome.DelayMsg") + thread_name), | |
| 137 process_times_(base::Histogram::FactoryGet( | |
| 138 std::string("Chrome.ProcMsgL ") + thread_name, | |
| 139 1, 3600000, 50, base::Histogram::kUmaTargetedHistogramFlag)), | |
| 140 total_times_(base::Histogram::FactoryGet( | |
| 141 std::string("Chrome.TotalMsgL ") + thread_name, | |
| 142 1, 3600000, 50, base::Histogram::kUmaTargetedHistogramFlag)), | |
| 143 total_time_watchdog_(excessive_duration, thread_name, watchdog_enable) { | |
| 144 if (discard_count_ > 0) { | |
| 145 // Select a vaguely random sample-start-point. | |
| 146 events_till_measurement_ = static_cast<int>( | |
| 147 (TimeTicks::Now() - TimeTicks()).InSeconds() % (discard_count_ + 1)); | |
| 148 } | |
| 149 } | |
| 150 | |
| 151 JankObserverHelper::~JankObserverHelper() {} | |
| 152 | |
| 153 // Called when a message has just begun processing, initializes | |
| 154 // per-message variables and timers. | |
| 155 void JankObserverHelper::StartProcessingTimers(const TimeDelta& queueing_time) { | |
| 156 DCHECK(measure_current_message_); | |
| 157 begin_process_message_ = TimeTicks::Now(); | |
| 158 queueing_time_ = queueing_time; | |
| 159 | |
| 160 // Simulate arming when the message entered the queue. | |
| 161 total_time_watchdog_.ArmSomeTimeDeltaAgo(queueing_time_); | |
| 162 if (queueing_time_ > max_message_delay_) { | |
| 163 // Message is too delayed. | |
| 164 queueing_delay_counter_.Increment(); | |
| 165 if (kPlaySounds) | |
| 166 MessageBeep(MB_ICONASTERISK); | |
| 167 } | |
| 168 } | |
| 169 | |
| 170 // Called when a message has just finished processing, finalizes | |
| 171 // per-message variables and timers. | |
| 172 void JankObserverHelper::EndProcessingTimers() { | |
| 173 if (!measure_current_message_) | |
| 174 return; | |
| 175 total_time_watchdog_.Disarm(); | |
| 176 TimeTicks now = TimeTicks::Now(); | |
| 177 if (begin_process_message_ != TimeTicks()) { | |
| 178 TimeDelta processing_time = now - begin_process_message_; | |
| 179 process_times_->AddTime(processing_time); | |
| 180 total_times_->AddTime(queueing_time_ + processing_time); | |
| 181 } | |
| 182 if (now - begin_process_message_ > | |
| 183 TimeDelta::FromMilliseconds(kMaxMessageProcessingMs)) { | |
| 184 // Message took too long to process. | |
| 185 slow_processing_counter_.Increment(); | |
| 186 if (kPlaySounds) | |
| 187 MessageBeep(MB_ICONHAND); | |
| 188 } | |
| 189 | |
| 190 // Reset message specific times. | |
| 191 begin_process_message_ = base::TimeTicks(); | |
| 192 queueing_time_ = base::TimeDelta(); | |
| 193 } | |
| 194 | |
| 195 bool JankObserverHelper::MessageWillBeMeasured() { | |
| 196 measure_current_message_ = events_till_measurement_ <= 0; | |
| 197 if (!measure_current_message_) | |
| 198 --events_till_measurement_; | |
| 199 else | |
| 200 events_till_measurement_ = discard_count_; | |
| 201 return measure_current_message_; | |
| 202 } | |
| 203 | |
| 204 // static | |
| 205 int JankObserverHelper::discard_count_ = 99; // Measure only 1 in 100. | |
| 206 | |
| 207 //------------------------------------------------------------------------------ | |
| 208 class IOJankObserver : public base::RefCountedThreadSafe<IOJankObserver>, | |
| 209 public base::MessageLoopForIO::IOObserver, | |
| 210 public base::MessageLoop::TaskObserver { | |
| 211 public: | |
| 212 IOJankObserver(const char* thread_name, | |
| 213 TimeDelta excessive_duration, | |
| 214 bool watchdog_enable) | |
| 215 : helper_(thread_name, excessive_duration, watchdog_enable) {} | |
| 216 | |
| 217 // Attaches the observer to the current thread's message loop. You can only | |
| 218 // attach to the current thread, so this function can be invoked on another | |
| 219 // thread to attach it. | |
| 220 void AttachToCurrentThread() { | |
| 221 base::MessageLoop::current()->AddTaskObserver(this); | |
| 222 base::MessageLoopForIO::current()->AddIOObserver(this); | |
| 223 } | |
| 224 | |
| 225 // Detaches the observer to the current thread's message loop. | |
| 226 void DetachFromCurrentThread() { | |
| 227 base::MessageLoopForIO::current()->RemoveIOObserver(this); | |
| 228 base::MessageLoop::current()->RemoveTaskObserver(this); | |
| 229 } | |
| 230 | |
| 231 virtual void WillProcessIOEvent() OVERRIDE { | |
| 232 if (!helper_.MessageWillBeMeasured()) | |
| 233 return; | |
| 234 helper_.StartProcessingTimers(base::TimeDelta()); | |
| 235 } | |
| 236 | |
| 237 virtual void DidProcessIOEvent() OVERRIDE { | |
| 238 helper_.EndProcessingTimers(); | |
| 239 } | |
| 240 | |
| 241 virtual void WillProcessTask(const base::PendingTask& pending_task) OVERRIDE { | |
| 242 if (!helper_.MessageWillBeMeasured()) | |
| 243 return; | |
| 244 base::TimeTicks now = base::TimeTicks::Now(); | |
| 245 const base::TimeDelta queueing_time = now - pending_task.time_posted; | |
| 246 helper_.StartProcessingTimers(queueing_time); | |
| 247 } | |
| 248 | |
| 249 virtual void DidProcessTask(const base::PendingTask& pending_task) OVERRIDE { | |
| 250 helper_.EndProcessingTimers(); | |
| 251 } | |
| 252 | |
| 253 private: | |
| 254 friend class base::RefCountedThreadSafe<IOJankObserver>; | |
| 255 | |
| 256 virtual ~IOJankObserver() {} | |
| 257 | |
| 258 JankObserverHelper helper_; | |
| 259 | |
| 260 DISALLOW_COPY_AND_ASSIGN(IOJankObserver); | |
| 261 }; | |
| 262 | |
| 263 //------------------------------------------------------------------------------ | |
| 264 class UIJankObserver : public base::RefCountedThreadSafe<UIJankObserver>, | |
| 265 public base::MessageLoop::TaskObserver, | |
| 266 public base::MessageLoopForUI::Observer { | |
| 267 public: | |
| 268 UIJankObserver(const char* thread_name, | |
| 269 TimeDelta excessive_duration, | |
| 270 bool watchdog_enable) | |
| 271 : helper_(thread_name, excessive_duration, watchdog_enable) {} | |
| 272 | |
| 273 // Attaches the observer to the current thread's message loop. You can only | |
| 274 // attach to the current thread, so this function can be invoked on another | |
| 275 // thread to attach it. | |
| 276 void AttachToCurrentThread() { | |
| 277 DCHECK(base::MessageLoopForUI::IsCurrent()); | |
| 278 base::MessageLoopForUI::current()->AddObserver(this); | |
| 279 base::MessageLoop::current()->AddTaskObserver(this); | |
| 280 } | |
| 281 | |
| 282 // Detaches the observer to the current thread's message loop. | |
| 283 void DetachFromCurrentThread() { | |
| 284 DCHECK(base::MessageLoopForUI::IsCurrent()); | |
| 285 base::MessageLoop::current()->RemoveTaskObserver(this); | |
| 286 base::MessageLoopForUI::current()->RemoveObserver(this); | |
| 287 } | |
| 288 | |
| 289 virtual void WillProcessTask(const base::PendingTask& pending_task) OVERRIDE { | |
| 290 if (!helper_.MessageWillBeMeasured()) | |
| 291 return; | |
| 292 base::TimeTicks now = base::TimeTicks::Now(); | |
| 293 const base::TimeDelta queueing_time = now - pending_task.time_posted; | |
| 294 helper_.StartProcessingTimers(queueing_time); | |
| 295 } | |
| 296 | |
| 297 virtual void DidProcessTask(const base::PendingTask& pending_task) OVERRIDE { | |
| 298 helper_.EndProcessingTimers(); | |
| 299 } | |
| 300 | |
| 301 virtual void WillProcessEvent(const base::NativeEvent& event) OVERRIDE { | |
| 302 if (!helper_.MessageWillBeMeasured()) | |
| 303 return; | |
| 304 // GetMessageTime returns a LONG (signed 32-bit) and GetTickCount returns | |
| 305 // a DWORD (unsigned 32-bit). They both wrap around when the time is longer | |
| 306 // than they can hold. I'm not sure if GetMessageTime wraps around to 0, | |
| 307 // or if the original time comes from GetTickCount, it might wrap around | |
| 308 // to -1. | |
| 309 // | |
| 310 // Therefore, I cast to DWORD so if it wraps to -1 we will correct it. If | |
| 311 // it doesn't, then our time delta will be negative if a message happens | |
| 312 // to straddle the wraparound point, it will still be OK. | |
| 313 DWORD cur_message_issue_time = static_cast<DWORD>(event.time); | |
| 314 DWORD cur_time = GetTickCount(); | |
| 315 base::TimeDelta queueing_time = | |
| 316 base::TimeDelta::FromMilliseconds(cur_time - cur_message_issue_time); | |
| 317 | |
| 318 helper_.StartProcessingTimers(queueing_time); | |
| 319 } | |
| 320 | |
| 321 virtual void DidProcessEvent(const base::NativeEvent& event) OVERRIDE { | |
| 322 helper_.EndProcessingTimers(); | |
| 323 } | |
| 324 | |
| 325 private: | |
| 326 friend class base::RefCountedThreadSafe<UIJankObserver>; | |
| 327 | |
| 328 virtual ~UIJankObserver() {} | |
| 329 | |
| 330 JankObserverHelper helper_; | |
| 331 | |
| 332 DISALLOW_COPY_AND_ASSIGN(UIJankObserver); | |
| 333 }; | |
| 334 | |
| 335 // These objects are created by InstallJankometer and leaked. | |
| 336 const scoped_refptr<UIJankObserver>* ui_observer = NULL; | |
| 337 const scoped_refptr<IOJankObserver>* io_observer = NULL; | |
| 338 | |
| 339 } // namespace | |
| 340 | |
| 341 void InstallJankometer(const CommandLine& parsed_command_line) { | |
| 342 if (ui_observer || io_observer) { | |
| 343 NOTREACHED() << "Initializing jank-o-meter twice"; | |
| 344 return; | |
| 345 } | |
| 346 | |
| 347 bool ui_watchdog_enabled = false; | |
| 348 bool io_watchdog_enabled = false; | |
| 349 if (parsed_command_line.HasSwitch(switches::kEnableWatchdog)) { | |
| 350 std::string list = | |
| 351 parsed_command_line.GetSwitchValueASCII(switches::kEnableWatchdog); | |
| 352 if (list.npos != list.find("ui")) | |
| 353 ui_watchdog_enabled = true; | |
| 354 if (list.npos != list.find("io")) | |
| 355 io_watchdog_enabled = true; | |
| 356 } | |
| 357 | |
| 358 if (ui_watchdog_enabled || io_watchdog_enabled) | |
| 359 JankObserverHelper::SetDefaultMessagesToSkip(0); // Watch everything. | |
| 360 | |
| 361 // Install on the UI thread. | |
| 362 ui_observer = new scoped_refptr<UIJankObserver>( | |
| 363 new UIJankObserver( | |
| 364 "UI", | |
| 365 TimeDelta::FromMilliseconds(kMaxUIMessageDelayMs), | |
| 366 ui_watchdog_enabled)); | |
| 367 (*ui_observer)->AttachToCurrentThread(); | |
| 368 | |
| 369 // Now install on the I/O thread. Hiccups on that thread will block | |
| 370 // interaction with web pages. We must proxy to that thread before we can | |
| 371 // add our observer. | |
| 372 io_observer = new scoped_refptr<IOJankObserver>( | |
| 373 new IOJankObserver( | |
| 374 "IO", | |
| 375 TimeDelta::FromMilliseconds(kMaxIOMessageDelayMs), | |
| 376 io_watchdog_enabled)); | |
| 377 BrowserThread::PostTask( | |
| 378 BrowserThread::IO, FROM_HERE, | |
| 379 base::Bind(&IOJankObserver::AttachToCurrentThread, io_observer->get())); | |
| 380 } | |
| 381 | |
| 382 void UninstallJankometer() { | |
| 383 if (ui_observer) { | |
| 384 (*ui_observer)->DetachFromCurrentThread(); | |
| 385 delete ui_observer; | |
| 386 ui_observer = NULL; | |
| 387 } | |
| 388 if (io_observer) { | |
| 389 // IO thread can't be running when we remove observers. | |
| 390 DCHECK((!g_browser_process) || !(g_browser_process->io_thread())); | |
| 391 delete io_observer; | |
| 392 io_observer = NULL; | |
| 393 } | |
| 394 } | |
| OLD | NEW |
|---|
Chromium Code Reviews
