| OLD | NEW |
| 1 // Copyright 2015 The Chromium Authors. All rights reserved. | 1 // Copyright 2015 The Chromium Authors. All rights reserved. |
| 2 // Use of this source code is governed by a BSD-style license that can be | 2 // Use of this source code is governed by a BSD-style license that can be |
| 3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
| 4 | 4 |
| 5 #include "chrome/browser/page_load_metrics/metrics_web_contents_observer.h" | 5 #include "chrome/browser/page_load_metrics/metrics_web_contents_observer.h" |
| 6 | 6 |
| 7 #include <algorithm> | 7 #include <algorithm> |
| 8 #include <ostream> | 8 #include <ostream> |
| 9 #include <string> | 9 #include <string> |
| 10 #include <utility> | 10 #include <utility> |
| 11 | 11 |
| 12 #include "base/location.h" | 12 #include "base/location.h" |
| 13 #include "base/logging.h" | |
| 14 #include "base/memory/ptr_util.h" | 13 #include "base/memory/ptr_util.h" |
| 15 #include "base/metrics/histogram_macros.h" | 14 #include "base/metrics/histogram_macros.h" |
| 16 #include "base/metrics/user_metrics.h" | 15 #include "base/metrics/user_metrics.h" |
| 17 #include "chrome/browser/page_load_metrics/browser_page_track_decider.h" | 16 #include "chrome/browser/page_load_metrics/browser_page_track_decider.h" |
| 17 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface.
h" |
| 18 #include "chrome/browser/page_load_metrics/page_load_metrics_util.h" | 18 #include "chrome/browser/page_load_metrics/page_load_metrics_util.h" |
| 19 #include "chrome/browser/page_load_metrics/page_load_tracker.h" |
| 19 #include "chrome/common/page_load_metrics/page_load_metrics_messages.h" | 20 #include "chrome/common/page_load_metrics/page_load_metrics_messages.h" |
| 20 #include "chrome/common/page_load_metrics/page_load_timing.h" | 21 #include "chrome/common/page_load_metrics/page_load_timing.h" |
| 21 #include "content/public/browser/browser_thread.h" | 22 #include "content/public/browser/browser_thread.h" |
| 22 #include "content/public/browser/navigation_details.h" | 23 #include "content/public/browser/navigation_details.h" |
| 23 #include "content/public/browser/navigation_handle.h" | 24 #include "content/public/browser/navigation_handle.h" |
| 24 #include "content/public/browser/render_frame_host.h" | 25 #include "content/public/browser/render_frame_host.h" |
| 25 #include "content/public/browser/render_view_host.h" | 26 #include "content/public/browser/render_view_host.h" |
| 26 #include "content/public/browser/web_contents.h" | 27 #include "content/public/browser/web_contents.h" |
| 27 #include "content/public/browser/web_contents_observer.h" | 28 #include "content/public/browser/web_contents_observer.h" |
| 28 #include "content/public/browser/web_contents_user_data.h" | 29 #include "content/public/browser/web_contents_user_data.h" |
| 29 #include "ipc/ipc_message.h" | 30 #include "ipc/ipc_message.h" |
| 30 #include "ipc/ipc_message_macros.h" | 31 #include "ipc/ipc_message_macros.h" |
| 32 #include "net/base/net_errors.h" |
| 31 #include "ui/base/page_transition_types.h" | 33 #include "ui/base/page_transition_types.h" |
| 32 | 34 |
| 33 DEFINE_WEB_CONTENTS_USER_DATA_KEY( | 35 DEFINE_WEB_CONTENTS_USER_DATA_KEY( |
| 34 page_load_metrics::MetricsWebContentsObserver); | 36 page_load_metrics::MetricsWebContentsObserver); |
| 35 | 37 |
| 36 // This macro invokes the specified method on each observer, passing the | |
| 37 // variable length arguments as the method's arguments, and removes the observer | |
| 38 // from the list of observers if the given method returns STOP_OBSERVING. | |
| 39 #define INVOKE_AND_PRUNE_OBSERVERS(observers, Method, ...) \ | |
| 40 for (auto it = observers.begin(); it != observers.end();) { \ | |
| 41 if ((*it)->Method(__VA_ARGS__) == \ | |
| 42 PageLoadMetricsObserver::STOP_OBSERVING) { \ | |
| 43 it = observers.erase(it); \ | |
| 44 } else { \ | |
| 45 ++it; \ | |
| 46 } \ | |
| 47 } | |
| 48 | |
| 49 namespace page_load_metrics { | 38 namespace page_load_metrics { |
| 50 | 39 |
| 51 namespace internal { | |
| 52 | |
| 53 const char kErrorEvents[] = "PageLoad.Internal.ErrorCode"; | |
| 54 const char kAbortChainSizeReload[] = | |
| 55 "PageLoad.Internal.ProvisionalAbortChainSize.Reload"; | |
| 56 const char kAbortChainSizeForwardBack[] = | |
| 57 "PageLoad.Internal.ProvisionalAbortChainSize.ForwardBack"; | |
| 58 const char kAbortChainSizeNewNavigation[] = | |
| 59 "PageLoad.Internal.ProvisionalAbortChainSize.NewNavigation"; | |
| 60 const char kAbortChainSizeSameURL[] = | |
| 61 "PageLoad.Internal.ProvisionalAbortChainSize.SameURL"; | |
| 62 const char kAbortChainSizeNoCommit[] = | |
| 63 "PageLoad.Internal.ProvisionalAbortChainSize.NoCommit"; | |
| 64 const char kClientRedirectFirstPaintToNavigation[] = | |
| 65 "PageLoad.Internal.ClientRedirect.FirstPaintToNavigation"; | |
| 66 const char kClientRedirectWithoutPaint[] = | |
| 67 "PageLoad.Internal.ClientRedirect.NavigationWithoutPaint"; | |
| 68 const char kPageLoadCompletedAfterAppBackground[] = | |
| 69 "PageLoad.Internal.PageLoadCompleted.AfterAppBackground"; | |
| 70 | |
| 71 } // namespace internal | |
| 72 | |
| 73 namespace { | 40 namespace { |
| 74 | 41 |
| 75 // Helper to allow use of Optional<> values in LOG() messages. | |
| 76 std::ostream& operator<<(std::ostream& os, | |
| 77 const base::Optional<base::TimeDelta>& opt) { | |
| 78 if (opt) | |
| 79 os << opt.value(); | |
| 80 else | |
| 81 os << "(unset)"; | |
| 82 return os; | |
| 83 } | |
| 84 | |
| 85 // If second is non-zero, first must also be non-zero and less than or equal to | |
| 86 // second. | |
| 87 bool EventsInOrder(const base::Optional<base::TimeDelta>& first, | |
| 88 const base::Optional<base::TimeDelta>& second) { | |
| 89 if (!second) { | |
| 90 return true; | |
| 91 } | |
| 92 return first && first <= second; | |
| 93 } | |
| 94 | |
| 95 bool IsValidPageLoadTiming(const PageLoadTiming& timing) { | |
| 96 if (timing.IsEmpty()) | |
| 97 return false; | |
| 98 | |
| 99 // If we have a non-empty timing, it should always have a navigation start. | |
| 100 if (timing.navigation_start.is_null()) { | |
| 101 NOTREACHED() << "Received null navigation_start."; | |
| 102 return false; | |
| 103 } | |
| 104 | |
| 105 // Verify proper ordering between the various timings. | |
| 106 | |
| 107 if (!EventsInOrder(timing.response_start, timing.parse_start)) { | |
| 108 // We sometimes get a zero response_start with a non-zero parse start. See | |
| 109 // crbug.com/590212. | |
| 110 DLOG(ERROR) << "Invalid response_start " << timing.response_start | |
| 111 << " for parse_start " << timing.parse_start; | |
| 112 return false; | |
| 113 } | |
| 114 | |
| 115 if (!EventsInOrder(timing.parse_start, timing.parse_stop)) { | |
| 116 NOTREACHED() << "Invalid parse_start " << timing.parse_start | |
| 117 << " for parse_stop " << timing.parse_stop; | |
| 118 return false; | |
| 119 } | |
| 120 | |
| 121 if (timing.parse_stop) { | |
| 122 const base::TimeDelta parse_duration = | |
| 123 timing.parse_stop.value() - timing.parse_start.value(); | |
| 124 if (timing.parse_blocked_on_script_load_duration > parse_duration) { | |
| 125 NOTREACHED() << "Invalid parse_blocked_on_script_load_duration " | |
| 126 << timing.parse_blocked_on_script_load_duration | |
| 127 << " for parse duration " << parse_duration; | |
| 128 return false; | |
| 129 } | |
| 130 if (timing.parse_blocked_on_script_execution_duration > parse_duration) { | |
| 131 NOTREACHED() << "Invalid parse_blocked_on_script_execution_duration " | |
| 132 << timing.parse_blocked_on_script_execution_duration | |
| 133 << " for parse duration " << parse_duration; | |
| 134 return false; | |
| 135 } | |
| 136 } | |
| 137 | |
| 138 if (timing.parse_blocked_on_script_load_from_document_write_duration > | |
| 139 timing.parse_blocked_on_script_load_duration) { | |
| 140 NOTREACHED() | |
| 141 << "Invalid parse_blocked_on_script_load_from_document_write_duration " | |
| 142 << timing.parse_blocked_on_script_load_from_document_write_duration | |
| 143 << " for parse_blocked_on_script_load_duration " | |
| 144 << timing.parse_blocked_on_script_load_duration; | |
| 145 return false; | |
| 146 } | |
| 147 | |
| 148 if (timing.parse_blocked_on_script_execution_from_document_write_duration > | |
| 149 timing.parse_blocked_on_script_execution_duration) { | |
| 150 NOTREACHED() | |
| 151 << "Invalid " | |
| 152 "parse_blocked_on_script_execution_from_document_write_duration " | |
| 153 << timing.parse_blocked_on_script_execution_from_document_write_duration | |
| 154 << " for parse_blocked_on_script_execution_duration " | |
| 155 << timing.parse_blocked_on_script_execution_duration; | |
| 156 return false; | |
| 157 } | |
| 158 | |
| 159 if (!EventsInOrder(timing.parse_stop, | |
| 160 timing.dom_content_loaded_event_start)) { | |
| 161 NOTREACHED() << "Invalid parse_stop " << timing.parse_stop | |
| 162 << " for dom_content_loaded_event_start " | |
| 163 << timing.dom_content_loaded_event_start; | |
| 164 return false; | |
| 165 } | |
| 166 | |
| 167 if (!EventsInOrder(timing.dom_content_loaded_event_start, | |
| 168 timing.load_event_start)) { | |
| 169 NOTREACHED() << "Invalid dom_content_loaded_event_start " | |
| 170 << timing.dom_content_loaded_event_start | |
| 171 << " for load_event_start " << timing.load_event_start; | |
| 172 return false; | |
| 173 } | |
| 174 | |
| 175 if (!EventsInOrder(timing.parse_start, timing.first_layout)) { | |
| 176 NOTREACHED() << "Invalid parse_start " << timing.parse_start | |
| 177 << " for first_layout " << timing.first_layout; | |
| 178 return false; | |
| 179 } | |
| 180 | |
| 181 if (!EventsInOrder(timing.first_layout, timing.first_paint)) { | |
| 182 // This can happen when we process an XHTML document that doesn't contain | |
| 183 // well formed XML. See crbug.com/627607. | |
| 184 DLOG(ERROR) << "Invalid first_layout " << timing.first_layout | |
| 185 << " for first_paint " << timing.first_paint; | |
| 186 return false; | |
| 187 } | |
| 188 | |
| 189 if (!EventsInOrder(timing.first_paint, timing.first_text_paint)) { | |
| 190 NOTREACHED() << "Invalid first_paint " << timing.first_paint | |
| 191 << " for first_text_paint " << timing.first_text_paint; | |
| 192 return false; | |
| 193 } | |
| 194 | |
| 195 if (!EventsInOrder(timing.first_paint, timing.first_image_paint)) { | |
| 196 NOTREACHED() << "Invalid first_paint " << timing.first_paint | |
| 197 << " for first_image_paint " << timing.first_image_paint; | |
| 198 return false; | |
| 199 } | |
| 200 | |
| 201 if (!EventsInOrder(timing.first_paint, timing.first_contentful_paint)) { | |
| 202 NOTREACHED() << "Invalid first_paint " << timing.first_paint | |
| 203 << " for first_contentful_paint " | |
| 204 << timing.first_contentful_paint; | |
| 205 return false; | |
| 206 } | |
| 207 | |
| 208 if (!EventsInOrder(timing.first_paint, timing.first_meaningful_paint)) { | |
| 209 NOTREACHED() << "Invalid first_paint " << timing.first_paint | |
| 210 << " for first_meaningful_paint " | |
| 211 << timing.first_meaningful_paint; | |
| 212 return false; | |
| 213 } | |
| 214 | |
| 215 return true; | |
| 216 } | |
| 217 | |
| 218 void RecordInternalError(InternalErrorLoadEvent event) { | |
| 219 UMA_HISTOGRAM_ENUMERATION(internal::kErrorEvents, event, ERR_LAST_ENTRY); | |
| 220 } | |
| 221 | |
| 222 void RecordAppBackgroundPageLoadCompleted(bool completed_after_background) { | |
| 223 UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadCompletedAfterAppBackground, | |
| 224 completed_after_background); | |
| 225 } | |
| 226 | |
| 227 // TODO(csharrison): Add a case for client side redirects, which is what JS | |
| 228 // initiated window.location / window.history navigations get set to. | |
| 229 UserAbortType AbortTypeForPageTransition(ui::PageTransition transition) { | |
| 230 if (transition & ui::PAGE_TRANSITION_CLIENT_REDIRECT) { | |
| 231 return ABORT_CLIENT_REDIRECT; | |
| 232 } | |
| 233 if (ui::PageTransitionCoreTypeIs(transition, ui::PAGE_TRANSITION_RELOAD)) | |
| 234 return ABORT_RELOAD; | |
| 235 if (transition & ui::PAGE_TRANSITION_FORWARD_BACK) | |
| 236 return ABORT_FORWARD_BACK; | |
| 237 if (ui::PageTransitionIsNewNavigation(transition)) | |
| 238 return ABORT_NEW_NAVIGATION; | |
| 239 NOTREACHED() | |
| 240 << "AbortTypeForPageTransition received unexpected ui::PageTransition: " | |
| 241 << transition; | |
| 242 return ABORT_OTHER; | |
| 243 } | |
| 244 | |
| 245 void LogAbortChainSameURLHistogram(int aborted_chain_size_same_url) { | |
| 246 if (aborted_chain_size_same_url > 0) { | |
| 247 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeSameURL, | |
| 248 aborted_chain_size_same_url); | |
| 249 } | |
| 250 } | |
| 251 | |
| 252 void DispatchObserverTimingCallbacks(PageLoadMetricsObserver* observer, | |
| 253 const PageLoadTiming& last_timing, | |
| 254 const PageLoadTiming& new_timing, | |
| 255 const PageLoadMetadata& last_metadata, | |
| 256 const PageLoadExtraInfo& extra_info) { | |
| 257 if (last_timing != new_timing) | |
| 258 observer->OnTimingUpdate(new_timing, extra_info); | |
| 259 if (new_timing.dom_content_loaded_event_start && | |
| 260 !last_timing.dom_content_loaded_event_start) | |
| 261 observer->OnDomContentLoadedEventStart(new_timing, extra_info); | |
| 262 if (new_timing.load_event_start && !last_timing.load_event_start) | |
| 263 observer->OnLoadEventStart(new_timing, extra_info); | |
| 264 if (new_timing.first_layout && !last_timing.first_layout) | |
| 265 observer->OnFirstLayout(new_timing, extra_info); | |
| 266 if (new_timing.first_paint && !last_timing.first_paint) | |
| 267 observer->OnFirstPaint(new_timing, extra_info); | |
| 268 if (new_timing.first_text_paint && !last_timing.first_text_paint) | |
| 269 observer->OnFirstTextPaint(new_timing, extra_info); | |
| 270 if (new_timing.first_image_paint && !last_timing.first_image_paint) | |
| 271 observer->OnFirstImagePaint(new_timing, extra_info); | |
| 272 if (new_timing.first_contentful_paint && !last_timing.first_contentful_paint) | |
| 273 observer->OnFirstContentfulPaint(new_timing, extra_info); | |
| 274 if (new_timing.first_meaningful_paint && !last_timing.first_meaningful_paint) | |
| 275 observer->OnFirstMeaningfulPaint(new_timing, extra_info); | |
| 276 if (new_timing.parse_start && !last_timing.parse_start) | |
| 277 observer->OnParseStart(new_timing, extra_info); | |
| 278 if (new_timing.parse_stop && !last_timing.parse_stop) | |
| 279 observer->OnParseStop(new_timing, extra_info); | |
| 280 if (extra_info.metadata.behavior_flags != last_metadata.behavior_flags) | |
| 281 observer->OnLoadingBehaviorObserved(extra_info); | |
| 282 } | |
| 283 | |
| 284 // TODO(crbug.com/617904): Browser initiated navigations should have | 42 // TODO(crbug.com/617904): Browser initiated navigations should have |
| 285 // HasUserGesture() set to true. Update this once we get enough data from just | 43 // HasUserGesture() set to true. Update this once we get enough data from just |
| 286 // renderer initiated aborts. | 44 // renderer initiated aborts. |
| 287 bool IsNavigationUserInitiated(content::NavigationHandle* handle) { | 45 bool IsNavigationUserInitiated(content::NavigationHandle* handle) { |
| 288 return handle->HasUserGesture(); | 46 return handle->HasUserGesture(); |
| 289 } | 47 } |
| 290 | 48 |
| 291 } // namespace | 49 } // namespace |
| 292 | 50 |
| 293 PageLoadTracker::PageLoadTracker( | |
| 294 bool in_foreground, | |
| 295 PageLoadMetricsEmbedderInterface* embedder_interface, | |
| 296 const GURL& currently_committed_url, | |
| 297 content::NavigationHandle* navigation_handle, | |
| 298 int aborted_chain_size, | |
| 299 int aborted_chain_size_same_url) | |
| 300 : did_stop_tracking_(false), | |
| 301 app_entered_background_(false), | |
| 302 navigation_start_(navigation_handle->NavigationStart()), | |
| 303 start_url_(navigation_handle->GetURL()), | |
| 304 abort_type_(ABORT_NONE), | |
| 305 abort_user_initiated_(false), | |
| 306 started_in_foreground_(in_foreground), | |
| 307 page_transition_(navigation_handle->GetPageTransition()), | |
| 308 num_cache_requests_(0), | |
| 309 num_network_requests_(0), | |
| 310 user_gesture_(IsNavigationUserInitiated(navigation_handle)), | |
| 311 aborted_chain_size_(aborted_chain_size), | |
| 312 aborted_chain_size_same_url_(aborted_chain_size_same_url), | |
| 313 embedder_interface_(embedder_interface) { | |
| 314 DCHECK(!navigation_handle->HasCommitted()); | |
| 315 if (embedder_interface_->IsPrerendering( | |
| 316 navigation_handle->GetWebContents())) { | |
| 317 DCHECK(!started_in_foreground_); | |
| 318 // For the time being, we do not track prerenders. See crbug.com/648338 for | |
| 319 // details. | |
| 320 StopTracking(); | |
| 321 return; | |
| 322 } | |
| 323 | |
| 324 embedder_interface_->RegisterObservers(this); | |
| 325 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnStart, navigation_handle, | |
| 326 currently_committed_url, started_in_foreground_); | |
| 327 } | |
| 328 | |
| 329 PageLoadTracker::~PageLoadTracker() { | |
| 330 if (app_entered_background_) { | |
| 331 RecordAppBackgroundPageLoadCompleted(true); | |
| 332 } | |
| 333 | |
| 334 if (did_stop_tracking_) | |
| 335 return; | |
| 336 | |
| 337 if (committed_url_.is_empty()) { | |
| 338 if (!failed_provisional_load_info_) | |
| 339 RecordInternalError(ERR_NO_COMMIT_OR_FAILED_PROVISIONAL_LOAD); | |
| 340 | |
| 341 // Don't include any aborts that resulted in a new navigation, as the chain | |
| 342 // length will be included in the aborter PageLoadTracker. | |
| 343 if (abort_type_ != ABORT_RELOAD && abort_type_ != ABORT_FORWARD_BACK && | |
| 344 abort_type_ != ABORT_NEW_NAVIGATION) { | |
| 345 LogAbortChainHistograms(nullptr); | |
| 346 } | |
| 347 } else if (timing_.IsEmpty()) { | |
| 348 RecordInternalError(ERR_NO_IPCS_RECEIVED); | |
| 349 } | |
| 350 | |
| 351 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); | |
| 352 for (const auto& observer : observers_) { | |
| 353 if (failed_provisional_load_info_) { | |
| 354 observer->OnFailedProvisionalLoad(*failed_provisional_load_info_, info); | |
| 355 } else if (!info.committed_url.is_empty()) { | |
| 356 observer->OnComplete(timing_, info); | |
| 357 } | |
| 358 } | |
| 359 } | |
| 360 | |
| 361 void PageLoadTracker::LogAbortChainHistograms( | |
| 362 content::NavigationHandle* final_navigation) { | |
| 363 if (aborted_chain_size_ == 0) | |
| 364 return; | |
| 365 // Note that this could be broken out by this navigation's abort type, if more | |
| 366 // granularity is needed. Add one to the chain size to count the current | |
| 367 // navigation. In the other cases, the current navigation is the final | |
| 368 // navigation (which commits). | |
| 369 if (!final_navigation) { | |
| 370 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeNoCommit, | |
| 371 aborted_chain_size_ + 1); | |
| 372 LogAbortChainSameURLHistogram(aborted_chain_size_same_url_ + 1); | |
| 373 return; | |
| 374 } | |
| 375 | |
| 376 // The following is only executed for committing trackers. | |
| 377 DCHECK(!committed_url_.is_empty()); | |
| 378 | |
| 379 // Note that histograms could be separated out by this commit's transition | |
| 380 // type, but for simplicity they will all be bucketed together. | |
| 381 LogAbortChainSameURLHistogram(aborted_chain_size_same_url_); | |
| 382 | |
| 383 ui::PageTransition committed_transition = | |
| 384 final_navigation->GetPageTransition(); | |
| 385 switch (AbortTypeForPageTransition(committed_transition)) { | |
| 386 case ABORT_RELOAD: | |
| 387 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeReload, | |
| 388 aborted_chain_size_); | |
| 389 return; | |
| 390 case ABORT_FORWARD_BACK: | |
| 391 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeForwardBack, | |
| 392 aborted_chain_size_); | |
| 393 return; | |
| 394 // TODO(csharrison): Refactor this code so it is based on the WillStart* | |
| 395 // code path instead of the committed load code path. Then, for every abort | |
| 396 // chain, log a histogram of the counts of each of these metrics. For now, | |
| 397 // merge client redirects with new navigations, which was (basically) the | |
| 398 // previous behavior. | |
| 399 case ABORT_CLIENT_REDIRECT: | |
| 400 case ABORT_NEW_NAVIGATION: | |
| 401 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeNewNavigation, | |
| 402 aborted_chain_size_); | |
| 403 return; | |
| 404 default: | |
| 405 NOTREACHED() | |
| 406 << "LogAbortChainHistograms received unexpected ui::PageTransition: " | |
| 407 << committed_transition; | |
| 408 return; | |
| 409 } | |
| 410 } | |
| 411 | |
| 412 void PageLoadTracker::WebContentsHidden() { | |
| 413 // Only log the first time we background in a given page load. | |
| 414 if (background_time_.is_null()) { | |
| 415 // Make sure we either started in the foreground and haven't been | |
| 416 // foregrounded yet, or started in the background and have already been | |
| 417 // foregrounded. | |
| 418 DCHECK_EQ(started_in_foreground_, foreground_time_.is_null()); | |
| 419 background_time_ = base::TimeTicks::Now(); | |
| 420 ClampBrowserTimestampIfInterProcessTimeTickSkew(&background_time_); | |
| 421 // Though most cases where a tab is backgrounded are user initiated, we | |
| 422 // can't be certain that we were backgrounded due to a user action. For | |
| 423 // example, on Android, the screen times out after a period of inactivity, | |
| 424 // resulting in a non-user-initiated backgrounding. | |
| 425 const bool abort_is_user_initiated = false; | |
| 426 NotifyAbort(ABORT_BACKGROUND, abort_is_user_initiated, background_time_, | |
| 427 true); | |
| 428 } | |
| 429 | |
| 430 for (const auto& observer : observers_) | |
| 431 observer->OnHidden(); | |
| 432 } | |
| 433 | |
| 434 void PageLoadTracker::WebContentsShown() { | |
| 435 // Only log the first time we foreground in a given page load. | |
| 436 if (foreground_time_.is_null()) { | |
| 437 // Make sure we either started in the background and haven't been | |
| 438 // backgrounded yet, or started in the foreground and have already been | |
| 439 // backgrounded. | |
| 440 DCHECK_NE(started_in_foreground_, background_time_.is_null()); | |
| 441 foreground_time_ = base::TimeTicks::Now(); | |
| 442 ClampBrowserTimestampIfInterProcessTimeTickSkew(&foreground_time_); | |
| 443 } | |
| 444 | |
| 445 for (const auto& observer : observers_) | |
| 446 observer->OnShown(); | |
| 447 } | |
| 448 | |
| 449 void PageLoadTracker::Commit(content::NavigationHandle* navigation_handle) { | |
| 450 committed_url_ = navigation_handle->GetURL(); | |
| 451 // Some transitions (like CLIENT_REDIRECT) are only known at commit time. | |
| 452 page_transition_ = navigation_handle->GetPageTransition(); | |
| 453 user_gesture_ = navigation_handle->HasUserGesture(); | |
| 454 | |
| 455 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnCommit, navigation_handle); | |
| 456 LogAbortChainHistograms(navigation_handle); | |
| 457 } | |
| 458 | |
| 459 void PageLoadTracker::FailedProvisionalLoad( | |
| 460 content::NavigationHandle* navigation_handle) { | |
| 461 DCHECK(!failed_provisional_load_info_); | |
| 462 failed_provisional_load_info_.reset(new FailedProvisionalLoadInfo( | |
| 463 base::TimeTicks::Now() - navigation_handle->NavigationStart(), | |
| 464 navigation_handle->GetNetErrorCode())); | |
| 465 } | |
| 466 | |
| 467 void PageLoadTracker::Redirect(content::NavigationHandle* navigation_handle) { | |
| 468 for (const auto& observer : observers_) { | |
| 469 observer->OnRedirect(navigation_handle); | |
| 470 } | |
| 471 } | |
| 472 | |
| 473 void PageLoadTracker::OnInputEvent(const blink::WebInputEvent& event) { | |
| 474 for (const auto& observer : observers_) { | |
| 475 observer->OnUserInput(event); | |
| 476 } | |
| 477 } | |
| 478 | |
| 479 void PageLoadTracker::FlushMetricsOnAppEnterBackground() { | |
| 480 if (!app_entered_background_) { | |
| 481 RecordAppBackgroundPageLoadCompleted(false); | |
| 482 app_entered_background_ = true; | |
| 483 } | |
| 484 | |
| 485 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); | |
| 486 INVOKE_AND_PRUNE_OBSERVERS(observers_, FlushMetricsOnAppEnterBackground, | |
| 487 timing_, info); | |
| 488 } | |
| 489 | |
| 490 void PageLoadTracker::NotifyClientRedirectTo( | |
| 491 const PageLoadTracker& destination) { | |
| 492 if (timing_.first_paint) { | |
| 493 base::TimeTicks first_paint_time = | |
| 494 navigation_start() + timing_.first_paint.value(); | |
| 495 base::TimeDelta first_paint_to_navigation; | |
| 496 if (destination.navigation_start() > first_paint_time) | |
| 497 first_paint_to_navigation = | |
| 498 destination.navigation_start() - first_paint_time; | |
| 499 PAGE_LOAD_HISTOGRAM(internal::kClientRedirectFirstPaintToNavigation, | |
| 500 first_paint_to_navigation); | |
| 501 } else { | |
| 502 UMA_HISTOGRAM_BOOLEAN(internal::kClientRedirectWithoutPaint, true); | |
| 503 } | |
| 504 } | |
| 505 | |
| 506 bool PageLoadTracker::UpdateTiming(const PageLoadTiming& new_timing, | |
| 507 const PageLoadMetadata& new_metadata) { | |
| 508 // Throw away IPCs that are not relevant to the current navigation. | |
| 509 // Two timing structures cannot refer to the same navigation if they indicate | |
| 510 // that a navigation started at different times, so a new timing struct with a | |
| 511 // different start time from an earlier struct is considered invalid. | |
| 512 bool valid_timing_descendent = | |
| 513 timing_.navigation_start.is_null() || | |
| 514 timing_.navigation_start == new_timing.navigation_start; | |
| 515 // Ensure flags sent previously are still present in the new metadata fields. | |
| 516 bool valid_behavior_descendent = | |
| 517 (metadata_.behavior_flags & new_metadata.behavior_flags) == | |
| 518 metadata_.behavior_flags; | |
| 519 if (IsValidPageLoadTiming(new_timing) && valid_timing_descendent && | |
| 520 valid_behavior_descendent) { | |
| 521 DCHECK(!committed_url_.is_empty()); // OnCommit() must be called first. | |
| 522 // There are some subtle ordering constraints here. GetPageLoadMetricsInfo() | |
| 523 // must be called before DispatchObserverTimingCallbacks, but its | |
| 524 // implementation depends on the state of metadata_, so we need to update | |
| 525 // metadata_ before calling GetPageLoadMetricsInfo. Thus, we make a copy of | |
| 526 // timing here, update timing_ and metadata_, and then proceed to dispatch | |
| 527 // the observer timing callbacks. | |
| 528 const PageLoadTiming last_timing = timing_; | |
| 529 timing_ = new_timing; | |
| 530 | |
| 531 const PageLoadMetadata last_metadata = metadata_; | |
| 532 metadata_ = new_metadata; | |
| 533 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); | |
| 534 for (const auto& observer : observers_) { | |
| 535 DispatchObserverTimingCallbacks(observer.get(), last_timing, new_timing, | |
| 536 last_metadata, info); | |
| 537 } | |
| 538 return true; | |
| 539 } | |
| 540 return false; | |
| 541 } | |
| 542 | |
| 543 void PageLoadTracker::OnLoadedSubresource(bool was_cached) { | |
| 544 if (was_cached) { | |
| 545 ++num_cache_requests_; | |
| 546 } else { | |
| 547 ++num_network_requests_; | |
| 548 } | |
| 549 } | |
| 550 | |
| 551 void PageLoadTracker::StopTracking() { | |
| 552 did_stop_tracking_ = true; | |
| 553 observers_.clear(); | |
| 554 } | |
| 555 | |
| 556 void PageLoadTracker::AddObserver( | |
| 557 std::unique_ptr<PageLoadMetricsObserver> observer) { | |
| 558 observers_.push_back(std::move(observer)); | |
| 559 } | |
| 560 | |
| 561 void PageLoadTracker::ClampBrowserTimestampIfInterProcessTimeTickSkew( | |
| 562 base::TimeTicks* event_time) { | |
| 563 DCHECK(event_time != nullptr); | |
| 564 // Windows 10 GCE bot non-deterministically failed because TimeTicks::Now() | |
| 565 // called in the browser process e.g. commit_time was less than | |
| 566 // navigation_start_ that was populated in the renderer process because the | |
| 567 // clock was not system-wide monotonic. | |
| 568 // Note that navigation_start_ can also be set in the browser process in | |
| 569 // some cases and in those cases event_time should never be < | |
| 570 // navigation_start_. If it is due to a code error and it gets clamped in this | |
| 571 // function, on high resolution systems it should lead to a dcheck failure. | |
| 572 | |
| 573 // TODO(shivanisha): Currently IsHighResolution is the best way to check | |
| 574 // if the clock is system-wide monotonic. However IsHighResolution | |
| 575 // does a broader check to see if the clock in use is high resolution | |
| 576 // which also implies it is system-wide monotonic (on Windows). | |
| 577 if (base::TimeTicks::IsHighResolution()) { | |
| 578 DCHECK(event_time->is_null() || *event_time >= navigation_start_); | |
| 579 return; | |
| 580 } | |
| 581 | |
| 582 if (!event_time->is_null() && *event_time < navigation_start_) { | |
| 583 RecordInternalError(ERR_INTER_PROCESS_TIME_TICK_SKEW); | |
| 584 *event_time = navigation_start_; | |
| 585 } | |
| 586 } | |
| 587 | |
| 588 PageLoadExtraInfo PageLoadTracker::ComputePageLoadExtraInfo() { | |
| 589 base::Optional<base::TimeDelta> first_background_time; | |
| 590 base::Optional<base::TimeDelta> first_foreground_time; | |
| 591 base::Optional<base::TimeDelta> time_to_abort; | |
| 592 | |
| 593 if (!background_time_.is_null()) { | |
| 594 DCHECK_GE(background_time_, navigation_start_); | |
| 595 first_background_time = background_time_ - navigation_start_; | |
| 596 } | |
| 597 | |
| 598 if (!foreground_time_.is_null()) { | |
| 599 DCHECK_GE(foreground_time_, navigation_start_); | |
| 600 first_foreground_time = foreground_time_ - navigation_start_; | |
| 601 } | |
| 602 | |
| 603 if (abort_type_ != ABORT_NONE) { | |
| 604 DCHECK_GE(abort_time_, navigation_start_); | |
| 605 time_to_abort = abort_time_ - navigation_start_; | |
| 606 } else { | |
| 607 DCHECK(abort_time_.is_null()); | |
| 608 } | |
| 609 | |
| 610 // abort_type_ == ABORT_NONE implies !abort_user_initiated_. | |
| 611 DCHECK(abort_type_ != ABORT_NONE || !abort_user_initiated_); | |
| 612 return PageLoadExtraInfo( | |
| 613 first_background_time, first_foreground_time, started_in_foreground_, | |
| 614 user_gesture_, committed_url_, start_url_, abort_type_, | |
| 615 abort_user_initiated_, time_to_abort, num_cache_requests_, | |
| 616 num_network_requests_, metadata_); | |
| 617 } | |
| 618 | |
| 619 void PageLoadTracker::NotifyAbort(UserAbortType abort_type, | |
| 620 bool user_initiated, | |
| 621 base::TimeTicks timestamp, | |
| 622 bool is_certainly_browser_timestamp) { | |
| 623 DCHECK_NE(abort_type, ABORT_NONE); | |
| 624 // Use UpdateAbort to update an already notified PageLoadTracker. | |
| 625 if (abort_type_ != ABORT_NONE) | |
| 626 return; | |
| 627 | |
| 628 UpdateAbortInternal(abort_type, user_initiated, timestamp, | |
| 629 is_certainly_browser_timestamp); | |
| 630 } | |
| 631 | |
| 632 void PageLoadTracker::UpdateAbort(UserAbortType abort_type, | |
| 633 bool user_initiated, | |
| 634 base::TimeTicks timestamp, | |
| 635 bool is_certainly_browser_timestamp) { | |
| 636 DCHECK_NE(abort_type, ABORT_NONE); | |
| 637 DCHECK_NE(abort_type, ABORT_OTHER); | |
| 638 DCHECK_EQ(abort_type_, ABORT_OTHER); | |
| 639 | |
| 640 // For some aborts (e.g. navigations), the initiated timestamp can be earlier | |
| 641 // than the timestamp that aborted the load. Taking the minimum gives the | |
| 642 // closest user initiated time known. | |
| 643 UpdateAbortInternal(abort_type, user_initiated, | |
| 644 std::min(abort_time_, timestamp), | |
| 645 is_certainly_browser_timestamp); | |
| 646 } | |
| 647 | |
| 648 bool PageLoadTracker::IsLikelyProvisionalAbort( | |
| 649 base::TimeTicks abort_cause_time) const { | |
| 650 // Note that |abort_cause_time - abort_time| can be negative. | |
| 651 return abort_type_ == ABORT_OTHER && | |
| 652 (abort_cause_time - abort_time_).InMilliseconds() < 100; | |
| 653 } | |
| 654 | |
| 655 bool PageLoadTracker::MatchesOriginalNavigation( | |
| 656 content::NavigationHandle* navigation_handle) { | |
| 657 // Neither navigation should have committed. | |
| 658 DCHECK(!navigation_handle->HasCommitted()); | |
| 659 DCHECK(committed_url_.is_empty()); | |
| 660 return navigation_handle->GetURL() == start_url_; | |
| 661 } | |
| 662 | |
| 663 void PageLoadTracker::UpdateAbortInternal(UserAbortType abort_type, | |
| 664 bool user_initiated, | |
| 665 base::TimeTicks timestamp, | |
| 666 bool is_certainly_browser_timestamp) { | |
| 667 // When a provisional navigation commits, that navigation's start time is | |
| 668 // interpreted as the abort time for other provisional loads in the tab. | |
| 669 // However, this only makes sense if the committed load started after the | |
| 670 // aborted provisional loads started. Thus we ignore cases where the committed | |
| 671 // load started before the aborted provisional load, as this would result in | |
| 672 // recording a negative time-to-abort. The real issue here is that we have to | |
| 673 // infer the cause of aborts. It would be better if the navigation code could | |
| 674 // instead report the actual cause of an aborted navigation. See crbug/571647 | |
| 675 // for details. | |
| 676 if (timestamp < navigation_start_) { | |
| 677 RecordInternalError(ERR_ABORT_BEFORE_NAVIGATION_START); | |
| 678 abort_type_ = ABORT_NONE; | |
| 679 abort_time_ = base::TimeTicks(); | |
| 680 return; | |
| 681 } | |
| 682 abort_type_ = abort_type; | |
| 683 abort_time_ = timestamp; | |
| 684 abort_user_initiated_ = user_initiated && abort_type != ABORT_CLIENT_REDIRECT; | |
| 685 | |
| 686 if (is_certainly_browser_timestamp) { | |
| 687 ClampBrowserTimestampIfInterProcessTimeTickSkew(&abort_time_); | |
| 688 } | |
| 689 } | |
| 690 | |
| 691 // static | 51 // static |
| 692 MetricsWebContentsObserver::MetricsWebContentsObserver( | 52 MetricsWebContentsObserver::MetricsWebContentsObserver( |
| 693 content::WebContents* web_contents, | 53 content::WebContents* web_contents, |
| 694 std::unique_ptr<PageLoadMetricsEmbedderInterface> embedder_interface) | 54 std::unique_ptr<PageLoadMetricsEmbedderInterface> embedder_interface) |
| 695 : content::WebContentsObserver(web_contents), | 55 : content::WebContentsObserver(web_contents), |
| 696 in_foreground_(false), | 56 in_foreground_(false), |
| 697 embedder_interface_(std::move(embedder_interface)), | 57 embedder_interface_(std::move(embedder_interface)), |
| 698 has_navigated_(false) { | 58 has_navigated_(false) { |
| 699 RegisterInputEventObserver(web_contents->GetRenderViewHost()); | 59 RegisterInputEventObserver(web_contents->GetRenderViewHost()); |
| 700 } | 60 } |
| (...skipping 389 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 1090 content::NavigationHandle* navigation_handle) const { | 450 content::NavigationHandle* navigation_handle) const { |
| 1091 DCHECK(navigation_handle->IsInMainFrame()); | 451 DCHECK(navigation_handle->IsInMainFrame()); |
| 1092 DCHECK(!navigation_handle->HasCommitted() || | 452 DCHECK(!navigation_handle->HasCommitted() || |
| 1093 !navigation_handle->IsSamePage()); | 453 !navigation_handle->IsSamePage()); |
| 1094 | 454 |
| 1095 return BrowserPageTrackDecider(embedder_interface_.get(), web_contents(), | 455 return BrowserPageTrackDecider(embedder_interface_.get(), web_contents(), |
| 1096 navigation_handle).ShouldTrack(); | 456 navigation_handle).ShouldTrack(); |
| 1097 } | 457 } |
| 1098 | 458 |
| 1099 } // namespace page_load_metrics | 459 } // namespace page_load_metrics |
| OLD | NEW |