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