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: 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 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 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 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 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 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 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 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 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 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 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 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 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 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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
