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 15 using base::Time; 16 using base::TimeTicks; 17 using webkit_glue::ResourceLoaderBridge; 18 using webkit_glue::ResourceLoadTimingInfo; 19 20 const size_t kMaxNumEntries = 1000; 21 22 namespace { 23 24 const 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. 29 static 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 44 static 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 53 LoadTimingObserver::URLRequestRecord::URLRequestRecord() 54 : connect_job_id(net::NetLog::Source::kInvalidId), 55 socket_log_id(net::NetLog::Source::kInvalidId), 56 socket_reused(false) { 57 } 58 59 LoadTimingObserver::HTTPStreamJobRecord::HTTPStreamJobRecord() 60 : socket_log_id(net::NetLog::Source::kInvalidId), 61 socket_reused(false) { 62 } 63 64 LoadTimingObserver::LoadTimingObserver() 65 : ThreadSafeObserver(net::NetLog::LOG_BASIC), 66 last_connect_job_id_(net::NetLog::Source::kInvalidId) { 67 } 68 69 LoadTimingObserver::~LoadTimingObserver() { 70 } 71 72 LoadTimingObserver::URLRequestRecord* 73 LoadTimingObserver::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 82 void 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 101 void 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 123 void 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 218 void 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 290 void 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 335 void 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
