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/net/load_time_stats.h"
6
7#include "base/debug/trace_event.h"
8#include "base/metrics/histogram.h"
9#include "base/stl_util.h"
10#include "base/strings/string_number_conversions.h"
11#include "base/timer/timer.h"
12#include "chrome/browser/browser_process.h"
13#include "chrome/browser/io_thread.h"
14#include "chrome/browser/profiles/profile.h"
15#include "content/public/browser/browser_thread.h"
16#include "content/public/browser/render_process_host.h"
17#include "content/public/browser/render_view_host.h"
18#include "content/public/browser/resource_request_info.h"
19#include "content/public/browser/web_contents.h"
20#include "net/url_request/url_request.h"
21
22using content::BrowserThread;
23using content::RenderViewHost;
24using content::ResourceRequestInfo;
25using std::string;
26
27DEFINE_WEB_CONTENTS_USER_DATA_KEY(chrome_browser_net::LoadTimeStatsTabHelper);
28
29namespace {
30
31bool GetRenderView(const net::URLRequest& request,
32                   int* process_id, int* route_id) {
33  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
34  const ResourceRequestInfo* info = ResourceRequestInfo::ForRequest(&request);
35  if (!info)
36    return false;
37  return info->GetAssociatedRenderView(process_id, route_id);
38}
39
40void CallLoadTimeStatsTabEventOnIOThread(
41    std::pair<int, int> render_view_id,
42    chrome_browser_net::LoadTimeStats::TabEvent event,
43    IOThread* io_thread) {
44  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
45  if (io_thread)
46    io_thread->globals()->load_time_stats->OnTabEvent(render_view_id, event);
47}
48
49// Times after a load has started at which stats are collected.
50const int kStatsCollectionTimesMs[] = {
51  1000,
52  2000,
53  4000,
54  20000
55};
56
57static int kTabLoadStatsAutoCleanupTimeoutSeconds = 30;
58
59const char* kRequestStatusNames[] = {
60  "CacheWait",
61  "NetworkWait",
62  "Active",
63  "None",
64  "Max"
65};
66
67COMPILE_ASSERT(arraysize(kRequestStatusNames) ==
68               chrome_browser_net::LoadTimeStats::REQUEST_STATUS_MAX + 1,
69               LoadTimeStats_RequestStatus_names_mismatch);
70
71const char* kHistogramTypeNames[] = {
72  "FinalAggregate",
73  "FinalCumulativePercentage",
74  "IntermediateAggregate",
75  "IntermediateCumulativePercentage",
76  "Max"
77};
78
79COMPILE_ASSERT(arraysize(kHistogramTypeNames) ==
80               chrome_browser_net::LoadTimeStats::HISTOGRAM_MAX + 1,
81               LoadTimeStats_HistogramType_names_mismatch);
82
83}  // namespace
84
85namespace chrome_browser_net {
86
87// Helper struct keeping stats about the page load progress & cache usage
88// stats during the pageload so far for a given RenderView, identified
89// by a pair of process id and route id.
90class LoadTimeStats::TabLoadStats {
91 public:
92  // Stores the time taken by all requests while they have a certain
93  // RequestStatus.
94  class PerStatusStats {
95   public:
96    PerStatusStats() : num_active_(0) {
97    }
98
99    void UpdateTotalTimes() {
100      DCHECK_GE(num_active_, 0);
101      base::TimeTicks now = base::TimeTicks::Now();
102      if (num_active_ > 0) {
103        total_time_ += now - last_update_time_;
104        total_cumulative_time_ +=
105            (now - last_update_time_) * static_cast<int64>(num_active_);
106      }
107      last_update_time_ = now;
108    }
109
110    void ResetTimes() {
111      last_update_time_ = base::TimeTicks::Now();
112      total_time_ = base::TimeDelta();
113      total_cumulative_time_ = base::TimeDelta();
114    }
115
116    void IncrementNumActive() {
117      num_active_++;
118    }
119
120    void DecrementNumActiveIfPositive() {
121      if (num_active_ > 0)
122        num_active_--;
123    }
124
125    int num_active() { return num_active_; }
126    void set_num_active(int num_active) { num_active_ = num_active; }
127    base::TimeDelta total_time() { return total_time_; }
128    base::TimeDelta total_cumulative_time() { return total_cumulative_time_; }
129
130   private:
131    int num_active_;
132    base::TimeTicks last_update_time_;
133    base::TimeDelta total_time_;
134    base::TimeDelta total_cumulative_time_;
135  };
136
137  TabLoadStats(std::pair<int, int> render_view_id, LoadTimeStats* owner)
138      : render_view_id_(render_view_id),
139        spinner_started_(false),
140        next_timer_index_(0),
141        timer_(false, false) {
142    // Initialize the timer to do an automatic cleanup.  If a pageload is
143    // started for the TabLoadStats within that timeframe, LoadTimeStats
144    // will start using the timer, thereby cancelling the cleanup.
145    // Once LoadTimeStats starts the timer, the object is guaranteed to be
146    // destroyed eventually, so there is no more need for automatic cleanup at
147    // that point.
148    timer_.Start(FROM_HERE,
149                 base::TimeDelta::FromSeconds(
150                     kTabLoadStatsAutoCleanupTimeoutSeconds),
151                 base::Bind(&LoadTimeStats::RemoveTabLoadStats,
152                            base::Unretained(owner),
153                            render_view_id_));
154  }
155
156  typedef std::pair<int, int> RenderViewId;
157  typedef PerStatusStats PerStatusStatsArray[REQUEST_STATUS_MAX];
158  typedef base::hash_map<const net::URLRequest*, RequestStatus> RequestMap;
159
160  RenderViewId& render_view_id() { return render_view_id_; }
161  PerStatusStatsArray& per_status_stats() { return per_status_stats_; }
162  bool spinner_started() { return spinner_started_; }
163  void set_spinner_started(bool value) { spinner_started_ = value; }
164  base::TimeTicks load_start_time() { return load_start_time_; }
165  void set_load_start_time(base::TimeTicks time) { load_start_time_ = time; }
166  int next_timer_index() { return next_timer_index_; }
167  void set_next_timer_index(int index) { next_timer_index_ = index; }
168  base::Timer& timer() { return timer_; }
169  RequestMap& active_requests() { return active_requests_; }
170
171 private:
172  RenderViewId render_view_id_;
173  PerStatusStatsArray per_status_stats_;
174  bool spinner_started_;
175  base::TimeTicks load_start_time_;
176  int next_timer_index_;
177  base::Timer timer_;
178  // Currently active URLRequests.
179  RequestMap active_requests_;
180};
181
182class LoadTimeStats::URLRequestStats {
183 public:
184  URLRequestStats()
185      : done_(false),
186        start_time_(GetCurrentTime()),
187        status_(REQUEST_STATUS_ACTIVE) {
188  }
189  void OnStatusChange(RequestStatus new_status) {
190    if (done_)
191      return;
192    DCHECK_GE(status_, 0);
193    DCHECK_GE(new_status, 0);
194    DCHECK_LE(status_, REQUEST_STATUS_ACTIVE);
195    DCHECK_LE(new_status, REQUEST_STATUS_ACTIVE);
196    base::TimeTicks now = GetCurrentTime();
197    base::TimeDelta elapsed = now - start_time_;
198    status_times_[status_] += elapsed;
199    start_time_ = now;
200    status_ = new_status;
201  }
202  void RequestDone() {
203    DCHECK(!done_);
204    // Dummy status change to add last elapsed time.
205    OnStatusChange(REQUEST_STATUS_ACTIVE);
206    done_ = true;
207
208    UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_CacheWait_Time",
209                        status_times_[REQUEST_STATUS_CACHE_WAIT]);
210    UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_NetworkWait_Time",
211                        status_times_[REQUEST_STATUS_NETWORK_WAIT]);
212    UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_Active_Time",
213                        status_times_[REQUEST_STATUS_ACTIVE]);
214
215    base::TimeDelta total_time;
216    for (int status = REQUEST_STATUS_CACHE_WAIT;
217         status <= REQUEST_STATUS_ACTIVE;
218         status++) {
219      total_time += status_times_[status];
220    }
221    if (total_time.InMilliseconds() <= 0)
222      return;
223
224    for (int status = REQUEST_STATUS_CACHE_WAIT;
225         status <= REQUEST_STATUS_ACTIVE;
226         status++) {
227      int64 fraction_percentage = 100 *
228          status_times_[status].InMilliseconds() /
229          total_time.InMilliseconds();
230      DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100);
231      switch (status) {
232        case REQUEST_STATUS_CACHE_WAIT:
233          UMA_HISTOGRAM_PERCENTAGE(
234              "LoadTimeStats.Request_CacheWait_Percentage",
235              fraction_percentage);
236          break;
237        case REQUEST_STATUS_NETWORK_WAIT:
238          UMA_HISTOGRAM_PERCENTAGE(
239              "LoadTimeStats.Request_NetworkWait_Percentage",
240              fraction_percentage);
241          break;
242        case REQUEST_STATUS_ACTIVE:
243          UMA_HISTOGRAM_PERCENTAGE(
244              "LoadTimeStats.Request_Active_Percentage", fraction_percentage);
245          break;
246      }
247    }
248  }
249
250 private:
251  base::TimeTicks GetCurrentTime() {
252    return base::TimeTicks::Now();
253  }
254  bool done_;
255  base::TimeTicks start_time_;
256  RequestStatus status_;
257  base::TimeDelta status_times_[REQUEST_STATUS_MAX];
258};
259
260LoadTimeStatsTabHelper::LoadTimeStatsTabHelper(
261    content::WebContents* web_contents)
262    : content::WebContentsObserver(web_contents) {
263  is_otr_profile_ = web_contents->GetBrowserContext()->IsOffTheRecord();
264}
265
266LoadTimeStatsTabHelper::~LoadTimeStatsTabHelper() {
267}
268
269void LoadTimeStatsTabHelper::DidStartProvisionalLoadForFrame(
270    int64 frame_id,
271    int64 parent_frame_id,
272    bool is_main_frame,
273    const GURL& validated_url,
274    bool is_error_page,
275    bool is_iframe_srcdoc,
276    content::RenderViewHost* render_view_host) {
277  if (!is_main_frame)
278    return;
279  if (!validated_url.SchemeIs("http"))
280    return;
281  NotifyLoadTimeStats(LoadTimeStats::SPINNER_START, render_view_host);
282}
283
284void LoadTimeStatsTabHelper::DidStopLoading(RenderViewHost* render_view_host) {
285  NotifyLoadTimeStats(LoadTimeStats::SPINNER_STOP, render_view_host);
286}
287
288void LoadTimeStatsTabHelper::NotifyLoadTimeStats(
289    LoadTimeStats::TabEvent event,
290    RenderViewHost* render_view_host) {
291  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
292  if (is_otr_profile_)
293    return;
294  int process_id = render_view_host->GetProcess()->GetID();
295  int route_id = render_view_host->GetRoutingID();
296  BrowserThread::PostTask(
297      BrowserThread::IO, FROM_HERE,
298      base::Bind(&CallLoadTimeStatsTabEventOnIOThread,
299                 std::pair<int, int>(process_id, route_id),
300                 event,
301                 base::Unretained(g_browser_process->io_thread())));
302}
303
304LoadTimeStats::LoadTimeStats() {
305  TRACE_EVENT0("browser", "LoadTimeStats::ctor");
306  for (int status = REQUEST_STATUS_CACHE_WAIT;
307       status <= REQUEST_STATUS_ACTIVE;
308       status++) {
309    for (int histogram_type = HISTOGRAM_FINAL_AGGREGATE;
310         histogram_type < HISTOGRAM_MAX;
311         histogram_type++) {
312      for (int i = 0;
313           i < static_cast<int>(arraysize(kStatsCollectionTimesMs));
314           i++) {
315        string histogram_name = string("LoadTimeStats.Fraction_") +
316            string(kRequestStatusNames[status]) + string("_") +
317            string(kHistogramTypeNames[histogram_type]) + string("_") +
318            base::IntToString(kStatsCollectionTimesMs[i]);
319        histograms_[status][histogram_type].push_back(
320            base::LinearHistogram::FactoryGet(
321                histogram_name,
322                0, 101, 51, base::HistogramBase::kUmaTargetedHistogramFlag));
323      }
324      DCHECK_EQ(histograms_[status][histogram_type].size(),
325                arraysize(kStatsCollectionTimesMs));
326    }
327  }
328}
329
330LoadTimeStats::~LoadTimeStats() {
331  STLDeleteValues(&tab_load_stats_);
332  STLDeleteValues(&request_stats_);
333}
334
335LoadTimeStats::URLRequestStats* LoadTimeStats::GetRequestStats(
336    const net::URLRequest* request) {
337  RequestStatsMap::const_iterator it = request_stats_.find(request);
338  if (it != request_stats_.end())
339    return it->second;
340  URLRequestStats* new_request_stats = new URLRequestStats();
341  request_stats_[request] = new_request_stats;
342  return new_request_stats;
343}
344
345LoadTimeStats::TabLoadStats* LoadTimeStats::GetTabLoadStats(
346    std::pair<int, int> render_view_id) {
347  TabLoadStatsMap::const_iterator it = tab_load_stats_.find(render_view_id);
348  if (it != tab_load_stats_.end())
349    return it->second;
350  TabLoadStats* new_tab_load_stats = new TabLoadStats(render_view_id, this);
351  tab_load_stats_[render_view_id] = new_tab_load_stats;
352  return new_tab_load_stats;
353}
354
355void LoadTimeStats::RemoveTabLoadStats(std::pair<int, int> render_view_id) {
356  TabLoadStatsMap::iterator it = tab_load_stats_.find(render_view_id);
357  if (it != tab_load_stats_.end()) {
358    delete it->second;
359    tab_load_stats_.erase(it);
360  }
361}
362
363void LoadTimeStats::OnRequestWaitStateChange(
364    const net::URLRequest& request,
365    net::NetworkDelegate::RequestWaitState state) {
366  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
367  if (main_request_contexts_.count(request.context()) < 1)
368    return;
369  int process_id, route_id;
370  if (!GetRenderView(request, &process_id, &route_id))
371    return;
372  TabLoadStats* stats =
373      GetTabLoadStats(std::pair<int, int>(process_id, route_id));
374  RequestStatus old_status = REQUEST_STATUS_NONE;
375  if (stats->active_requests().count(&request) > 0)
376    old_status = stats->active_requests()[&request];
377  RequestStatus new_status = REQUEST_STATUS_NONE;
378  switch (state) {
379    case net::NetworkDelegate::REQUEST_WAIT_STATE_CACHE_START:
380      DCHECK(old_status == REQUEST_STATUS_NONE ||
381             old_status == REQUEST_STATUS_ACTIVE);
382      new_status = REQUEST_STATUS_CACHE_WAIT;
383      break;
384    case net::NetworkDelegate::REQUEST_WAIT_STATE_CACHE_FINISH:
385      DCHECK(old_status == REQUEST_STATUS_NONE ||
386             old_status == REQUEST_STATUS_CACHE_WAIT);
387      new_status = REQUEST_STATUS_ACTIVE;
388      break;
389    case net::NetworkDelegate::REQUEST_WAIT_STATE_NETWORK_START:
390      DCHECK(old_status == REQUEST_STATUS_NONE ||
391             old_status == REQUEST_STATUS_ACTIVE);
392      new_status = REQUEST_STATUS_NETWORK_WAIT;
393      break;
394    case net::NetworkDelegate::REQUEST_WAIT_STATE_NETWORK_FINISH:
395      DCHECK(old_status == REQUEST_STATUS_NONE ||
396             old_status == REQUEST_STATUS_NETWORK_WAIT);
397      new_status = REQUEST_STATUS_ACTIVE;
398      break;
399    case net::NetworkDelegate::REQUEST_WAIT_STATE_RESET:
400      new_status = REQUEST_STATUS_NONE;
401      break;
402  }
403  if (old_status == new_status)
404    return;
405  if (old_status != REQUEST_STATUS_NONE) {
406    TabLoadStats::PerStatusStats* status_stats =
407        &(stats->per_status_stats()[old_status]);
408    DCHECK_GE(status_stats->num_active(), 0);
409    status_stats->UpdateTotalTimes();
410    status_stats->DecrementNumActiveIfPositive();
411    DCHECK_GE(status_stats->num_active(), 0);
412  }
413  if (new_status != REQUEST_STATUS_NONE) {
414    TabLoadStats::PerStatusStats* status_stats =
415        &(stats->per_status_stats()[new_status]);
416    DCHECK_GE(status_stats->num_active(), 0);
417    status_stats->UpdateTotalTimes();
418    status_stats->IncrementNumActive();
419    DCHECK_GE(status_stats->num_active(), 0);
420    stats->active_requests()[&request] = new_status;
421    URLRequestStats* request_stats = GetRequestStats(&request);
422    request_stats->OnStatusChange(new_status);
423  } else {
424    stats->active_requests().erase(&request);
425  }
426}
427
428void LoadTimeStats::OnURLRequestDestroyed(const net::URLRequest& request) {
429  if (request_stats_.count(&request) < 1)
430    return;
431  scoped_ptr<URLRequestStats> request_stats(GetRequestStats(&request));
432  request_stats_.erase(&request);
433  request_stats->RequestDone();
434}
435
436void LoadTimeStats::OnTabEvent(std::pair<int, int> render_view_id,
437                            TabEvent event) {
438  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
439  TabLoadStats* stats = GetTabLoadStats(render_view_id);
440  if (event == SPINNER_START) {
441    stats->set_spinner_started(true);
442    stats->set_load_start_time(base::TimeTicks::Now());
443    for (int status = REQUEST_STATUS_CACHE_WAIT;
444         status <= REQUEST_STATUS_ACTIVE; status++) {
445      stats->per_status_stats()[status].ResetTimes();
446    }
447    stats->set_next_timer_index(0);
448    ScheduleTimer(stats);
449  } else {
450    DCHECK_EQ(event, SPINNER_STOP);
451    if (stats->spinner_started()) {
452      stats->set_spinner_started(false);
453      base::TimeDelta load_time =
454          base::TimeTicks::Now() - stats->load_start_time();
455      RecordHistograms(load_time, stats, true);
456    }
457    RemoveTabLoadStats(render_view_id);
458  }
459}
460
461void LoadTimeStats::ScheduleTimer(TabLoadStats* stats) {
462  int timer_index = stats->next_timer_index();
463  DCHECK(timer_index >= 0 &&
464         timer_index < static_cast<int>(arraysize(kStatsCollectionTimesMs)));
465  base::TimeDelta delta =
466      base::TimeDelta::FromMilliseconds(kStatsCollectionTimesMs[timer_index]);
467  delta -= base::TimeTicks::Now() - stats->load_start_time();
468
469  // If the ScheduleTimer call was delayed significantly, like when one's using
470  // a debugger, don't try to start the timer with a negative time.
471  if (delta < base::TimeDelta()) {
472    RemoveTabLoadStats(stats->render_view_id());
473    return;
474  }
475
476  stats->timer().Start(FROM_HERE,
477                       delta,
478                       base::Bind(&LoadTimeStats::TimerCallback,
479                                  base::Unretained(this),
480                                  base::Unretained(stats)));
481}
482
483void LoadTimeStats::TimerCallback(TabLoadStats* stats) {
484  DCHECK(stats->spinner_started());
485  base::TimeDelta load_time = base::TimeTicks::Now() - stats->load_start_time();
486  RecordHistograms(load_time, stats, false);
487  stats->set_next_timer_index(stats->next_timer_index() + 1);
488  if (stats->next_timer_index() <
489      static_cast<int>(arraysize(kStatsCollectionTimesMs))) {
490    ScheduleTimer(stats);
491  } else {
492    RemoveTabLoadStats(stats->render_view_id());
493  }
494}
495
496void LoadTimeStats::RecordHistograms(base::TimeDelta elapsed,
497                                  TabLoadStats* stats,
498                                  bool is_load_done) {
499  int timer_index = stats->next_timer_index();
500  DCHECK(timer_index >= 0 &&
501         timer_index < static_cast<int>(arraysize(kStatsCollectionTimesMs)));
502
503  if (elapsed.InMilliseconds() <= 0)
504    return;
505
506  base::TimeDelta total_cumulative;
507  for (int status = REQUEST_STATUS_CACHE_WAIT;
508       status <= REQUEST_STATUS_ACTIVE;
509       status++) {
510    total_cumulative +=
511        stats->per_status_stats()[status].total_cumulative_time();
512  }
513
514  for (int status = REQUEST_STATUS_CACHE_WAIT;
515       status <= REQUEST_STATUS_ACTIVE;
516       status++) {
517    TabLoadStats::PerStatusStats* status_stats =
518        &(stats->per_status_stats()[status]);
519
520    int64 fraction_percentage = 100 *
521        status_stats->total_time().InMilliseconds() / elapsed.InMilliseconds();
522    DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100);
523    if (is_load_done) {
524      histograms_[status][HISTOGRAM_FINAL_AGGREGATE][timer_index]->Add(
525          fraction_percentage);
526    } else {
527      histograms_[status][HISTOGRAM_INTERMEDIATE_AGGREGATE][timer_index]->Add(
528          fraction_percentage);
529    }
530
531    if (total_cumulative.InMilliseconds() > 0) {
532      fraction_percentage = 100 *
533          status_stats->total_cumulative_time().InMilliseconds() /
534          total_cumulative.InMilliseconds();
535      DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100);
536      if (is_load_done) {
537        histograms_[status][HISTOGRAM_FINAL_CUMULATIVE_PERCENTAGE]
538            [timer_index]->Add(fraction_percentage);
539      } else {
540        histograms_[status][HISTOGRAM_INTERMEDIATE_CUMULATIVE_PERCENTAGE]
541            [timer_index]->Add(fraction_percentage);
542      }
543    }
544  }
545}
546
547void LoadTimeStats::RegisterURLRequestContext(
548    const net::URLRequestContext* context,
549    ChromeURLRequestContext::ContextType type) {
550  if (type == ChromeURLRequestContext::CONTEXT_TYPE_MAIN)
551    main_request_contexts_.insert(context);
552}
553
554void LoadTimeStats::UnregisterURLRequestContext(
555    const net::URLRequestContext* context) {
556  main_request_contexts_.erase(context);
557}
558
559}  // namespace chrome_browser_net
560