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