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/time.h"
8#include "chrome/browser/net/chrome_net_log.h"
9#include "content/browser/browser_thread.h"
10#include "content/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;
18using webkit_glue::ResourceLoadTimingInfo;
19
20const size_t kMaxNumEntries = 1000;
21
22namespace {
23
24const int64 kSyncPeriodMicroseconds = 1000 * 1000 * 10;
25
26// We know that this conversion is not solid and suffers from world clock
27// changes, but given that we sync clock every 10 seconds, it should be good
28// enough for the load timing info.
29static Time TimeTicksToTime(const TimeTicks& time_ticks) {
30  static int64 tick_to_time_offset;
31  static int64 last_sync_ticks = 0;
32  if (time_ticks.ToInternalValue() - last_sync_ticks >
33          kSyncPeriodMicroseconds) {
34    int64 cur_time = (Time::Now() - Time()).InMicroseconds();
35    int64 cur_time_ticks = (TimeTicks::Now() - TimeTicks()).InMicroseconds();
36    // If we add this number to a time tick value, it gives the timestamp.
37    tick_to_time_offset = cur_time - cur_time_ticks;
38    last_sync_ticks = time_ticks.ToInternalValue();
39  }
40  return Time::FromInternalValue(time_ticks.ToInternalValue() +
41                                 tick_to_time_offset);
42}
43
44static int32 TimeTicksToOffset(
45    const TimeTicks& time_ticks,
46    LoadTimingObserver::URLRequestRecord* record) {
47  return static_cast<int32>(
48      (time_ticks - record->base_ticks).InMillisecondsRoundedUp());
49}
50
51}  // namespace
52
53LoadTimingObserver::URLRequestRecord::URLRequestRecord()
54    : connect_job_id(net::NetLog::Source::kInvalidId),
55      socket_log_id(net::NetLog::Source::kInvalidId),
56      socket_reused(false) {
57}
58
59LoadTimingObserver::HTTPStreamJobRecord::HTTPStreamJobRecord()
60    : socket_log_id(net::NetLog::Source::kInvalidId),
61      socket_reused(false) {
62}
63
64LoadTimingObserver::LoadTimingObserver()
65    : ThreadSafeObserver(net::NetLog::LOG_BASIC),
66      last_connect_job_id_(net::NetLog::Source::kInvalidId) {
67}
68
69LoadTimingObserver::~LoadTimingObserver() {
70}
71
72LoadTimingObserver::URLRequestRecord*
73LoadTimingObserver::GetURLRequestRecord(uint32 source_id) {
74  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
75
76  URLRequestToRecordMap::iterator it = url_request_to_record_.find(source_id);
77  if (it != url_request_to_record_.end())
78    return &it->second;
79  return NULL;
80}
81
82void LoadTimingObserver::OnAddEntry(net::NetLog::EventType type,
83                                    const base::TimeTicks& time,
84                                    const net::NetLog::Source& source,
85                                    net::NetLog::EventPhase phase,
86                                    net::NetLog::EventParameters* params) {
87  // The events that the Observer is interested in only occur on the IO thread.
88  if (!BrowserThread::CurrentlyOn(BrowserThread::IO))
89    return;
90  if (source.type == net::NetLog::SOURCE_URL_REQUEST)
91    OnAddURLRequestEntry(type, time, source, phase, params);
92  else if (source.type == net::NetLog::SOURCE_HTTP_STREAM_JOB)
93    OnAddHTTPStreamJobEntry(type, time, source, phase, params);
94  else if (source.type == net::NetLog::SOURCE_CONNECT_JOB)
95    OnAddConnectJobEntry(type, time, source, phase, params);
96  else if (source.type == net::NetLog::SOURCE_SOCKET)
97    OnAddSocketEntry(type, time, source, phase, params);
98}
99
100// static
101void LoadTimingObserver::PopulateTimingInfo(net::URLRequest* request,
102                                            ResourceResponse* response) {
103  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
104  if (!(request->load_flags() & net::LOAD_ENABLE_LOAD_TIMING))
105    return;
106
107  ChromeNetLog* chrome_net_log = static_cast<ChromeNetLog*>(
108      request->net_log().net_log());
109  if (chrome_net_log == NULL)
110    return;
111
112  uint32 source_id = request->net_log().source().id;
113  LoadTimingObserver* observer = chrome_net_log->load_timing_observer();
114  LoadTimingObserver::URLRequestRecord* record =
115      observer->GetURLRequestRecord(source_id);
116  if (record) {
117    response->response_head.connection_id = record->socket_log_id;
118    response->response_head.connection_reused = record->socket_reused;
119    response->response_head.load_timing = record->timing;
120  }
121}
122
123void LoadTimingObserver::OnAddURLRequestEntry(
124    net::NetLog::EventType type,
125    const base::TimeTicks& time,
126    const net::NetLog::Source& source,
127    net::NetLog::EventPhase phase,
128    net::NetLog::EventParameters* params) {
129  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
130
131  bool is_begin = phase == net::NetLog::PHASE_BEGIN;
132  bool is_end = phase == net::NetLog::PHASE_END;
133
134  if (type == net::NetLog::TYPE_URL_REQUEST_START_JOB) {
135    if (is_begin) {
136      // Only record timing for entries with corresponding flag.
137      int load_flags =
138          static_cast<net::URLRequestStartEventParameters*>(params)->
139              load_flags();
140      if (!(load_flags & net::LOAD_ENABLE_LOAD_TIMING))
141        return;
142
143      // Prevents us from passively growing the memory unbounded in case
144      // something went wrong. Should not happen.
145      if (url_request_to_record_.size() > kMaxNumEntries) {
146        LOG(WARNING) << "The load timing observer url request count has grown "
147                        "larger than expected, resetting";
148        url_request_to_record_.clear();
149      }
150
151      URLRequestRecord& record = url_request_to_record_[source.id];
152      record.base_ticks = time;
153      record.timing.base_time = TimeTicksToTime(time);
154    }
155    return;
156  } else if (type == net::NetLog::TYPE_REQUEST_ALIVE) {
157    // Cleanup records based on the TYPE_REQUEST_ALIVE entry.
158    if (is_end)
159      url_request_to_record_.erase(source.id);
160    return;
161  }
162
163  URLRequestRecord* record = GetURLRequestRecord(source.id);
164  if (!record)
165    return;
166
167  ResourceLoadTimingInfo& timing = record->timing;
168
169  switch (type) {
170    case net::NetLog::TYPE_PROXY_SERVICE:
171      if (is_begin)
172        timing.proxy_start = TimeTicksToOffset(time, record);
173      else if (is_end)
174        timing.proxy_end = TimeTicksToOffset(time, record);
175      break;
176    case net::NetLog::TYPE_HTTP_STREAM_REQUEST_BOUND_TO_JOB: {
177      uint32 http_stream_job_id = static_cast<net::NetLogSourceParameter*>(
178          params)->value().id;
179      HTTPStreamJobToRecordMap::iterator it =
180          http_stream_job_to_record_.find(http_stream_job_id);
181      if (it == http_stream_job_to_record_.end())
182        return;
183      if (!it->second.connect_start.is_null()) {
184        timing.connect_start = TimeTicksToOffset(it->second.connect_start,
185                                                 record);
186      }
187      if (!it->second.connect_end.is_null())
188        timing.connect_end = TimeTicksToOffset(it->second.connect_end, record);
189      if (!it->second.dns_start.is_null())
190        timing.dns_start = TimeTicksToOffset(it->second.dns_start, record);
191      if (!it->second.dns_end.is_null())
192        timing.dns_end = TimeTicksToOffset(it->second.dns_end, record);
193      if (!it->second.ssl_start.is_null())
194        timing.ssl_start = TimeTicksToOffset(it->second.ssl_start, record);
195      if (!it->second.ssl_end.is_null())
196        timing.ssl_end = TimeTicksToOffset(it->second.ssl_end, record);
197      record->socket_reused = it->second.socket_reused;
198      record->socket_log_id = it->second.socket_log_id;
199      break;
200    }
201    case net::NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST:
202      if (is_begin)
203        timing.send_start = TimeTicksToOffset(time, record);
204      else if (is_end)
205        timing.send_end = TimeTicksToOffset(time, record);
206      break;
207    case net::NetLog::TYPE_HTTP_TRANSACTION_READ_HEADERS:
208      if (is_begin)
209        timing.receive_headers_start =  TimeTicksToOffset(time, record);
210      else if (is_end)
211        timing.receive_headers_end =  TimeTicksToOffset(time, record);
212      break;
213    default:
214      break;
215  }
216}
217
218void LoadTimingObserver::OnAddHTTPStreamJobEntry(
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  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
225
226  bool is_begin = phase == net::NetLog::PHASE_BEGIN;
227  bool is_end = phase == net::NetLog::PHASE_END;
228
229  if (type == net::NetLog::TYPE_HTTP_STREAM_JOB) {
230    if (is_begin) {
231      // Prevents us from passively growing the memory unbounded in
232      // case something went wrong. Should not happen.
233      if (http_stream_job_to_record_.size() > kMaxNumEntries) {
234        LOG(WARNING) << "The load timing observer http stream job count "
235                        "has grown larger than expected, resetting";
236        http_stream_job_to_record_.clear();
237      }
238
239      http_stream_job_to_record_.insert(
240          std::make_pair(source.id, HTTPStreamJobRecord()));
241    } else if (is_end) {
242      http_stream_job_to_record_.erase(source.id);
243    }
244    return;
245  }
246
247  HTTPStreamJobToRecordMap::iterator it =
248      http_stream_job_to_record_.find(source.id);
249  if (it == http_stream_job_to_record_.end())
250    return;
251
252  switch (type) {
253    case net::NetLog::TYPE_SOCKET_POOL:
254      if (is_begin)
255        it->second.connect_start = time;
256      else if (is_end)
257        it->second.connect_end = time;
258      break;
259    case net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB: {
260      uint32 connect_job_id = static_cast<net::NetLogSourceParameter*>(
261          params)->value().id;
262      if (last_connect_job_id_ == connect_job_id &&
263          !last_connect_job_record_.dns_start.is_null()) {
264        it->second.dns_start = last_connect_job_record_.dns_start;
265        it->second.dns_end = last_connect_job_record_.dns_end;
266      }
267      break;
268    }
269    case net::NetLog::TYPE_SOCKET_POOL_REUSED_AN_EXISTING_SOCKET:
270      it->second.socket_reused = true;
271      break;
272    case net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET:
273      it->second.socket_log_id = static_cast<net::NetLogSourceParameter*>(
274        params)->value().id;
275      if (!it->second.socket_reused) {
276        SocketToRecordMap::iterator socket_it =
277            socket_to_record_.find(it->second.socket_log_id);
278        if (socket_it != socket_to_record_.end() &&
279            !socket_it->second.ssl_start.is_null()) {
280          it->second.ssl_start = socket_it->second.ssl_start;
281          it->second.ssl_end = socket_it->second.ssl_end;
282        }
283      }
284      break;
285    default:
286      break;
287  }
288}
289
290void LoadTimingObserver::OnAddConnectJobEntry(
291    net::NetLog::EventType type,
292    const base::TimeTicks& time,
293    const net::NetLog::Source& source,
294    net::NetLog::EventPhase phase,
295    net::NetLog::EventParameters* params) {
296  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
297
298  bool is_begin = phase == net::NetLog::PHASE_BEGIN;
299  bool is_end = phase == net::NetLog::PHASE_END;
300
301  // Manage record lifetime based on the SOCKET_POOL_CONNECT_JOB entry.
302  if (type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB) {
303    if (is_begin) {
304      // Prevents us from passively growing the memory unbounded in case
305      // something went wrong. Should not happen.
306      if (connect_job_to_record_.size() > kMaxNumEntries) {
307        LOG(WARNING) << "The load timing observer connect job count has grown "
308                        "larger than expected, resetting";
309        connect_job_to_record_.clear();
310      }
311
312      connect_job_to_record_.insert(
313          std::make_pair(source.id, ConnectJobRecord()));
314    } else if (is_end) {
315      ConnectJobToRecordMap::iterator it =
316          connect_job_to_record_.find(source.id);
317      if (it != connect_job_to_record_.end()) {
318        last_connect_job_id_ = it->first;
319        last_connect_job_record_ = it->second;
320        connect_job_to_record_.erase(it);
321      }
322    }
323  } else if (type == net::NetLog::TYPE_HOST_RESOLVER_IMPL) {
324    ConnectJobToRecordMap::iterator it =
325        connect_job_to_record_.find(source.id);
326    if (it != connect_job_to_record_.end()) {
327      if (is_begin)
328        it->second.dns_start = time;
329      else if (is_end)
330        it->second.dns_end = time;
331    }
332  }
333}
334
335void LoadTimingObserver::OnAddSocketEntry(
336    net::NetLog::EventType type,
337    const base::TimeTicks& time,
338    const net::NetLog::Source& source,
339    net::NetLog::EventPhase phase,
340    net::NetLog::EventParameters* params) {
341  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
342
343  bool is_begin = phase == net::NetLog::PHASE_BEGIN;
344  bool is_end = phase == net::NetLog::PHASE_END;
345
346  // Manage record lifetime based on the SOCKET_ALIVE entry.
347  if (type == net::NetLog::TYPE_SOCKET_ALIVE) {
348    if (is_begin) {
349      // Prevents us from passively growing the memory unbounded in case
350      // something went wrong. Should not happen.
351      if (socket_to_record_.size() > kMaxNumEntries) {
352        LOG(WARNING) << "The load timing observer socket count has grown "
353                        "larger than expected, resetting";
354        socket_to_record_.clear();
355      }
356
357      socket_to_record_.insert(
358          std::make_pair(source.id, SocketRecord()));
359    } else if (is_end) {
360      socket_to_record_.erase(source.id);
361    }
362    return;
363  }
364  SocketToRecordMap::iterator it = socket_to_record_.find(source.id);
365  if (it == socket_to_record_.end())
366    return;
367
368  if (type == net::NetLog::TYPE_SSL_CONNECT) {
369    if (is_begin)
370      it->second.ssl_start = time;
371    else if (is_end)
372      it->second.ssl_end = time;
373  }
374}
375