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 "third_party/blink/renderer/core/paint/paint_timing.h"
6
7 #include <memory>
8 #include <utility>
9
10 #include "base/metrics/histogram_macros.h"
11 #include "base/time/default_tick_clock.h"
12 #include "third_party/blink/renderer/core/dom/document.h"
13 #include "third_party/blink/renderer/core/dom/frame_request_callback_collection.h"
14 #include "third_party/blink/renderer/core/frame/local_dom_window.h"
15 #include "third_party/blink/renderer/core/frame/local_frame.h"
16 #include "third_party/blink/renderer/core/frame/local_frame_view.h"
17 #include "third_party/blink/renderer/core/loader/document_loader.h"
18 #include "third_party/blink/renderer/core/loader/interactive_detector.h"
19 #include "third_party/blink/renderer/core/loader/progress_tracker.h"
20 #include "third_party/blink/renderer/core/page/chrome_client.h"
21 #include "third_party/blink/renderer/core/page/page.h"
22 #include "third_party/blink/renderer/core/probe/core_probes.h"
23 #include "third_party/blink/renderer/core/timing/dom_window_performance.h"
24 #include "third_party/blink/renderer/core/timing/window_performance.h"
25 #include "third_party/blink/renderer/platform/instrumentation/resource_coordinator/document_resource_coordinator.h"
26 #include "third_party/blink/renderer/platform/instrumentation/tracing/trace_event.h"
27 #include "third_party/blink/renderer/platform/loader/fetch/resource_fetcher.h"
28 #include "third_party/blink/renderer/platform/scheduler/public/frame_scheduler.h"
29 #include "third_party/blink/renderer/platform/wtf/cross_thread_functional.h"
30 #include "third_party/blink/renderer/platform/wtf/wtf.h"
31
32 namespace blink {
33
34 namespace {
35
GetPerformanceInstance(LocalFrame * frame)36 WindowPerformance* GetPerformanceInstance(LocalFrame* frame) {
37 WindowPerformance* performance = nullptr;
38 if (frame && frame->DomWindow()) {
39 performance = DOMWindowPerformance::performance(*frame->DomWindow());
40 }
41 return performance;
42 }
43
44 } // namespace
45
46 class RecodingTimeAfterBackForwardCacheRestoreFrameCallback
47 : public FrameCallback {
48 public:
RecodingTimeAfterBackForwardCacheRestoreFrameCallback(PaintTiming * paint_timing,size_t record_index)49 RecodingTimeAfterBackForwardCacheRestoreFrameCallback(
50 PaintTiming* paint_timing,
51 size_t record_index)
52 : paint_timing_(paint_timing), record_index_(record_index) {}
53 ~RecodingTimeAfterBackForwardCacheRestoreFrameCallback() override = default;
54
Invoke(double high_res_time_ms)55 void Invoke(double high_res_time_ms) override {
56 // Instead of |high_res_time_ms|, use PaintTiming's |clock_->NowTicks()| for
57 // consistency and testability.
58 paint_timing_->SetRequestAnimationFrameAfterBackForwardCacheRestore(
59 record_index_, count_);
60
61 count_++;
62 if (count_ ==
63 WebPerformance::
64 kRequestAnimationFramesToRecordAfterBackForwardCacheRestore) {
65 paint_timing_->NotifyPaintTimingChanged();
66 return;
67 }
68
69 if (auto* frame = paint_timing_->GetFrame()) {
70 if (auto* document = frame->GetDocument()) {
71 document->RequestAnimationFrame(this);
72 }
73 }
74 }
75
Trace(Visitor * visitor) const76 void Trace(Visitor* visitor) const override {
77 visitor->Trace(paint_timing_);
78 FrameCallback::Trace(visitor);
79 }
80
81 private:
82 Member<PaintTiming> paint_timing_;
83 const size_t record_index_;
84 size_t count_ = 0;
85 };
86
87 // static
88 const char PaintTiming::kSupplementName[] = "PaintTiming";
89
90 // static
From(Document & document)91 PaintTiming& PaintTiming::From(Document& document) {
92 PaintTiming* timing = Supplement<Document>::From<PaintTiming>(document);
93 if (!timing) {
94 timing = MakeGarbageCollected<PaintTiming>(document);
95 ProvideTo(document, timing);
96 }
97 return *timing;
98 }
99
MarkFirstPaint()100 void PaintTiming::MarkFirstPaint() {
101 // Test that |first_paint_| is non-zero here, as well as in setFirstPaint, so
102 // we avoid invoking monotonicallyIncreasingTime() on every call to
103 // markFirstPaint().
104 if (!first_paint_.is_null())
105 return;
106 SetFirstPaint(clock_->NowTicks());
107 }
108
MarkFirstContentfulPaint()109 void PaintTiming::MarkFirstContentfulPaint() {
110 // Test that |first_contentful_paint_| is non-zero here, as well as in
111 // setFirstContentfulPaint, so we avoid invoking
112 // monotonicallyIncreasingTime() on every call to
113 // markFirstContentfulPaint().
114 if (!first_contentful_paint_.is_null())
115 return;
116 SetFirstContentfulPaint(clock_->NowTicks());
117 }
118
MarkFirstImagePaint()119 void PaintTiming::MarkFirstImagePaint() {
120 if (!first_image_paint_.is_null())
121 return;
122 first_image_paint_ = clock_->NowTicks();
123 SetFirstContentfulPaint(first_image_paint_);
124 RegisterNotifySwapTime(PaintEvent::kFirstImagePaint);
125 }
126
MarkFirstEligibleToPaint()127 void PaintTiming::MarkFirstEligibleToPaint() {
128 if (!first_eligible_to_paint_.is_null())
129 return;
130
131 first_eligible_to_paint_ = clock_->NowTicks();
132 NotifyPaintTimingChanged();
133 }
134
135 // We deliberately use |first_paint_| here rather than |first_paint_swap_|,
136 // because |first_paint_swap_| is set asynchronously and we need to be able to
137 // rely on a synchronous check that SetFirstPaintSwap hasn't been scheduled or
138 // run.
MarkIneligibleToPaint()139 void PaintTiming::MarkIneligibleToPaint() {
140 if (first_eligible_to_paint_.is_null() || !first_paint_.is_null())
141 return;
142
143 first_eligible_to_paint_ = base::TimeTicks();
144 NotifyPaintTimingChanged();
145 }
146
SetFirstMeaningfulPaintCandidate(base::TimeTicks timestamp)147 void PaintTiming::SetFirstMeaningfulPaintCandidate(base::TimeTicks timestamp) {
148 if (!first_meaningful_paint_candidate_.is_null())
149 return;
150 first_meaningful_paint_candidate_ = timestamp;
151 if (GetFrame() && GetFrame()->View() && !GetFrame()->View()->IsAttached()) {
152 GetFrame()->GetFrameScheduler()->OnFirstMeaningfulPaint();
153 }
154 }
155
SetFirstMeaningfulPaint(base::TimeTicks swap_stamp,FirstMeaningfulPaintDetector::HadUserInput had_input)156 void PaintTiming::SetFirstMeaningfulPaint(
157 base::TimeTicks swap_stamp,
158 FirstMeaningfulPaintDetector::HadUserInput had_input) {
159 DCHECK(first_meaningful_paint_swap_.is_null());
160 DCHECK(!swap_stamp.is_null());
161
162 TRACE_EVENT_MARK_WITH_TIMESTAMP2(
163 "loading,rail,devtools.timeline", "firstMeaningfulPaint", swap_stamp,
164 "frame", ToTraceValue(GetFrame()), "afterUserInput", had_input);
165
166 // Notify FMP for UMA only if there's no user input before FMP, so that layout
167 // changes caused by user interactions wouldn't be considered as FMP.
168 if (had_input == FirstMeaningfulPaintDetector::kNoUserInput) {
169 first_meaningful_paint_swap_ = swap_stamp;
170 NotifyPaintTimingChanged();
171 }
172 }
173
NotifyPaint(bool is_first_paint,bool text_painted,bool image_painted)174 void PaintTiming::NotifyPaint(bool is_first_paint,
175 bool text_painted,
176 bool image_painted) {
177 if (is_first_paint)
178 MarkFirstPaint();
179 if (text_painted)
180 MarkFirstContentfulPaint();
181 if (image_painted)
182 MarkFirstImagePaint();
183 fmp_detector_->NotifyPaint();
184 }
185
OnPortalActivate()186 void PaintTiming::OnPortalActivate() {
187 last_portal_activated_swap_ = base::TimeTicks();
188 RegisterNotifySwapTime(PaintEvent::kPortalActivatedPaint);
189 }
190
SetPortalActivatedPaint(base::TimeTicks stamp)191 void PaintTiming::SetPortalActivatedPaint(base::TimeTicks stamp) {
192 DCHECK(last_portal_activated_swap_.is_null());
193 last_portal_activated_swap_ = stamp;
194 NotifyPaintTimingChanged();
195 }
196
SetTickClockForTesting(const base::TickClock * clock)197 void PaintTiming::SetTickClockForTesting(const base::TickClock* clock) {
198 clock_ = clock;
199 }
200
Trace(Visitor * visitor) const201 void PaintTiming::Trace(Visitor* visitor) const {
202 visitor->Trace(fmp_detector_);
203 Supplement<Document>::Trace(visitor);
204 }
205
PaintTiming(Document & document)206 PaintTiming::PaintTiming(Document& document)
207 : Supplement<Document>(document),
208 fmp_detector_(MakeGarbageCollected<FirstMeaningfulPaintDetector>(this)),
209 clock_(base::DefaultTickClock::GetInstance()) {}
210
GetFrame() const211 LocalFrame* PaintTiming::GetFrame() const {
212 return GetSupplementable()->GetFrame();
213 }
214
NotifyPaintTimingChanged()215 void PaintTiming::NotifyPaintTimingChanged() {
216 if (GetSupplementable()->Loader())
217 GetSupplementable()->Loader()->DidChangePerformanceTiming();
218 }
219
SetFirstPaint(base::TimeTicks stamp)220 void PaintTiming::SetFirstPaint(base::TimeTicks stamp) {
221 if (!first_paint_.is_null())
222 return;
223
224 LocalFrame* frame = GetFrame();
225 if (frame && frame->GetDocument()) {
226 Document* document = frame->GetDocument();
227 document->MarkFirstPaint();
228 if (frame->IsMainFrame())
229 document->Fetcher()->MarkFirstPaint();
230 }
231
232 first_paint_ = stamp;
233 RegisterNotifySwapTime(PaintEvent::kFirstPaint);
234 }
235
SetFirstContentfulPaint(base::TimeTicks stamp)236 void PaintTiming::SetFirstContentfulPaint(base::TimeTicks stamp) {
237 if (!first_contentful_paint_.is_null())
238 return;
239 SetFirstPaint(stamp);
240 first_contentful_paint_ = stamp;
241 RegisterNotifySwapTime(PaintEvent::kFirstContentfulPaint);
242
243 // Restart commits that may have been deferred.
244 LocalFrame* frame = GetFrame();
245 if (!frame || !frame->IsMainFrame())
246 return;
247 frame->View()->OnFirstContentfulPaint();
248
249 if (frame->GetDocument() && frame->GetDocument()->Fetcher())
250 frame->GetDocument()->Fetcher()->MarkFirstContentfulPaint();
251
252 if (frame->GetFrameScheduler())
253 frame->GetFrameScheduler()->OnFirstContentfulPaint();
254 }
255
RegisterNotifySwapTime(PaintEvent event)256 void PaintTiming::RegisterNotifySwapTime(PaintEvent event) {
257 RegisterNotifySwapTime(
258 CrossThreadBindOnce(&PaintTiming::ReportSwapTime,
259 WrapCrossThreadWeakPersistent(this), event));
260 }
261
RegisterNotifyFirstPaintAfterBackForwardCacheRestoreSwapTime(size_t index)262 void PaintTiming::RegisterNotifyFirstPaintAfterBackForwardCacheRestoreSwapTime(
263 size_t index) {
264 RegisterNotifySwapTime(CrossThreadBindOnce(
265 &PaintTiming::ReportFirstPaintAfterBackForwardCacheRestoreSwapTime,
266 WrapCrossThreadWeakPersistent(this), index));
267 }
268
RegisterNotifySwapTime(ReportTimeCallback callback)269 void PaintTiming::RegisterNotifySwapTime(ReportTimeCallback callback) {
270 // ReportSwapTime will queue a swap-promise, the callback is called when the
271 // compositor submission of the current render frame completes or fails to
272 // happen.
273 if (!GetFrame() || !GetFrame()->GetPage())
274 return;
275 GetFrame()->GetPage()->GetChromeClient().NotifySwapTime(*GetFrame(),
276 std::move(callback));
277 }
278
ReportSwapTime(PaintEvent event,WebSwapResult result,base::TimeTicks timestamp)279 void PaintTiming::ReportSwapTime(PaintEvent event,
280 WebSwapResult result,
281 base::TimeTicks timestamp) {
282 DCHECK(IsMainThread());
283 // If the swap fails for any reason, we use the timestamp when the SwapPromise
284 // was broken. |result| == WebSwapResult::kDidNotSwapSwapFails
285 // usually means the compositor decided not swap because there was no actual
286 // damage, which can happen when what's being painted isn't visible. In this
287 // case, the timestamp will be consistent with the case where the swap
288 // succeeds, as they both capture the time up to swap. In other failure cases
289 // (aborts during commit), this timestamp is an improvement over the blink
290 // paint time, but does not capture some time we're interested in, e.g. image
291 // decoding.
292 //
293 // TODO(crbug.com/738235): Consider not reporting any timestamp when failing
294 // for reasons other than kDidNotSwapSwapFails.
295 ReportSwapResultHistogram(result);
296 switch (event) {
297 case PaintEvent::kFirstPaint:
298 SetFirstPaintSwap(timestamp);
299 return;
300 case PaintEvent::kFirstContentfulPaint:
301 SetFirstContentfulPaintSwap(timestamp);
302 return;
303 case PaintEvent::kFirstImagePaint:
304 SetFirstImagePaintSwap(timestamp);
305 return;
306 case PaintEvent::kPortalActivatedPaint:
307 SetPortalActivatedPaint(timestamp);
308 return;
309 default:
310 NOTREACHED();
311 }
312 }
313
ReportFirstPaintAfterBackForwardCacheRestoreSwapTime(size_t index,WebSwapResult result,base::TimeTicks timestamp)314 void PaintTiming::ReportFirstPaintAfterBackForwardCacheRestoreSwapTime(
315 size_t index,
316 WebSwapResult result,
317 base::TimeTicks timestamp) {
318 DCHECK(IsMainThread());
319 ReportSwapResultHistogram(result);
320 SetFirstPaintAfterBackForwardCacheRestoreSwap(timestamp, index);
321 }
322
SetFirstPaintSwap(base::TimeTicks stamp)323 void PaintTiming::SetFirstPaintSwap(base::TimeTicks stamp) {
324 DCHECK(first_paint_swap_.is_null());
325 first_paint_swap_ = stamp;
326 probe::PaintTiming(GetSupplementable(), "firstPaint",
327 first_paint_swap_.since_origin().InSecondsF());
328 WindowPerformance* performance = GetPerformanceInstance(GetFrame());
329 if (performance)
330 performance->AddFirstPaintTiming(first_paint_swap_);
331 NotifyPaintTimingChanged();
332 }
333
SetFirstContentfulPaintSwap(base::TimeTicks stamp)334 void PaintTiming::SetFirstContentfulPaintSwap(base::TimeTicks stamp) {
335 DCHECK(first_contentful_paint_swap_.is_null());
336 TRACE_EVENT_INSTANT_WITH_TIMESTAMP0("loading", "FirstContentfulPaint",
337 TRACE_EVENT_SCOPE_GLOBAL, stamp);
338 first_contentful_paint_swap_ = stamp;
339 probe::PaintTiming(GetSupplementable(), "firstContentfulPaint",
340 first_contentful_paint_swap_.since_origin().InSecondsF());
341 WindowPerformance* performance = GetPerformanceInstance(GetFrame());
342 if (performance)
343 performance->AddFirstContentfulPaintTiming(first_contentful_paint_swap_);
344 if (GetFrame())
345 GetFrame()->Loader().Progress().DidFirstContentfulPaint();
346 NotifyPaintTimingChanged();
347 fmp_detector_->NotifyFirstContentfulPaint(first_contentful_paint_swap_);
348 InteractiveDetector* interactive_detector =
349 InteractiveDetector::From(*GetSupplementable());
350 if (interactive_detector) {
351 interactive_detector->OnFirstContentfulPaint(first_contentful_paint_swap_);
352 }
353 auto* coordinator = GetSupplementable()->GetResourceCoordinator();
354 if (coordinator && GetFrame() && GetFrame()->IsMainFrame()) {
355 PerformanceTiming* timing = performance->timing();
356 base::TimeDelta fcp = stamp - timing->NavigationStartAsMonotonicTime();
357 coordinator->OnFirstContentfulPaint(fcp);
358 }
359 }
360
SetFirstImagePaintSwap(base::TimeTicks stamp)361 void PaintTiming::SetFirstImagePaintSwap(base::TimeTicks stamp) {
362 DCHECK(first_image_paint_swap_.is_null());
363 first_image_paint_swap_ = stamp;
364 probe::PaintTiming(GetSupplementable(), "firstImagePaint",
365 first_image_paint_swap_.since_origin().InSecondsF());
366 NotifyPaintTimingChanged();
367 }
368
SetFirstPaintAfterBackForwardCacheRestoreSwap(base::TimeTicks stamp,size_t index)369 void PaintTiming::SetFirstPaintAfterBackForwardCacheRestoreSwap(
370 base::TimeTicks stamp,
371 size_t index) {
372 // The elements are allocated when the page is restored from the cache.
373 DCHECK_GE(first_paints_after_back_forward_cache_restore_swap_.size(), index);
374 DCHECK(first_paints_after_back_forward_cache_restore_swap_[index].is_null());
375 first_paints_after_back_forward_cache_restore_swap_[index] = stamp;
376 NotifyPaintTimingChanged();
377 }
378
SetRequestAnimationFrameAfterBackForwardCacheRestore(size_t index,size_t count)379 void PaintTiming::SetRequestAnimationFrameAfterBackForwardCacheRestore(
380 size_t index,
381 size_t count) {
382 auto now = clock_->NowTicks();
383
384 // The elements are allocated when the page is restored from the cache.
385 DCHECK_LT(index,
386 request_animation_frames_after_back_forward_cache_restore_.size());
387 auto& current_rafs =
388 request_animation_frames_after_back_forward_cache_restore_[index];
389 DCHECK_LT(count, current_rafs.size());
390 DCHECK_EQ(current_rafs[count], base::TimeTicks());
391 current_rafs[count] = now;
392 }
393
ReportSwapResultHistogram(WebSwapResult result)394 void PaintTiming::ReportSwapResultHistogram(WebSwapResult result) {
395 UMA_HISTOGRAM_ENUMERATION("PageLoad.Internal.Renderer.PaintTiming.SwapResult",
396 result);
397 }
398
OnRestoredFromBackForwardCache()399 void PaintTiming::OnRestoredFromBackForwardCache() {
400 // Allocate the last element with 0, which indicates that the first paint
401 // after this navigation doesn't happen yet.
402 size_t index = first_paints_after_back_forward_cache_restore_swap_.size();
403 DCHECK_EQ(index,
404 request_animation_frames_after_back_forward_cache_restore_.size());
405
406 first_paints_after_back_forward_cache_restore_swap_.push_back(
407 base::TimeTicks());
408 RegisterNotifyFirstPaintAfterBackForwardCacheRestoreSwapTime(index);
409
410 request_animation_frames_after_back_forward_cache_restore_.push_back(
411 RequestAnimationFrameTimesAfterBackForwardCacheRestore{});
412
413 LocalFrame* frame = GetFrame();
414 if (!frame->IsMainFrame()) {
415 return;
416 }
417
418 Document* document = frame->GetDocument();
419 DCHECK(document);
420
421 // Cancel if there is already a registered callback.
422 if (raf_after_bfcache_restore_measurement_callback_id_) {
423 document->CancelAnimationFrame(
424 raf_after_bfcache_restore_measurement_callback_id_);
425 raf_after_bfcache_restore_measurement_callback_id_ = 0;
426 }
427
428 raf_after_bfcache_restore_measurement_callback_id_ =
429 document->RequestAnimationFrame(
430 MakeGarbageCollected<
431 RecodingTimeAfterBackForwardCacheRestoreFrameCallback>(this,
432 index));
433 }
434
435 } // namespace blink
436