Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(36)

Side by Side Diff: chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.cc

Issue 2904533002: Factor management of metrics updates into its own class. (Closed)
Patch Set: address comment Created 3 years, 7 months ago
Use n/p to move between diff chunks; N/P to move between comments. Draft comments are only viewable by you.
Jump to:
View unified diff | Download patch
OLDNEW
1 // Copyright 2016 The Chromium Authors. All rights reserved. 1 // Copyright 2017 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/page_load_tracker.h" 5 #include "chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.h "
6 6
7 #include <algorithm>
8 #include <ostream>
Charlie Harrison 2017/05/24 21:02:51 shouldn't be removed
Bryan McQuade 2017/05/25 02:30:21 done
9 #include <string>
10 #include <utility> 7 #include <utility>
11 8
12 #include "base/logging.h"
Charlie Harrison 2017/05/24 21:02:51 shouldn't be removed
Bryan McQuade 2017/05/25 02:30:21 done
13 #include "base/memory/ptr_util.h"
14 #include "base/metrics/histogram_macros.h"
Charlie Harrison 2017/05/24 21:02:51 We're still using UMA_HISTOGRAM_ENUMERATION
Bryan McQuade 2017/05/25 02:30:21 done
15 #include "chrome/browser/page_load_metrics/browser_page_track_decider.h" 9 #include "chrome/browser/page_load_metrics/browser_page_track_decider.h"
16 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface. h" 10 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface. h"
17 #include "chrome/browser/page_load_metrics/page_load_metrics_util.h" 11 #include "chrome/browser/page_load_metrics/page_load_metrics_util.h"
18 #include "chrome/browser/prerender/prerender_contents.h" 12 #include "chrome/browser/page_load_metrics/page_load_tracker.h"
19 #include "chrome/common/page_load_metrics/page_load_timing.h" 13 #include "chrome/common/page_load_metrics/page_load_metrics_util.h"
20 #include "content/public/browser/navigation_details.h"
21 #include "content/public/browser/navigation_handle.h" 14 #include "content/public/browser/navigation_handle.h"
22 #include "content/public/browser/render_frame_host.h" 15 #include "content/public/browser/render_frame_host.h"
23 #include "content/public/browser/web_contents.h"
24 #include "content/public/browser/web_contents_observer.h"
25 #include "content/public/common/browser_side_navigation_policy.h"
26 #include "ui/base/page_transition_types.h"
27
28 // This macro invokes the specified method on each observer, passing the
29 // variable length arguments as the method's arguments, and removes the observer
30 // from the list of observers if the given method returns STOP_OBSERVING.
31 #define INVOKE_AND_PRUNE_OBSERVERS(observers, Method, ...) \
32 for (auto it = observers.begin(); it != observers.end();) { \
33 if ((*it)->Method(__VA_ARGS__) == \
34 PageLoadMetricsObserver::STOP_OBSERVING) { \
35 it = observers.erase(it); \
36 } else { \
37 ++it; \
38 } \
39 }
40 16
41 namespace page_load_metrics { 17 namespace page_load_metrics {
42 18
43 namespace internal { 19 namespace internal {
44 20
45 const char kErrorEvents[] = "PageLoad.Internal.ErrorCode";
46 const char kAbortChainSizeReload[] =
47 "PageLoad.Internal.ProvisionalAbortChainSize.Reload";
48 const char kAbortChainSizeForwardBack[] =
49 "PageLoad.Internal.ProvisionalAbortChainSize.ForwardBack";
50 const char kAbortChainSizeNewNavigation[] =
51 "PageLoad.Internal.ProvisionalAbortChainSize.NewNavigation";
52 const char kAbortChainSizeSameURL[] =
53 "PageLoad.Internal.ProvisionalAbortChainSize.SameURL";
54 const char kAbortChainSizeNoCommit[] =
55 "PageLoad.Internal.ProvisionalAbortChainSize.NoCommit";
56 const char kClientRedirectFirstPaintToNavigation[] =
57 "PageLoad.Internal.ClientRedirect.FirstPaintToNavigation";
58 const char kClientRedirectWithoutPaint[] =
59 "PageLoad.Internal.ClientRedirect.NavigationWithoutPaint";
60 const char kPageLoadCompletedAfterAppBackground[] =
61 "PageLoad.Internal.PageLoadCompleted.AfterAppBackground";
62 const char kPageLoadStartedInForeground[] =
63 "PageLoad.Internal.NavigationStartedInForeground";
64 const char kPageLoadPrerender[] = "PageLoad.Internal.Prerender";
65 const char kPageLoadTimingStatus[] = "PageLoad.Internal.PageLoadTimingStatus"; 21 const char kPageLoadTimingStatus[] = "PageLoad.Internal.PageLoadTimingStatus";
66 const char kPageLoadTimingDispatchStatus[] = 22 const char kPageLoadTimingDispatchStatus[] =
67 "PageLoad.Internal.PageLoadTimingStatus.AtTimingCallbackDispatch"; 23 "PageLoad.Internal.PageLoadTimingStatus.AtTimingCallbackDispatch";
68 24
69 } // namespace internal 25 } // namespace internal
70 26
71 void RecordInternalError(InternalErrorLoadEvent event) {
72 UMA_HISTOGRAM_ENUMERATION(internal::kErrorEvents, event, ERR_LAST_ENTRY);
73 }
74
75 // TODO(csharrison): Add a case for client side redirects, which is what JS
76 // initiated window.location / window.history navigations get set to.
77 PageEndReason EndReasonForPageTransition(ui::PageTransition transition) {
78 if (transition & ui::PAGE_TRANSITION_CLIENT_REDIRECT) {
79 return END_CLIENT_REDIRECT;
80 }
81 if (ui::PageTransitionCoreTypeIs(transition, ui::PAGE_TRANSITION_RELOAD))
82 return END_RELOAD;
83 if (transition & ui::PAGE_TRANSITION_FORWARD_BACK)
84 return END_FORWARD_BACK;
85 if (ui::PageTransitionIsNewNavigation(transition))
86 return END_NEW_NAVIGATION;
87 NOTREACHED()
88 << "EndReasonForPageTransition received unexpected ui::PageTransition: "
89 << transition;
90 return END_OTHER;
91 }
92
93 void LogAbortChainSameURLHistogram(int aborted_chain_size_same_url) {
94 if (aborted_chain_size_same_url > 0) {
95 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeSameURL,
96 aborted_chain_size_same_url);
97 }
98 }
99
100 bool IsNavigationUserInitiated(content::NavigationHandle* handle) {
101 // TODO(crbug.com/617904): Browser initiated navigations should have
102 // HasUserGesture() set to true. In the meantime, we consider all
103 // browser-initiated navigations to be user initiated.
104 //
105 // TODO(crbug.com/637345): Some browser-initiated navigations incorrectly
106 // report that they are renderer-initiated. We will currently report that
107 // these navigations are not user initiated, when in fact they are user
108 // initiated.
109 return handle->HasUserGesture() || !handle->IsRendererInitiated();
110 }
111
112 namespace { 27 namespace {
113 28
114 // Helper to allow use of Optional<> values in LOG() messages. 29 // Helper to allow use of Optional<> values in LOG() messages.
115 std::ostream& operator<<(std::ostream& os, 30 std::ostream& operator<<(std::ostream& os,
116 const base::Optional<base::TimeDelta>& opt) { 31 const base::Optional<base::TimeDelta>& opt) {
Charlie Harrison 2017/05/24 21:02:51 include optional
117 if (opt) 32 if (opt)
118 os << opt.value(); 33 os << opt.value();
119 else 34 else
120 os << "(unset)"; 35 os << "(unset)";
121 return os; 36 return os;
122 } 37 }
123 38
124 // If second is non-zero, first must also be non-zero and less than or equal to 39 // If second is non-zero, first must also be non-zero and less than or equal to
125 // second. 40 // second.
126 bool EventsInOrder(const base::Optional<base::TimeDelta>& first, 41 bool EventsInOrder(const base::Optional<base::TimeDelta>& first,
(...skipping 182 matching lines...) Expand 10 before | Expand all | Expand 10 after
309 // occasionally, as inter-frame updates can arrive out of order. Record a 224 // occasionally, as inter-frame updates can arrive out of order. Record a
310 // histogram to track how frequently it happens, along with the magnitude 225 // histogram to track how frequently it happens, along with the magnitude
311 // of the delta. 226 // of the delta.
312 PAGE_LOAD_HISTOGRAM("PageLoad.Internal.OutOfOrderInterFrameTiming", 227 PAGE_LOAD_HISTOGRAM("PageLoad.Internal.OutOfOrderInterFrameTiming",
313 inout_existing_value->value() - candidate_new_value); 228 inout_existing_value->value() - candidate_new_value);
314 } 229 }
315 230
316 *inout_existing_value = candidate_new_value; 231 *inout_existing_value = candidate_new_value;
317 } 232 }
318 233
319 void RecordAppBackgroundPageLoadCompleted(bool completed_after_background) {
320 UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadCompletedAfterAppBackground,
321 completed_after_background);
322 }
323
324 void DispatchObserverTimingCallbacks(
325 PageLoadMetricsObserver* observer,
326 const mojom::PageLoadTiming& last_timing,
327 const mojom::PageLoadTiming& new_timing,
328 const mojom::PageLoadMetadata& last_metadata,
329 const PageLoadExtraInfo& extra_info) {
330 if (extra_info.main_frame_metadata.behavior_flags !=
331 last_metadata.behavior_flags)
332 observer->OnLoadingBehaviorObserved(extra_info);
333 if (!last_timing.Equals(new_timing))
334 observer->OnTimingUpdate(new_timing, extra_info);
335 if (new_timing.document_timing->dom_content_loaded_event_start &&
336 !last_timing.document_timing->dom_content_loaded_event_start)
337 observer->OnDomContentLoadedEventStart(new_timing, extra_info);
338 if (new_timing.document_timing->load_event_start &&
339 !last_timing.document_timing->load_event_start)
340 observer->OnLoadEventStart(new_timing, extra_info);
341 if (new_timing.document_timing->first_layout &&
342 !last_timing.document_timing->first_layout)
343 observer->OnFirstLayout(new_timing, extra_info);
344 if (new_timing.paint_timing->first_paint &&
345 !last_timing.paint_timing->first_paint)
346 observer->OnFirstPaintInPage(new_timing, extra_info);
347 if (new_timing.paint_timing->first_text_paint &&
348 !last_timing.paint_timing->first_text_paint)
349 observer->OnFirstTextPaintInPage(new_timing, extra_info);
350 if (new_timing.paint_timing->first_image_paint &&
351 !last_timing.paint_timing->first_image_paint)
352 observer->OnFirstImagePaintInPage(new_timing, extra_info);
353 if (new_timing.paint_timing->first_contentful_paint &&
354 !last_timing.paint_timing->first_contentful_paint)
355 observer->OnFirstContentfulPaintInPage(new_timing, extra_info);
356 if (new_timing.paint_timing->first_meaningful_paint &&
357 !last_timing.paint_timing->first_meaningful_paint)
358 observer->OnFirstMeaningfulPaintInMainFrameDocument(new_timing, extra_info);
359 if (new_timing.parse_timing->parse_start &&
360 !last_timing.parse_timing->parse_start)
361 observer->OnParseStart(new_timing, extra_info);
362 if (new_timing.parse_timing->parse_stop &&
363 !last_timing.parse_timing->parse_stop)
364 observer->OnParseStop(new_timing, extra_info);
365 }
366
367 } // namespace 234 } // namespace
368 235
369 PageLoadTracker::PageLoadTracker( 236 PageLoadMetricsUpdateDispatcher::PageLoadMetricsUpdateDispatcher(
370 bool in_foreground, 237 PageLoadMetricsUpdateDispatcher::Client* client,
371 PageLoadMetricsEmbedderInterface* embedder_interface,
372 const GURL& currently_committed_url,
373 content::NavigationHandle* navigation_handle, 238 content::NavigationHandle* navigation_handle,
374 UserInitiatedInfo user_initiated_info, 239 PageLoadMetricsEmbedderInterface* embedder_interface)
375 int aborted_chain_size, 240 : client_(client),
376 int aborted_chain_size_same_url) 241 embedder_interface_(embedder_interface),
377 : did_stop_tracking_(false),
378 app_entered_background_(false),
379 navigation_start_(navigation_handle->NavigationStart()), 242 navigation_start_(navigation_handle->NavigationStart()),
380 url_(navigation_handle->GetURL()), 243 current_merged_page_timing_(CreatePageLoadTiming()),
381 start_url_(navigation_handle->GetURL()), 244 pending_merged_page_timing_(CreatePageLoadTiming()),
382 did_commit_(false), 245 main_frame_metadata_(mojom::PageLoadMetadata::New()),
383 page_end_reason_(END_NONE), 246 subframe_metadata_(mojom::PageLoadMetadata::New()) {}
384 page_end_user_initiated_info_(UserInitiatedInfo::NotUserInitiated()),
385 started_in_foreground_(in_foreground),
386 merged_page_timing_(CreatePageLoadTiming()),
387 last_dispatched_merged_page_timing_(CreatePageLoadTiming()),
388 last_dispatched_main_frame_metadata_(mojom::PageLoadMetadata::New()),
389 page_transition_(navigation_handle->GetPageTransition()),
390 user_initiated_info_(user_initiated_info),
391 aborted_chain_size_(aborted_chain_size),
392 aborted_chain_size_same_url_(aborted_chain_size_same_url),
393 embedder_interface_(embedder_interface) {
394 DCHECK(!navigation_handle->HasCommitted());
395 embedder_interface_->RegisterObservers(this);
396 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnStart, navigation_handle,
397 currently_committed_url, started_in_foreground_);
398 247
399 UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadStartedInForeground, 248 PageLoadMetricsUpdateDispatcher::~PageLoadMetricsUpdateDispatcher() {}
400 started_in_foreground_); 249
401 const bool is_prerender = prerender::PrerenderContents::FromWebContents( 250 void PageLoadMetricsUpdateDispatcher::UpdateMetrics(
402 navigation_handle->GetWebContents()) != nullptr; 251 content::RenderFrameHost* render_frame_host,
403 if (is_prerender) { 252 const mojom::PageLoadTiming& new_timing,
404 UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadPrerender, true); 253 const mojom::PageLoadMetadata& new_metadata) {
254 if (render_frame_host->GetParent() == nullptr) {
255 UpdateMainFrameMetadata(new_metadata);
256 UpdateMainFrameTiming(new_timing);
257 } else {
258 UpdateSubFrameMetadata(new_metadata);
259 UpdateSubFrameTiming(render_frame_host, new_timing);
405 } 260 }
406 } 261 }
407 262
408 PageLoadTracker::~PageLoadTracker() { 263 void PageLoadMetricsUpdateDispatcher::DidFinishSubFrameNavigation(
409 if (app_entered_background_) {
410 RecordAppBackgroundPageLoadCompleted(true);
411 }
412
413 if (did_stop_tracking_)
414 return;
415
416 if (page_end_time_.is_null()) {
417 // page_end_time_ can be unset in some cases, such as when a navigation is
418 // aborted by a navigation that started before it. In these cases, set the
419 // end time to the current time.
420 RecordInternalError(ERR_NO_PAGE_LOAD_END_TIME);
421 NotifyPageEnd(END_OTHER, UserInitiatedInfo::NotUserInitiated(),
422 base::TimeTicks::Now(), true);
423 }
424
425 if (!did_commit_) {
426 if (!failed_provisional_load_info_)
427 RecordInternalError(ERR_NO_COMMIT_OR_FAILED_PROVISIONAL_LOAD);
428
429 // Don't include any aborts that resulted in a new navigation, as the chain
430 // length will be included in the aborter PageLoadTracker.
431 if (page_end_reason_ != END_RELOAD &&
432 page_end_reason_ != END_FORWARD_BACK &&
433 page_end_reason_ != END_NEW_NAVIGATION) {
434 LogAbortChainHistograms(nullptr);
435 }
436 } else if (page_load_metrics::IsEmpty(*merged_page_timing_)) {
437 RecordInternalError(ERR_NO_IPCS_RECEIVED);
438 }
439
440 const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
441 for (const auto& observer : observers_) {
442 if (failed_provisional_load_info_) {
443 observer->OnFailedProvisionalLoad(*failed_provisional_load_info_, info);
444 } else if (did_commit_) {
445 observer->OnComplete(*merged_page_timing_, info);
446 }
447 }
448 }
449
450 void PageLoadTracker::LogAbortChainHistograms(
451 content::NavigationHandle* final_navigation) {
452 if (aborted_chain_size_ == 0)
453 return;
454 // Note that this could be broken out by this navigation's abort type, if more
455 // granularity is needed. Add one to the chain size to count the current
456 // navigation. In the other cases, the current navigation is the final
457 // navigation (which commits).
458 if (!final_navigation) {
459 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeNoCommit,
460 aborted_chain_size_ + 1);
461 LogAbortChainSameURLHistogram(aborted_chain_size_same_url_ + 1);
462 return;
463 }
464
465 // The following is only executed for committing trackers.
466 DCHECK(did_commit_);
467
468 // Note that histograms could be separated out by this commit's transition
469 // type, but for simplicity they will all be bucketed together.
470 LogAbortChainSameURLHistogram(aborted_chain_size_same_url_);
471
472 ui::PageTransition committed_transition =
473 final_navigation->GetPageTransition();
474 switch (EndReasonForPageTransition(committed_transition)) {
475 case END_RELOAD:
476 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeReload,
477 aborted_chain_size_);
478 return;
479 case END_FORWARD_BACK:
480 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeForwardBack,
481 aborted_chain_size_);
482 return;
483 // TODO(csharrison): Refactor this code so it is based on the WillStart*
484 // code path instead of the committed load code path. Then, for every abort
485 // chain, log a histogram of the counts of each of these metrics. For now,
486 // merge client redirects with new navigations, which was (basically) the
487 // previous behavior.
488 case END_CLIENT_REDIRECT:
489 case END_NEW_NAVIGATION:
490 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeNewNavigation,
491 aborted_chain_size_);
492 return;
493 default:
494 NOTREACHED()
495 << "LogAbortChainHistograms received unexpected ui::PageTransition: "
496 << committed_transition;
497 return;
498 }
499 }
500
501 void PageLoadTracker::WebContentsHidden() {
502 // Only log the first time we background in a given page load.
503 if (background_time_.is_null()) {
504 // Make sure we either started in the foreground and haven't been
505 // foregrounded yet, or started in the background and have already been
506 // foregrounded.
507 DCHECK_EQ(started_in_foreground_, foreground_time_.is_null());
508 background_time_ = base::TimeTicks::Now();
509 ClampBrowserTimestampIfInterProcessTimeTickSkew(&background_time_);
510 }
511 const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
512 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnHidden, *merged_page_timing_, info);
513 }
514
515 void PageLoadTracker::WebContentsShown() {
516 // Only log the first time we foreground in a given page load.
517 if (foreground_time_.is_null()) {
518 // Make sure we either started in the background and haven't been
519 // backgrounded yet, or started in the foreground and have already been
520 // backgrounded.
521 DCHECK_NE(started_in_foreground_, background_time_.is_null());
522 foreground_time_ = base::TimeTicks::Now();
523 ClampBrowserTimestampIfInterProcessTimeTickSkew(&foreground_time_);
524 }
525
526 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnShown);
527 }
528
529 void PageLoadTracker::WillProcessNavigationResponse(
530 content::NavigationHandle* navigation_handle) { 264 content::NavigationHandle* navigation_handle) {
531 DCHECK(!navigation_request_id_.has_value());
532 navigation_request_id_ = navigation_handle->GetGlobalRequestID();
533 DCHECK(navigation_request_id_.value() != content::GlobalRequestID());
534 }
535
536 void PageLoadTracker::Commit(content::NavigationHandle* navigation_handle) {
537 did_commit_ = true;
538 url_ = navigation_handle->GetURL();
539 // Some transitions (like CLIENT_REDIRECT) are only known at commit time.
540 page_transition_ = navigation_handle->GetPageTransition();
541 user_initiated_info_.user_gesture = navigation_handle->HasUserGesture();
542
543 INVOKE_AND_PRUNE_OBSERVERS(
544 observers_, ShouldObserveMimeType,
545 navigation_handle->GetWebContents()->GetContentsMimeType());
546
547 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnCommit, navigation_handle);
548 LogAbortChainHistograms(navigation_handle);
549 }
550
551 void PageLoadTracker::DidCommitSameDocumentNavigation(
552 content::NavigationHandle* navigation_handle) {
553 for (const auto& observer : observers_) {
554 observer->OnCommitSameDocumentNavigation(navigation_handle);
555 }
556 }
557
558 void PageLoadTracker::DidFinishSubFrameNavigation(
559 content::NavigationHandle* navigation_handle) {
560 for (const auto& observer : observers_) {
561 observer->OnDidFinishSubFrameNavigation(navigation_handle);
562 }
563
564 if (!navigation_handle->HasCommitted()) 265 if (!navigation_handle->HasCommitted())
565 return; 266 return;
566 267
567 // We have a new committed navigation, so discard information about the 268 // We have a new committed navigation, so discard information about the
568 // previously committed navigation. 269 // previously committed navigation.
569 subframe_navigation_start_offset_.erase( 270 subframe_navigation_start_offset_.erase(
570 navigation_handle->GetFrameTreeNodeId()); 271 navigation_handle->GetFrameTreeNodeId());
571 272
572 BrowserPageTrackDecider decider(embedder_interface_, 273 BrowserPageTrackDecider decider(embedder_interface_,
573 navigation_handle->GetWebContents(), 274 navigation_handle->GetWebContents(),
574 navigation_handle); 275 navigation_handle);
575 if (!decider.ShouldTrack()) 276 if (!decider.ShouldTrack())
576 return; 277 return;
577 278
578 if (navigation_start_ > navigation_handle->NavigationStart()) { 279 if (navigation_start_ > navigation_handle->NavigationStart()) {
579 RecordInternalError(ERR_SUBFRAME_NAVIGATION_START_BEFORE_MAIN_FRAME); 280 RecordInternalError(ERR_SUBFRAME_NAVIGATION_START_BEFORE_MAIN_FRAME);
580 return; 281 return;
581 } 282 }
582 base::TimeDelta navigation_delta = 283 base::TimeDelta navigation_delta =
583 navigation_handle->NavigationStart() - navigation_start_; 284 navigation_handle->NavigationStart() - navigation_start_;
584 subframe_navigation_start_offset_.insert(std::make_pair( 285 subframe_navigation_start_offset_.insert(std::make_pair(
585 navigation_handle->GetFrameTreeNodeId(), navigation_delta)); 286 navigation_handle->GetFrameTreeNodeId(), navigation_delta));
586 } 287 }
587 288
588 void PageLoadTracker::FailedProvisionalLoad( 289 void PageLoadMetricsUpdateDispatcher::UpdateSubFrameTiming(
589 content::NavigationHandle* navigation_handle,
590 base::TimeTicks failed_load_time) {
591 DCHECK(!failed_provisional_load_info_);
592 failed_provisional_load_info_.reset(new FailedProvisionalLoadInfo(
593 failed_load_time - navigation_handle->NavigationStart(),
594 navigation_handle->GetNetErrorCode()));
595 }
596
597 void PageLoadTracker::Redirect(content::NavigationHandle* navigation_handle) {
598 url_ = navigation_handle->GetURL();
599 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnRedirect, navigation_handle);
600 }
601
602 void PageLoadTracker::OnInputEvent(const blink::WebInputEvent& event) {
603 input_tracker_.OnInputEvent(event);
604 for (const auto& observer : observers_) {
605 observer->OnUserInput(event);
606 }
607 }
608
609 void PageLoadTracker::FlushMetricsOnAppEnterBackground() {
610 if (!app_entered_background_) {
611 RecordAppBackgroundPageLoadCompleted(false);
612 app_entered_background_ = true;
613 }
614
615 const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
616 INVOKE_AND_PRUNE_OBSERVERS(observers_, FlushMetricsOnAppEnterBackground,
617 *merged_page_timing_, info);
618 }
619
620 void PageLoadTracker::NotifyClientRedirectTo(
621 const PageLoadTracker& destination) {
622 if (merged_page_timing_->paint_timing->first_paint) {
623 base::TimeTicks first_paint_time =
624 navigation_start() +
625 merged_page_timing_->paint_timing->first_paint.value();
626 base::TimeDelta first_paint_to_navigation;
627 if (destination.navigation_start() > first_paint_time)
628 first_paint_to_navigation =
629 destination.navigation_start() - first_paint_time;
630 PAGE_LOAD_HISTOGRAM(internal::kClientRedirectFirstPaintToNavigation,
631 first_paint_to_navigation);
632 } else {
633 UMA_HISTOGRAM_BOOLEAN(internal::kClientRedirectWithoutPaint, true);
634 }
635 }
636
637 void PageLoadTracker::UpdateSubFrameTiming(
638 content::RenderFrameHost* render_frame_host, 290 content::RenderFrameHost* render_frame_host,
639 const mojom::PageLoadTiming& new_timing, 291 const mojom::PageLoadTiming& new_timing) {
640 const mojom::PageLoadMetadata& new_metadata) {
641 UpdateSubFrameMetadata(new_metadata);
642 const auto it = subframe_navigation_start_offset_.find( 292 const auto it = subframe_navigation_start_offset_.find(
643 render_frame_host->GetFrameTreeNodeId()); 293 render_frame_host->GetFrameTreeNodeId());
644 if (it == subframe_navigation_start_offset_.end()) { 294 if (it == subframe_navigation_start_offset_.end()) {
645 // We received timing information for an untracked load. Ignore it. 295 // We received timing information for an untracked load. Ignore it.
646 return; 296 return;
647 } 297 }
648 298
649 base::TimeDelta navigation_start_offset = it->second; 299 base::TimeDelta navigation_start_offset = it->second;
650 MergePaintTiming(navigation_start_offset, *(new_timing.paint_timing), 300 MergePaintTiming(navigation_start_offset, *(new_timing.paint_timing),
651 false /* is_main_frame */); 301 false /* is_main_frame */);
652 302
653 DispatchTimingUpdates(); 303 DispatchTimingUpdates();
654 } 304 }
655 305
656 void PageLoadTracker::MergePaintTiming( 306 void PageLoadMetricsUpdateDispatcher::MergePaintTiming(
657 base::TimeDelta navigation_start_offset, 307 base::TimeDelta navigation_start_offset,
658 const mojom::PaintTiming& new_paint_timing, 308 const mojom::PaintTiming& new_paint_timing,
659 bool is_main_frame) { 309 bool is_main_frame) {
660 MaybeUpdateTimeDelta(&merged_page_timing_->paint_timing->first_paint, 310 MaybeUpdateTimeDelta(&pending_merged_page_timing_->paint_timing->first_paint,
661 navigation_start_offset, new_paint_timing.first_paint); 311 navigation_start_offset, new_paint_timing.first_paint);
662 MaybeUpdateTimeDelta(&merged_page_timing_->paint_timing->first_text_paint,
663 navigation_start_offset,
664 new_paint_timing.first_text_paint);
665 MaybeUpdateTimeDelta(&merged_page_timing_->paint_timing->first_image_paint,
666 navigation_start_offset,
667 new_paint_timing.first_image_paint);
668 MaybeUpdateTimeDelta( 312 MaybeUpdateTimeDelta(
669 &merged_page_timing_->paint_timing->first_contentful_paint, 313 &pending_merged_page_timing_->paint_timing->first_text_paint,
314 navigation_start_offset, new_paint_timing.first_text_paint);
315 MaybeUpdateTimeDelta(
316 &pending_merged_page_timing_->paint_timing->first_image_paint,
317 navigation_start_offset, new_paint_timing.first_image_paint);
318 MaybeUpdateTimeDelta(
319 &pending_merged_page_timing_->paint_timing->first_contentful_paint,
670 navigation_start_offset, new_paint_timing.first_contentful_paint); 320 navigation_start_offset, new_paint_timing.first_contentful_paint);
671 if (is_main_frame) { 321 if (is_main_frame) {
672 // first meaningful paint is only tracked in the main frame. 322 // first meaningful paint is only tracked in the main frame.
673 merged_page_timing_->paint_timing->first_meaningful_paint = 323 pending_merged_page_timing_->paint_timing->first_meaningful_paint =
674 new_paint_timing.first_meaningful_paint; 324 new_paint_timing.first_meaningful_paint;
675 } 325 }
676 } 326 }
677 327
678 void PageLoadTracker::UpdateSubFrameMetadata( 328 void PageLoadMetricsUpdateDispatcher::UpdateSubFrameMetadata(
679 const mojom::PageLoadMetadata& subframe_metadata) { 329 const mojom::PageLoadMetadata& subframe_metadata) {
680 // Merge the subframe loading behavior flags with any we've already observed, 330 // Merge the subframe loading behavior flags with any we've already observed,
681 // possibly from other subframes. 331 // possibly from other subframes.
682 const int last_subframe_loading_behavior_flags = 332 const int last_subframe_loading_behavior_flags =
683 subframe_metadata_.behavior_flags; 333 subframe_metadata_->behavior_flags;
684 subframe_metadata_.behavior_flags |= subframe_metadata.behavior_flags; 334 subframe_metadata_->behavior_flags |= subframe_metadata.behavior_flags;
685 if (last_subframe_loading_behavior_flags == subframe_metadata_.behavior_flags) 335 if (last_subframe_loading_behavior_flags ==
336 subframe_metadata_->behavior_flags)
686 return; 337 return;
687 338
688 PageLoadExtraInfo extra_info(ComputePageLoadExtraInfo()); 339 client_->OnSubframeMetadataChanged();
689 for (const auto& observer : observers_) {
690 observer->OnLoadingBehaviorObserved(extra_info);
691 }
692 } 340 }
693 341
694 void PageLoadTracker::UpdateTiming( 342 void PageLoadMetricsUpdateDispatcher::UpdateMainFrameTiming(
695 const mojom::PageLoadTiming& new_timing, 343 const mojom::PageLoadTiming& new_timing) {
696 const mojom::PageLoadMetadata& new_metadata) {
697 // Throw away IPCs that are not relevant to the current navigation. 344 // Throw away IPCs that are not relevant to the current navigation.
698 // Two timing structures cannot refer to the same navigation if they indicate 345 // Two timing structures cannot refer to the same navigation if they indicate
699 // that a navigation started at different times, so a new timing struct with a 346 // that a navigation started at different times, so a new timing struct with a
700 // different start time from an earlier struct is considered invalid. 347 // different start time from an earlier struct is considered invalid.
701 const bool valid_timing_descendent = 348 const bool valid_timing_descendent =
702 merged_page_timing_->navigation_start.is_null() || 349 pending_merged_page_timing_->navigation_start.is_null() ||
703 merged_page_timing_->navigation_start == new_timing.navigation_start; 350 pending_merged_page_timing_->navigation_start ==
351 new_timing.navigation_start;
704 if (!valid_timing_descendent) { 352 if (!valid_timing_descendent) {
705 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING_DESCENDENT); 353 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING_DESCENDENT);
706 return; 354 return;
707 } 355 }
708 356
709 // Ensure flags sent previously are still present in the new metadata fields.
710 const bool valid_behavior_descendent =
711 (main_frame_metadata_.behavior_flags & new_metadata.behavior_flags) ==
712 main_frame_metadata_.behavior_flags;
713 if (!valid_behavior_descendent) {
714 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_BEHAVIOR_DESCENDENT);
715 return;
716 }
717 internal::PageLoadTimingStatus status = IsValidPageLoadTiming(new_timing); 357 internal::PageLoadTimingStatus status = IsValidPageLoadTiming(new_timing);
718 UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingStatus, status, 358 UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingStatus, status,
719 internal::LAST_PAGE_LOAD_TIMING_STATUS); 359 internal::LAST_PAGE_LOAD_TIMING_STATUS);
720 if (status != internal::VALID) { 360 if (status != internal::VALID) {
721 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING); 361 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING);
722 return; 362 return;
723 } 363 }
724 364
725 DCHECK(did_commit_); // OnCommit() must be called first. 365 mojom::PaintTimingPtr last_paint_timing =
726 // There are some subtle ordering constraints here. GetPageLoadMetricsInfo() 366 std::move(pending_merged_page_timing_->paint_timing);
727 // must be called before DispatchObserverTimingCallbacks, but its 367 // Update the pending_merged_page_timing_, making sure to merge the previously
728 // implementation depends on the state of main_frame_metadata_, so we need
729 // to update main_frame_metadata_ before calling GetPageLoadMetricsInfo.
730 // Thus, we make a copy of timing here, update merged_page_timing_ and
731 // main_frame_metadata_, and then proceed to dispatch the observer timing
732 // callbacks.
733 const mojom::PaintTimingPtr last_paint_timing =
734 std::move(merged_page_timing_->paint_timing);
735
736 // Update the merged_page_timing_, making sure to merge the previously
737 // observed |paint_timing|, which is tracked across all frames in the page. 368 // observed |paint_timing|, which is tracked across all frames in the page.
738 merged_page_timing_ = new_timing.Clone(); 369 pending_merged_page_timing_ = new_timing.Clone();
739 merged_page_timing_->paint_timing = last_paint_timing.Clone(); 370 pending_merged_page_timing_->paint_timing = std::move(last_paint_timing);
740 MergePaintTiming(base::TimeDelta(), *new_timing.paint_timing, 371 MergePaintTiming(base::TimeDelta(), *new_timing.paint_timing,
741 true /* is_main_frame */); 372 true /* is_main_frame */);
742 373
743 main_frame_metadata_ = new_metadata;
744
745 DispatchTimingUpdates(); 374 DispatchTimingUpdates();
746 } 375 }
747 376
748 void PageLoadTracker::DispatchTimingUpdates() { 377 void PageLoadMetricsUpdateDispatcher::UpdateMainFrameMetadata(
749 if (last_dispatched_merged_page_timing_->Equals(*merged_page_timing_) && 378 const mojom::PageLoadMetadata& new_metadata) {
750 last_dispatched_main_frame_metadata_->Equals(main_frame_metadata_)) { 379 if (main_frame_metadata_->Equals(new_metadata))
380 return;
381
382 // Ensure flags sent previously are still present in the new metadata fields.
383 const bool valid_behavior_descendent =
384 (main_frame_metadata_->behavior_flags & new_metadata.behavior_flags) ==
385 main_frame_metadata_->behavior_flags;
386 if (!valid_behavior_descendent) {
387 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_BEHAVIOR_DESCENDENT);
751 return; 388 return;
752 } 389 }
753 390
754 if (merged_page_timing_->paint_timing->first_paint) { 391 main_frame_metadata_ = new_metadata.Clone();
755 if (!merged_page_timing_->parse_timing->parse_start || 392 client_->OnMainFrameMetadataChanged();
756 !merged_page_timing_->document_timing->first_layout) { 393 }
394
395 void PageLoadMetricsUpdateDispatcher::DispatchTimingUpdates() {
396 if (pending_merged_page_timing_->paint_timing->first_paint) {
397 if (!pending_merged_page_timing_->parse_timing->parse_start ||
398 !pending_merged_page_timing_->document_timing->first_layout) {
757 // When merging paint events across frames, we can sometimes encounter 399 // When merging paint events across frames, we can sometimes encounter
758 // cases where we've received a first paint event for a child frame before 400 // cases where we've received a first paint event for a child frame before
759 // receiving required earlier events in the main frame, due to buffering 401 // receiving required earlier events in the main frame, due to buffering
760 // in the render process which results in out of order delivery. For 402 // in the render process which results in out of order delivery. For
761 // example, we may receive a notification for a first paint in a child 403 // example, we may receive a notification for a first paint in a child
762 // frame before we've received a notification for parse start or first 404 // frame before we've received a notification for parse start or first
763 // layout in the main frame. In these cases, we delay sending timing 405 // layout in the main frame. In these cases, we delay sending timing
764 // updates until we've received all expected events (e.g. wait to receive 406 // updates until we've received all expected events (e.g. wait to receive
765 // a parse or layout event before dispatching a paint event), so observers 407 // a parse or layout event before dispatching a paint event), so observers
766 // can make assumptions about ordering of these events in their callbacks. 408 // can make assumptions about ordering of these events in their callbacks.
767 return; 409 return;
768 } 410 }
769 } 411 }
770 412
413 if (current_merged_page_timing_->Equals(*pending_merged_page_timing_))
414 return;
415 current_merged_page_timing_ = pending_merged_page_timing_->Clone();
416
771 internal::PageLoadTimingStatus status = 417 internal::PageLoadTimingStatus status =
772 IsValidPageLoadTiming(*merged_page_timing_); 418 IsValidPageLoadTiming(*pending_merged_page_timing_);
773 UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingDispatchStatus, status, 419 UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingDispatchStatus, status,
774 internal::LAST_PAGE_LOAD_TIMING_STATUS); 420 internal::LAST_PAGE_LOAD_TIMING_STATUS);
775 421
776 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); 422 client_->OnTimingChanged();
777 for (const auto& observer : observers_) {
778 DispatchObserverTimingCallbacks(
779 observer.get(), *last_dispatched_merged_page_timing_,
780 *merged_page_timing_, *last_dispatched_main_frame_metadata_, info);
781 }
782 last_dispatched_merged_page_timing_ = merged_page_timing_->Clone();
783 last_dispatched_main_frame_metadata_ = main_frame_metadata_.Clone();
784 }
785
786 void PageLoadTracker::OnStartedResource(
787 const ExtraRequestStartInfo& extra_request_start_info) {
788 for (const auto& observer : observers_) {
789 observer->OnStartedResource(extra_request_start_info);
790 }
791 }
792
793 void PageLoadTracker::OnLoadedResource(
794 const ExtraRequestCompleteInfo& extra_request_complete_info) {
795 for (const auto& observer : observers_) {
796 observer->OnLoadedResource(extra_request_complete_info);
797 }
798 }
799
800 void PageLoadTracker::StopTracking() {
801 did_stop_tracking_ = true;
802 observers_.clear();
803 }
804
805 void PageLoadTracker::AddObserver(
806 std::unique_ptr<PageLoadMetricsObserver> observer) {
807 observers_.push_back(std::move(observer));
808 }
809
810 void PageLoadTracker::ClampBrowserTimestampIfInterProcessTimeTickSkew(
811 base::TimeTicks* event_time) {
812 DCHECK(event_time != nullptr);
813 // Windows 10 GCE bot non-deterministically failed because TimeTicks::Now()
814 // called in the browser process e.g. commit_time was less than
815 // navigation_start_ that was populated in the renderer process because the
816 // clock was not system-wide monotonic.
817 // Note that navigation_start_ can also be set in the browser process in
818 // some cases and in those cases event_time should never be <
819 // navigation_start_. If it is due to a code error and it gets clamped in this
820 // function, on high resolution systems it should lead to a dcheck failure.
821
822 // TODO(shivanisha): Currently IsHighResolution is the best way to check
823 // if the clock is system-wide monotonic. However IsHighResolution
824 // does a broader check to see if the clock in use is high resolution
825 // which also implies it is system-wide monotonic (on Windows).
826 if (base::TimeTicks::IsHighResolution()) {
827 DCHECK(event_time->is_null() || *event_time >= navigation_start_);
828 return;
829 }
830
831 if (!event_time->is_null() && *event_time < navigation_start_) {
832 RecordInternalError(ERR_INTER_PROCESS_TIME_TICK_SKEW);
833 *event_time = navigation_start_;
834 }
835 }
836
837 PageLoadExtraInfo PageLoadTracker::ComputePageLoadExtraInfo() {
838 base::Optional<base::TimeDelta> first_background_time;
839 base::Optional<base::TimeDelta> first_foreground_time;
840 base::Optional<base::TimeDelta> page_end_time;
841
842 if (!background_time_.is_null()) {
843 DCHECK_GE(background_time_, navigation_start_);
844 first_background_time = background_time_ - navigation_start_;
845 }
846
847 if (!foreground_time_.is_null()) {
848 DCHECK_GE(foreground_time_, navigation_start_);
849 first_foreground_time = foreground_time_ - navigation_start_;
850 }
851
852 if (page_end_reason_ != END_NONE) {
853 DCHECK_GE(page_end_time_, navigation_start_);
854 page_end_time = page_end_time_ - navigation_start_;
855 } else {
856 DCHECK(page_end_time_.is_null());
857 }
858
859 // page_end_reason_ == END_NONE implies page_end_user_initiated_info_ is not
860 // user initiated.
861 DCHECK(page_end_reason_ != END_NONE ||
862 (!page_end_user_initiated_info_.browser_initiated &&
863 !page_end_user_initiated_info_.user_gesture &&
864 !page_end_user_initiated_info_.user_input_event));
865 return PageLoadExtraInfo(
866 navigation_start_, first_background_time, first_foreground_time,
867 started_in_foreground_, user_initiated_info_, url(), start_url_,
868 did_commit_, page_end_reason_, page_end_user_initiated_info_,
869 page_end_time, main_frame_metadata_, subframe_metadata_);
870 }
871
872 bool PageLoadTracker::HasMatchingNavigationRequestID(
873 const content::GlobalRequestID& request_id) const {
874 DCHECK(request_id != content::GlobalRequestID());
875 return navigation_request_id_.has_value() &&
876 navigation_request_id_.value() == request_id;
877 }
878
879 void PageLoadTracker::NotifyPageEnd(PageEndReason page_end_reason,
880 UserInitiatedInfo user_initiated_info,
881 base::TimeTicks timestamp,
882 bool is_certainly_browser_timestamp) {
883 DCHECK_NE(page_end_reason, END_NONE);
884 // Use UpdatePageEnd to update an already notified PageLoadTracker.
885 if (page_end_reason_ != END_NONE)
886 return;
887
888 UpdatePageEndInternal(page_end_reason, user_initiated_info, timestamp,
889 is_certainly_browser_timestamp);
890 }
891
892 void PageLoadTracker::UpdatePageEnd(PageEndReason page_end_reason,
893 UserInitiatedInfo user_initiated_info,
894 base::TimeTicks timestamp,
895 bool is_certainly_browser_timestamp) {
896 DCHECK_NE(page_end_reason, END_NONE);
897 DCHECK_NE(page_end_reason, END_OTHER);
898 DCHECK_EQ(page_end_reason_, END_OTHER);
899 DCHECK(!page_end_time_.is_null());
900 if (page_end_time_.is_null() || page_end_reason_ != END_OTHER)
901 return;
902
903 // For some aborts (e.g. navigations), the initiated timestamp can be earlier
904 // than the timestamp that aborted the load. Taking the minimum gives the
905 // closest user initiated time known.
906 UpdatePageEndInternal(page_end_reason, user_initiated_info,
907 std::min(page_end_time_, timestamp),
908 is_certainly_browser_timestamp);
909 }
910
911 bool PageLoadTracker::IsLikelyProvisionalAbort(
912 base::TimeTicks abort_cause_time) const {
913 // Note that |abort_cause_time - page_end_time_| can be negative.
914 return page_end_reason_ == END_OTHER &&
915 (abort_cause_time - page_end_time_).InMilliseconds() < 100;
916 }
917
918 bool PageLoadTracker::MatchesOriginalNavigation(
919 content::NavigationHandle* navigation_handle) {
920 // Neither navigation should have committed.
921 DCHECK(!navigation_handle->HasCommitted());
922 DCHECK(!did_commit_);
923 return navigation_handle->GetURL() == start_url_;
924 }
925
926 void PageLoadTracker::UpdatePageEndInternal(
927 PageEndReason page_end_reason,
928 UserInitiatedInfo user_initiated_info,
929 base::TimeTicks timestamp,
930 bool is_certainly_browser_timestamp) {
931 // When a provisional navigation commits, that navigation's start time is
932 // interpreted as the abort time for other provisional loads in the tab.
933 // However, this only makes sense if the committed load started after the
934 // aborted provisional loads started. Thus we ignore cases where the committed
935 // load started before the aborted provisional load, as this would result in
936 // recording a negative time-to-abort. The real issue here is that we have to
937 // infer the cause of aborts. It would be better if the navigation code could
938 // instead report the actual cause of an aborted navigation. See crbug/571647
939 // for details.
940 if (timestamp < navigation_start_) {
941 RecordInternalError(ERR_END_BEFORE_NAVIGATION_START);
942 page_end_reason_ = END_NONE;
943 page_end_time_ = base::TimeTicks();
944 return;
945 }
946 page_end_reason_ = page_end_reason;
947 page_end_time_ = timestamp;
948 // A client redirect can never be user initiated. Due to the way Blink
949 // implements user gesture tracking, where all events that occur within 1
950 // second after a user interaction are considered to be triggered by user
951 // activation (based on HTML spec:
952 // https://html.spec.whatwg.org/multipage/interaction.html#triggered-by-user-a ctivation),
953 // these navs may sometimes be reported as user initiated by Blink. Thus, we
954 // explicitly filter these types of aborts out when deciding if the abort was
955 // user initiated.
956 if (page_end_reason != END_CLIENT_REDIRECT)
957 page_end_user_initiated_info_ = user_initiated_info;
958
959 if (is_certainly_browser_timestamp) {
960 ClampBrowserTimestampIfInterProcessTimeTickSkew(&page_end_time_);
961 }
962 }
963
964 void PageLoadTracker::MediaStartedPlaying(
965 const content::WebContentsObserver::MediaPlayerInfo& video_type,
966 bool is_in_main_frame) {
967 for (const auto& observer : observers_)
968 observer->MediaStartedPlaying(video_type, is_in_main_frame);
969 }
970
971 void PageLoadTracker::OnNavigationDelayComplete(base::TimeDelta scheduled_delay,
972 base::TimeDelta actual_delay) {
973 for (const auto& observer : observers_)
974 observer->OnNavigationDelayComplete(scheduled_delay, actual_delay);
975 } 423 }
976 424
977 } // namespace page_load_metrics 425 } // namespace page_load_metrics
OLDNEW

Powered by Google App Engine
This is Rietveld 408576698