path: root/chrome/browser/jankometer.cc

// Copyright (c) 2006-2008 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.

#include <limits>

#include "chrome/browser/jankometer.h"

#include "base/basictypes.h"
#include "base/command_line.h"
#include "base/histogram.h"
#include "base/message_loop.h"
#include "base/ref_counted.h"
#include "base/stats_counters.h"
#include "base/string_util.h"
#include "base/thread.h"
#include "base/time.h"
#include "base/watchdog.h"
#include "chrome/browser/browser_process.h"
#include "chrome/common/chrome_switches.h"

using base::TimeDelta;
using base::TimeTicks;

namespace {

// The maximum threshold of delay of the message  before considering it a delay.
// For a debug build, you may want to set IO delay around 500ms.
// For a release build, setting it around 350ms is sensible.
// Visit about:histograms to see what the distribution is on your system, with
// your build. Be sure to do some work to get interesting stats.
// The numbers below came from a warm start (you'll get about 5-10 alarms with
// a cold start), and running the page-cycler for 5 rounds.
#ifdef NDEBUG
const int kMaxUIMessageDelayMs = 350;
const int kMaxIOMessageDelayMs = 200;
#else
const int kMaxUIMessageDelayMs = 500;
const int kMaxIOMessageDelayMs = 400;
#endif

// Maximum processing time (excluding queueing delay) for a message before
// considering it delayed.
const int kMaxMessageProcessingMs = 100;

// TODO(brettw) Consider making this a pref.
const bool kPlaySounds = false;

//------------------------------------------------------------------------------
// Provide a special watchdog to make it easy to set the breakpoint on this
// class only.
class JankWatchdog : public Watchdog {
 public:
  JankWatchdog(const TimeDelta& duration,
               const std::string& thread_watched_name,
               bool enabled)
      : Watchdog(duration, ASCIIToWide(thread_watched_name), enabled),
        thread_name_watched_(thread_watched_name),
        alarm_count_(0) {
  }

  virtual ~JankWatchdog() {}

  virtual void Alarm() {
    // Put break point here if you want to stop threads and look at what caused
    // the jankiness.
    alarm_count_++;
    Watchdog::Alarm();
  }

 private:
  std::string thread_name_watched_;
  int alarm_count_;

  DISALLOW_EVIL_CONSTRUCTORS(JankWatchdog);
};

//------------------------------------------------------------------------------
class JankObserver : public base::RefCountedThreadSafe<JankObserver>,
                     public MessageLoopForUI::Observer {
 public:
  JankObserver(const char* thread_name,
               const TimeDelta& excessive_duration,
               bool watchdog_enable)
      : MaxMessageDelay_(excessive_duration),
        slow_processing_counter_(std::string("Chrome.SlowMsg") + thread_name),
        queueing_delay_counter_(std::string("Chrome.DelayMsg") + thread_name),
        process_times_((std::wstring(L"Chrome.ProcMsgL ")
                        + ASCIIToWide(thread_name)).c_str(), 1, 3600000, 50),
        total_times_((std::wstring(L"Chrome.TotalMsgL ")
                      + ASCIIToWide(thread_name)).c_str(), 1, 3600000, 50),
        total_time_watchdog_(excessive_duration, thread_name, watchdog_enable) {
    process_times_.SetFlags(kUmaTargetedHistogramFlag);
    total_times_.SetFlags(kUmaTargetedHistogramFlag);
  }

  // Attaches the observer to the current thread's message loop. You can only
  // attach to the current thread, so this function can be invoked on another
  // thread to attach it.
  void AttachToCurrentThread() {
    // TODO(darin): support monitoring jankiness on non-UI threads!
    if (MessageLoop::current()->type() == MessageLoop::TYPE_UI)
      MessageLoopForUI::current()->AddObserver(this);
  }

  // Detaches the observer to the current thread's message loop.
  void DetachFromCurrentThread() {
    if (MessageLoop::current()->type() == MessageLoop::TYPE_UI)
      MessageLoopForUI::current()->RemoveObserver(this);
  }

  void WillProcessMessage(const MSG& msg) {
    begin_process_message_ = TimeTicks::Now();

    // 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,
    // or if the original time comes from GetTickCount, it might wrap around
    // to -1.
    //
    // Therefore, I cast to DWORD so if it wraps to -1 we will correct it. If
    // it doesn't, then our time delta will be negative if a message happens
    // to straddle the wraparound point, it will still be OK.
    DWORD cur_message_issue_time = static_cast<DWORD>(msg.time);
    DWORD cur_time = GetTickCount();
    queueing_time_ = TimeDelta::FromMilliseconds(cur_time
                                                 - cur_message_issue_time);
    // Simulate arming when the message entered the queue.
    total_time_watchdog_.ArmSomeTimeDeltaAgo(queueing_time_);
    if (queueing_time_ > MaxMessageDelay_) {
      // Message is too delayed.
      queueing_delay_counter_.Increment();
      if (kPlaySounds)
        MessageBeep(MB_ICONASTERISK);
    }
  }

  void DidProcessMessage(const MSG& msg) {
    total_time_watchdog_.Disarm();
    TimeTicks now = TimeTicks::Now();
    if (begin_process_message_ != TimeTicks()) {
      TimeDelta processing_time = now - begin_process_message_;
      process_times_.AddTime(processing_time);
      total_times_.AddTime(queueing_time_ + processing_time);
    }
    if (now - begin_process_message_ >
        TimeDelta::FromMilliseconds(kMaxMessageProcessingMs)) {
      // Message took too long to process.
      slow_processing_counter_.Increment();
      if (kPlaySounds)
        MessageBeep(MB_ICONHAND);
    }
  }

 private:
  const TimeDelta MaxMessageDelay_;
  TimeTicks begin_process_message_;
  TimeDelta queueing_time_;

  // Counters for the two types of jank we measure.
  StatsCounter slow_processing_counter_;  // Messages with long processing time.
  StatsCounter queueing_delay_counter_;   // Messages with long queueing delay.
  Histogram process_times_;           // Time spent processing task.
  Histogram total_times_;             // Total of queueing plus processing time.
  JankWatchdog total_time_watchdog_;  // Watching for excessive total_time.

  DISALLOW_EVIL_CONSTRUCTORS(JankObserver);
};

// These objects are created by InstallJankometer and leaked.
JankObserver* ui_observer = NULL;
JankObserver* io_observer = NULL;

}  // namespace

void InstallJankometer(const CommandLine &parsed_command_line) {
  if (ui_observer || io_observer) {
    NOTREACHED() << "Initializing jank-o-meter twice";
    return;
  }

  bool ui_watchdog_enabled = false;
  bool io_watchdog_enabled = false;
  if (parsed_command_line.HasSwitch(switches::kEnableWatchdog)) {
    std::wstring list =
        parsed_command_line.GetSwitchValue(switches::kEnableWatchdog);
    if (list.npos != list.find(L"ui"))
      ui_watchdog_enabled = true;
    if (list.npos != list.find(L"io"))
      io_watchdog_enabled = true;
  }

  // Install on the UI thread.
  ui_observer = new JankObserver(
      "UI",
      TimeDelta::FromMilliseconds(kMaxUIMessageDelayMs),
      ui_watchdog_enabled);
  ui_observer->AddRef();
  ui_observer->AttachToCurrentThread();

  // Now install on the I/O thread. Hiccups on that thread will block
  // interaction with web pages. We must proxy to that thread before we can
  // add our observer.
  io_observer = new JankObserver(
      "IO",
      TimeDelta::FromMilliseconds(kMaxIOMessageDelayMs),
      io_watchdog_enabled);
  io_observer->AddRef();
  base::Thread* io_thread = g_browser_process->io_thread();
  if (io_thread) {
    io_thread->message_loop()->PostTask(FROM_HERE,
        NewRunnableMethod(io_observer,
            &JankObserver::AttachToCurrentThread));
  }
}

void UninstallJankometer() {
  if (ui_observer) {
    ui_observer->DetachFromCurrentThread();
    ui_observer->Release();
    ui_observer = NULL;
  }
  if (io_observer) {
    // IO thread can't be running when we remove observers.
    DCHECK((!g_browser_process) || !(g_browser_process->io_thread()));
    io_observer->Release();
    io_observer = NULL;
  }
}