load_timing_observer.cc revision c407dc5cd9bdc5668497f21b26b09d988ab439de 
1// Copyright (c) 2010 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_timing_observer.h"
6
7#include "base/compiler_specific.h"
8#include "base/time.h"
9#include "net/base/load_flags.h"
10#include "net/url_request/url_request_netlog_params.h"
11
12using base::Time;
13using base::TimeTicks;
14using webkit_glue::ResourceLoaderBridge;
15
16const size_t kMaxNumEntries = 1000;
17
18namespace {
19
20// We know that this conversion is not solid and suffers from world clock
21// changes, but it should be good enough for the load timing info.
22static Time TimeTicksToTime(const TimeTicks& time_ticks) {
23  static int64 tick_to_time_offset;
24  static bool tick_to_time_offset_available = false;
25  if (!tick_to_time_offset_available) {
26    int64 cur_time = (Time::Now() - Time()).InMicroseconds();
27    int64 cur_time_ticks = (TimeTicks::Now() - TimeTicks()).InMicroseconds();
28    // If we add this number to a time tick value, it gives the timestamp.
29    tick_to_time_offset = cur_time - cur_time_ticks;
30    tick_to_time_offset_available = true;
31  }
32  return Time::FromInternalValue(time_ticks.ToInternalValue() +
33                                 tick_to_time_offset);
34}
35
36static int32 TimeTicksToOffset(
37    const TimeTicks& time_ticks,
38    LoadTimingObserver::URLRequestRecord* record) {
39  return static_cast<int32>(
40      (time_ticks - record->base_ticks).InMillisecondsRoundedUp());
41}
42
43}
44
45LoadTimingObserver::URLRequestRecord::URLRequestRecord()
46    : connect_job_id(net::NetLog::Source::kInvalidId),
47      socket_log_id(net::NetLog::Source::kInvalidId),
48      socket_reused(false) {
49}
50
51LoadTimingObserver::LoadTimingObserver() {
52}
53
54LoadTimingObserver::~LoadTimingObserver() {
55}
56
57LoadTimingObserver::URLRequestRecord*
58LoadTimingObserver::GetURLRequestRecord(uint32 source_id) {
59  URLRequestToRecordMap::iterator it = url_request_to_record_.find(source_id);
60  if (it != url_request_to_record_.end())
61    return &it->second;
62  return NULL;
63}
64
65void LoadTimingObserver::OnAddEntry(net::NetLog::EventType type,
66                                    const base::TimeTicks& time,
67                                    const net::NetLog::Source& source,
68                                    net::NetLog::EventPhase phase,
69                                    net::NetLog::EventParameters* params) {
70  if (source.type == net::NetLog::SOURCE_URL_REQUEST)
71    OnAddURLRequestEntry(type, time, source, phase, params);
72  else if (source.type == net::NetLog::SOURCE_CONNECT_JOB)
73    OnAddConnectJobEntry(type, time, source, phase, params);
74  else if (source.type == net::NetLog::SOURCE_SOCKET)
75    OnAddSocketEntry(type, time, source, phase, params);
76}
77
78void LoadTimingObserver::OnAddURLRequestEntry(
79    net::NetLog::EventType type,
80    const base::TimeTicks& time,
81    const net::NetLog::Source& source,
82    net::NetLog::EventPhase phase,
83    net::NetLog::EventParameters* params) {
84  bool is_begin = phase == net::NetLog::PHASE_BEGIN;
85  bool is_end = phase == net::NetLog::PHASE_END;
86
87  if (type == net::NetLog::TYPE_URL_REQUEST_START_JOB) {
88    if (is_begin) {
89      // Only record timing for entries with corresponding flag.
90      int load_flags = static_cast<URLRequestStartEventParameters*>(params)->
91          load_flags();
92      if (!(load_flags & net::LOAD_ENABLE_LOAD_TIMING))
93        return;
94
95      // Prevents us from passively growing the memory memory unbounded in case
96      // something went wrong. Should not happen.
97      if (url_request_to_record_.size() > kMaxNumEntries) {
98        LOG(WARNING) << "The load timing observer url request count has grown "
99                        "larger than expected, resetting";
100        url_request_to_record_.clear();
101      }
102
103      URLRequestRecord& record = url_request_to_record_[source.id];
104      record.base_ticks = time;
105      record.timing.base_time = TimeTicksToTime(time);
106    }
107    return;
108  } else if (type == net::NetLog::TYPE_REQUEST_ALIVE) {
109    // Cleanup records based on the TYPE_REQUEST_ALIVE entry.
110    if (is_end)
111      url_request_to_record_.erase(source.id);
112    return;
113  }
114
115  URLRequestRecord* record = GetURLRequestRecord(source.id);
116  if (!record)
117    return;
118
119  ResourceLoaderBridge::LoadTimingInfo& timing = record->timing;
120
121  switch(type) {
122    case net::NetLog::TYPE_PROXY_SERVICE:
123      if (is_begin)
124        timing.proxy_start = TimeTicksToOffset(time, record);
125      else if (is_end)
126        timing.proxy_end = TimeTicksToOffset(time, record);
127      break;
128    case net::NetLog::TYPE_SOCKET_POOL:
129      if (is_begin)
130        timing.connect_start = TimeTicksToOffset(time, record);
131      else if (is_end)
132        timing.connect_end = TimeTicksToOffset(time, record);
133      break;
134    case net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB:
135      {
136        uint32 connect_job_id = static_cast<net::NetLogSourceParameter*>(
137            params)->value().id;
138        ConnectJobToRecordMap::iterator it =
139            connect_job_to_record_.find(connect_job_id);
140        if (it != connect_job_to_record_.end() &&
141                !it->second.dns_start.is_null()) {
142          timing.dns_start = TimeTicksToOffset(it->second.dns_start, record);
143          timing.dns_end = TimeTicksToOffset(it->second.dns_end, record);
144        }
145      }
146      break;
147    case net::NetLog::TYPE_SOCKET_POOL_REUSED_AN_EXISTING_SOCKET:
148      record->socket_reused = true;
149      break;
150    case net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET:
151      record->socket_log_id = static_cast<net::NetLogSourceParameter*>(
152          params)->value().id;
153      if (!record->socket_reused) {
154        SocketToRecordMap::iterator it =
155            socket_to_record_.find(record->socket_log_id);
156        if (it != socket_to_record_.end() && !it->second.ssl_start.is_null()) {
157            timing.ssl_start = TimeTicksToOffset(it->second.ssl_start, record);
158            timing.ssl_end = TimeTicksToOffset(it->second.ssl_end, record);
159        }
160      }
161      break;
162    case net::NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST:
163    case net::NetLog::TYPE_SPDY_TRANSACTION_SEND_REQUEST:
164      if (is_begin)
165        timing.send_start = TimeTicksToOffset(time, record);
166      else if (is_end)
167        timing.send_end = TimeTicksToOffset(time, record);
168      break;
169    case net::NetLog::TYPE_HTTP_TRANSACTION_READ_HEADERS:
170    case net::NetLog::TYPE_SPDY_TRANSACTION_READ_HEADERS:
171      if (is_begin)
172        timing.receive_headers_start =  TimeTicksToOffset(time, record);
173      else if (is_end)
174        timing.receive_headers_end =  TimeTicksToOffset(time, record);
175      break;
176    default:
177      break;
178  }
179}
180
181void LoadTimingObserver::OnAddConnectJobEntry(
182    net::NetLog::EventType type,
183    const base::TimeTicks& time,
184    const net::NetLog::Source& source,
185    net::NetLog::EventPhase phase,
186    net::NetLog::EventParameters* params) {
187  bool is_begin = phase == net::NetLog::PHASE_BEGIN;
188  bool is_end = phase == net::NetLog::PHASE_END;
189
190  // Manage record lifetime based on the SOCKET_POOL_CONNECT_JOB entry.
191  if (type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB) {
192    if (is_begin) {
193      // Prevents us from passively growing the memory memory unbounded in case
194      // something went wrong. Should not happen.
195      if (connect_job_to_record_.size() > kMaxNumEntries) {
196        LOG(WARNING) << "The load timing observer connect job count has grown "
197                        "larger than expected, resetting";
198        connect_job_to_record_.clear();
199      }
200
201      connect_job_to_record_.insert(
202          std::make_pair(source.id, ConnectJobRecord()));
203    } else if (is_end) {
204      connect_job_to_record_.erase(source.id);
205    }
206  } else if (type == net::NetLog::TYPE_HOST_RESOLVER_IMPL) {
207    ConnectJobToRecordMap::iterator it =
208        connect_job_to_record_.find(source.id);
209    if (it != connect_job_to_record_.end()) {
210      if (is_begin)
211        it->second.dns_start = time;
212      else if (is_end)
213        it->second.dns_end = time;
214    }
215  }
216}
217
218void LoadTimingObserver::OnAddSocketEntry(
219    net::NetLog::EventType type,
220    const base::TimeTicks& time,
221    const net::NetLog::Source& source,
222    net::NetLog::EventPhase phase,
223    net::NetLog::EventParameters* params) {
224  bool is_begin = phase == net::NetLog::PHASE_BEGIN;
225  bool is_end = phase == net::NetLog::PHASE_END;
226
227  // Manage record lifetime based on the SOCKET_ALIVE entry.
228  if (type == net::NetLog::TYPE_SOCKET_ALIVE) {
229    if (is_begin) {
230      // Prevents us from passively growing the memory memory unbounded in case
231      // something went wrong. Should not happen.
232      if (socket_to_record_.size() > kMaxNumEntries) {
233        LOG(WARNING) << "The load timing observer socket count has grown "
234                        "larger than expected, resetting";
235        socket_to_record_.clear();
236      }
237
238      socket_to_record_.insert(
239          std::make_pair(source.id, SocketRecord()));
240    } else if (is_end) {
241      socket_to_record_.erase(source.id);
242    }
243    return;
244  }
245  SocketToRecordMap::iterator it = socket_to_record_.find(source.id);
246  if (it == socket_to_record_.end())
247    return;
248
249  if (type == net::NetLog::TYPE_SSL_CONNECT) {
250    if (is_begin)
251      it->second.ssl_start = time;
252    else if (is_end)
253      it->second.ssl_end = time;
254  }
255}
256