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