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/format_macros.h"
9#include "base/string_util.h"
10#include "base/time.h"
11#include "content/browser/browser_thread.h"
12#include "net/base/load_flags.h"
13#include "net/url_request/url_request_netlog_params.h"
14#include "testing/gtest/include/gtest/gtest.h"
15
16namespace {
17
18using net::NetLog;
19using base::TimeDelta;
20
21// Serves to Identify the current thread as the IO thread.
22class LoadTimingObserverTest : public testing::Test {
23 public:
24  LoadTimingObserverTest() : io_thread_(BrowserThread::IO, &message_loop_) {
25  }
26
27 private:
28  MessageLoop message_loop_;
29  BrowserThread io_thread_;
30};
31
32base::TimeTicks current_time;
33
34void AddStartEntry(LoadTimingObserver& observer,
35                   const NetLog::Source& source,
36                   NetLog::EventType type,
37                   NetLog::EventParameters* params) {
38  observer.OnAddEntry(type, current_time, source, NetLog::PHASE_BEGIN, params);
39}
40
41void AddEndEntry(LoadTimingObserver& observer,
42                 const NetLog::Source& source,
43                 NetLog::EventType type,
44                 NetLog::EventParameters* params) {
45  observer.OnAddEntry(type, current_time, source, NetLog::PHASE_END, params);
46}
47
48void AddStartURLRequestEntries(LoadTimingObserver& observer,
49                               uint32 id,
50                               bool request_timing) {
51  scoped_refptr<net::URLRequestStartEventParameters> params(
52      new net::URLRequestStartEventParameters(
53          GURL(StringPrintf("http://req%d", id)),
54          "GET",
55          request_timing ? net::LOAD_ENABLE_LOAD_TIMING : 0,
56          net::LOW));
57  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, id);
58  AddStartEntry(observer, source, NetLog::TYPE_REQUEST_ALIVE, NULL);
59  AddStartEntry(observer,
60                source,
61                NetLog::TYPE_URL_REQUEST_START_JOB,
62                params.get());
63}
64
65void AddEndURLRequestEntries(LoadTimingObserver& observer, uint32 id) {
66  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, id);
67  AddEndEntry(observer, source, NetLog::TYPE_REQUEST_ALIVE, NULL);
68  AddEndEntry(observer,
69              source,
70              NetLog::TYPE_URL_REQUEST_START_JOB,
71              NULL);
72}
73
74void AddStartHTTPStreamJobEntries(LoadTimingObserver& observer, uint32 id) {
75  NetLog::Source source(NetLog::SOURCE_HTTP_STREAM_JOB, id);
76  AddStartEntry(observer, source, NetLog::TYPE_HTTP_STREAM_JOB, NULL);
77}
78
79void AddEndHTTPStreamJobEntries(LoadTimingObserver& observer, uint32 id) {
80  NetLog::Source source(NetLog::SOURCE_HTTP_STREAM_JOB, id);
81  AddEndEntry(observer, source, NetLog::TYPE_HTTP_STREAM_JOB, NULL);
82}
83
84void AddStartConnectJobEntries(LoadTimingObserver& observer, uint32 id) {
85  NetLog::Source source(NetLog::SOURCE_CONNECT_JOB, id);
86  AddStartEntry(observer, source, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL);
87}
88
89void AddEndConnectJobEntries(LoadTimingObserver& observer, uint32 id) {
90  NetLog::Source source(NetLog::SOURCE_CONNECT_JOB, id);
91  AddEndEntry(observer, source, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL);
92}
93
94void AddStartSocketEntries(LoadTimingObserver& observer, uint32 id) {
95  NetLog::Source source(NetLog::SOURCE_SOCKET, id);
96  AddStartEntry(observer, source, NetLog::TYPE_SOCKET_ALIVE, NULL);
97}
98
99void AddEndSocketEntries(LoadTimingObserver& observer, uint32 id) {
100  NetLog::Source source(NetLog::SOURCE_SOCKET, id);
101  AddEndEntry(observer, source, NetLog::TYPE_SOCKET_ALIVE, NULL);
102}
103
104void BindURLRequestToHTTPStreamJob(LoadTimingObserver& observer,
105                                   NetLog::Source url_request_source,
106                                   NetLog::Source http_stream_job_source) {
107  scoped_refptr<net::NetLogSourceParameter> params(
108      new net::NetLogSourceParameter("source_dependency",
109                                     http_stream_job_source));
110  AddStartEntry(observer,
111                url_request_source,
112                NetLog::TYPE_HTTP_STREAM_REQUEST_BOUND_TO_JOB,
113                params.get());
114}
115
116void BindHTTPStreamJobToConnectJob(LoadTimingObserver& observer,
117                                   NetLog::Source& http_stream_job_source,
118                                   NetLog::Source& connect_source) {
119  scoped_refptr<net::NetLogSourceParameter> params(
120      new net::NetLogSourceParameter("source_dependency", connect_source));
121  AddStartEntry(observer,
122                http_stream_job_source,
123                NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
124                params.get());
125}
126
127void BindHTTPStreamJobToSocket(LoadTimingObserver& observer,
128                               NetLog::Source& http_stream_job_source,
129                               NetLog::Source& socket_source) {
130  scoped_refptr<net::NetLogSourceParameter> params(
131      new net::NetLogSourceParameter("source_dependency", socket_source));
132  AddStartEntry(observer,
133                http_stream_job_source,
134                NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET,
135                params.get());
136}
137
138}  // namespace
139
140// Test that net::URLRequest with no load timing flag is not processed.
141TEST_F(LoadTimingObserverTest, NoLoadTimingEnabled) {
142  LoadTimingObserver observer;
143
144  AddStartURLRequestEntries(observer, 0, false);
145  LoadTimingObserver::URLRequestRecord* record =
146      observer.GetURLRequestRecord(0);
147  ASSERT_TRUE(record == NULL);
148}
149
150// Test that URLRequestRecord is created, deleted and is not growing unbound.
151TEST_F(LoadTimingObserverTest, URLRequestRecord) {
152  LoadTimingObserver observer;
153
154  // Create record.
155  AddStartURLRequestEntries(observer, 0, true);
156  LoadTimingObserver::URLRequestRecord* record =
157      observer.GetURLRequestRecord(0);
158  ASSERT_FALSE(record == NULL);
159
160  // Collect record.
161  AddEndURLRequestEntries(observer, 0);
162  record = observer.GetURLRequestRecord(0);
163  ASSERT_TRUE(record == NULL);
164
165  // Check unbound growth.
166  for (size_t i = 1; i < 1100; ++i)
167    AddStartURLRequestEntries(observer, i, true);
168  record = observer.GetURLRequestRecord(1);
169  ASSERT_TRUE(record == NULL);
170}
171
172// Test that HTTPStreamJobRecord is created, deleted and is not growing unbound.
173TEST_F(LoadTimingObserverTest, HTTPStreamJobRecord) {
174  LoadTimingObserver observer;
175
176  // Create record.
177  AddStartHTTPStreamJobEntries(observer, 0);
178  ASSERT_FALSE(observer.http_stream_job_to_record_.find(0) ==
179                   observer.http_stream_job_to_record_.end());
180
181  // Collect record.
182  AddEndHTTPStreamJobEntries(observer, 0);
183  ASSERT_TRUE(observer.http_stream_job_to_record_.find(0) ==
184                   observer.http_stream_job_to_record_.end());
185
186  // Check unbound growth.
187  for (size_t i = 1; i < 1100; ++i)
188    AddStartHTTPStreamJobEntries(observer, i);
189  ASSERT_TRUE(observer.http_stream_job_to_record_.find(1) ==
190                  observer.http_stream_job_to_record_.end());
191}
192
193// Test that ConnectJobRecord is created, deleted and is not growing unbound.
194TEST_F(LoadTimingObserverTest, ConnectJobRecord) {
195  LoadTimingObserver observer;
196
197  // Create record.
198  AddStartConnectJobEntries(observer, 0);
199  ASSERT_FALSE(observer.connect_job_to_record_.find(0) ==
200                   observer.connect_job_to_record_.end());
201
202  // Collect record.
203  AddEndConnectJobEntries(observer, 0);
204  ASSERT_TRUE(observer.connect_job_to_record_.find(0) ==
205                   observer.connect_job_to_record_.end());
206
207  // Check unbound growth.
208  for (size_t i = 1; i < 1100; ++i)
209    AddStartConnectJobEntries(observer, i);
210  ASSERT_TRUE(observer.connect_job_to_record_.find(1) ==
211                  observer.connect_job_to_record_.end());
212}
213
214// Test that SocketRecord is created, deleted and is not growing unbound.
215TEST_F(LoadTimingObserverTest, SocketRecord) {
216  LoadTimingObserver observer;
217
218  // Create record.
219  AddStartSocketEntries(observer, 0);
220  ASSERT_FALSE(observer.socket_to_record_.find(0) ==
221                   observer.socket_to_record_.end());
222
223  // Collect record.
224  AddEndSocketEntries(observer, 0);
225  ASSERT_TRUE(observer.socket_to_record_.find(0) ==
226                   observer.socket_to_record_.end());
227
228
229  // Check unbound growth.
230  for (size_t i = 1; i < 1100; ++i)
231    AddStartSocketEntries(observer, i);
232  ASSERT_TRUE(observer.socket_to_record_.find(1) ==
233                  observer.socket_to_record_.end());
234}
235
236// Test that basic time is set to the request.
237TEST_F(LoadTimingObserverTest, BaseTicks) {
238  LoadTimingObserver observer;
239  current_time += TimeDelta::FromSeconds(1);
240  AddStartURLRequestEntries(observer, 0, true);
241
242  LoadTimingObserver::URLRequestRecord* record =
243      observer.GetURLRequestRecord(0);
244  ASSERT_EQ(1000000, record->base_ticks.ToInternalValue());
245}
246
247// Test proxy time detection.
248TEST_F(LoadTimingObserverTest, ProxyTime) {
249  LoadTimingObserver observer;
250  current_time += TimeDelta::FromSeconds(1);
251
252  AddStartURLRequestEntries(observer, 0, true);
253  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
254
255  current_time += TimeDelta::FromSeconds(2);
256  AddStartEntry(observer, source, NetLog::TYPE_PROXY_SERVICE, NULL);
257  current_time += TimeDelta::FromSeconds(3);
258  AddEndEntry(observer, source, NetLog::TYPE_PROXY_SERVICE, NULL);
259
260  LoadTimingObserver::URLRequestRecord* record =
261      observer.GetURLRequestRecord(0);
262  ASSERT_EQ(2000, record->timing.proxy_start);
263  ASSERT_EQ(5000, record->timing.proxy_end);
264}
265
266// Test connect time detection.
267TEST_F(LoadTimingObserverTest, ConnectTime) {
268  LoadTimingObserver observer;
269  current_time += TimeDelta::FromSeconds(1);
270
271  AddStartURLRequestEntries(observer, 0, true);
272  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
273
274  NetLog::Source http_stream_job_source(NetLog::SOURCE_HTTP_STREAM_JOB, 1);
275  AddStartHTTPStreamJobEntries(observer, 1);
276
277  current_time += TimeDelta::FromSeconds(2);
278  AddStartEntry(observer, http_stream_job_source, NetLog::TYPE_SOCKET_POOL,
279                NULL);
280  current_time += TimeDelta::FromSeconds(3);
281  AddEndEntry(observer, http_stream_job_source, NetLog::TYPE_SOCKET_POOL, NULL);
282
283  BindURLRequestToHTTPStreamJob(observer, source, http_stream_job_source);
284
285  LoadTimingObserver::URLRequestRecord* record =
286      observer.GetURLRequestRecord(0);
287  ASSERT_EQ(2000, record->timing.connect_start);
288  ASSERT_EQ(5000, record->timing.connect_end);
289}
290
291// Test dns time detection.
292TEST_F(LoadTimingObserverTest, DnsTime) {
293  LoadTimingObserver observer;
294
295  // Start request.
296  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
297  AddStartURLRequestEntries(observer, 0, true);
298  current_time += TimeDelta::FromSeconds(1);
299
300  // Add resolver entry.
301  AddStartConnectJobEntries(observer, 1);
302  NetLog::Source connect_source(NetLog::SOURCE_CONNECT_JOB, 1);
303  AddStartEntry(observer,
304                connect_source,
305                NetLog::TYPE_HOST_RESOLVER_IMPL,
306                NULL);
307  current_time += TimeDelta::FromSeconds(2);
308  AddEndEntry(observer, connect_source, NetLog::TYPE_HOST_RESOLVER_IMPL, NULL);
309  AddEndConnectJobEntries(observer, 1);
310
311  NetLog::Source http_stream_job_source(NetLog::SOURCE_HTTP_STREAM_JOB, 2);
312  AddStartHTTPStreamJobEntries(observer, 2);
313
314  BindHTTPStreamJobToConnectJob(observer, http_stream_job_source,
315                                connect_source);
316  BindURLRequestToHTTPStreamJob(observer, source, http_stream_job_source);
317
318  LoadTimingObserver::URLRequestRecord* record =
319      observer.GetURLRequestRecord(0);
320  ASSERT_EQ(1000, record->timing.dns_start);
321  ASSERT_EQ(3000, record->timing.dns_end);
322}
323
324// Test send time detection.
325TEST_F(LoadTimingObserverTest, SendTime) {
326  LoadTimingObserver observer;
327
328  // Start request.
329  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
330  AddStartURLRequestEntries(observer, 0, true);
331  current_time += TimeDelta::FromSeconds(2);
332
333  // Add send request entry.
334  AddStartEntry(observer,
335                source,
336                NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST,
337                NULL);
338  current_time += TimeDelta::FromSeconds(5);
339  AddEndEntry(observer,
340              source,
341              NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST,
342              NULL);
343
344  LoadTimingObserver::URLRequestRecord* record =
345      observer.GetURLRequestRecord(0);
346  ASSERT_EQ(2000, record->timing.send_start);
347  ASSERT_EQ(7000, record->timing.send_end);
348}
349
350// Test receive time detection.
351TEST_F(LoadTimingObserverTest, ReceiveTime) {
352  LoadTimingObserver observer;
353
354  // Start request.
355  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
356  AddStartURLRequestEntries(observer, 0, true);
357  current_time += TimeDelta::FromSeconds(2);
358
359  // Add send request entry.
360  AddStartEntry(observer,
361                source,
362                NetLog::TYPE_HTTP_TRANSACTION_READ_HEADERS,
363                NULL);
364  current_time += TimeDelta::FromSeconds(5);
365  AddEndEntry(observer,
366              source,
367              NetLog::TYPE_HTTP_TRANSACTION_READ_HEADERS,
368              NULL);
369
370  LoadTimingObserver::URLRequestRecord* record =
371      observer.GetURLRequestRecord(0);
372  ASSERT_EQ(2000, record->timing.receive_headers_start);
373  ASSERT_EQ(7000, record->timing.receive_headers_end);
374}
375
376// Test ssl time detection.
377TEST_F(LoadTimingObserverTest, SslTime) {
378  LoadTimingObserver observer;
379
380  // Start request.
381  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
382  AddStartURLRequestEntries(observer, 0, true);
383  current_time += TimeDelta::FromSeconds(1);
384
385  // Add resolver entry.
386  AddStartSocketEntries(observer, 1);
387  NetLog::Source socket_source(NetLog::SOURCE_SOCKET, 1);
388  AddStartEntry(observer, socket_source, NetLog::TYPE_SSL_CONNECT, NULL);
389  current_time += TimeDelta::FromSeconds(2);
390  AddEndEntry(observer, socket_source, NetLog::TYPE_SSL_CONNECT, NULL);
391
392  NetLog::Source http_stream_job_source(NetLog::SOURCE_HTTP_STREAM_JOB, 2);
393  AddStartHTTPStreamJobEntries(observer, 2);
394
395  BindHTTPStreamJobToSocket(observer, http_stream_job_source, socket_source);
396  BindURLRequestToHTTPStreamJob(observer, source, http_stream_job_source);
397
398  LoadTimingObserver::URLRequestRecord* record =
399      observer.GetURLRequestRecord(0);
400  ASSERT_EQ(1000, record->timing.ssl_start);
401  ASSERT_EQ(3000, record->timing.ssl_end);
402}
403