New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 894440 link

Starred by 2 users

Issue metadata

Status: Started
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Android , Windows
Pri: 1
Type: Bug-Regression

Blocking:
issue 899847
issue 895020



Sign in to add a comment

Investigate large presentation-times

Project Member Reported by sadrul@chromium.org, Oct 11

Issue description

The various paint-time metrics in blink were switched to using presentation-time in  issue 811961 . However, it turns out that it caused a large increase in the overflow bucket for the metric. It is possible that the presentation timestamp chrome is receiving from the platform is too large, or there are some other issues happening in chrome. This bug is to investigate the large timetamps.
 
Project Member

Comment 1 by bugdroid1@chromium.org, Oct 12

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/31c0c1c2517f38fb1e0ed336c4e70d261b97e69d

commit 31c0c1c2517f38fb1e0ed336c4e70d261b97e69d
Author: Sadrul Habib Chowdhury <sadrul@chromium.org>
Date: Fri Oct 12 02:55:52 2018

android: Dump for delayed presentation timestamp.

It looks like on android, presentation timestamps can sometimes be very
large. DumpWithoutCrashing() in such cases to collect some data to
understand why/when/where this is happening.

BUG=894440

Cq-Include-Trybots: luci.chromium.try:android_optional_gpu_tests_rel
Change-Id: I22817f68014c3f57f7180accc593506eee86f291
Reviewed-on: https://chromium-review.googlesource.com/c/1276549
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Reviewed-by: kylechar <kylechar@chromium.org>
Reviewed-by: Antoine Labour <piman@chromium.org>
Cr-Commit-Position: refs/heads/master@{#599079}
[modify] https://crrev.com/31c0c1c2517f38fb1e0ed336c4e70d261b97e69d/base/timer/elapsed_timer.h
[modify] https://crrev.com/31c0c1c2517f38fb1e0ed336c4e70d261b97e69d/components/viz/service/display/display.cc
[modify] https://crrev.com/31c0c1c2517f38fb1e0ed336c4e70d261b97e69d/components/viz/service/display/display.h

Blocking: 895020
Cc: briander...@chromium.org vikassoni@chromium.org
+vikassoni@, +brianderson@

Crash logs: https://crash.corp.google.com/browse?q=expanded_custom_data.ChromeCrashProto.magic_signature_1.name%3D%27%5BDump+without+crash%5D+viz%3A%3ADisplay%3A%3ADidReceivePresentationFeedback%27#-propertyselector,-daygraph,productname:1000,-magicsignature:50,-magicsignature2:50,-stablesignature:50

It looks like when the crash happens, the presentation-times we get are ahead of 'Now()'. Is that expected/allowed? Should we allow presentation-time to be a little bit ahead of Now()?

The relevant code is here: https://cs.chromium.org/chromium/src/components/viz/service/display/display.cc?l=523
Cc: bmcquade@chromium.org
Thanks Sadrul for investigating this!

Do we know how much ahead of Now() the timestamp is, in this case?

If it's just slightly ahead of Now() then it's possible there's a small clock skew issue (e.g. hardware may use a slightly different clock source that's not in sync with our clock source). If it's way ahead of Now() that suggests to me that the presentation timestamp is just invalid.

Do we have UMA histograms that tell us how far out of sync the presentation timestamp is with a timestamp that we trust? That seems like an important addition to get insight here.
I have put up https://chromium-review.googlesource.com/c/chromium/src/+/1294193 to report how far into the future the presentation timestamps are.

From the dump-reports, it doesn't look like this happens for too many users (we have dumps from only < 250 users [1]). From the dumps, it doesn't look like this is happening very frequently, i.e. it seems to happen for only a small number of users, and not very often. It will be interesting to see what the UMA data shows.

[1] https://crash.corp.google.com/browse?q=expanded_custom_data.ChromeCrashProto.magic_signature_1.name%3D%27%5BDump+without+crash%5D+viz%3A%3ADisplay%3A%3ADidReceivePresentationFeedback%27#-propertyselector,-daygraph,-samplereports,productname:1000,magicsignature:50,magicsignature2:50,-stablesignature:50,clientid:1000,gpuvendorid,gpudeviceid,gpudriverversion:100

sorry i missed this. +1 to bmcquade@ comments. UMA data will give more insights and we can make a decision based on that.
Project Member

Comment 7 by bugdroid1@chromium.org, Oct 22

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/32ae2261c1390ad14be3e48ea57af23b9d81f928

commit 32ae2261c1390ad14be3e48ea57af23b9d81f928
Author: Sadrul Habib Chowdhury <sadrul@chromium.org>
Date: Mon Oct 22 21:46:52 2018

viz: Report how far ahead invalid presentation timestamps are.

On android, it turns out the presentation timestamp coming from the
driver can be from the future. Report how far ahead in the future
these timestamps are.

BUG=894440

Change-Id: Ic9bf5620721de3279e8b74277273e8db63da0842
Reviewed-on: https://chromium-review.googlesource.com/c/1294193
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Reviewed-by: Antoine Labour <piman@chromium.org>
Reviewed-by: Mark Pearson <mpearson@chromium.org>
Cr-Commit-Position: refs/heads/master@{#601737}
[modify] https://crrev.com/32ae2261c1390ad14be3e48ea57af23b9d81f928/components/viz/service/display/display.cc
[modify] https://crrev.com/32ae2261c1390ad14be3e48ea57af23b9d81f928/tools/metrics/histograms/histograms.xml

We have ~a week's data now [1]. Two observations:
 . Almost all of the cases (~99%) where the timestamp is from the future is a long time in the future (more than 3 minutes).
 . This still seems to happen only rarely, considering that we request the presentation timestamp every frame. Comparing the sample count with another metric that we report every frame: Compositing.DirectRenderer.GL.DrawFrameUs [2], the future-timestamp has ~500K samples, compared to ~8.5B samples for DrawFrameUs.


[1] https://uma.googleplex.com/p/chrome/histograms/?endDate=latest&dayCount=7&histograms=Graphics.PresentationTimestamp.InvalidFromFuture&fixupData=true&showMax=true&filters=platform%2Ceq%2CA%2Cchannel%2Ceq%2C1%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial
[2] https://uma.googleplex.com/p/chrome/histograms/?endDate=latest&dayCount=7&histograms=Compositing.DirectRenderer.GL.DrawFrameUs%2CGraphics.PresentationTimestamp.InvalidFromFuture&fixupData=true&showMax=true&filters=platform%2Ceq%2CA%2Cchannel%2Ceq%2C1%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial
Blocking: 899847
I still think this happens rarely enough that we do not need to do blacklisting, and instead use chrome's timestamp when the timestamp is detected to be invalid.
yes i think that sounds good.
Cc: ligim...@chromium.org
Labels: ReleaseBlock-Stable Target-72 M-72 FoundIn-72
300 reports from 130+ clients in latest Dev- 72.0.3596.0.

Since work is in progress, adding and RB label for tracking purpose.
Project Member

Comment 14 by bugdroid1@chromium.org, Nov 9

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/665265a9e27b9df34cff6c7a9e07d01294225d70

commit 665265a9e27b9df34cff6c7a9e07d01294225d70
Author: Sadrul Habib Chowdhury <sadrul@chromium.org>
Date: Fri Nov 09 18:44:16 2018

viz: Report invalid older presentation-timestamps.

Report when the presentation-timestamp reporter by the driver is earlier
than the swap-time. Report this metric on all platforms. Change the
metric for reporting presentation-timestamps from the future to be
reported on all platforms (instead of just android).

This also removes DumpWithoutCrashing() for the future-timestamps.

BUG=894440

Change-Id: I663fdeab41b3f7de3e76f0e0ae440efbdae79bd8
Reviewed-on: https://chromium-review.googlesource.com/c/1325417
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Reviewed-by: Antoine Labour <piman@chromium.org>
Reviewed-by: Robert Kaplow <rkaplow@chromium.org>
Cr-Commit-Position: refs/heads/master@{#606913}
[modify] https://crrev.com/665265a9e27b9df34cff6c7a9e07d01294225d70/components/viz/service/display/display.cc
[modify] https://crrev.com/665265a9e27b9df34cff6c7a9e07d01294225d70/components/viz/service/display/display_unittest.cc
[modify] https://crrev.com/665265a9e27b9df34cff6c7a9e07d01294225d70/tools/metrics/histograms/histograms.xml

Comment 15 by ajha@chromium.org, Nov 12 (5 days ago)

Cc: srinivassista@chromium.org
Labels: -Type-Bug -Pri-2 ReleaseBlock-Dev OS-Mac OS-Windows Pri-1 Type-Bug-Regression
CL from C#14 has resulted in Dump without crashes on Windows, Mac and Android in the recent M-72 canary.

Magic signature: [Dump without crash] viz::Display::DidReceivePresentationFeedback

Link to the crashes:
====================
https://crash.corp.google.com/browse?q=expanded_custom_data.ChromeCrashProto.magic_signature_1.name%3D%27%5BDump+without+crash%5D+viz%3A%3ADisplay%3A%3ADidReceivePresentationFeedback%27#-propertyselector,productname:1000,productversion:100,-magicsignature:50,-magicsignature2:50,-stablesignature:50

72.0.3607.0 win canary reported 1468 crashes from 1188 clients and Mac & Android canary has reported lesser(1-2 digits) crashes.

Though the Dump without crash are not real crashes but may result in skewing the crash metrics since this is showing considerable spike on win canary.

Marking this as M-72 Dev blocker for Desktop(Windows) for tracking.

sadrul@: Could you please revert the CL from C#14 to unblock the next M-72 dev release scheduled for tomorrow(11/13).

Thank you!

Comment 16 by ligim...@chromium.org, Nov 12 (4 days ago)

Labels: -OS-Android -OS-Mac
This is blocking our Dev release and contributes ~ 60% of Win browser crash. No reports from Mac and Android.

sadrul@ please revert the CL ASAP.

Comment 17 by sadrul@chromium.org, Nov 12 (4 days ago)

Labels: -ReleaseBlock-Dev -ReleaseBlock-Stable
We shouldn't revert the CL. I am removing the release-block labels from our offline discussion, since this is not a crash. I will put up a separate CL to replace the DumpWithoutCrashing(), although having the dumps in the channels would be useful.
Project Member

Comment 18 by bugdroid1@chromium.org, Nov 12 (4 days ago)

Labels: merge-merged-3608
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/dbeb9ae3da0d596b909d8ed3e48cdf2fca0815b3

commit dbeb9ae3da0d596b909d8ed3e48cdf2fca0815b3
Author: Sadrul Habib Chowdhury <sadrul@chromium.org>
Date: Mon Nov 12 23:56:15 2018

viz: Remove a DumpWithoutCrashing(), and report a UMA instead.

BUG=894440

Change-Id: I0757af5f6a2058d0c98b68ff1e71c3083a1a76f2
Reviewed-on: https://chromium-review.googlesource.com/c/1332774
Reviewed-by: Abdul Syed <abdulsyed@google.com>
Cr-Commit-Position: refs/branch-heads/3608@{#6}
Cr-Branched-From: 809d8fb01773e476e122ad1739530caa3d02dfed-refs/heads/master@{#607123}
[modify] https://crrev.com/dbeb9ae3da0d596b909d8ed3e48cdf2fca0815b3/components/viz/service/display/display.cc
[modify] https://crrev.com/dbeb9ae3da0d596b909d8ed3e48cdf2fca0815b3/tools/metrics/histograms/histograms.xml

Project Member

Comment 19 by bugdroid1@chromium.org, Nov 13 (4 days ago)

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/b05de7e561c1c08ecefd5e98688668b80d1f92b8

commit b05de7e561c1c08ecefd5e98688668b80d1f92b8
Author: Sadrul Habib Chowdhury <sadrul@chromium.org>
Date: Tue Nov 13 01:35:54 2018

viz: Remove a DumpWithoutCrashing(), and report a UMA instead.

BUG=894440

Change-Id: I0757af5f6a2058d0c98b68ff1e71c3083a1a76f2
Reviewed-on: https://chromium-review.googlesource.com/c/1332249
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Reviewed-by: Robert Kaplow <rkaplow@chromium.org>
Cr-Commit-Position: refs/heads/master@{#607411}
[modify] https://crrev.com/b05de7e561c1c08ecefd5e98688668b80d1f92b8/components/viz/service/display/display.cc
[modify] https://crrev.com/b05de7e561c1c08ecefd5e98688668b80d1f92b8/tools/metrics/histograms/histograms.xml

Comment 20 by ajha@chromium.org, Nov 13 (3 days ago)

Labels: TE-Verified-M72 TE-Verified-72.0.3608.4
72.0.3608.4 Win canary has been live for 7 hrs and has not reported any crashes for '[Dump without crash] viz::Display::DidReceivePresentationFeedback'.

Looks to be fixed based on the available crash data and due to merge in C#18.

Comment 21 by sadrul@chromium.org, Nov 13 (3 days ago)

Labels: OS-Android
Summary: Investigate large presentation-times (was: Investigate large presentation-time on android)
Updating the bug, since it looks like we can get large presentation times on Windows too. It also seems to happen pretty rarely, but good to keep an eye on it. Graphics.PresentationTimestamp.LargePresentationDelta tracks how often this happens, and how large they can get.

Sign in to add a comment