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

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 comments 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> 7 #include <ostream>
9 #include <string>
10 #include <utility> 8 #include <utility>
11 9
12 #include "base/logging.h" 10 #include "base/logging.h"
13 #include "base/memory/ptr_util.h"
14 #include "base/metrics/histogram_macros.h" 11 #include "base/metrics/histogram_macros.h"
12 #include "base/optional.h"
15 #include "chrome/browser/page_load_metrics/browser_page_track_decider.h" 13 #include "chrome/browser/page_load_metrics/browser_page_track_decider.h"
16 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface. h" 14 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface. h"
17 #include "chrome/browser/page_load_metrics/page_load_metrics_util.h" 15 #include "chrome/browser/page_load_metrics/page_load_metrics_util.h"
18 #include "chrome/browser/prerender/prerender_contents.h" 16 #include "chrome/browser/page_load_metrics/page_load_tracker.h"
19 #include "chrome/common/page_load_metrics/page_load_timing.h" 17 #include "chrome/common/page_load_metrics/page_load_metrics_constants.h"
20 #include "content/public/browser/navigation_details.h"
21 #include "content/public/browser/navigation_handle.h" 18 #include "content/public/browser/navigation_handle.h"
22 #include "content/public/browser/render_frame_host.h" 19 #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 20
41 namespace page_load_metrics { 21 namespace page_load_metrics {
42 22
43 namespace internal { 23 namespace internal {
44 24
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"; 25 const char kPageLoadTimingStatus[] = "PageLoad.Internal.PageLoadTimingStatus";
66 const char kPageLoadTimingDispatchStatus[] = 26 const char kPageLoadTimingDispatchStatus[] =
67 "PageLoad.Internal.PageLoadTimingStatus.AtTimingCallbackDispatch"; 27 "PageLoad.Internal.PageLoadTimingStatus.AtTimingCallbackDispatch";
68 28
69 } // namespace internal 29 } // namespace internal
70 30
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 { 31 namespace {
113 32
114 // Helper to allow use of Optional<> values in LOG() messages. 33 // Helper to allow use of Optional<> values in LOG() messages.
115 std::ostream& operator<<(std::ostream& os, 34 std::ostream& operator<<(std::ostream& os,
116 const base::Optional<base::TimeDelta>& opt) { 35 const base::Optional<base::TimeDelta>& opt) {
117 if (opt) 36 if (opt)
118 os << opt.value(); 37 os << opt.value();
119 else 38 else
120 os << "(unset)"; 39 os << "(unset)";
121 return os; 40 return os;
(...skipping 187 matching lines...) Expand 10 before | Expand all | Expand 10 after
309 // occasionally, as inter-frame updates can arrive out of order. Record a 228 // occasionally, as inter-frame updates can arrive out of order. Record a
310 // histogram to track how frequently it happens, along with the magnitude 229 // histogram to track how frequently it happens, along with the magnitude
311 // of the delta. 230 // of the delta.
312 PAGE_LOAD_HISTOGRAM("PageLoad.Internal.OutOfOrderInterFrameTiming", 231 PAGE_LOAD_HISTOGRAM("PageLoad.Internal.OutOfOrderInterFrameTiming",
313 inout_existing_value->value() - candidate_new_value); 232 inout_existing_value->value() - candidate_new_value);
314 } 233 }
315 234
316 *inout_existing_value = candidate_new_value; 235 *inout_existing_value = candidate_new_value;
317 } 236 }
318 237
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 238 } // namespace
368 239
369 PageLoadTracker::PageLoadTracker( 240 PageLoadMetricsUpdateDispatcher::PageLoadMetricsUpdateDispatcher(
370 bool in_foreground, 241 PageLoadMetricsUpdateDispatcher::Client* client,
371 PageLoadMetricsEmbedderInterface* embedder_interface,
372 const GURL& currently_committed_url,
373 content::NavigationHandle* navigation_handle, 242 content::NavigationHandle* navigation_handle,
374 UserInitiatedInfo user_initiated_info, 243 PageLoadMetricsEmbedderInterface* embedder_interface)
375 int aborted_chain_size, 244 : client_(client),
376 int aborted_chain_size_same_url) 245 embedder_interface_(embedder_interface),
377 : did_stop_tracking_(false),
378 app_entered_background_(false),
379 navigation_start_(navigation_handle->NavigationStart()), 246 navigation_start_(navigation_handle->NavigationStart()),
380 url_(navigation_handle->GetURL()), 247 current_merged_page_timing_(CreatePageLoadTiming()),
381 start_url_(navigation_handle->GetURL()), 248 pending_merged_page_timing_(CreatePageLoadTiming()),
382 did_commit_(false), 249 main_frame_metadata_(mojom::PageLoadMetadata::New()),
383 page_end_reason_(END_NONE), 250 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 251
399 UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadStartedInForeground, 252 PageLoadMetricsUpdateDispatcher::~PageLoadMetricsUpdateDispatcher() {}
400 started_in_foreground_); 253
401 const bool is_prerender = prerender::PrerenderContents::FromWebContents( 254 void PageLoadMetricsUpdateDispatcher::UpdateMetrics(
402 navigation_handle->GetWebContents()) != nullptr; 255 content::RenderFrameHost* render_frame_host,
403 if (is_prerender) { 256 const mojom::PageLoadTiming& new_timing,
404 UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadPrerender, true); 257 const mojom::PageLoadMetadata& new_metadata) {
258 if (render_frame_host->GetParent() == nullptr) {
259 UpdateMainFrameMetadata(new_metadata);
260 UpdateMainFrameTiming(new_timing);
261 } else {
262 UpdateSubFrameMetadata(new_metadata);
263 UpdateSubFrameTiming(render_frame_host, new_timing);
405 } 264 }
406 } 265 }
407 266
408 PageLoadTracker::~PageLoadTracker() { 267 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) { 268 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()) 269 if (!navigation_handle->HasCommitted())
565 return; 270 return;
566 271
567 // We have a new committed navigation, so discard information about the 272 // We have a new committed navigation, so discard information about the
568 // previously committed navigation. 273 // previously committed navigation.
569 subframe_navigation_start_offset_.erase( 274 subframe_navigation_start_offset_.erase(
570 navigation_handle->GetFrameTreeNodeId()); 275 navigation_handle->GetFrameTreeNodeId());
571 276
572 BrowserPageTrackDecider decider(embedder_interface_, 277 BrowserPageTrackDecider decider(embedder_interface_,
573 navigation_handle->GetWebContents(), 278 navigation_handle->GetWebContents(),
574 navigation_handle); 279 navigation_handle);
575 if (!decider.ShouldTrack()) 280 if (!decider.ShouldTrack())
576 return; 281 return;
577 282
578 if (navigation_start_ > navigation_handle->NavigationStart()) { 283 if (navigation_start_ > navigation_handle->NavigationStart()) {
579 RecordInternalError(ERR_SUBFRAME_NAVIGATION_START_BEFORE_MAIN_FRAME); 284 RecordInternalError(ERR_SUBFRAME_NAVIGATION_START_BEFORE_MAIN_FRAME);
580 return; 285 return;
581 } 286 }
582 base::TimeDelta navigation_delta = 287 base::TimeDelta navigation_delta =
583 navigation_handle->NavigationStart() - navigation_start_; 288 navigation_handle->NavigationStart() - navigation_start_;
584 subframe_navigation_start_offset_.insert(std::make_pair( 289 subframe_navigation_start_offset_.insert(std::make_pair(
585 navigation_handle->GetFrameTreeNodeId(), navigation_delta)); 290 navigation_handle->GetFrameTreeNodeId(), navigation_delta));
586 } 291 }
587 292
588 void PageLoadTracker::FailedProvisionalLoad( 293 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, 294 content::RenderFrameHost* render_frame_host,
639 const mojom::PageLoadTiming& new_timing, 295 const mojom::PageLoadTiming& new_timing) {
640 const mojom::PageLoadMetadata& new_metadata) {
641 UpdateSubFrameMetadata(new_metadata);
642 const auto it = subframe_navigation_start_offset_.find( 296 const auto it = subframe_navigation_start_offset_.find(
643 render_frame_host->GetFrameTreeNodeId()); 297 render_frame_host->GetFrameTreeNodeId());
644 if (it == subframe_navigation_start_offset_.end()) { 298 if (it == subframe_navigation_start_offset_.end()) {
645 // We received timing information for an untracked load. Ignore it. 299 // We received timing information for an untracked load. Ignore it.
646 return; 300 return;
647 } 301 }
648 302
649 base::TimeDelta navigation_start_offset = it->second; 303 base::TimeDelta navigation_start_offset = it->second;
650 MergePaintTiming(navigation_start_offset, *(new_timing.paint_timing), 304 MergePaintTiming(navigation_start_offset, *(new_timing.paint_timing),
651 false /* is_main_frame */); 305 false /* is_main_frame */);
652 306
653 DispatchTimingUpdates(); 307 DispatchTimingUpdates();
654 } 308 }
655 309
656 void PageLoadTracker::MergePaintTiming( 310 void PageLoadMetricsUpdateDispatcher::MergePaintTiming(
657 base::TimeDelta navigation_start_offset, 311 base::TimeDelta navigation_start_offset,
658 const mojom::PaintTiming& new_paint_timing, 312 const mojom::PaintTiming& new_paint_timing,
659 bool is_main_frame) { 313 bool is_main_frame) {
660 MaybeUpdateTimeDelta(&merged_page_timing_->paint_timing->first_paint, 314 MaybeUpdateTimeDelta(&pending_merged_page_timing_->paint_timing->first_paint,
661 navigation_start_offset, new_paint_timing.first_paint); 315 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( 316 MaybeUpdateTimeDelta(
669 &merged_page_timing_->paint_timing->first_contentful_paint, 317 &pending_merged_page_timing_->paint_timing->first_text_paint,
318 navigation_start_offset, new_paint_timing.first_text_paint);
319 MaybeUpdateTimeDelta(
320 &pending_merged_page_timing_->paint_timing->first_image_paint,
321 navigation_start_offset, new_paint_timing.first_image_paint);
322 MaybeUpdateTimeDelta(
323 &pending_merged_page_timing_->paint_timing->first_contentful_paint,
670 navigation_start_offset, new_paint_timing.first_contentful_paint); 324 navigation_start_offset, new_paint_timing.first_contentful_paint);
671 if (is_main_frame) { 325 if (is_main_frame) {
672 // first meaningful paint is only tracked in the main frame. 326 // first meaningful paint is only tracked in the main frame.
673 merged_page_timing_->paint_timing->first_meaningful_paint = 327 pending_merged_page_timing_->paint_timing->first_meaningful_paint =
674 new_paint_timing.first_meaningful_paint; 328 new_paint_timing.first_meaningful_paint;
675 } 329 }
676 } 330 }
677 331
678 void PageLoadTracker::UpdateSubFrameMetadata( 332 void PageLoadMetricsUpdateDispatcher::UpdateSubFrameMetadata(
679 const mojom::PageLoadMetadata& subframe_metadata) { 333 const mojom::PageLoadMetadata& subframe_metadata) {
680 // Merge the subframe loading behavior flags with any we've already observed, 334 // Merge the subframe loading behavior flags with any we've already observed,
681 // possibly from other subframes. 335 // possibly from other subframes.
682 const int last_subframe_loading_behavior_flags = 336 const int last_subframe_loading_behavior_flags =
683 subframe_metadata_.behavior_flags; 337 subframe_metadata_->behavior_flags;
684 subframe_metadata_.behavior_flags |= subframe_metadata.behavior_flags; 338 subframe_metadata_->behavior_flags |= subframe_metadata.behavior_flags;
685 if (last_subframe_loading_behavior_flags == subframe_metadata_.behavior_flags) 339 if (last_subframe_loading_behavior_flags ==
340 subframe_metadata_->behavior_flags)
686 return; 341 return;
687 342
688 PageLoadExtraInfo extra_info(ComputePageLoadExtraInfo()); 343 client_->OnSubframeMetadataChanged();
689 for (const auto& observer : observers_) {
690 observer->OnLoadingBehaviorObserved(extra_info);
691 }
692 } 344 }
693 345
694 void PageLoadTracker::UpdateTiming( 346 void PageLoadMetricsUpdateDispatcher::UpdateMainFrameTiming(
695 const mojom::PageLoadTiming& new_timing, 347 const mojom::PageLoadTiming& new_timing) {
696 const mojom::PageLoadMetadata& new_metadata) {
697 // Throw away IPCs that are not relevant to the current navigation. 348 // Throw away IPCs that are not relevant to the current navigation.
698 // Two timing structures cannot refer to the same navigation if they indicate 349 // 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 350 // 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. 351 // different start time from an earlier struct is considered invalid.
701 const bool valid_timing_descendent = 352 const bool valid_timing_descendent =
702 merged_page_timing_->navigation_start.is_null() || 353 pending_merged_page_timing_->navigation_start.is_null() ||
703 merged_page_timing_->navigation_start == new_timing.navigation_start; 354 pending_merged_page_timing_->navigation_start ==
355 new_timing.navigation_start;
704 if (!valid_timing_descendent) { 356 if (!valid_timing_descendent) {
705 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING_DESCENDENT); 357 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING_DESCENDENT);
706 return; 358 return;
707 } 359 }
708 360
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); 361 internal::PageLoadTimingStatus status = IsValidPageLoadTiming(new_timing);
718 UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingStatus, status, 362 UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingStatus, status,
719 internal::LAST_PAGE_LOAD_TIMING_STATUS); 363 internal::LAST_PAGE_LOAD_TIMING_STATUS);
720 if (status != internal::VALID) { 364 if (status != internal::VALID) {
721 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING); 365 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING);
722 return; 366 return;
723 } 367 }
724 368
725 DCHECK(did_commit_); // OnCommit() must be called first. 369 mojom::PaintTimingPtr last_paint_timing =
726 // There are some subtle ordering constraints here. GetPageLoadMetricsInfo() 370 std::move(pending_merged_page_timing_->paint_timing);
727 // must be called before DispatchObserverTimingCallbacks, but its 371 // 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. 372 // observed |paint_timing|, which is tracked across all frames in the page.
738 merged_page_timing_ = new_timing.Clone(); 373 pending_merged_page_timing_ = new_timing.Clone();
739 merged_page_timing_->paint_timing = last_paint_timing.Clone(); 374 pending_merged_page_timing_->paint_timing = std::move(last_paint_timing);
740 MergePaintTiming(base::TimeDelta(), *new_timing.paint_timing, 375 MergePaintTiming(base::TimeDelta(), *new_timing.paint_timing,
741 true /* is_main_frame */); 376 true /* is_main_frame */);
742 377
743 main_frame_metadata_ = new_metadata;
744
745 DispatchTimingUpdates(); 378 DispatchTimingUpdates();
746 } 379 }
747 380
748 void PageLoadTracker::DispatchTimingUpdates() { 381 void PageLoadMetricsUpdateDispatcher::UpdateMainFrameMetadata(
749 if (last_dispatched_merged_page_timing_->Equals(*merged_page_timing_) && 382 const mojom::PageLoadMetadata& new_metadata) {
750 last_dispatched_main_frame_metadata_->Equals(main_frame_metadata_)) { 383 if (main_frame_metadata_->Equals(new_metadata))
384 return;
385
386 // Ensure flags sent previously are still present in the new metadata fields.
387 const bool valid_behavior_descendent =
388 (main_frame_metadata_->behavior_flags & new_metadata.behavior_flags) ==
389 main_frame_metadata_->behavior_flags;
390 if (!valid_behavior_descendent) {
391 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_BEHAVIOR_DESCENDENT);
751 return; 392 return;
752 } 393 }
753 394
754 if (merged_page_timing_->paint_timing->first_paint) { 395 main_frame_metadata_ = new_metadata.Clone();
755 if (!merged_page_timing_->parse_timing->parse_start || 396 client_->OnMainFrameMetadataChanged();
756 !merged_page_timing_->document_timing->first_layout) { 397 }
398
399 void PageLoadMetricsUpdateDispatcher::DispatchTimingUpdates() {
400 if (pending_merged_page_timing_->paint_timing->first_paint) {
401 if (!pending_merged_page_timing_->parse_timing->parse_start ||
402 !pending_merged_page_timing_->document_timing->first_layout) {
757 // When merging paint events across frames, we can sometimes encounter 403 // 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 404 // 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 405 // receiving required earlier events in the main frame, due to buffering
760 // in the render process which results in out of order delivery. For 406 // 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 407 // 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 408 // 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 409 // 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 410 // 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 411 // a parse or layout event before dispatching a paint event), so observers
766 // can make assumptions about ordering of these events in their callbacks. 412 // can make assumptions about ordering of these events in their callbacks.
767 return; 413 return;
768 } 414 }
769 } 415 }
770 416
417 if (current_merged_page_timing_->Equals(*pending_merged_page_timing_))
418 return;
419 current_merged_page_timing_ = pending_merged_page_timing_->Clone();
420
771 internal::PageLoadTimingStatus status = 421 internal::PageLoadTimingStatus status =
772 IsValidPageLoadTiming(*merged_page_timing_); 422 IsValidPageLoadTiming(*pending_merged_page_timing_);
773 UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingDispatchStatus, status, 423 UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingDispatchStatus, status,
774 internal::LAST_PAGE_LOAD_TIMING_STATUS); 424 internal::LAST_PAGE_LOAD_TIMING_STATUS);
775 425
776 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); 426 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 } 427 }
976 428
977 } // namespace page_load_metrics 429 } // namespace page_load_metrics
OLDNEW

Powered by Google App Engine
This is Rietveld 408576698