chrome/browser/net/load_time_stats.cc

// Copyright (c) 2012 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 "chrome/browser/net/load_time_stats.h"

#include "base/debug/trace_event.h"
#include "base/metrics/histogram.h"
#include "base/stl_util.h"
#include "base/strings/string_number_conversions.h"
#include "base/timer/timer.h"
#include "chrome/browser/browser_process.h"
#include "chrome/browser/io_thread.h"
#include "chrome/browser/profiles/profile.h"
#include "content/public/browser/browser_thread.h"
#include "content/public/browser/render_process_host.h"
#include "content/public/browser/render_view_host.h"
#include "content/public/browser/resource_request_info.h"
#include "content/public/browser/web_contents.h"
#include "net/url_request/url_request.h"

using content::BrowserThread;
using content::RenderViewHost;
using content::ResourceRequestInfo;
using std::string;

DEFINE_WEB_CONTENTS_USER_DATA_KEY(chrome_browser_net::LoadTimeStatsTabHelper);

namespace {

bool GetRenderView(const net::URLRequest& request,
                   int* process_id, int* route_id) {
  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
  const ResourceRequestInfo* info = ResourceRequestInfo::ForRequest(&request);
  if (!info)
    return false;
  return info->GetAssociatedRenderView(process_id, route_id);
}

void CallLoadTimeStatsTabEventOnIOThread(
    std::pair<int, int> render_view_id,
    chrome_browser_net::LoadTimeStats::TabEvent event,
    IOThread* io_thread) {
  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
  if (io_thread)
    io_thread->globals()->load_time_stats->OnTabEvent(render_view_id, event);
}

// Times after a load has started at which stats are collected.
const int kStatsCollectionTimesMs[] = {
  1000,
  2000,
  4000,
  20000
};

static int kTabLoadStatsAutoCleanupTimeoutSeconds = 30;

const char* kRequestStatusNames[] = {
  "CacheWait",
  "NetworkWait",
  "Active",
  "None",
  "Max"
};

COMPILE_ASSERT(arraysize(kRequestStatusNames) ==
               chrome_browser_net::LoadTimeStats::REQUEST_STATUS_MAX + 1,
               LoadTimeStats_RequestStatus_names_mismatch);

const char* kHistogramTypeNames[] = {
  "FinalAggregate",
  "FinalCumulativePercentage",
  "IntermediateAggregate",
  "IntermediateCumulativePercentage",
  "Max"
};

COMPILE_ASSERT(arraysize(kHistogramTypeNames) ==
               chrome_browser_net::LoadTimeStats::HISTOGRAM_MAX + 1,
               LoadTimeStats_HistogramType_names_mismatch);

}  // namespace

namespace chrome_browser_net {

// Helper struct keeping stats about the page load progress & cache usage
// stats during the pageload so far for a given RenderView, identified
// by a pair of process id and route id.
class LoadTimeStats::TabLoadStats {
 public:
  // Stores the time taken by all requests while they have a certain
  // RequestStatus.
  class PerStatusStats {
   public:
    PerStatusStats() : num_active_(0) {
    }

    void UpdateTotalTimes() {
      DCHECK_GE(num_active_, 0);
      base::TimeTicks now = base::TimeTicks::Now();
      if (num_active_ > 0) {
        total_time_ += now - last_update_time_;
        total_cumulative_time_ +=
            (now - last_update_time_) * static_cast<int64>(num_active_);
      }
      last_update_time_ = now;
    }

    void ResetTimes() {
      last_update_time_ = base::TimeTicks::Now();
      total_time_ = base::TimeDelta();
      total_cumulative_time_ = base::TimeDelta();
    }

    void IncrementNumActive() {
      num_active_++;
    }

    void DecrementNumActiveIfPositive() {
      if (num_active_ > 0)
        num_active_--;
    }

    int num_active() { return num_active_; }
    void set_num_active(int num_active) { num_active_ = num_active; }
    base::TimeDelta total_time() { return total_time_; }
    base::TimeDelta total_cumulative_time() { return total_cumulative_time_; }

   private:
    int num_active_;
    base::TimeTicks last_update_time_;
    base::TimeDelta total_time_;
    base::TimeDelta total_cumulative_time_;
  };

  TabLoadStats(std::pair<int, int> render_view_id, LoadTimeStats* owner)
      : render_view_id_(render_view_id),
        spinner_started_(false),
        next_timer_index_(0),
        timer_(false, false) {
    // Initialize the timer to do an automatic cleanup.  If a pageload is
    // started for the TabLoadStats within that timeframe, LoadTimeStats
    // will start using the timer, thereby cancelling the cleanup.
    // Once LoadTimeStats starts the timer, the object is guaranteed to be
    // destroyed eventually, so there is no more need for automatic cleanup at
    // that point.
    timer_.Start(FROM_HERE,
                 base::TimeDelta::FromSeconds(
                     kTabLoadStatsAutoCleanupTimeoutSeconds),
                 base::Bind(&LoadTimeStats::RemoveTabLoadStats,
                            base::Unretained(owner),
                            render_view_id_));
  }

  typedef std::pair<int, int> RenderViewId;
  typedef PerStatusStats PerStatusStatsArray[REQUEST_STATUS_MAX];
  typedef base::hash_map<const net::URLRequest*, RequestStatus> RequestMap;

  RenderViewId& render_view_id() { return render_view_id_; }
  PerStatusStatsArray& per_status_stats() { return per_status_stats_; }
  bool spinner_started() { return spinner_started_; }
  void set_spinner_started(bool value) { spinner_started_ = value; }
  base::TimeTicks load_start_time() { return load_start_time_; }
  void set_load_start_time(base::TimeTicks time) { load_start_time_ = time; }
  int next_timer_index() { return next_timer_index_; }
  void set_next_timer_index(int index) { next_timer_index_ = index; }
  base::Timer& timer() { return timer_; }
  RequestMap& active_requests() { return active_requests_; }

 private:
  RenderViewId render_view_id_;
  PerStatusStatsArray per_status_stats_;
  bool spinner_started_;
  base::TimeTicks load_start_time_;
  int next_timer_index_;
  base::Timer timer_;
  // Currently active URLRequests.
  RequestMap active_requests_;
};

class LoadTimeStats::URLRequestStats {
 public:
  URLRequestStats()
      : done_(false),
        start_time_(GetCurrentTime()),
        status_(REQUEST_STATUS_ACTIVE) {
  }
  void OnStatusChange(RequestStatus new_status) {
    if (done_)
      return;
    DCHECK_GE(status_, 0);
    DCHECK_GE(new_status, 0);
    DCHECK_LE(status_, REQUEST_STATUS_ACTIVE);
    DCHECK_LE(new_status, REQUEST_STATUS_ACTIVE);
    base::TimeTicks now = GetCurrentTime();
    base::TimeDelta elapsed = now - start_time_;
    status_times_[status_] += elapsed;
    start_time_ = now;
    status_ = new_status;
  }
  void RequestDone() {
    DCHECK(!done_);
    // Dummy status change to add last elapsed time.
    OnStatusChange(REQUEST_STATUS_ACTIVE);
    done_ = true;

    UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_CacheWait_Time",
                        status_times_[REQUEST_STATUS_CACHE_WAIT]);
    UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_NetworkWait_Time",
                        status_times_[REQUEST_STATUS_NETWORK_WAIT]);
    UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_Active_Time",
                        status_times_[REQUEST_STATUS_ACTIVE]);

    base::TimeDelta total_time;
    for (int status = REQUEST_STATUS_CACHE_WAIT;
         status <= REQUEST_STATUS_ACTIVE;
         status++) {
      total_time += status_times_[status];
    }
    if (total_time.InMilliseconds() <= 0)
      return;

    for (int status = REQUEST_STATUS_CACHE_WAIT;
         status <= REQUEST_STATUS_ACTIVE;
         status++) {
      int64 fraction_percentage = 100 *
          status_times_[status].InMilliseconds() /
          total_time.InMilliseconds();
      DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100);
      switch (status) {
        case REQUEST_STATUS_CACHE_WAIT:
          UMA_HISTOGRAM_PERCENTAGE(
              "LoadTimeStats.Request_CacheWait_Percentage",
              fraction_percentage);
          break;
        case REQUEST_STATUS_NETWORK_WAIT:
          UMA_HISTOGRAM_PERCENTAGE(
              "LoadTimeStats.Request_NetworkWait_Percentage",
              fraction_percentage);
          break;
        case REQUEST_STATUS_ACTIVE:
          UMA_HISTOGRAM_PERCENTAGE(
              "LoadTimeStats.Request_Active_Percentage", fraction_percentage);
          break;
      }
    }
  }

 private:
  base::TimeTicks GetCurrentTime() {
    return base::TimeTicks::Now();
  }
  bool done_;
  base::TimeTicks start_time_;
  RequestStatus status_;
  base::TimeDelta status_times_[REQUEST_STATUS_MAX];
};

LoadTimeStatsTabHelper::LoadTimeStatsTabHelper(
    content::WebContents* web_contents)
    : content::WebContentsObserver(web_contents) {
  is_otr_profile_ = web_contents->GetBrowserContext()->IsOffTheRecord();
}

LoadTimeStatsTabHelper::~LoadTimeStatsTabHelper() {
}

void LoadTimeStatsTabHelper::DidStartProvisionalLoadForFrame(
    int64 frame_id,
    int64 parent_frame_id,
    bool is_main_frame,
    const GURL& validated_url,
    bool is_error_page,
    bool is_iframe_srcdoc,
    content::RenderViewHost* render_view_host) {
  if (!is_main_frame)
    return;
  if (!validated_url.SchemeIs("http"))
    return;
  NotifyLoadTimeStats(LoadTimeStats::SPINNER_START, render_view_host);
}

void LoadTimeStatsTabHelper::DidStopLoading(RenderViewHost* render_view_host) {
  NotifyLoadTimeStats(LoadTimeStats::SPINNER_STOP, render_view_host);
}

void LoadTimeStatsTabHelper::NotifyLoadTimeStats(
    LoadTimeStats::TabEvent event,
    RenderViewHost* render_view_host) {
  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
  if (is_otr_profile_)
    return;
  int process_id = render_view_host->GetProcess()->GetID();
  int route_id = render_view_host->GetRoutingID();
  BrowserThread::PostTask(
      BrowserThread::IO, FROM_HERE,
      base::Bind(&CallLoadTimeStatsTabEventOnIOThread,
                 std::pair<int, int>(process_id, route_id),
                 event,
                 base::Unretained(g_browser_process->io_thread())));
}

LoadTimeStats::LoadTimeStats() {
  TRACE_EVENT0("browser", "LoadTimeStats::ctor");
  for (int status = REQUEST_STATUS_CACHE_WAIT;
       status <= REQUEST_STATUS_ACTIVE;
       status++) {
    for (int histogram_type = HISTOGRAM_FINAL_AGGREGATE;
         histogram_type < HISTOGRAM_MAX;
         histogram_type++) {
      for (int i = 0;
           i < static_cast<int>(arraysize(kStatsCollectionTimesMs));
           i++) {
        string histogram_name = string("LoadTimeStats.Fraction_") +
            string(kRequestStatusNames[status]) + string("_") +
            string(kHistogramTypeNames[histogram_type]) + string("_") +
            base::IntToString(kStatsCollectionTimesMs[i]);
        histograms_[status][histogram_type].push_back(
            base::LinearHistogram::FactoryGet(
                histogram_name,
                0, 101, 51, base::HistogramBase::kUmaTargetedHistogramFlag));
      }
      DCHECK_EQ(histograms_[status][histogram_type].size(),
                arraysize(kStatsCollectionTimesMs));
    }
  }
}

LoadTimeStats::~LoadTimeStats() {
  STLDeleteValues(&tab_load_stats_);
  STLDeleteValues(&request_stats_);
}

LoadTimeStats::URLRequestStats* LoadTimeStats::GetRequestStats(
    const net::URLRequest* request) {
  RequestStatsMap::const_iterator it = request_stats_.find(request);
  if (it != request_stats_.end())
    return it->second;
  URLRequestStats* new_request_stats = new URLRequestStats();
  request_stats_[request] = new_request_stats;
  return new_request_stats;
}

LoadTimeStats::TabLoadStats* LoadTimeStats::GetTabLoadStats(
    std::pair<int, int> render_view_id) {
  TabLoadStatsMap::const_iterator it = tab_load_stats_.find(render_view_id);
  if (it != tab_load_stats_.end())
    return it->second;
  TabLoadStats* new_tab_load_stats = new TabLoadStats(render_view_id, this);
  tab_load_stats_[render_view_id] = new_tab_load_stats;
  return new_tab_load_stats;
}

void LoadTimeStats::RemoveTabLoadStats(std::pair<int, int> render_view_id) {
  TabLoadStatsMap::iterator it = tab_load_stats_.find(render_view_id);
  if (it != tab_load_stats_.end()) {
    delete it->second;
    tab_load_stats_.erase(it);
  }
}

void LoadTimeStats::OnRequestWaitStateChange(
    const net::URLRequest& request,
    net::NetworkDelegate::RequestWaitState state) {
  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
  if (main_request_contexts_.count(request.context()) < 1)
    return;
  int process_id, route_id;
  if (!GetRenderView(request, &process_id, &route_id))
    return;
  TabLoadStats* stats =
      GetTabLoadStats(std::pair<int, int>(process_id, route_id));
  RequestStatus old_status = REQUEST_STATUS_NONE;
  if (stats->active_requests().count(&request) > 0)
    old_status = stats->active_requests()[&request];
  RequestStatus new_status = REQUEST_STATUS_NONE;
  switch (state) {
    case net::NetworkDelegate::REQUEST_WAIT_STATE_CACHE_START:
      DCHECK(old_status == REQUEST_STATUS_NONE ||
             old_status == REQUEST_STATUS_ACTIVE);
      new_status = REQUEST_STATUS_CACHE_WAIT;
      break;
    case net::NetworkDelegate::REQUEST_WAIT_STATE_CACHE_FINISH:
      DCHECK(old_status == REQUEST_STATUS_NONE ||
             old_status == REQUEST_STATUS_CACHE_WAIT);
      new_status = REQUEST_STATUS_ACTIVE;
      break;
    case net::NetworkDelegate::REQUEST_WAIT_STATE_NETWORK_START:
      DCHECK(old_status == REQUEST_STATUS_NONE ||
             old_status == REQUEST_STATUS_ACTIVE);
      new_status = REQUEST_STATUS_NETWORK_WAIT;
      break;
    case net::NetworkDelegate::REQUEST_WAIT_STATE_NETWORK_FINISH:
      DCHECK(old_status == REQUEST_STATUS_NONE ||
             old_status == REQUEST_STATUS_NETWORK_WAIT);
      new_status = REQUEST_STATUS_ACTIVE;
      break;
    case net::NetworkDelegate::REQUEST_WAIT_STATE_RESET:
      new_status = REQUEST_STATUS_NONE;
      break;
  }
  if (old_status == new_status)
    return;
  if (old_status != REQUEST_STATUS_NONE) {
    TabLoadStats::PerStatusStats* status_stats =
        &(stats->per_status_stats()[old_status]);
    DCHECK_GE(status_stats->num_active(), 0);
    status_stats->UpdateTotalTimes();
    status_stats->DecrementNumActiveIfPositive();
    DCHECK_GE(status_stats->num_active(), 0);
  }
  if (new_status != REQUEST_STATUS_NONE) {
    TabLoadStats::PerStatusStats* status_stats =
        &(stats->per_status_stats()[new_status]);
    DCHECK_GE(status_stats->num_active(), 0);
    status_stats->UpdateTotalTimes();
    status_stats->IncrementNumActive();
    DCHECK_GE(status_stats->num_active(), 0);
    stats->active_requests()[&request] = new_status;
    URLRequestStats* request_stats = GetRequestStats(&request);
    request_stats->OnStatusChange(new_status);
  } else {
    stats->active_requests().erase(&request);
  }
}

void LoadTimeStats::OnURLRequestDestroyed(const net::URLRequest& request) {
  if (request_stats_.count(&request) < 1)
    return;
  scoped_ptr<URLRequestStats> request_stats(GetRequestStats(&request));
  request_stats_.erase(&request);
  request_stats->RequestDone();
}

void LoadTimeStats::OnTabEvent(std::pair<int, int> render_view_id,
                            TabEvent event) {
  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
  TabLoadStats* stats = GetTabLoadStats(render_view_id);
  if (event == SPINNER_START) {
    stats->set_spinner_started(true);
    stats->set_load_start_time(base::TimeTicks::Now());
    for (int status = REQUEST_STATUS_CACHE_WAIT;
         status <= REQUEST_STATUS_ACTIVE; status++) {
      stats->per_status_stats()[status].ResetTimes();
    }
    stats->set_next_timer_index(0);
    ScheduleTimer(stats);
  } else {
    DCHECK_EQ(event, SPINNER_STOP);
    if (stats->spinner_started()) {
      stats->set_spinner_started(false);
      base::TimeDelta load_time =
          base::TimeTicks::Now() - stats->load_start_time();
      RecordHistograms(load_time, stats, true);
    }
    RemoveTabLoadStats(render_view_id);
  }
}

void LoadTimeStats::ScheduleTimer(TabLoadStats* stats) {
  int timer_index = stats->next_timer_index();
  DCHECK(timer_index >= 0 &&
         timer_index < static_cast<int>(arraysize(kStatsCollectionTimesMs)));
  base::TimeDelta delta =
      base::TimeDelta::FromMilliseconds(kStatsCollectionTimesMs[timer_index]);
  delta -= base::TimeTicks::Now() - stats->load_start_time();

  // If the ScheduleTimer call was delayed significantly, like when one's using
  // a debugger, don't try to start the timer with a negative time.
  if (delta < base::TimeDelta()) {
    RemoveTabLoadStats(stats->render_view_id());
    return;
  }

  stats->timer().Start(FROM_HERE,
                       delta,
                       base::Bind(&LoadTimeStats::TimerCallback,
                                  base::Unretained(this),
                                  base::Unretained(stats)));
}

void LoadTimeStats::TimerCallback(TabLoadStats* stats) {
  DCHECK(stats->spinner_started());
  base::TimeDelta load_time = base::TimeTicks::Now() - stats->load_start_time();
  RecordHistograms(load_time, stats, false);
  stats->set_next_timer_index(stats->next_timer_index() + 1);
  if (stats->next_timer_index() <
      static_cast<int>(arraysize(kStatsCollectionTimesMs))) {
    ScheduleTimer(stats);
  } else {
    RemoveTabLoadStats(stats->render_view_id());
  }
}

void LoadTimeStats::RecordHistograms(base::TimeDelta elapsed,
                                  TabLoadStats* stats,
                                  bool is_load_done) {
  int timer_index = stats->next_timer_index();
  DCHECK(timer_index >= 0 &&
         timer_index < static_cast<int>(arraysize(kStatsCollectionTimesMs)));

  if (elapsed.InMilliseconds() <= 0)
    return;

  base::TimeDelta total_cumulative;
  for (int status = REQUEST_STATUS_CACHE_WAIT;
       status <= REQUEST_STATUS_ACTIVE;
       status++) {
    total_cumulative +=
        stats->per_status_stats()[status].total_cumulative_time();
  }

  for (int status = REQUEST_STATUS_CACHE_WAIT;
       status <= REQUEST_STATUS_ACTIVE;
       status++) {
    TabLoadStats::PerStatusStats* status_stats =
        &(stats->per_status_stats()[status]);

    int64 fraction_percentage = 100 *
        status_stats->total_time().InMilliseconds() / elapsed.InMilliseconds();
    DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100);
    if (is_load_done) {
      histograms_[status][HISTOGRAM_FINAL_AGGREGATE][timer_index]->Add(
          fraction_percentage);
    } else {
      histograms_[status][HISTOGRAM_INTERMEDIATE_AGGREGATE][timer_index]->Add(
          fraction_percentage);
    }

    if (total_cumulative.InMilliseconds() > 0) {
      fraction_percentage = 100 *
          status_stats->total_cumulative_time().InMilliseconds() /
          total_cumulative.InMilliseconds();
      DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100);
      if (is_load_done) {
        histograms_[status][HISTOGRAM_FINAL_CUMULATIVE_PERCENTAGE]
            [timer_index]->Add(fraction_percentage);
      } else {
        histograms_[status][HISTOGRAM_INTERMEDIATE_CUMULATIVE_PERCENTAGE]
            [timer_index]->Add(fraction_percentage);
      }
    }
  }
}

void LoadTimeStats::RegisterURLRequestContext(
    const net::URLRequestContext* context,
    ChromeURLRequestContext::ContextType type) {
  if (type == ChromeURLRequestContext::CONTEXT_TYPE_MAIN)
    main_request_contexts_.insert(context);
}

void LoadTimeStats::UnregisterURLRequestContext(
    const net::URLRequestContext* context) {
  main_request_contexts_.erase(context);
}

}  // namespace chrome_browser_net