OLD | NEW |
| (Empty) |
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 | |
3 // found in the LICENSE file. | |
4 | |
5 #include "components/page_load_metrics/browser/metrics_web_contents_observer.h" | |
6 | |
7 #include <algorithm> | |
8 #include <ostream> | |
9 #include <string> | |
10 #include <utility> | |
11 | |
12 #include "base/location.h" | |
13 #include "base/logging.h" | |
14 #include "base/memory/ptr_util.h" | |
15 #include "base/metrics/histogram.h" | |
16 #include "base/metrics/user_metrics.h" | |
17 #include "components/page_load_metrics/browser/page_load_metrics_util.h" | |
18 #include "components/page_load_metrics/common/page_load_metrics_messages.h" | |
19 #include "components/page_load_metrics/common/page_load_timing.h" | |
20 #include "content/public/browser/browser_thread.h" | |
21 #include "content/public/browser/navigation_details.h" | |
22 #include "content/public/browser/navigation_handle.h" | |
23 #include "content/public/browser/render_frame_host.h" | |
24 #include "content/public/browser/render_view_host.h" | |
25 #include "content/public/browser/web_contents.h" | |
26 #include "content/public/browser/web_contents_observer.h" | |
27 #include "content/public/browser/web_contents_user_data.h" | |
28 #include "ipc/ipc_message.h" | |
29 #include "ipc/ipc_message_macros.h" | |
30 #include "ui/base/page_transition_types.h" | |
31 | |
32 DEFINE_WEB_CONTENTS_USER_DATA_KEY( | |
33 page_load_metrics::MetricsWebContentsObserver); | |
34 | |
35 namespace page_load_metrics { | |
36 | |
37 namespace internal { | |
38 | |
39 const char kErrorEvents[] = "PageLoad.Events.InternalError"; | |
40 const char kAbortChainSizeReload[] = | |
41 "PageLoad.Internal.ProvisionalAbortChainSize.Reload"; | |
42 const char kAbortChainSizeForwardBack[] = | |
43 "PageLoad.Internal.ProvisionalAbortChainSize.ForwardBack"; | |
44 const char kAbortChainSizeNewNavigation[] = | |
45 "PageLoad.Internal.ProvisionalAbortChainSize.NewNavigation"; | |
46 const char kAbortChainSizeSameURL[] = | |
47 "PageLoad.Internal.ProvisionalAbortChainSize.SameURL"; | |
48 const char kAbortChainSizeNoCommit[] = | |
49 "PageLoad.Internal.ProvisionalAbortChainSize.NoCommit"; | |
50 const char kClientRedirectFirstPaintToNavigation[] = | |
51 "PageLoad.Internal.ClientRedirect.FirstPaintToNavigation"; | |
52 const char kClientRedirectWithoutPaint[] = | |
53 "PageLoad.Internal.ClientRedirect.NavigationWithoutPaint"; | |
54 const char kCommitToCompleteNoTimingIPCs[] = | |
55 "PageLoad.Internal.CommitToComplete.NoTimingIPCs"; | |
56 | |
57 } // namespace internal | |
58 | |
59 namespace { | |
60 | |
61 // Helper to allow use of Optional<> values in LOG() messages. | |
62 std::ostream& operator<<(std::ostream& os, | |
63 const base::Optional<base::TimeDelta>& opt) { | |
64 if (opt) | |
65 os << opt.value(); | |
66 else | |
67 os << "(unset)"; | |
68 return os; | |
69 } | |
70 | |
71 // If second is non-zero, first must also be non-zero and less than or equal to | |
72 // second. | |
73 bool EventsInOrder(const base::Optional<base::TimeDelta>& first, | |
74 const base::Optional<base::TimeDelta>& second) { | |
75 if (!second) { | |
76 return true; | |
77 } | |
78 return first && first <= second; | |
79 } | |
80 | |
81 bool IsValidPageLoadTiming(const PageLoadTiming& timing) { | |
82 if (timing.IsEmpty()) | |
83 return false; | |
84 | |
85 // If we have a non-empty timing, it should always have a navigation start. | |
86 if (timing.navigation_start.is_null()) { | |
87 NOTREACHED() << "Received null navigation_start."; | |
88 return false; | |
89 } | |
90 | |
91 // Verify proper ordering between the various timings. | |
92 | |
93 if (!EventsInOrder(timing.response_start, timing.dom_loading)) { | |
94 // We sometimes get a zero response_start with a non-zero DOM loading. See | |
95 // crbug.com/590212. | |
96 DLOG(ERROR) << "Invalid response_start " << timing.response_start | |
97 << " for dom_loading " << timing.dom_loading; | |
98 return false; | |
99 } | |
100 | |
101 if (!EventsInOrder(timing.response_start, timing.parse_start)) { | |
102 // We sometimes get a zero response_start with a non-zero parse start. See | |
103 // crbug.com/590212. | |
104 DLOG(ERROR) << "Invalid response_start " << timing.response_start | |
105 << " for parse_start " << timing.parse_start; | |
106 return false; | |
107 } | |
108 | |
109 if (!EventsInOrder(timing.parse_start, timing.parse_stop)) { | |
110 NOTREACHED() << "Invalid parse_start " << timing.parse_start | |
111 << " for parse_stop " << timing.parse_stop; | |
112 return false; | |
113 } | |
114 | |
115 if (timing.parse_stop) { | |
116 const base::TimeDelta parse_duration = | |
117 timing.parse_stop.value() - timing.parse_start.value(); | |
118 if (timing.parse_blocked_on_script_load_duration > parse_duration) { | |
119 NOTREACHED() << "Invalid parse_blocked_on_script_load_duration " | |
120 << timing.parse_blocked_on_script_load_duration | |
121 << " for parse duration " << parse_duration; | |
122 return false; | |
123 } | |
124 } | |
125 | |
126 if (timing.parse_blocked_on_script_load_from_document_write_duration > | |
127 timing.parse_blocked_on_script_load_duration) { | |
128 NOTREACHED() | |
129 << "Invalid parse_blocked_on_script_load_from_document_write_duration " | |
130 << timing.parse_blocked_on_script_load_from_document_write_duration | |
131 << " for parse_blocked_on_script_load_duration " | |
132 << timing.parse_blocked_on_script_load_duration; | |
133 return false; | |
134 } | |
135 | |
136 if (!EventsInOrder(timing.dom_loading, | |
137 timing.dom_content_loaded_event_start)) { | |
138 NOTREACHED() << "Invalid dom_loading " << timing.dom_loading | |
139 << " for dom_content_loaded_event_start " | |
140 << timing.dom_content_loaded_event_start; | |
141 return false; | |
142 } | |
143 | |
144 if (!EventsInOrder(timing.dom_content_loaded_event_start, | |
145 timing.load_event_start)) { | |
146 NOTREACHED() << "Invalid dom_content_loaded_event_start " | |
147 << timing.dom_content_loaded_event_start | |
148 << " for load_event_start " << timing.load_event_start; | |
149 return false; | |
150 } | |
151 | |
152 if (!EventsInOrder(timing.dom_loading, timing.first_layout)) { | |
153 NOTREACHED() << "Invalid dom_loading " << timing.dom_loading | |
154 << " for first_layout " << timing.first_layout; | |
155 return false; | |
156 } | |
157 | |
158 if (!EventsInOrder(timing.first_layout, timing.first_paint)) { | |
159 NOTREACHED() << "Invalid first_layout " << timing.first_layout | |
160 << " for first_paint " << timing.first_paint; | |
161 return false; | |
162 } | |
163 | |
164 if (!EventsInOrder(timing.first_paint, timing.first_text_paint)) { | |
165 NOTREACHED() << "Invalid first_paint " << timing.first_paint | |
166 << " for first_text_paint " << timing.first_text_paint; | |
167 return false; | |
168 } | |
169 | |
170 if (!EventsInOrder(timing.first_paint, timing.first_image_paint)) { | |
171 NOTREACHED() << "Invalid first_paint " << timing.first_paint | |
172 << " for first_image_paint " << timing.first_image_paint; | |
173 return false; | |
174 } | |
175 | |
176 if (!EventsInOrder(timing.first_paint, timing.first_contentful_paint)) { | |
177 NOTREACHED() << "Invalid first_paint " << timing.first_paint | |
178 << " for first_contentful_paint " | |
179 << timing.first_contentful_paint; | |
180 return false; | |
181 } | |
182 | |
183 return true; | |
184 } | |
185 | |
186 void RecordInternalError(InternalErrorLoadEvent event) { | |
187 UMA_HISTOGRAM_ENUMERATION(internal::kErrorEvents, event, ERR_LAST_ENTRY); | |
188 } | |
189 | |
190 UserAbortType AbortTypeForPageTransition(ui::PageTransition transition) { | |
191 if (ui::PageTransitionCoreTypeIs(transition, ui::PAGE_TRANSITION_RELOAD)) | |
192 return ABORT_RELOAD; | |
193 if (transition & ui::PAGE_TRANSITION_FORWARD_BACK) | |
194 return ABORT_FORWARD_BACK; | |
195 if (ui::PageTransitionIsNewNavigation(transition)) | |
196 return ABORT_NEW_NAVIGATION; | |
197 NOTREACHED() | |
198 << "AbortTypeForPageTransition received unexpected ui::PageTransition: " | |
199 << transition; | |
200 return ABORT_OTHER; | |
201 } | |
202 | |
203 void LogAbortChainSameURLHistogram(int aborted_chain_size_same_url) { | |
204 if (aborted_chain_size_same_url > 0) { | |
205 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeSameURL, | |
206 aborted_chain_size_same_url); | |
207 } | |
208 } | |
209 | |
210 void DispatchObserverTimingCallbacks(PageLoadMetricsObserver* observer, | |
211 const PageLoadTiming& last_timing, | |
212 const PageLoadTiming& new_timing, | |
213 const PageLoadMetadata& last_metadata, | |
214 const PageLoadExtraInfo& extra_info) { | |
215 if (last_timing != new_timing) | |
216 observer->OnTimingUpdate(new_timing, extra_info); | |
217 if (new_timing.dom_content_loaded_event_start && | |
218 !last_timing.dom_content_loaded_event_start) | |
219 observer->OnDomContentLoadedEventStart(new_timing, extra_info); | |
220 if (new_timing.load_event_start && !last_timing.load_event_start) | |
221 observer->OnLoadEventStart(new_timing, extra_info); | |
222 if (new_timing.first_layout && !last_timing.first_layout) | |
223 observer->OnFirstLayout(new_timing, extra_info); | |
224 if (new_timing.first_paint && !last_timing.first_paint) | |
225 observer->OnFirstPaint(new_timing, extra_info); | |
226 if (new_timing.first_text_paint && !last_timing.first_text_paint) | |
227 observer->OnFirstTextPaint(new_timing, extra_info); | |
228 if (new_timing.first_image_paint && !last_timing.first_image_paint) | |
229 observer->OnFirstImagePaint(new_timing, extra_info); | |
230 if (new_timing.first_contentful_paint && !last_timing.first_contentful_paint) | |
231 observer->OnFirstContentfulPaint(new_timing, extra_info); | |
232 if (new_timing.parse_start && !last_timing.parse_start) | |
233 observer->OnParseStart(new_timing, extra_info); | |
234 if (new_timing.parse_stop && !last_timing.parse_stop) | |
235 observer->OnParseStop(new_timing, extra_info); | |
236 if (extra_info.metadata.behavior_flags != last_metadata.behavior_flags) | |
237 observer->OnLoadingBehaviorObserved(extra_info); | |
238 } | |
239 | |
240 } // namespace | |
241 | |
242 PageLoadTracker::PageLoadTracker( | |
243 bool in_foreground, | |
244 PageLoadMetricsEmbedderInterface* embedder_interface, | |
245 const GURL& currently_committed_url, | |
246 content::NavigationHandle* navigation_handle, | |
247 int aborted_chain_size, | |
248 int aborted_chain_size_same_url) | |
249 : did_stop_tracking_(false), | |
250 navigation_start_(navigation_handle->NavigationStart()), | |
251 url_(navigation_handle->GetURL()), | |
252 abort_type_(ABORT_NONE), | |
253 started_in_foreground_(in_foreground), | |
254 aborted_chain_size_(aborted_chain_size), | |
255 aborted_chain_size_same_url_(aborted_chain_size_same_url), | |
256 embedder_interface_(embedder_interface) { | |
257 DCHECK(!navigation_handle->HasCommitted()); | |
258 embedder_interface_->RegisterObservers(this); | |
259 for (const auto& observer : observers_) { | |
260 observer->OnStart(navigation_handle, currently_committed_url, | |
261 started_in_foreground_); | |
262 } | |
263 } | |
264 | |
265 PageLoadTracker::~PageLoadTracker() { | |
266 if (did_stop_tracking_) | |
267 return; | |
268 | |
269 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); | |
270 DCHECK_NE(static_cast<bool>(info.time_to_commit), | |
271 static_cast<bool>(failed_provisional_load_info_)); | |
272 if (info.time_to_commit && timing_.IsEmpty()) { | |
273 RecordInternalError(ERR_NO_IPCS_RECEIVED); | |
274 const base::TimeTicks commit_time = | |
275 navigation_start_ + info.time_to_commit.value(); | |
276 PAGE_LOAD_HISTOGRAM(internal::kCommitToCompleteNoTimingIPCs, | |
277 base::TimeTicks::Now() - commit_time); | |
278 } | |
279 // Recall that trackers that are given ABORT_UNKNOWN_NAVIGATION have their | |
280 // chain length added to the next navigation. Take care not to double count | |
281 // them. Also do not double count committed loads, which call this already. | |
282 if (commit_time_.is_null() && abort_type_ != ABORT_UNKNOWN_NAVIGATION) | |
283 LogAbortChainHistograms(nullptr); | |
284 | |
285 for (const auto& observer : observers_) { | |
286 if (failed_provisional_load_info_) { | |
287 observer->OnFailedProvisionalLoad(*failed_provisional_load_info_, info); | |
288 } else { | |
289 observer->OnComplete(timing_, info); | |
290 } | |
291 } | |
292 } | |
293 | |
294 void PageLoadTracker::LogAbortChainHistograms( | |
295 content::NavigationHandle* final_navigation) { | |
296 if (aborted_chain_size_ == 0) | |
297 return; | |
298 // Note that this could be broken out by this navigation's abort type, if more | |
299 // granularity is needed. Add one to the chain size to count the current | |
300 // navigation. In the other cases, the current navigation is the final | |
301 // navigation (which commits). | |
302 if (!final_navigation) { | |
303 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeNoCommit, | |
304 aborted_chain_size_ + 1); | |
305 LogAbortChainSameURLHistogram(aborted_chain_size_same_url_ + 1); | |
306 return; | |
307 } | |
308 | |
309 // The following is only executed for committing trackers. | |
310 DCHECK(!commit_time_.is_null()); | |
311 | |
312 // Note that histograms could be separated out by this commit's transition | |
313 // type, but for simplicity they will all be bucketed together. | |
314 LogAbortChainSameURLHistogram(aborted_chain_size_same_url_); | |
315 | |
316 ui::PageTransition committed_transition = | |
317 final_navigation->GetPageTransition(); | |
318 switch (AbortTypeForPageTransition(committed_transition)) { | |
319 case ABORT_RELOAD: | |
320 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeReload, | |
321 aborted_chain_size_); | |
322 return; | |
323 case ABORT_FORWARD_BACK: | |
324 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeForwardBack, | |
325 aborted_chain_size_); | |
326 return; | |
327 case ABORT_NEW_NAVIGATION: | |
328 UMA_HISTOGRAM_COUNTS(internal::kAbortChainSizeNewNavigation, | |
329 aborted_chain_size_); | |
330 return; | |
331 default: | |
332 NOTREACHED() | |
333 << "LogAbortChainHistograms received unexpected ui::PageTransition: " | |
334 << committed_transition; | |
335 return; | |
336 } | |
337 } | |
338 | |
339 void PageLoadTracker::WebContentsHidden() { | |
340 // Only log the first time we background in a given page load. | |
341 if (background_time_.is_null()) { | |
342 // Make sure we either started in the foreground and haven't been | |
343 // foregrounded yet, or started in the background and have already been | |
344 // foregrounded. | |
345 DCHECK_EQ(started_in_foreground_, foreground_time_.is_null()); | |
346 background_time_ = base::TimeTicks::Now(); | |
347 ClampBrowserTimestampIfInterProcessTimeTickSkew(&background_time_); | |
348 } | |
349 | |
350 for (const auto& observer : observers_) | |
351 observer->OnHidden(); | |
352 } | |
353 | |
354 void PageLoadTracker::WebContentsShown() { | |
355 // Only log the first time we foreground in a given page load. | |
356 if (foreground_time_.is_null()) { | |
357 // Make sure we either started in the background and haven't been | |
358 // backgrounded yet, or started in the foreground and have already been | |
359 // backgrounded. | |
360 DCHECK_NE(started_in_foreground_, background_time_.is_null()); | |
361 foreground_time_ = base::TimeTicks::Now(); | |
362 ClampBrowserTimestampIfInterProcessTimeTickSkew(&foreground_time_); | |
363 } | |
364 | |
365 for (const auto& observer : observers_) | |
366 observer->OnShown(); | |
367 } | |
368 | |
369 void PageLoadTracker::Commit(content::NavigationHandle* navigation_handle) { | |
370 // TODO(bmcquade): To improve accuracy, consider adding commit time to | |
371 // NavigationHandle. Taking a timestamp here should be close enough for now. | |
372 commit_time_ = base::TimeTicks::Now(); | |
373 ClampBrowserTimestampIfInterProcessTimeTickSkew(&commit_time_); | |
374 url_ = navigation_handle->GetURL(); | |
375 for (const auto& observer : observers_) { | |
376 observer->OnCommit(navigation_handle); | |
377 } | |
378 LogAbortChainHistograms(navigation_handle); | |
379 } | |
380 | |
381 void PageLoadTracker::FailedProvisionalLoad( | |
382 content::NavigationHandle* navigation_handle) { | |
383 DCHECK(!failed_provisional_load_info_); | |
384 failed_provisional_load_info_.reset(new FailedProvisionalLoadInfo( | |
385 base::TimeTicks::Now() - navigation_handle->NavigationStart(), | |
386 navigation_handle->GetNetErrorCode())); | |
387 } | |
388 | |
389 void PageLoadTracker::Redirect(content::NavigationHandle* navigation_handle) { | |
390 for (const auto& observer : observers_) { | |
391 observer->OnRedirect(navigation_handle); | |
392 } | |
393 } | |
394 | |
395 void PageLoadTracker::OnInputEvent(const blink::WebInputEvent& event) { | |
396 for (const auto& observer : observers_) { | |
397 observer->OnUserInput(event); | |
398 } | |
399 } | |
400 | |
401 void PageLoadTracker::NotifyClientRedirectTo( | |
402 const PageLoadTracker& destination) { | |
403 if (timing_.first_paint) { | |
404 base::TimeTicks first_paint_time = | |
405 navigation_start() + timing_.first_paint.value(); | |
406 base::TimeDelta first_paint_to_navigation; | |
407 if (destination.navigation_start() > first_paint_time) | |
408 first_paint_to_navigation = | |
409 destination.navigation_start() - first_paint_time; | |
410 PAGE_LOAD_HISTOGRAM(internal::kClientRedirectFirstPaintToNavigation, | |
411 first_paint_to_navigation); | |
412 } else { | |
413 UMA_HISTOGRAM_BOOLEAN(internal::kClientRedirectWithoutPaint, true); | |
414 } | |
415 } | |
416 | |
417 bool PageLoadTracker::UpdateTiming(const PageLoadTiming& new_timing, | |
418 const PageLoadMetadata& new_metadata) { | |
419 // Throw away IPCs that are not relevant to the current navigation. | |
420 // Two timing structures cannot refer to the same navigation if they indicate | |
421 // that a navigation started at different times, so a new timing struct with a | |
422 // different start time from an earlier struct is considered invalid. | |
423 bool valid_timing_descendent = | |
424 timing_.navigation_start.is_null() || | |
425 timing_.navigation_start == new_timing.navigation_start; | |
426 // Ensure flags sent previously are still present in the new metadata fields. | |
427 bool valid_behavior_descendent = | |
428 (metadata_.behavior_flags & new_metadata.behavior_flags) == | |
429 metadata_.behavior_flags; | |
430 if (IsValidPageLoadTiming(new_timing) && valid_timing_descendent && | |
431 valid_behavior_descendent) { | |
432 // There are some subtle ordering constraints here. GetPageLoadMetricsInfo() | |
433 // must be called before DispatchObserverTimingCallbacks, but its | |
434 // implementation depends on the state of metadata_, so we need to update | |
435 // metadata_ before calling GetPageLoadMetricsInfo. Thus, we make a copy of | |
436 // timing here, update timing_ and metadata_, and then proceed to dispatch | |
437 // the observer timing callbacks. | |
438 const PageLoadTiming last_timing = timing_; | |
439 timing_ = new_timing; | |
440 | |
441 const PageLoadMetadata last_metadata = metadata_; | |
442 metadata_ = new_metadata; | |
443 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); | |
444 for (const auto& observer : observers_) { | |
445 DispatchObserverTimingCallbacks(observer.get(), last_timing, new_timing, | |
446 last_metadata, info); | |
447 } | |
448 return true; | |
449 } | |
450 return false; | |
451 } | |
452 | |
453 void PageLoadTracker::StopTracking() { | |
454 did_stop_tracking_ = true; | |
455 } | |
456 | |
457 void PageLoadTracker::AddObserver( | |
458 std::unique_ptr<PageLoadMetricsObserver> observer) { | |
459 observers_.push_back(std::move(observer)); | |
460 } | |
461 | |
462 void PageLoadTracker::ClampBrowserTimestampIfInterProcessTimeTickSkew( | |
463 base::TimeTicks* event_time) { | |
464 DCHECK(event_time != nullptr); | |
465 // Windows 10 GCE bot non-deterministically failed because TimeTicks::Now() | |
466 // called in the browser process e.g. commit_time was less than | |
467 // navigation_start_ that was populated in the renderer process because the | |
468 // clock was not system-wide monotonic. | |
469 // Note that navigation_start_ can also be set in the browser process in | |
470 // some cases and in those cases event_time should never be < | |
471 // navigation_start_. If it is due to a code error and it gets clamped in this | |
472 // function, on high resolution systems it should lead to a dcheck failure. | |
473 | |
474 // TODO(shivanisha): Currently IsHighResolution is the best way to check | |
475 // if the clock is system-wide monotonic. However IsHighResolution | |
476 // does a broader check to see if the clock in use is high resolution | |
477 // which also implies it is system-wide monotonic (on Windows). | |
478 if (base::TimeTicks::IsHighResolution()) { | |
479 DCHECK(event_time->is_null() || *event_time >= navigation_start_); | |
480 return; | |
481 } | |
482 | |
483 if (!event_time->is_null() && *event_time < navigation_start_) { | |
484 RecordInternalError(ERR_INTER_PROCESS_TIME_TICK_SKEW); | |
485 *event_time = navigation_start_; | |
486 } | |
487 } | |
488 | |
489 PageLoadExtraInfo PageLoadTracker::ComputePageLoadExtraInfo() { | |
490 base::Optional<base::TimeDelta> first_background_time; | |
491 base::Optional<base::TimeDelta> first_foreground_time; | |
492 base::Optional<base::TimeDelta> time_to_abort; | |
493 base::Optional<base::TimeDelta> time_to_commit; | |
494 | |
495 if (!background_time_.is_null()) { | |
496 DCHECK_GE(background_time_, navigation_start_); | |
497 first_background_time = background_time_ - navigation_start_; | |
498 } | |
499 | |
500 if (!foreground_time_.is_null()) { | |
501 DCHECK_GE(foreground_time_, navigation_start_); | |
502 first_foreground_time = foreground_time_ - navigation_start_; | |
503 } | |
504 | |
505 if (abort_type_ != ABORT_NONE) { | |
506 DCHECK_GE(abort_time_, navigation_start_); | |
507 time_to_abort = abort_time_ - navigation_start_; | |
508 } else { | |
509 DCHECK(abort_time_.is_null()); | |
510 } | |
511 | |
512 if (!commit_time_.is_null()) { | |
513 DCHECK_GE(commit_time_, navigation_start_); | |
514 time_to_commit = commit_time_ - navigation_start_; | |
515 } | |
516 | |
517 return PageLoadExtraInfo( | |
518 first_background_time, first_foreground_time, started_in_foreground_, | |
519 commit_time_.is_null() ? GURL() : url_, time_to_commit, abort_type_, | |
520 time_to_abort, metadata_); | |
521 } | |
522 | |
523 void PageLoadTracker::NotifyAbort(UserAbortType abort_type, | |
524 base::TimeTicks timestamp, | |
525 bool is_certainly_browser_timestamp) { | |
526 DCHECK_NE(abort_type, ABORT_NONE); | |
527 // Use UpdateAbort to update an already notified PageLoadTracker. | |
528 if (abort_type_ != ABORT_NONE) | |
529 return; | |
530 | |
531 UpdateAbortInternal(abort_type, timestamp, is_certainly_browser_timestamp); | |
532 } | |
533 | |
534 void PageLoadTracker::UpdateAbort(UserAbortType abort_type, | |
535 base::TimeTicks timestamp, | |
536 bool is_certainly_browser_timestamp) { | |
537 DCHECK_NE(abort_type, ABORT_NONE); | |
538 DCHECK_NE(abort_type, ABORT_OTHER); | |
539 DCHECK_EQ(abort_type_, ABORT_OTHER); | |
540 | |
541 // For some aborts (e.g. navigations), the initiated timestamp can be earlier | |
542 // than the timestamp that aborted the load. Taking the minimum gives the | |
543 // closest user initiated time known. | |
544 UpdateAbortInternal(abort_type, std::min(abort_time_, timestamp), | |
545 is_certainly_browser_timestamp); | |
546 } | |
547 | |
548 bool PageLoadTracker::IsLikelyProvisionalAbort( | |
549 base::TimeTicks abort_cause_time) { | |
550 // Note that |abort_cause_time - abort_time| can be negative. | |
551 return abort_type_ == ABORT_OTHER && | |
552 (abort_cause_time - abort_time_).InMilliseconds() < 100; | |
553 } | |
554 | |
555 bool PageLoadTracker::MatchesOriginalNavigation( | |
556 content::NavigationHandle* navigation_handle) { | |
557 // Neither navigation should have committed. | |
558 DCHECK(!navigation_handle->HasCommitted()); | |
559 DCHECK(commit_time_.is_null()); | |
560 return navigation_handle->GetURL() == url_; | |
561 } | |
562 | |
563 void PageLoadTracker::UpdateAbortInternal(UserAbortType abort_type, | |
564 base::TimeTicks timestamp, | |
565 bool is_certainly_browser_timestamp) { | |
566 // When a provisional navigation commits, that navigation's start time is | |
567 // interpreted as the abort time for other provisional loads in the tab. | |
568 // However, this only makes sense if the committed load started after the | |
569 // aborted provisional loads started. Thus we ignore cases where the committed | |
570 // load started before the aborted provisional load, as this would result in | |
571 // recording a negative time-to-abort. The real issue here is that we have to | |
572 // infer the cause of aborts. It would be better if the navigation code could | |
573 // instead report the actual cause of an aborted navigation. See crbug/571647 | |
574 // for details. | |
575 if (timestamp < navigation_start_) { | |
576 RecordInternalError(ERR_ABORT_BEFORE_NAVIGATION_START); | |
577 abort_type_ = ABORT_NONE; | |
578 abort_time_ = base::TimeTicks(); | |
579 return; | |
580 } | |
581 abort_type_ = abort_type; | |
582 abort_time_ = timestamp; | |
583 | |
584 if (is_certainly_browser_timestamp) { | |
585 ClampBrowserTimestampIfInterProcessTimeTickSkew(&abort_time_); | |
586 } | |
587 } | |
588 | |
589 // static | |
590 MetricsWebContentsObserver::MetricsWebContentsObserver( | |
591 content::WebContents* web_contents, | |
592 std::unique_ptr<PageLoadMetricsEmbedderInterface> embedder_interface) | |
593 : content::WebContentsObserver(web_contents), | |
594 in_foreground_(false), | |
595 embedder_interface_(std::move(embedder_interface)), | |
596 has_navigated_(false) { | |
597 RegisterInputEventObserver(web_contents->GetRenderViewHost()); | |
598 } | |
599 | |
600 MetricsWebContentsObserver* MetricsWebContentsObserver::CreateForWebContents( | |
601 content::WebContents* web_contents, | |
602 std::unique_ptr<PageLoadMetricsEmbedderInterface> embedder_interface) { | |
603 DCHECK(web_contents); | |
604 | |
605 MetricsWebContentsObserver* metrics = FromWebContents(web_contents); | |
606 if (!metrics) { | |
607 metrics = new MetricsWebContentsObserver(web_contents, | |
608 std::move(embedder_interface)); | |
609 web_contents->SetUserData(UserDataKey(), metrics); | |
610 } | |
611 return metrics; | |
612 } | |
613 | |
614 MetricsWebContentsObserver::~MetricsWebContentsObserver() { | |
615 NotifyAbortAllLoads(ABORT_CLOSE); | |
616 } | |
617 | |
618 void MetricsWebContentsObserver::RegisterInputEventObserver( | |
619 content::RenderViewHost* host) { | |
620 if (host != nullptr) | |
621 host->GetWidget()->AddInputEventObserver(this); | |
622 } | |
623 | |
624 void MetricsWebContentsObserver::UnregisterInputEventObserver( | |
625 content::RenderViewHost* host) { | |
626 if (host != nullptr) | |
627 host->GetWidget()->RemoveInputEventObserver(this); | |
628 } | |
629 | |
630 void MetricsWebContentsObserver::RenderViewHostChanged( | |
631 content::RenderViewHost* old_host, | |
632 content::RenderViewHost* new_host) { | |
633 UnregisterInputEventObserver(old_host); | |
634 RegisterInputEventObserver(new_host); | |
635 } | |
636 | |
637 bool MetricsWebContentsObserver::OnMessageReceived( | |
638 const IPC::Message& message, | |
639 content::RenderFrameHost* render_frame_host) { | |
640 DCHECK_CURRENTLY_ON(content::BrowserThread::UI); | |
641 bool handled = true; | |
642 IPC_BEGIN_MESSAGE_MAP_WITH_PARAM(MetricsWebContentsObserver, message, | |
643 render_frame_host) | |
644 IPC_MESSAGE_HANDLER(PageLoadMetricsMsg_TimingUpdated, OnTimingUpdated) | |
645 IPC_MESSAGE_UNHANDLED(handled = false) | |
646 IPC_END_MESSAGE_MAP() | |
647 return handled; | |
648 } | |
649 | |
650 void MetricsWebContentsObserver::DidStartNavigation( | |
651 content::NavigationHandle* navigation_handle) { | |
652 if (!navigation_handle->IsInMainFrame()) | |
653 return; | |
654 | |
655 std::unique_ptr<PageLoadTracker> last_aborted = | |
656 NotifyAbortedProvisionalLoadsNewNavigation(navigation_handle); | |
657 | |
658 int chain_size_same_url = 0; | |
659 int chain_size = 0; | |
660 if (last_aborted) { | |
661 if (last_aborted->MatchesOriginalNavigation(navigation_handle)) { | |
662 chain_size_same_url = last_aborted->aborted_chain_size_same_url() + 1; | |
663 } else if (last_aborted->aborted_chain_size_same_url() > 0) { | |
664 LogAbortChainSameURLHistogram( | |
665 last_aborted->aborted_chain_size_same_url()); | |
666 } | |
667 chain_size = last_aborted->aborted_chain_size() + 1; | |
668 } | |
669 | |
670 if (!ShouldTrackNavigation(navigation_handle)) | |
671 return; | |
672 | |
673 // TODO(bmcquade): add support for tracking prerendered pages when they become | |
674 // visible. | |
675 if (embedder_interface_->IsPrerendering(web_contents())) | |
676 return; | |
677 | |
678 // Pass in the last committed url to the PageLoadTracker. If the MWCO has | |
679 // never observed a committed load, use the last committed url from this | |
680 // WebContent's opener. This is more accurate than using referrers due to | |
681 // referrer sanitizing and origin referrers. Note that this could potentially | |
682 // be inaccurate if the opener has since navigated. | |
683 content::WebContents* opener = web_contents()->GetOpener(); | |
684 const GURL& opener_url = | |
685 !has_navigated_ && opener | |
686 ? web_contents()->GetOpener()->GetLastCommittedURL() | |
687 : GURL::EmptyGURL(); | |
688 const GURL& currently_committed_url = | |
689 committed_load_ ? committed_load_->committed_url() : opener_url; | |
690 has_navigated_ = true; | |
691 | |
692 // We can have two provisional loads in some cases. E.g. a same-site | |
693 // navigation can have a concurrent cross-process navigation started | |
694 // from the omnibox. | |
695 DCHECK_GT(2ul, provisional_loads_.size()); | |
696 // Passing raw pointers to observers_ and embedder_interface_ is safe because | |
697 // the MetricsWebContentsObserver owns them both list and they are torn down | |
698 // after the PageLoadTracker. The PageLoadTracker does not hold on to | |
699 // committed_load_ or navigation_handle beyond the scope of the constructor. | |
700 provisional_loads_.insert(std::make_pair( | |
701 navigation_handle, | |
702 base::WrapUnique(new PageLoadTracker( | |
703 in_foreground_, embedder_interface_.get(), currently_committed_url, | |
704 navigation_handle, chain_size, chain_size_same_url)))); | |
705 } | |
706 | |
707 const PageLoadExtraInfo | |
708 MetricsWebContentsObserver::GetPageLoadExtraInfoForCommittedLoad() { | |
709 DCHECK(committed_load_); | |
710 return committed_load_->ComputePageLoadExtraInfo(); | |
711 } | |
712 | |
713 void MetricsWebContentsObserver::DidFinishNavigation( | |
714 content::NavigationHandle* navigation_handle) { | |
715 if (!navigation_handle->IsInMainFrame()) | |
716 return; | |
717 | |
718 std::unique_ptr<PageLoadTracker> finished_nav( | |
719 std::move(provisional_loads_[navigation_handle])); | |
720 provisional_loads_.erase(navigation_handle); | |
721 | |
722 const bool should_track = | |
723 finished_nav && ShouldTrackNavigation(navigation_handle); | |
724 | |
725 if (finished_nav && !should_track) | |
726 finished_nav->StopTracking(); | |
727 | |
728 if (navigation_handle->HasCommitted()) { | |
729 // Ignore same-page navigations. | |
730 if (navigation_handle->IsSamePage()) | |
731 return; | |
732 | |
733 // Notify other loads that they may have been aborted by this committed | |
734 // load. Note that by using the committed navigation start as the abort | |
735 // cause, we lose data on provisional loads that were aborted by other | |
736 // provisional loads. Those will either be listed as ABORT_OTHER or as being | |
737 // aborted by this load. | |
738 // is_certainly_browser_timestamp is set to false because NavigationStart() | |
739 // could be set in either the renderer or browser process. | |
740 NotifyAbortAllLoadsWithTimestamp( | |
741 AbortTypeForPageTransition(navigation_handle->GetPageTransition()), | |
742 navigation_handle->NavigationStart(), false); | |
743 | |
744 if (should_track) { | |
745 HandleCommittedNavigationForTrackedLoad(navigation_handle, | |
746 std::move(finished_nav)); | |
747 } else { | |
748 committed_load_.reset(); | |
749 } | |
750 } else if (should_track) { | |
751 HandleFailedNavigationForTrackedLoad(navigation_handle, | |
752 std::move(finished_nav)); | |
753 } | |
754 } | |
755 | |
756 // Handle a pre-commit error. Navigations that result in an error page will be | |
757 // ignored. Note that downloads/204s will result in HasCommitted() returning | |
758 // false. | |
759 // TODO(csharrison): Track changes to NavigationHandle for signals when this is | |
760 // the case (HTTP response headers). | |
761 void MetricsWebContentsObserver::HandleFailedNavigationForTrackedLoad( | |
762 content::NavigationHandle* navigation_handle, | |
763 std::unique_ptr<PageLoadTracker> tracker) { | |
764 tracker->FailedProvisionalLoad(navigation_handle); | |
765 | |
766 net::Error error = navigation_handle->GetNetErrorCode(); | |
767 | |
768 // net::OK: This case occurs when the NavigationHandle finishes and reports | |
769 // !HasCommitted(), but reports no net::Error. This should not occur | |
770 // pre-PlzNavigate, but afterwards it should represent the navigation stopped | |
771 // by the user before it was ready to commit. | |
772 // net::ERR_ABORTED: An aborted provisional load has error | |
773 // net::ERR_ABORTED. Note that this can come from some non user-initiated | |
774 // errors, such as downloads, or 204 responses. See crbug.com/542369. | |
775 if ((error == net::OK) || (error == net::ERR_ABORTED)) { | |
776 tracker->NotifyAbort(ABORT_OTHER, base::TimeTicks::Now(), true); | |
777 aborted_provisional_loads_.push_back(std::move(tracker)); | |
778 } | |
779 } | |
780 | |
781 void MetricsWebContentsObserver::HandleCommittedNavigationForTrackedLoad( | |
782 content::NavigationHandle* navigation_handle, | |
783 std::unique_ptr<PageLoadTracker> tracker) { | |
784 if (!navigation_handle->HasUserGesture() && | |
785 (navigation_handle->GetPageTransition() & | |
786 ui::PAGE_TRANSITION_CLIENT_REDIRECT) != 0 && | |
787 committed_load_) | |
788 committed_load_->NotifyClientRedirectTo(*tracker); | |
789 | |
790 committed_load_ = std::move(tracker); | |
791 committed_load_->Commit(navigation_handle); | |
792 } | |
793 | |
794 void MetricsWebContentsObserver::NavigationStopped() { | |
795 NotifyAbortAllLoads(ABORT_STOP); | |
796 } | |
797 | |
798 void MetricsWebContentsObserver::OnInputEvent( | |
799 const blink::WebInputEvent& event) { | |
800 // Ignore browser navigation or reload which comes with type Undefined. | |
801 if (event.type == blink::WebInputEvent::Type::Undefined) | |
802 return; | |
803 | |
804 if (committed_load_) | |
805 committed_load_->OnInputEvent(event); | |
806 } | |
807 | |
808 void MetricsWebContentsObserver::DidRedirectNavigation( | |
809 content::NavigationHandle* navigation_handle) { | |
810 if (!navigation_handle->IsInMainFrame()) | |
811 return; | |
812 auto it = provisional_loads_.find(navigation_handle); | |
813 if (it == provisional_loads_.end()) | |
814 return; | |
815 it->second->Redirect(navigation_handle); | |
816 } | |
817 | |
818 void MetricsWebContentsObserver::WasShown() { | |
819 if (in_foreground_) | |
820 return; | |
821 in_foreground_ = true; | |
822 if (committed_load_) | |
823 committed_load_->WebContentsShown(); | |
824 for (const auto& kv : provisional_loads_) { | |
825 kv.second->WebContentsShown(); | |
826 } | |
827 } | |
828 | |
829 void MetricsWebContentsObserver::WasHidden() { | |
830 if (!in_foreground_) | |
831 return; | |
832 in_foreground_ = false; | |
833 if (committed_load_) | |
834 committed_load_->WebContentsHidden(); | |
835 for (const auto& kv : provisional_loads_) { | |
836 kv.second->WebContentsHidden(); | |
837 } | |
838 } | |
839 | |
840 // This will occur when the process for the main RenderFrameHost exits, either | |
841 // normally or from a crash. We eagerly log data from the last committed load if | |
842 // we have one. Don't notify aborts here because this is probably not user | |
843 // initiated. If it is (e.g. browser shutdown), other code paths will take care | |
844 // of notifying. | |
845 void MetricsWebContentsObserver::RenderProcessGone( | |
846 base::TerminationStatus status) { | |
847 // Other code paths will be run for normal renderer shutdown. Note that we | |
848 // sometimes get the STILL_RUNNING value on fast shutdown. | |
849 if (status == base::TERMINATION_STATUS_NORMAL_TERMINATION || | |
850 status == base::TERMINATION_STATUS_STILL_RUNNING) { | |
851 return; | |
852 } | |
853 | |
854 // If this is a crash, eagerly log the aborted provisional loads and the | |
855 // committed load. |provisional_loads_| don't need to be destroyed here | |
856 // because their lifetime is tied to the NavigationHandle. | |
857 committed_load_.reset(); | |
858 aborted_provisional_loads_.clear(); | |
859 } | |
860 | |
861 void MetricsWebContentsObserver::NotifyAbortAllLoads(UserAbortType abort_type) { | |
862 NotifyAbortAllLoadsWithTimestamp(abort_type, base::TimeTicks::Now(), true); | |
863 } | |
864 | |
865 void MetricsWebContentsObserver::NotifyAbortAllLoadsWithTimestamp( | |
866 UserAbortType abort_type, | |
867 base::TimeTicks timestamp, | |
868 bool is_certainly_browser_timestamp) { | |
869 if (committed_load_) | |
870 committed_load_->NotifyAbort(abort_type, timestamp, | |
871 is_certainly_browser_timestamp); | |
872 for (const auto& kv : provisional_loads_) { | |
873 kv.second->NotifyAbort(abort_type, timestamp, | |
874 is_certainly_browser_timestamp); | |
875 } | |
876 for (const auto& tracker : aborted_provisional_loads_) { | |
877 if (tracker->IsLikelyProvisionalAbort(timestamp)) | |
878 tracker->UpdateAbort(abort_type, timestamp, | |
879 is_certainly_browser_timestamp); | |
880 } | |
881 aborted_provisional_loads_.clear(); | |
882 } | |
883 | |
884 std::unique_ptr<PageLoadTracker> | |
885 MetricsWebContentsObserver::NotifyAbortedProvisionalLoadsNewNavigation( | |
886 content::NavigationHandle* new_navigation) { | |
887 // If there are multiple aborted loads that can be attributed to this one, | |
888 // just count the latest one for simplicity. Other loads will fall into the | |
889 // OTHER bucket, though there shouldn't be very many. | |
890 if (aborted_provisional_loads_.size() == 0) | |
891 return nullptr; | |
892 if (aborted_provisional_loads_.size() > 1) | |
893 RecordInternalError(ERR_NAVIGATION_SIGNALS_MULIPLE_ABORTED_LOADS); | |
894 | |
895 std::unique_ptr<PageLoadTracker> last_aborted_load = | |
896 std::move(aborted_provisional_loads_.back()); | |
897 aborted_provisional_loads_.pop_back(); | |
898 | |
899 base::TimeTicks timestamp = new_navigation->NavigationStart(); | |
900 if (last_aborted_load->IsLikelyProvisionalAbort(timestamp)) | |
901 last_aborted_load->UpdateAbort(ABORT_UNKNOWN_NAVIGATION, timestamp, false); | |
902 | |
903 aborted_provisional_loads_.clear(); | |
904 return last_aborted_load; | |
905 } | |
906 | |
907 void MetricsWebContentsObserver::OnTimingUpdated( | |
908 content::RenderFrameHost* render_frame_host, | |
909 const PageLoadTiming& timing, | |
910 const PageLoadMetadata& metadata) { | |
911 bool error = false; | |
912 if (!committed_load_) { | |
913 RecordInternalError(ERR_IPC_WITH_NO_RELEVANT_LOAD); | |
914 error = true; | |
915 } | |
916 | |
917 // We may receive notifications from frames that have been navigated away | |
918 // from. We simply ignore them. | |
919 if (render_frame_host != web_contents()->GetMainFrame()) { | |
920 RecordInternalError(ERR_IPC_FROM_WRONG_FRAME); | |
921 error = true; | |
922 } | |
923 | |
924 // For urls like chrome://newtab, the renderer and browser disagree, | |
925 // so we have to double check that the renderer isn't sending data from a | |
926 // bad url like https://www.google.com/_/chrome/newtab. | |
927 if (!web_contents()->GetLastCommittedURL().SchemeIsHTTPOrHTTPS()) { | |
928 RecordInternalError(ERR_IPC_FROM_BAD_URL_SCHEME); | |
929 error = true; | |
930 } | |
931 | |
932 if (error) | |
933 return; | |
934 | |
935 if (!committed_load_->UpdateTiming(timing, metadata)) { | |
936 // If the page load tracker cannot update its timing, something is wrong | |
937 // with the IPC (it's from another load, or it's invalid in some other way). | |
938 // We expect this to be a rare occurrence. | |
939 RecordInternalError(ERR_BAD_TIMING_IPC); | |
940 } | |
941 } | |
942 | |
943 bool MetricsWebContentsObserver::ShouldTrackNavigation( | |
944 content::NavigationHandle* navigation_handle) const { | |
945 DCHECK(navigation_handle->IsInMainFrame()); | |
946 if (!navigation_handle->GetURL().SchemeIsHTTPOrHTTPS()) | |
947 return false; | |
948 if (embedder_interface_->IsNewTabPageUrl(navigation_handle->GetURL())) | |
949 return false; | |
950 if (navigation_handle->HasCommitted()) { | |
951 if (navigation_handle->IsSamePage() || navigation_handle->IsErrorPage()) | |
952 return false; | |
953 const std::string& mime_type = web_contents()->GetContentsMimeType(); | |
954 if (mime_type != "text/html" && mime_type != "application/xhtml+xml") | |
955 return false; | |
956 } | |
957 return true; | |
958 } | |
959 | |
960 } // namespace page_load_metrics | |
OLD | NEW |