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
16 namespace {
17
18 using net::NetLog;
19 using base::TimeDelta;
20
21 // Serves to Identify the current thread as the IO thread.
22 class LoadTimingObserverTest : public testing::Test {
23 public:
LoadTimingObserverTest()24 LoadTimingObserverTest() : io_thread_(BrowserThread::IO, &message_loop_) {
25 }
26
27 private:
28 MessageLoop message_loop_;
29 BrowserThread io_thread_;
30 };
31
32 base::TimeTicks current_time;
33
AddStartEntry(LoadTimingObserver & observer,const NetLog::Source & source,NetLog::EventType type,NetLog::EventParameters * params)34 void 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
AddEndEntry(LoadTimingObserver & observer,const NetLog::Source & source,NetLog::EventType type,NetLog::EventParameters * params)41 void 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
AddStartURLRequestEntries(LoadTimingObserver & observer,uint32 id,bool request_timing)48 void 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
AddEndURLRequestEntries(LoadTimingObserver & observer,uint32 id)65 void 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
AddStartHTTPStreamJobEntries(LoadTimingObserver & observer,uint32 id)74 void 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
AddEndHTTPStreamJobEntries(LoadTimingObserver & observer,uint32 id)79 void 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
AddStartConnectJobEntries(LoadTimingObserver & observer,uint32 id)84 void 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
AddEndConnectJobEntries(LoadTimingObserver & observer,uint32 id)89 void 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
AddStartSocketEntries(LoadTimingObserver & observer,uint32 id)94 void AddStartSocketEntries(LoadTimingObserver& observer, uint32 id) {
95 NetLog::Source source(NetLog::SOURCE_SOCKET, id);
96 AddStartEntry(observer, source, NetLog::TYPE_SOCKET_ALIVE, NULL);
97 }
98
AddEndSocketEntries(LoadTimingObserver & observer,uint32 id)99 void AddEndSocketEntries(LoadTimingObserver& observer, uint32 id) {
100 NetLog::Source source(NetLog::SOURCE_SOCKET, id);
101 AddEndEntry(observer, source, NetLog::TYPE_SOCKET_ALIVE, NULL);
102 }
103
BindURLRequestToHTTPStreamJob(LoadTimingObserver & observer,NetLog::Source url_request_source,NetLog::Source http_stream_job_source)104 void 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
BindHTTPStreamJobToConnectJob(LoadTimingObserver & observer,NetLog::Source & http_stream_job_source,NetLog::Source & connect_source)116 void 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
BindHTTPStreamJobToSocket(LoadTimingObserver & observer,NetLog::Source & http_stream_job_source,NetLog::Source & socket_source)127 void 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.
TEST_F(LoadTimingObserverTest,NoLoadTimingEnabled)141 TEST_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.
TEST_F(LoadTimingObserverTest,URLRequestRecord)151 TEST_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.
TEST_F(LoadTimingObserverTest,HTTPStreamJobRecord)173 TEST_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.
TEST_F(LoadTimingObserverTest,ConnectJobRecord)194 TEST_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.
TEST_F(LoadTimingObserverTest,SocketRecord)215 TEST_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.
TEST_F(LoadTimingObserverTest,BaseTicks)237 TEST_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.
TEST_F(LoadTimingObserverTest,ProxyTime)248 TEST_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.
TEST_F(LoadTimingObserverTest,ConnectTime)267 TEST_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.
TEST_F(LoadTimingObserverTest,DnsTime)292 TEST_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.
TEST_F(LoadTimingObserverTest,SendTime)325 TEST_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.
TEST_F(LoadTimingObserverTest,ReceiveTime)351 TEST_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.
TEST_F(LoadTimingObserverTest,SslTime)377 TEST_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