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 defined(OS_WIN) 166 if (kPlaySounds) 167 MessageBeep(MB_ICONASTERISK); 168 #endif 169 } 170 } 171 172 // Called when a message has just finished processing, finalizes 173 // per-message variables and timers. 174 void JankObserverHelper::EndProcessingTimers() { 175 if (!measure_current_message_) 176 return; 177 total_time_watchdog_.Disarm(); 178 TimeTicks now = TimeTicks::Now(); 179 if (begin_process_message_ != TimeTicks()) { 180 TimeDelta processing_time = now - begin_process_message_; 181 process_times_->AddTime(processing_time); 182 total_times_->AddTime(queueing_time_ + processing_time); 183 } 184 if (now - begin_process_message_ > 185 TimeDelta::FromMilliseconds(kMaxMessageProcessingMs)) { 186 // Message took too long to process. 187 slow_processing_counter_.Increment(); 188 #if defined(OS_WIN) 189 if (kPlaySounds) 190 MessageBeep(MB_ICONHAND); 191 #endif 192 } 193 194 // Reset message specific times. 195 begin_process_message_ = base::TimeTicks(); 196 queueing_time_ = base::TimeDelta(); 197 } 198 199 bool JankObserverHelper::MessageWillBeMeasured() { 200 measure_current_message_ = events_till_measurement_ <= 0; 201 if (!measure_current_message_) 202 --events_till_measurement_; 203 else 204 events_till_measurement_ = discard_count_; 205 return measure_current_message_; 206 } 207 208 // static 209 int JankObserverHelper::discard_count_ = 99; // Measure only 1 in 100. 210 211 //------------------------------------------------------------------------------ 212 class IOJankObserver : public base::RefCountedThreadSafe<IOJankObserver>, 213 public base::MessageLoopForIO::IOObserver, 214 public base::MessageLoop::TaskObserver { 215 public: 216 IOJankObserver(const char* thread_name, 217 TimeDelta excessive_duration, 218 bool watchdog_enable) 219 : helper_(thread_name, excessive_duration, watchdog_enable) {} 220 221 // Attaches the observer to the current thread's message loop. You can only 222 // attach to the current thread, so this function can be invoked on another 223 // thread to attach it. 224 void AttachToCurrentThread() { 225 base::MessageLoop::current()->AddTaskObserver(this); 226 base::MessageLoopForIO::current()->AddIOObserver(this); 227 } 228 229 // Detaches the observer to the current thread's message loop. 230 void DetachFromCurrentThread() { 231 base::MessageLoopForIO::current()->RemoveIOObserver(this); 232 base::MessageLoop::current()->RemoveTaskObserver(this); 233 } 234 235 virtual void WillProcessIOEvent() OVERRIDE { 236 if (!helper_.MessageWillBeMeasured()) 237 return; 238 helper_.StartProcessingTimers(base::TimeDelta()); 239 } 240 241 virtual void DidProcessIOEvent() OVERRIDE { 242 helper_.EndProcessingTimers(); 243 } 244 245 virtual void WillProcessTask(const base::PendingTask& pending_task) OVERRIDE { 246 if (!helper_.MessageWillBeMeasured()) 247 return; 248 base::TimeTicks now = base::TimeTicks::Now(); 249 const base::TimeDelta queueing_time = now - pending_task.time_posted; 250 helper_.StartProcessingTimers(queueing_time); 251 } 252 253 virtual void DidProcessTask(const base::PendingTask& pending_task) OVERRIDE { 254 helper_.EndProcessingTimers(); 255 } 256 257 private: 258 friend class base::RefCountedThreadSafe<IOJankObserver>; 259 260 virtual ~IOJankObserver() {} 261 262 JankObserverHelper helper_; 263 264 DISALLOW_COPY_AND_ASSIGN(IOJankObserver); 265 }; 266 267 //------------------------------------------------------------------------------ 268 class UIJankObserver : public base::RefCountedThreadSafe<UIJankObserver>, 269 public base::MessageLoop::TaskObserver, 270 public base::MessageLoopForUI::Observer { 271 public: 272 UIJankObserver(const char* thread_name, 273 TimeDelta excessive_duration, 274 bool watchdog_enable) 275 : helper_(thread_name, excessive_duration, watchdog_enable) {} 276 277 // Attaches the observer to the current thread's message loop. You can only 278 // attach to the current thread, so this function can be invoked on another 279 // thread to attach it. 280 void AttachToCurrentThread() { 281 DCHECK_EQ(base::MessageLoop::current()->type(), base::MessageLoop::TYPE_UI); 282 base::MessageLoopForUI::current()->AddObserver(this); 283 base::MessageLoop::current()->AddTaskObserver(this); 284 } 285 286 // Detaches the observer to the current thread's message loop. 287 void DetachFromCurrentThread() { 288 DCHECK_EQ(base::MessageLoop::current()->type(), base::MessageLoop::TYPE_UI); 289 base::MessageLoop::current()->RemoveTaskObserver(this); 290 base::MessageLoopForUI::current()->RemoveObserver(this); 291 } 292 293 virtual void WillProcessTask(const base::PendingTask& pending_task) OVERRIDE { 294 if (!helper_.MessageWillBeMeasured()) 295 return; 296 base::TimeTicks now = base::TimeTicks::Now(); 297 const base::TimeDelta queueing_time = now - pending_task.time_posted; 298 helper_.StartProcessingTimers(queueing_time); 299 } 300 301 virtual void DidProcessTask(const base::PendingTask& pending_task) OVERRIDE { 302 helper_.EndProcessingTimers(); 303 } 304 305 #if defined(OS_WIN) 306 virtual base::EventStatus WillProcessEvent( 307 const base::NativeEvent& event) OVERRIDE { 308 if (!helper_.MessageWillBeMeasured()) 309 return base::EVENT_CONTINUE; 310 // GetMessageTime returns a LONG (signed 32-bit) and GetTickCount returns 311 // a DWORD (unsigned 32-bit). They both wrap around when the time is longer 312 // than they can hold. I'm not sure if GetMessageTime wraps around to 0, 313 // or if the original time comes from GetTickCount, it might wrap around 314 // to -1. 315 // 316 // Therefore, I cast to DWORD so if it wraps to -1 we will correct it. If 317 // it doesn't, then our time delta will be negative if a message happens 318 // to straddle the wraparound point, it will still be OK. 319 DWORD cur_message_issue_time = static_cast<DWORD>(event.time); 320 DWORD cur_time = GetTickCount(); 321 base::TimeDelta queueing_time = 322 base::TimeDelta::FromMilliseconds(cur_time - cur_message_issue_time); 323 324 helper_.StartProcessingTimers(queueing_time); 325 return base::EVENT_CONTINUE; 326 } 327 328 virtual void DidProcessEvent(const base::NativeEvent& event) OVERRIDE { 329 helper_.EndProcessingTimers(); 330 } 331 #elif defined(USE_AURA) 332 virtual base::EventStatus WillProcessEvent( 333 const base::NativeEvent& event) OVERRIDE { 334 return base::EVENT_CONTINUE; 335 } 336 337 virtual void DidProcessEvent(const base::NativeEvent& event) OVERRIDE { 338 } 339 #elif defined(TOOLKIT_GTK) 340 virtual void WillProcessEvent(GdkEvent* event) OVERRIDE { 341 if (!helper_.MessageWillBeMeasured()) 342 return; 343 // TODO(evanm): we want to set queueing_time_ using 344 // gdk_event_get_time, but how do you convert that info 345 // into a delta? 346 // guint event_time = gdk_event_get_time(event); 347 base::TimeDelta queueing_time = base::TimeDelta::FromMilliseconds(0); 348 helper_.StartProcessingTimers(queueing_time); 349 } 350 351 virtual void DidProcessEvent(GdkEvent* event) OVERRIDE { 352 helper_.EndProcessingTimers(); 353 } 354 #endif 355 356 private: 357 friend class base::RefCountedThreadSafe<UIJankObserver>; 358 359 virtual ~UIJankObserver() {} 360 361 JankObserverHelper helper_; 362 363 DISALLOW_COPY_AND_ASSIGN(UIJankObserver); 364 }; 365 366 // These objects are created by InstallJankometer and leaked. 367 const scoped_refptr<UIJankObserver>* ui_observer = NULL; 368 const scoped_refptr<IOJankObserver>* io_observer = NULL; 369 370 } // namespace 371 372 void InstallJankometer(const CommandLine& parsed_command_line) { 373 if (ui_observer || io_observer) { 374 NOTREACHED() << "Initializing jank-o-meter twice"; 375 return; 376 } 377 378 bool ui_watchdog_enabled = false; 379 bool io_watchdog_enabled = false; 380 if (parsed_command_line.HasSwitch(switches::kEnableWatchdog)) { 381 std::string list = 382 parsed_command_line.GetSwitchValueASCII(switches::kEnableWatchdog); 383 if (list.npos != list.find("ui")) 384 ui_watchdog_enabled = true; 385 if (list.npos != list.find("io")) 386 io_watchdog_enabled = true; 387 } 388 389 if (ui_watchdog_enabled || io_watchdog_enabled) 390 JankObserverHelper::SetDefaultMessagesToSkip(0); // Watch everything. 391 392 // Install on the UI thread. 393 ui_observer = new scoped_refptr<UIJankObserver>( 394 new UIJankObserver( 395 "UI", 396 TimeDelta::FromMilliseconds(kMaxUIMessageDelayMs), 397 ui_watchdog_enabled)); 398 (*ui_observer)->AttachToCurrentThread(); 399 400 // Now install on the I/O thread. Hiccups on that thread will block 401 // interaction with web pages. We must proxy to that thread before we can 402 // add our observer. 403 io_observer = new scoped_refptr<IOJankObserver>( 404 new IOJankObserver( 405 "IO", 406 TimeDelta::FromMilliseconds(kMaxIOMessageDelayMs), 407 io_watchdog_enabled)); 408 BrowserThread::PostTask( 409 BrowserThread::IO, FROM_HERE, 410 base::Bind(&IOJankObserver::AttachToCurrentThread, io_observer->get())); 411 } 412 413 void UninstallJankometer() { 414 if (ui_observer) { 415 (*ui_observer)->DetachFromCurrentThread(); 416 delete ui_observer; 417 ui_observer = NULL; 418 } 419 if (io_observer) { 420 // IO thread can't be running when we remove observers. 421 DCHECK((!g_browser_process) || !(g_browser_process->io_thread())); 422 delete io_observer; 423 io_observer = NULL; 424 } 425 } 426