OLD | NEW |
1 // Copyright 2016 The Chromium Authors. All rights reserved. | 1 // Copyright 2016 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_tracker.h" |
6 | 6 |
7 #include <algorithm> | 7 #include <algorithm> |
8 #include <ostream> | 8 #include <ostream> |
9 #include <string> | 9 #include <string> |
10 #include <utility> | 10 #include <utility> |
11 | 11 |
12 #include "base/logging.h" | 12 #include "base/logging.h" |
13 #include "base/memory/ptr_util.h" | 13 #include "base/memory/ptr_util.h" |
14 #include "base/metrics/histogram_macros.h" | 14 #include "base/metrics/histogram_macros.h" |
15 #include "chrome/browser/page_load_metrics/browser_page_track_decider.h" | |
16 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface.
h" | 15 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface.
h" |
17 #include "chrome/browser/page_load_metrics/page_load_metrics_util.h" | 16 #include "chrome/browser/page_load_metrics/page_load_metrics_util.h" |
18 #include "chrome/browser/prerender/prerender_contents.h" | 17 #include "chrome/browser/prerender/prerender_contents.h" |
19 #include "chrome/common/page_load_metrics/page_load_timing.h" | 18 #include "chrome/common/page_load_metrics/page_load_timing.h" |
20 #include "content/public/browser/navigation_details.h" | 19 #include "content/public/browser/navigation_details.h" |
21 #include "content/public/browser/navigation_handle.h" | 20 #include "content/public/browser/navigation_handle.h" |
22 #include "content/public/browser/render_frame_host.h" | 21 #include "content/public/browser/render_frame_host.h" |
23 #include "content/public/browser/web_contents.h" | 22 #include "content/public/browser/web_contents.h" |
24 #include "content/public/browser/web_contents_observer.h" | 23 #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" | 24 #include "ui/base/page_transition_types.h" |
27 | 25 |
28 // This macro invokes the specified method on each observer, passing the | 26 // This macro invokes the specified method on each observer, passing the |
29 // variable length arguments as the method's arguments, and removes the observer | 27 // 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. | 28 // from the list of observers if the given method returns STOP_OBSERVING. |
31 #define INVOKE_AND_PRUNE_OBSERVERS(observers, Method, ...) \ | 29 #define INVOKE_AND_PRUNE_OBSERVERS(observers, Method, ...) \ |
32 for (auto it = observers.begin(); it != observers.end();) { \ | 30 for (auto it = observers.begin(); it != observers.end();) { \ |
33 if ((*it)->Method(__VA_ARGS__) == \ | 31 if ((*it)->Method(__VA_ARGS__) == \ |
34 PageLoadMetricsObserver::STOP_OBSERVING) { \ | 32 PageLoadMetricsObserver::STOP_OBSERVING) { \ |
35 it = observers.erase(it); \ | 33 it = observers.erase(it); \ |
(...skipping 19 matching lines...) Expand all Loading... |
55 "PageLoad.Internal.ProvisionalAbortChainSize.NoCommit"; | 53 "PageLoad.Internal.ProvisionalAbortChainSize.NoCommit"; |
56 const char kClientRedirectFirstPaintToNavigation[] = | 54 const char kClientRedirectFirstPaintToNavigation[] = |
57 "PageLoad.Internal.ClientRedirect.FirstPaintToNavigation"; | 55 "PageLoad.Internal.ClientRedirect.FirstPaintToNavigation"; |
58 const char kClientRedirectWithoutPaint[] = | 56 const char kClientRedirectWithoutPaint[] = |
59 "PageLoad.Internal.ClientRedirect.NavigationWithoutPaint"; | 57 "PageLoad.Internal.ClientRedirect.NavigationWithoutPaint"; |
60 const char kPageLoadCompletedAfterAppBackground[] = | 58 const char kPageLoadCompletedAfterAppBackground[] = |
61 "PageLoad.Internal.PageLoadCompleted.AfterAppBackground"; | 59 "PageLoad.Internal.PageLoadCompleted.AfterAppBackground"; |
62 const char kPageLoadStartedInForeground[] = | 60 const char kPageLoadStartedInForeground[] = |
63 "PageLoad.Internal.NavigationStartedInForeground"; | 61 "PageLoad.Internal.NavigationStartedInForeground"; |
64 const char kPageLoadPrerender[] = "PageLoad.Internal.Prerender"; | 62 const char kPageLoadPrerender[] = "PageLoad.Internal.Prerender"; |
65 const char kPageLoadTimingStatus[] = "PageLoad.Internal.PageLoadTimingStatus"; | |
66 const char kPageLoadTimingDispatchStatus[] = | |
67 "PageLoad.Internal.PageLoadTimingStatus.AtTimingCallbackDispatch"; | |
68 | 63 |
69 } // namespace internal | 64 } // namespace internal |
70 | 65 |
71 void RecordInternalError(InternalErrorLoadEvent event) { | 66 void RecordInternalError(InternalErrorLoadEvent event) { |
72 UMA_HISTOGRAM_ENUMERATION(internal::kErrorEvents, event, ERR_LAST_ENTRY); | 67 UMA_HISTOGRAM_ENUMERATION(internal::kErrorEvents, event, ERR_LAST_ENTRY); |
73 } | 68 } |
74 | 69 |
75 // TODO(csharrison): Add a case for client side redirects, which is what JS | 70 // TODO(csharrison): Add a case for client side redirects, which is what JS |
76 // initiated window.location / window.history navigations get set to. | 71 // initiated window.location / window.history navigations get set to. |
77 PageEndReason EndReasonForPageTransition(ui::PageTransition transition) { | 72 PageEndReason EndReasonForPageTransition(ui::PageTransition transition) { |
(...skipping 26 matching lines...) Expand all Loading... |
104 // | 99 // |
105 // TODO(crbug.com/637345): Some browser-initiated navigations incorrectly | 100 // TODO(crbug.com/637345): Some browser-initiated navigations incorrectly |
106 // report that they are renderer-initiated. We will currently report that | 101 // report that they are renderer-initiated. We will currently report that |
107 // these navigations are not user initiated, when in fact they are user | 102 // these navigations are not user initiated, when in fact they are user |
108 // initiated. | 103 // initiated. |
109 return handle->HasUserGesture() || !handle->IsRendererInitiated(); | 104 return handle->HasUserGesture() || !handle->IsRendererInitiated(); |
110 } | 105 } |
111 | 106 |
112 namespace { | 107 namespace { |
113 | 108 |
114 // Helper to allow use of Optional<> values in LOG() messages. | |
115 std::ostream& operator<<(std::ostream& os, | |
116 const base::Optional<base::TimeDelta>& opt) { | |
117 if (opt) | |
118 os << opt.value(); | |
119 else | |
120 os << "(unset)"; | |
121 return os; | |
122 } | |
123 | |
124 // If second is non-zero, first must also be non-zero and less than or equal to | |
125 // second. | |
126 bool EventsInOrder(const base::Optional<base::TimeDelta>& first, | |
127 const base::Optional<base::TimeDelta>& second) { | |
128 if (!second) { | |
129 return true; | |
130 } | |
131 return first && first <= second; | |
132 } | |
133 | |
134 internal::PageLoadTimingStatus IsValidPageLoadTiming( | |
135 const mojom::PageLoadTiming& timing) { | |
136 if (page_load_metrics::IsEmpty(timing)) | |
137 return internal::INVALID_EMPTY_TIMING; | |
138 | |
139 // If we have a non-empty timing, it should always have a navigation start. | |
140 if (timing.navigation_start.is_null()) { | |
141 LOG(ERROR) << "Received null navigation_start."; | |
142 return internal::INVALID_NULL_NAVIGATION_START; | |
143 } | |
144 | |
145 // Verify proper ordering between the various timings. | |
146 | |
147 if (!EventsInOrder(timing.response_start, timing.parse_timing->parse_start)) { | |
148 // We sometimes get a zero response_start with a non-zero parse start. See | |
149 // crbug.com/590212. | |
150 LOG(ERROR) << "Invalid response_start " << timing.response_start | |
151 << " for parse_start " << timing.parse_timing->parse_start; | |
152 // When browser-side navigation is enabled, we sometimes encounter this | |
153 // error case. For now, we disable reporting of this error, since most | |
154 // PageLoadMetricsObservers don't care about response_start and we want to | |
155 // see how much closer fixing this error will get us to page load metrics | |
156 // being consistent with and without browser side navigation enabled. See | |
157 // crbug.com/716587 for more details. | |
158 // | |
159 // return internal::INVALID_ORDER_RESPONSE_START_PARSE_START; | |
160 } | |
161 | |
162 if (!EventsInOrder(timing.parse_timing->parse_start, | |
163 timing.parse_timing->parse_stop)) { | |
164 LOG(ERROR) << "Invalid parse_start " << timing.parse_timing->parse_start | |
165 << " for parse_stop " << timing.parse_timing->parse_stop; | |
166 return internal::INVALID_ORDER_PARSE_START_PARSE_STOP; | |
167 } | |
168 | |
169 if (timing.parse_timing->parse_stop) { | |
170 const base::TimeDelta parse_duration = | |
171 timing.parse_timing->parse_stop.value() - | |
172 timing.parse_timing->parse_start.value(); | |
173 if (timing.parse_timing->parse_blocked_on_script_load_duration > | |
174 parse_duration) { | |
175 LOG(ERROR) << "Invalid parse_blocked_on_script_load_duration " | |
176 << timing.parse_timing->parse_blocked_on_script_load_duration | |
177 << " for parse duration " << parse_duration; | |
178 return internal::INVALID_SCRIPT_LOAD_LONGER_THAN_PARSE; | |
179 } | |
180 if (timing.parse_timing->parse_blocked_on_script_execution_duration > | |
181 parse_duration) { | |
182 LOG(ERROR) | |
183 << "Invalid parse_blocked_on_script_execution_duration " | |
184 << timing.parse_timing->parse_blocked_on_script_execution_duration | |
185 << " for parse duration " << parse_duration; | |
186 return internal::INVALID_SCRIPT_EXEC_LONGER_THAN_PARSE; | |
187 } | |
188 } | |
189 | |
190 if (timing.parse_timing | |
191 ->parse_blocked_on_script_load_from_document_write_duration > | |
192 timing.parse_timing->parse_blocked_on_script_load_duration) { | |
193 LOG(ERROR) | |
194 << "Invalid parse_blocked_on_script_load_from_document_write_duration " | |
195 << timing.parse_timing | |
196 ->parse_blocked_on_script_load_from_document_write_duration | |
197 << " for parse_blocked_on_script_load_duration " | |
198 << timing.parse_timing->parse_blocked_on_script_load_duration; | |
199 return internal::INVALID_SCRIPT_LOAD_DOC_WRITE_LONGER_THAN_SCRIPT_LOAD; | |
200 } | |
201 | |
202 if (timing.parse_timing | |
203 ->parse_blocked_on_script_execution_from_document_write_duration > | |
204 timing.parse_timing->parse_blocked_on_script_execution_duration) { | |
205 LOG(ERROR) | |
206 << "Invalid " | |
207 "parse_blocked_on_script_execution_from_document_write_duration " | |
208 << timing.parse_timing | |
209 ->parse_blocked_on_script_execution_from_document_write_duration | |
210 << " for parse_blocked_on_script_execution_duration " | |
211 << timing.parse_timing->parse_blocked_on_script_execution_duration; | |
212 return internal::INVALID_SCRIPT_EXEC_DOC_WRITE_LONGER_THAN_SCRIPT_EXEC; | |
213 } | |
214 | |
215 if (!EventsInOrder(timing.parse_timing->parse_stop, | |
216 timing.document_timing->dom_content_loaded_event_start)) { | |
217 LOG(ERROR) << "Invalid parse_stop " << timing.parse_timing->parse_stop | |
218 << " for dom_content_loaded_event_start " | |
219 << timing.document_timing->dom_content_loaded_event_start; | |
220 return internal::INVALID_ORDER_PARSE_STOP_DOM_CONTENT_LOADED; | |
221 } | |
222 | |
223 if (!EventsInOrder(timing.document_timing->dom_content_loaded_event_start, | |
224 timing.document_timing->load_event_start)) { | |
225 LOG(ERROR) << "Invalid dom_content_loaded_event_start " | |
226 << timing.document_timing->dom_content_loaded_event_start | |
227 << " for load_event_start " | |
228 << timing.document_timing->load_event_start; | |
229 return internal::INVALID_ORDER_DOM_CONTENT_LOADED_LOAD; | |
230 } | |
231 | |
232 if (!EventsInOrder(timing.parse_timing->parse_start, | |
233 timing.document_timing->first_layout)) { | |
234 LOG(ERROR) << "Invalid parse_start " << timing.parse_timing->parse_start | |
235 << " for first_layout " << timing.document_timing->first_layout; | |
236 return internal::INVALID_ORDER_PARSE_START_FIRST_LAYOUT; | |
237 } | |
238 | |
239 if (!EventsInOrder(timing.document_timing->first_layout, | |
240 timing.paint_timing->first_paint)) { | |
241 // This can happen when we process an XHTML document that doesn't contain | |
242 // well formed XML. See crbug.com/627607. | |
243 DLOG(ERROR) << "Invalid first_layout " | |
244 << timing.document_timing->first_layout << " for first_paint " | |
245 << timing.paint_timing->first_paint; | |
246 return internal::INVALID_ORDER_FIRST_LAYOUT_FIRST_PAINT; | |
247 } | |
248 | |
249 if (!EventsInOrder(timing.paint_timing->first_paint, | |
250 timing.paint_timing->first_text_paint)) { | |
251 LOG(ERROR) << "Invalid first_paint " << timing.paint_timing->first_paint | |
252 << " for first_text_paint " | |
253 << timing.paint_timing->first_text_paint; | |
254 return internal::INVALID_ORDER_FIRST_PAINT_FIRST_TEXT_PAINT; | |
255 } | |
256 | |
257 if (!EventsInOrder(timing.paint_timing->first_paint, | |
258 timing.paint_timing->first_image_paint)) { | |
259 LOG(ERROR) << "Invalid first_paint " << timing.paint_timing->first_paint | |
260 << " for first_image_paint " | |
261 << timing.paint_timing->first_image_paint; | |
262 return internal::INVALID_ORDER_FIRST_PAINT_FIRST_IMAGE_PAINT; | |
263 } | |
264 | |
265 if (!EventsInOrder(timing.paint_timing->first_paint, | |
266 timing.paint_timing->first_contentful_paint)) { | |
267 LOG(ERROR) << "Invalid first_paint " << timing.paint_timing->first_paint | |
268 << " for first_contentful_paint " | |
269 << timing.paint_timing->first_contentful_paint; | |
270 return internal::INVALID_ORDER_FIRST_PAINT_FIRST_CONTENTFUL_PAINT; | |
271 } | |
272 | |
273 if (!EventsInOrder(timing.paint_timing->first_paint, | |
274 timing.paint_timing->first_meaningful_paint)) { | |
275 LOG(ERROR) << "Invalid first_paint " << timing.paint_timing->first_paint | |
276 << " for first_meaningful_paint " | |
277 << timing.paint_timing->first_meaningful_paint; | |
278 return internal::INVALID_ORDER_FIRST_PAINT_FIRST_MEANINGFUL_PAINT; | |
279 } | |
280 | |
281 return internal::VALID; | |
282 } | |
283 | |
284 // Updates *|inout_existing_value| with |optional_candidate_new_value|, if | |
285 // either *|inout_existing_value| isn't set, or |optional_candidate_new_value| < | |
286 // |inout_existing_value|. | |
287 void MaybeUpdateTimeDelta( | |
288 base::Optional<base::TimeDelta>* inout_existing_value, | |
289 base::TimeDelta navigation_start_offset, | |
290 const base::Optional<base::TimeDelta>& optional_candidate_new_value) { | |
291 // If we don't get a new value, there's nothing to do | |
292 if (!optional_candidate_new_value) | |
293 return; | |
294 | |
295 // optional_candidate_new_value is relative to navigation start in its | |
296 // frame. We need to adjust it to be relative to navigation start in the main | |
297 // frame, so offset it by navigation_start_offset. | |
298 base::TimeDelta candidate_new_value = | |
299 navigation_start_offset + optional_candidate_new_value.value(); | |
300 | |
301 if (*inout_existing_value) { | |
302 // If we have a new value, but it is after the existing value, then keep the | |
303 // existing value. | |
304 if (*inout_existing_value <= candidate_new_value) | |
305 return; | |
306 | |
307 // We received a new timing event, but with a timestamp before the timestamp | |
308 // of a timing update we had received previously. We expect this to happen | |
309 // occasionally, as inter-frame updates can arrive out of order. Record a | |
310 // histogram to track how frequently it happens, along with the magnitude | |
311 // of the delta. | |
312 PAGE_LOAD_HISTOGRAM("PageLoad.Internal.OutOfOrderInterFrameTiming", | |
313 inout_existing_value->value() - candidate_new_value); | |
314 } | |
315 | |
316 *inout_existing_value = candidate_new_value; | |
317 } | |
318 | |
319 void RecordAppBackgroundPageLoadCompleted(bool completed_after_background) { | 109 void RecordAppBackgroundPageLoadCompleted(bool completed_after_background) { |
320 UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadCompletedAfterAppBackground, | 110 UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadCompletedAfterAppBackground, |
321 completed_after_background); | 111 completed_after_background); |
322 } | 112 } |
323 | 113 |
324 void DispatchObserverTimingCallbacks( | 114 void DispatchObserverTimingCallbacks( |
325 PageLoadMetricsObserver* observer, | 115 PageLoadMetricsObserver* observer, |
326 const mojom::PageLoadTiming& last_timing, | 116 const mojom::PageLoadTiming& last_timing, |
327 const mojom::PageLoadTiming& new_timing, | 117 const mojom::PageLoadTiming& new_timing, |
328 const mojom::PageLoadMetadata& last_metadata, | |
329 const PageLoadExtraInfo& extra_info) { | 118 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)) | 119 if (!last_timing.Equals(new_timing)) |
334 observer->OnTimingUpdate(new_timing, extra_info); | 120 observer->OnTimingUpdate(new_timing, extra_info); |
335 if (new_timing.document_timing->dom_content_loaded_event_start && | 121 if (new_timing.document_timing->dom_content_loaded_event_start && |
336 !last_timing.document_timing->dom_content_loaded_event_start) | 122 !last_timing.document_timing->dom_content_loaded_event_start) |
337 observer->OnDomContentLoadedEventStart(new_timing, extra_info); | 123 observer->OnDomContentLoadedEventStart(new_timing, extra_info); |
338 if (new_timing.document_timing->load_event_start && | 124 if (new_timing.document_timing->load_event_start && |
339 !last_timing.document_timing->load_event_start) | 125 !last_timing.document_timing->load_event_start) |
340 observer->OnLoadEventStart(new_timing, extra_info); | 126 observer->OnLoadEventStart(new_timing, extra_info); |
341 if (new_timing.document_timing->first_layout && | 127 if (new_timing.document_timing->first_layout && |
342 !last_timing.document_timing->first_layout) | 128 !last_timing.document_timing->first_layout) |
(...skipping 33 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
376 int aborted_chain_size_same_url) | 162 int aborted_chain_size_same_url) |
377 : did_stop_tracking_(false), | 163 : did_stop_tracking_(false), |
378 app_entered_background_(false), | 164 app_entered_background_(false), |
379 navigation_start_(navigation_handle->NavigationStart()), | 165 navigation_start_(navigation_handle->NavigationStart()), |
380 url_(navigation_handle->GetURL()), | 166 url_(navigation_handle->GetURL()), |
381 start_url_(navigation_handle->GetURL()), | 167 start_url_(navigation_handle->GetURL()), |
382 did_commit_(false), | 168 did_commit_(false), |
383 page_end_reason_(END_NONE), | 169 page_end_reason_(END_NONE), |
384 page_end_user_initiated_info_(UserInitiatedInfo::NotUserInitiated()), | 170 page_end_user_initiated_info_(UserInitiatedInfo::NotUserInitiated()), |
385 started_in_foreground_(in_foreground), | 171 started_in_foreground_(in_foreground), |
386 merged_page_timing_(CreatePageLoadTiming()), | |
387 last_dispatched_merged_page_timing_(CreatePageLoadTiming()), | 172 last_dispatched_merged_page_timing_(CreatePageLoadTiming()), |
388 last_dispatched_main_frame_metadata_(mojom::PageLoadMetadata::New()), | |
389 page_transition_(navigation_handle->GetPageTransition()), | 173 page_transition_(navigation_handle->GetPageTransition()), |
390 user_initiated_info_(user_initiated_info), | 174 user_initiated_info_(user_initiated_info), |
391 aborted_chain_size_(aborted_chain_size), | 175 aborted_chain_size_(aborted_chain_size), |
392 aborted_chain_size_same_url_(aborted_chain_size_same_url), | 176 aborted_chain_size_same_url_(aborted_chain_size_same_url), |
393 embedder_interface_(embedder_interface) { | 177 embedder_interface_(embedder_interface), |
| 178 metrics_update_dispatcher_(this, navigation_handle, embedder_interface) { |
394 DCHECK(!navigation_handle->HasCommitted()); | 179 DCHECK(!navigation_handle->HasCommitted()); |
395 embedder_interface_->RegisterObservers(this); | 180 embedder_interface_->RegisterObservers(this); |
396 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnStart, navigation_handle, | 181 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnStart, navigation_handle, |
397 currently_committed_url, started_in_foreground_); | 182 currently_committed_url, started_in_foreground_); |
398 | 183 |
399 UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadStartedInForeground, | 184 UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadStartedInForeground, |
400 started_in_foreground_); | 185 started_in_foreground_); |
401 const bool is_prerender = prerender::PrerenderContents::FromWebContents( | 186 const bool is_prerender = prerender::PrerenderContents::FromWebContents( |
402 navigation_handle->GetWebContents()) != nullptr; | 187 navigation_handle->GetWebContents()) != nullptr; |
403 if (is_prerender) { | 188 if (is_prerender) { |
(...skipping 22 matching lines...) Expand all Loading... |
426 if (!failed_provisional_load_info_) | 211 if (!failed_provisional_load_info_) |
427 RecordInternalError(ERR_NO_COMMIT_OR_FAILED_PROVISIONAL_LOAD); | 212 RecordInternalError(ERR_NO_COMMIT_OR_FAILED_PROVISIONAL_LOAD); |
428 | 213 |
429 // Don't include any aborts that resulted in a new navigation, as the chain | 214 // Don't include any aborts that resulted in a new navigation, as the chain |
430 // length will be included in the aborter PageLoadTracker. | 215 // length will be included in the aborter PageLoadTracker. |
431 if (page_end_reason_ != END_RELOAD && | 216 if (page_end_reason_ != END_RELOAD && |
432 page_end_reason_ != END_FORWARD_BACK && | 217 page_end_reason_ != END_FORWARD_BACK && |
433 page_end_reason_ != END_NEW_NAVIGATION) { | 218 page_end_reason_ != END_NEW_NAVIGATION) { |
434 LogAbortChainHistograms(nullptr); | 219 LogAbortChainHistograms(nullptr); |
435 } | 220 } |
436 } else if (page_load_metrics::IsEmpty(*merged_page_timing_)) { | 221 } else if (page_load_metrics::IsEmpty(metrics_update_dispatcher_.timing())) { |
437 RecordInternalError(ERR_NO_IPCS_RECEIVED); | 222 RecordInternalError(ERR_NO_IPCS_RECEIVED); |
438 } | 223 } |
439 | 224 |
440 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); | 225 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); |
441 for (const auto& observer : observers_) { | 226 for (const auto& observer : observers_) { |
442 if (failed_provisional_load_info_) { | 227 if (failed_provisional_load_info_) { |
443 observer->OnFailedProvisionalLoad(*failed_provisional_load_info_, info); | 228 observer->OnFailedProvisionalLoad(*failed_provisional_load_info_, info); |
444 } else if (did_commit_) { | 229 } else if (did_commit_) { |
445 observer->OnComplete(*merged_page_timing_, info); | 230 observer->OnComplete(metrics_update_dispatcher_.timing(), info); |
446 } | 231 } |
447 } | 232 } |
448 } | 233 } |
449 | 234 |
450 void PageLoadTracker::LogAbortChainHistograms( | 235 void PageLoadTracker::LogAbortChainHistograms( |
451 content::NavigationHandle* final_navigation) { | 236 content::NavigationHandle* final_navigation) { |
452 if (aborted_chain_size_ == 0) | 237 if (aborted_chain_size_ == 0) |
453 return; | 238 return; |
454 // Note that this could be broken out by this navigation's abort type, if more | 239 // 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 | 240 // granularity is needed. Add one to the chain size to count the current |
(...skipping 46 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
502 // Only log the first time we background in a given page load. | 287 // Only log the first time we background in a given page load. |
503 if (background_time_.is_null()) { | 288 if (background_time_.is_null()) { |
504 // Make sure we either started in the foreground and haven't been | 289 // Make sure we either started in the foreground and haven't been |
505 // foregrounded yet, or started in the background and have already been | 290 // foregrounded yet, or started in the background and have already been |
506 // foregrounded. | 291 // foregrounded. |
507 DCHECK_EQ(started_in_foreground_, foreground_time_.is_null()); | 292 DCHECK_EQ(started_in_foreground_, foreground_time_.is_null()); |
508 background_time_ = base::TimeTicks::Now(); | 293 background_time_ = base::TimeTicks::Now(); |
509 ClampBrowserTimestampIfInterProcessTimeTickSkew(&background_time_); | 294 ClampBrowserTimestampIfInterProcessTimeTickSkew(&background_time_); |
510 } | 295 } |
511 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); | 296 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); |
512 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnHidden, *merged_page_timing_, info); | 297 INVOKE_AND_PRUNE_OBSERVERS(observers_, OnHidden, |
| 298 metrics_update_dispatcher_.timing(), info); |
513 } | 299 } |
514 | 300 |
515 void PageLoadTracker::WebContentsShown() { | 301 void PageLoadTracker::WebContentsShown() { |
516 // Only log the first time we foreground in a given page load. | 302 // Only log the first time we foreground in a given page load. |
517 if (foreground_time_.is_null()) { | 303 if (foreground_time_.is_null()) { |
518 // Make sure we either started in the background and haven't been | 304 // Make sure we either started in the background and haven't been |
519 // backgrounded yet, or started in the foreground and have already been | 305 // backgrounded yet, or started in the foreground and have already been |
520 // backgrounded. | 306 // backgrounded. |
521 DCHECK_NE(started_in_foreground_, background_time_.is_null()); | 307 DCHECK_NE(started_in_foreground_, background_time_.is_null()); |
522 foreground_time_ = base::TimeTicks::Now(); | 308 foreground_time_ = base::TimeTicks::Now(); |
(...skipping 30 matching lines...) Expand all Loading... |
553 for (const auto& observer : observers_) { | 339 for (const auto& observer : observers_) { |
554 observer->OnCommitSameDocumentNavigation(navigation_handle); | 340 observer->OnCommitSameDocumentNavigation(navigation_handle); |
555 } | 341 } |
556 } | 342 } |
557 | 343 |
558 void PageLoadTracker::DidFinishSubFrameNavigation( | 344 void PageLoadTracker::DidFinishSubFrameNavigation( |
559 content::NavigationHandle* navigation_handle) { | 345 content::NavigationHandle* navigation_handle) { |
560 for (const auto& observer : observers_) { | 346 for (const auto& observer : observers_) { |
561 observer->OnDidFinishSubFrameNavigation(navigation_handle); | 347 observer->OnDidFinishSubFrameNavigation(navigation_handle); |
562 } | 348 } |
563 | |
564 if (!navigation_handle->HasCommitted()) | |
565 return; | |
566 | |
567 // We have a new committed navigation, so discard information about the | |
568 // previously committed navigation. | |
569 subframe_navigation_start_offset_.erase( | |
570 navigation_handle->GetFrameTreeNodeId()); | |
571 | |
572 BrowserPageTrackDecider decider(embedder_interface_, | |
573 navigation_handle->GetWebContents(), | |
574 navigation_handle); | |
575 if (!decider.ShouldTrack()) | |
576 return; | |
577 | |
578 if (navigation_start_ > navigation_handle->NavigationStart()) { | |
579 RecordInternalError(ERR_SUBFRAME_NAVIGATION_START_BEFORE_MAIN_FRAME); | |
580 return; | |
581 } | |
582 base::TimeDelta navigation_delta = | |
583 navigation_handle->NavigationStart() - navigation_start_; | |
584 subframe_navigation_start_offset_.insert(std::make_pair( | |
585 navigation_handle->GetFrameTreeNodeId(), navigation_delta)); | |
586 } | 349 } |
587 | 350 |
588 void PageLoadTracker::FailedProvisionalLoad( | 351 void PageLoadTracker::FailedProvisionalLoad( |
589 content::NavigationHandle* navigation_handle, | 352 content::NavigationHandle* navigation_handle, |
590 base::TimeTicks failed_load_time) { | 353 base::TimeTicks failed_load_time) { |
591 DCHECK(!failed_provisional_load_info_); | 354 DCHECK(!failed_provisional_load_info_); |
592 failed_provisional_load_info_.reset(new FailedProvisionalLoadInfo( | 355 failed_provisional_load_info_.reset(new FailedProvisionalLoadInfo( |
593 failed_load_time - navigation_handle->NavigationStart(), | 356 failed_load_time - navigation_handle->NavigationStart(), |
594 navigation_handle->GetNetErrorCode())); | 357 navigation_handle->GetNetErrorCode())); |
595 } | 358 } |
(...skipping 11 matching lines...) Expand all Loading... |
607 } | 370 } |
608 | 371 |
609 void PageLoadTracker::FlushMetricsOnAppEnterBackground() { | 372 void PageLoadTracker::FlushMetricsOnAppEnterBackground() { |
610 if (!app_entered_background_) { | 373 if (!app_entered_background_) { |
611 RecordAppBackgroundPageLoadCompleted(false); | 374 RecordAppBackgroundPageLoadCompleted(false); |
612 app_entered_background_ = true; | 375 app_entered_background_ = true; |
613 } | 376 } |
614 | 377 |
615 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); | 378 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); |
616 INVOKE_AND_PRUNE_OBSERVERS(observers_, FlushMetricsOnAppEnterBackground, | 379 INVOKE_AND_PRUNE_OBSERVERS(observers_, FlushMetricsOnAppEnterBackground, |
617 *merged_page_timing_, info); | 380 metrics_update_dispatcher_.timing(), info); |
618 } | 381 } |
619 | 382 |
620 void PageLoadTracker::NotifyClientRedirectTo( | 383 void PageLoadTracker::NotifyClientRedirectTo( |
621 const PageLoadTracker& destination) { | 384 const PageLoadTracker& destination) { |
622 if (merged_page_timing_->paint_timing->first_paint) { | 385 if (metrics_update_dispatcher_.timing().paint_timing->first_paint) { |
623 base::TimeTicks first_paint_time = | 386 base::TimeTicks first_paint_time = |
624 navigation_start() + | 387 navigation_start() + |
625 merged_page_timing_->paint_timing->first_paint.value(); | 388 metrics_update_dispatcher_.timing().paint_timing->first_paint.value(); |
626 base::TimeDelta first_paint_to_navigation; | 389 base::TimeDelta first_paint_to_navigation; |
627 if (destination.navigation_start() > first_paint_time) | 390 if (destination.navigation_start() > first_paint_time) |
628 first_paint_to_navigation = | 391 first_paint_to_navigation = |
629 destination.navigation_start() - first_paint_time; | 392 destination.navigation_start() - first_paint_time; |
630 PAGE_LOAD_HISTOGRAM(internal::kClientRedirectFirstPaintToNavigation, | 393 PAGE_LOAD_HISTOGRAM(internal::kClientRedirectFirstPaintToNavigation, |
631 first_paint_to_navigation); | 394 first_paint_to_navigation); |
632 } else { | 395 } else { |
633 UMA_HISTOGRAM_BOOLEAN(internal::kClientRedirectWithoutPaint, true); | 396 UMA_HISTOGRAM_BOOLEAN(internal::kClientRedirectWithoutPaint, true); |
634 } | 397 } |
635 } | 398 } |
636 | 399 |
637 void PageLoadTracker::UpdateSubFrameTiming( | |
638 content::RenderFrameHost* render_frame_host, | |
639 const mojom::PageLoadTiming& new_timing, | |
640 const mojom::PageLoadMetadata& new_metadata) { | |
641 UpdateSubFrameMetadata(new_metadata); | |
642 const auto it = subframe_navigation_start_offset_.find( | |
643 render_frame_host->GetFrameTreeNodeId()); | |
644 if (it == subframe_navigation_start_offset_.end()) { | |
645 // We received timing information for an untracked load. Ignore it. | |
646 return; | |
647 } | |
648 | |
649 base::TimeDelta navigation_start_offset = it->second; | |
650 MergePaintTiming(navigation_start_offset, *(new_timing.paint_timing), | |
651 false /* is_main_frame */); | |
652 | |
653 DispatchTimingUpdates(); | |
654 } | |
655 | |
656 void PageLoadTracker::MergePaintTiming( | |
657 base::TimeDelta navigation_start_offset, | |
658 const mojom::PaintTiming& new_paint_timing, | |
659 bool is_main_frame) { | |
660 MaybeUpdateTimeDelta(&merged_page_timing_->paint_timing->first_paint, | |
661 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( | |
669 &merged_page_timing_->paint_timing->first_contentful_paint, | |
670 navigation_start_offset, new_paint_timing.first_contentful_paint); | |
671 if (is_main_frame) { | |
672 // first meaningful paint is only tracked in the main frame. | |
673 merged_page_timing_->paint_timing->first_meaningful_paint = | |
674 new_paint_timing.first_meaningful_paint; | |
675 } | |
676 } | |
677 | |
678 void PageLoadTracker::UpdateSubFrameMetadata( | |
679 const mojom::PageLoadMetadata& subframe_metadata) { | |
680 // Merge the subframe loading behavior flags with any we've already observed, | |
681 // possibly from other subframes. | |
682 const int last_subframe_loading_behavior_flags = | |
683 subframe_metadata_.behavior_flags; | |
684 subframe_metadata_.behavior_flags |= subframe_metadata.behavior_flags; | |
685 if (last_subframe_loading_behavior_flags == subframe_metadata_.behavior_flags) | |
686 return; | |
687 | |
688 PageLoadExtraInfo extra_info(ComputePageLoadExtraInfo()); | |
689 for (const auto& observer : observers_) { | |
690 observer->OnLoadingBehaviorObserved(extra_info); | |
691 } | |
692 } | |
693 | |
694 void PageLoadTracker::UpdateTiming( | |
695 const mojom::PageLoadTiming& new_timing, | |
696 const mojom::PageLoadMetadata& new_metadata) { | |
697 // Throw away IPCs that are not relevant to the current navigation. | |
698 // 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 | |
700 // different start time from an earlier struct is considered invalid. | |
701 const bool valid_timing_descendent = | |
702 merged_page_timing_->navigation_start.is_null() || | |
703 merged_page_timing_->navigation_start == new_timing.navigation_start; | |
704 if (!valid_timing_descendent) { | |
705 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING_DESCENDENT); | |
706 return; | |
707 } | |
708 | |
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); | |
718 UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingStatus, status, | |
719 internal::LAST_PAGE_LOAD_TIMING_STATUS); | |
720 if (status != internal::VALID) { | |
721 RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING); | |
722 return; | |
723 } | |
724 | |
725 DCHECK(did_commit_); // OnCommit() must be called first. | |
726 // There are some subtle ordering constraints here. GetPageLoadMetricsInfo() | |
727 // must be called before DispatchObserverTimingCallbacks, but its | |
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. | |
738 merged_page_timing_ = new_timing.Clone(); | |
739 merged_page_timing_->paint_timing = last_paint_timing.Clone(); | |
740 MergePaintTiming(base::TimeDelta(), *new_timing.paint_timing, | |
741 true /* is_main_frame */); | |
742 | |
743 main_frame_metadata_ = new_metadata; | |
744 | |
745 DispatchTimingUpdates(); | |
746 } | |
747 | |
748 void PageLoadTracker::DispatchTimingUpdates() { | |
749 if (last_dispatched_merged_page_timing_->Equals(*merged_page_timing_) && | |
750 last_dispatched_main_frame_metadata_->Equals(main_frame_metadata_)) { | |
751 return; | |
752 } | |
753 | |
754 if (merged_page_timing_->paint_timing->first_paint) { | |
755 if (!merged_page_timing_->parse_timing->parse_start || | |
756 !merged_page_timing_->document_timing->first_layout) { | |
757 // 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 | |
759 // receiving required earlier events in the main frame, due to buffering | |
760 // 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 | |
762 // 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 | |
764 // 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 | |
766 // can make assumptions about ordering of these events in their callbacks. | |
767 return; | |
768 } | |
769 } | |
770 | |
771 internal::PageLoadTimingStatus status = | |
772 IsValidPageLoadTiming(*merged_page_timing_); | |
773 UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingDispatchStatus, status, | |
774 internal::LAST_PAGE_LOAD_TIMING_STATUS); | |
775 | |
776 const PageLoadExtraInfo info = ComputePageLoadExtraInfo(); | |
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( | 400 void PageLoadTracker::OnStartedResource( |
787 const ExtraRequestStartInfo& extra_request_start_info) { | 401 const ExtraRequestStartInfo& extra_request_start_info) { |
788 for (const auto& observer : observers_) { | 402 for (const auto& observer : observers_) { |
789 observer->OnStartedResource(extra_request_start_info); | 403 observer->OnStartedResource(extra_request_start_info); |
790 } | 404 } |
791 } | 405 } |
792 | 406 |
793 void PageLoadTracker::OnLoadedResource( | 407 void PageLoadTracker::OnLoadedResource( |
794 const ExtraRequestCompleteInfo& extra_request_complete_info) { | 408 const ExtraRequestCompleteInfo& extra_request_complete_info) { |
795 for (const auto& observer : observers_) { | 409 for (const auto& observer : observers_) { |
(...skipping 31 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
827 DCHECK(event_time->is_null() || *event_time >= navigation_start_); | 441 DCHECK(event_time->is_null() || *event_time >= navigation_start_); |
828 return; | 442 return; |
829 } | 443 } |
830 | 444 |
831 if (!event_time->is_null() && *event_time < navigation_start_) { | 445 if (!event_time->is_null() && *event_time < navigation_start_) { |
832 RecordInternalError(ERR_INTER_PROCESS_TIME_TICK_SKEW); | 446 RecordInternalError(ERR_INTER_PROCESS_TIME_TICK_SKEW); |
833 *event_time = navigation_start_; | 447 *event_time = navigation_start_; |
834 } | 448 } |
835 } | 449 } |
836 | 450 |
837 PageLoadExtraInfo PageLoadTracker::ComputePageLoadExtraInfo() { | 451 PageLoadExtraInfo PageLoadTracker::ComputePageLoadExtraInfo() const { |
838 base::Optional<base::TimeDelta> first_background_time; | 452 base::Optional<base::TimeDelta> first_background_time; |
839 base::Optional<base::TimeDelta> first_foreground_time; | 453 base::Optional<base::TimeDelta> first_foreground_time; |
840 base::Optional<base::TimeDelta> page_end_time; | 454 base::Optional<base::TimeDelta> page_end_time; |
841 | 455 |
842 if (!background_time_.is_null()) { | 456 if (!background_time_.is_null()) { |
843 DCHECK_GE(background_time_, navigation_start_); | 457 DCHECK_GE(background_time_, navigation_start_); |
844 first_background_time = background_time_ - navigation_start_; | 458 first_background_time = background_time_ - navigation_start_; |
845 } | 459 } |
846 | 460 |
847 if (!foreground_time_.is_null()) { | 461 if (!foreground_time_.is_null()) { |
(...skipping 11 matching lines...) Expand all Loading... |
859 // page_end_reason_ == END_NONE implies page_end_user_initiated_info_ is not | 473 // page_end_reason_ == END_NONE implies page_end_user_initiated_info_ is not |
860 // user initiated. | 474 // user initiated. |
861 DCHECK(page_end_reason_ != END_NONE || | 475 DCHECK(page_end_reason_ != END_NONE || |
862 (!page_end_user_initiated_info_.browser_initiated && | 476 (!page_end_user_initiated_info_.browser_initiated && |
863 !page_end_user_initiated_info_.user_gesture && | 477 !page_end_user_initiated_info_.user_gesture && |
864 !page_end_user_initiated_info_.user_input_event)); | 478 !page_end_user_initiated_info_.user_input_event)); |
865 return PageLoadExtraInfo( | 479 return PageLoadExtraInfo( |
866 navigation_start_, first_background_time, first_foreground_time, | 480 navigation_start_, first_background_time, first_foreground_time, |
867 started_in_foreground_, user_initiated_info_, url(), start_url_, | 481 started_in_foreground_, user_initiated_info_, url(), start_url_, |
868 did_commit_, page_end_reason_, page_end_user_initiated_info_, | 482 did_commit_, page_end_reason_, page_end_user_initiated_info_, |
869 page_end_time, main_frame_metadata_, subframe_metadata_); | 483 page_end_time, metrics_update_dispatcher_.main_frame_metadata(), |
| 484 metrics_update_dispatcher_.subframe_metadata()); |
870 } | 485 } |
871 | 486 |
872 bool PageLoadTracker::HasMatchingNavigationRequestID( | 487 bool PageLoadTracker::HasMatchingNavigationRequestID( |
873 const content::GlobalRequestID& request_id) const { | 488 const content::GlobalRequestID& request_id) const { |
874 DCHECK(request_id != content::GlobalRequestID()); | 489 DCHECK(request_id != content::GlobalRequestID()); |
875 return navigation_request_id_.has_value() && | 490 return navigation_request_id_.has_value() && |
876 navigation_request_id_.value() == request_id; | 491 navigation_request_id_.value() == request_id; |
877 } | 492 } |
878 | 493 |
879 void PageLoadTracker::NotifyPageEnd(PageEndReason page_end_reason, | 494 void PageLoadTracker::NotifyPageEnd(PageEndReason page_end_reason, |
(...skipping 87 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
967 for (const auto& observer : observers_) | 582 for (const auto& observer : observers_) |
968 observer->MediaStartedPlaying(video_type, is_in_main_frame); | 583 observer->MediaStartedPlaying(video_type, is_in_main_frame); |
969 } | 584 } |
970 | 585 |
971 void PageLoadTracker::OnNavigationDelayComplete(base::TimeDelta scheduled_delay, | 586 void PageLoadTracker::OnNavigationDelayComplete(base::TimeDelta scheduled_delay, |
972 base::TimeDelta actual_delay) { | 587 base::TimeDelta actual_delay) { |
973 for (const auto& observer : observers_) | 588 for (const auto& observer : observers_) |
974 observer->OnNavigationDelayComplete(scheduled_delay, actual_delay); | 589 observer->OnNavigationDelayComplete(scheduled_delay, actual_delay); |
975 } | 590 } |
976 | 591 |
| 592 void PageLoadTracker::OnTimingChanged() { |
| 593 DCHECK(!last_dispatched_merged_page_timing_->Equals( |
| 594 metrics_update_dispatcher_.timing())); |
| 595 |
| 596 PageLoadExtraInfo extra_info(ComputePageLoadExtraInfo()); |
| 597 for (const auto& observer : observers_) { |
| 598 DispatchObserverTimingCallbacks( |
| 599 observer.get(), *last_dispatched_merged_page_timing_, |
| 600 metrics_update_dispatcher_.timing(), extra_info); |
| 601 } |
| 602 last_dispatched_merged_page_timing_ = |
| 603 metrics_update_dispatcher_.timing().Clone(); |
| 604 } |
| 605 |
| 606 void PageLoadTracker::OnMainFrameMetadataChanged() { |
| 607 PageLoadExtraInfo extra_info(ComputePageLoadExtraInfo()); |
| 608 for (const auto& observer : observers_) { |
| 609 observer->OnLoadingBehaviorObserved(extra_info); |
| 610 } |
| 611 } |
| 612 |
| 613 void PageLoadTracker::OnSubframeMetadataChanged() { |
| 614 PageLoadExtraInfo extra_info(ComputePageLoadExtraInfo()); |
| 615 for (const auto& observer : observers_) { |
| 616 observer->OnLoadingBehaviorObserved(extra_info); |
| 617 } |
| 618 } |
| 619 |
977 } // namespace page_load_metrics | 620 } // namespace page_load_metrics |
OLD | NEW |