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

Issue 465105 link

Starred by 15 users

Issue metadata

Status: Available
Owner: ----
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Windows
Pri: 3
Type: Bug

Blocked on:
issue 465819

Blocking:
issue 422000



Sign in to add a comment

Chrome's "high latency mode" is frequently triggered by internal Chrome issues, and not by a rAF animation

Reported by jer...@duckware.com, Mar 8 2015

Issue description

UserAgent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.76 Safari/537.36
Chrome version: 43.0.2325.0  Channel: canary
OS Version: 6.1 (Windows 7, Windows Server 2008 R2)

Chrome enters "high latency mode", even for requestAnimationFrame() animations with virtually zero latency.

After experiencing problems with Chrome kicking a simple/fast animation (www.vsynctester.com) into "high latency mode" (see issue 464740), I tried making a simple animation to isolate the issue and find the trigger.  But after reducing the rAF animation code to nothing (http://www.duckware.com/test/chrome/raf-high-min.html):...

  function animate(tRAF) {
    ctx.clearRect( 0, 0, 100, 30 );
    ctx.fillText( window.performance.now()-tRAF>1?"HIGH":"low", 0, 20 );
    window.requestAnimationFrame(animate);
    }

..., the problem still remained.  The above code runs in less than 0.1 milliseconds, and when run unbounded (using "--disable-gpu-vsync"), Chrome reports over 500 frames per second.  So, why is Chrome kicking this animation (that has virtually no overhead and can run incredibly fast) into "high latency mode"?

Adding debug performance graphs back into this animation (to confirm that conditions that 'brianderson' states in issue 464740 is a higher latency operation), yields this final test code:

  http://www.duckware.com/test/chrome/raf-high-final.html

To reproduce this issue, follow these steps:

(1) Use Windows 7 with a 60Hz display (I see similar, but not exact, results from a Win8.1 system).
(2) Use Canary.  Do not use Chrome release, since VSYNC is busted in 'release' (see comment #137 in issue 422000)
(3) DO NOT FORGET THIS STEP.  After running Canary, make sure it is not maximized, then RESIZE the app window.  Canary has a known bug that it is not VSYNC aligned until this is done (see comment #62 in issue 422000).
(4) Copy/paste the above 'raf-high-final.html' URL into the Canary omnibox and press Enter.

You will then see a gray box with a moving line.  That is Chrome running the animation in low latency mode.  The background color changes to red when "high latency mode" is detected.  After 20 consecutive frames of "high latency mode" detected, an inter-frame (black) line will appear along with a render (blue) time.  These debug lines demonstrate that both the animation render times and the inter-frame times have remained flat (no timing/latency issues), and that the inter-frame times have been phase shifted as seen in issue 464740.

You may have to wait several minutes for Canary to all of a sudden just switch into "high latency mode" all by itself, but if you are impatient, I found that there are other triggers:

  (1) move the mouse over any of the icons left of the omnibox (do not click) -- works 100% for me
  (2) use the mouse and click on the URL in the omnibox -- works 100% for me
  (3) move the mouse around fast, in and out of app -- works sporadically.

If Chrome starts the test in "high latency mode (happens around 50% of the time for me), use the mouse to move the window (drag in title bar), which often causes a switch back to low latency mode.

How I captured the attached snap.jpg: With the background gray, wait for the moving line (representing the current position) to move to the center of the gray box, and then click inside the omnibox, and when the performance lines appear, take a screen snapshot.

 
snap.jpg
69.2 KB View Download
Attached is a video of moving the mouse over one of the buttons to the left of the omnibox, which triggers high latency mode.
high-latency-triggered.mp4
4.9 MB Download
Labels: Cr-Blink-Performance TE-NeedsFurtherTriage
WIN81: The raf-high-final.html test was modified slightly to run the late times through a low pass filter, and now the test procedure above also reproduces 100% of the time under Windows 8.1 (with Canary).

TIP: And a slight modification on how to force Chrome out of high latency mode: You must FIRST click in a blank area inside the web browser (to remove any hilight away from omnibar), then click on the title bar and drag the window.  If there is a highlight remaining in the omnibar, Chrome just immediately trips into high latency mode.
Cc: briander...@chromium.org
Labels: Hotlist-Scheduling
Owner: rmcilroy@chromium.org
Status: Assigned
Jerry mentioned that this regressed somewhere between r317807 and r317814.

r317814 is the only scheduling related patch I see in that range.
@rmcilroy: Any idea if your patch would affect behavior of a simple rAF loop?
briander, I went back and confirmed that for www.vsynctester.com, r317807 and r317814 IS the range.  HOWEVER...

... for http://www.duckware.com/test/chrome/raf-high-final.html, the range appears very different.  Because I have r312916 laying around from another bisect, for raf-high-final.html, it has the problem.  But www.vsynctester.com does NOT have the problem with that rev.

Then, in  issue 158234 , comment #69, blurbust stated in regards to inter-frame timing: "It seems that somebody is doing work in Chrome 33 Canary to achieve submillisecond precision.  It's frequently switching between millisecond precision and submillisecond precision..." -- now there is no way to tell 100%, but that sure sounds exactly like I see for my inter-frame times: from millisecond granularity (timer res of windows) to sub-millisecond granularity.  To me, it sounds like this issue, especially given the screen snapshots provided by blurbust, meaning the issue existed back in Chrome 33 Canary.

Putting all of this together -- sounds like a very subtle timing issue?

But at least the good news is that I have on numerous computers, replicated 100% of the time, the ability to switch into "high latency mode" (click in omnibox), and the switch to "low latency mode" (click/drag window) -- which hopefully means someone there can replicate as well 100% of the time, which should make this just a matter of time and tracking down the issue...

briander, I am going to try another bisect, this time using raf-high-final.html early tomorrow.  It may be a wild goose chase, but maybe it will pinpoint something...

Re #6: I'm pretty certain that r317814 wouldn't have affected this - it's only impact right now should be to slightly reduce the number of idle GC tasks when there is no more GC work to do. 

I think the theory in #7 sounds more likely, but happy to look into it if a bisect pinpoints r317814
New bisect results are r302284 to r302303 (using http://www.duckware.com/test/chrome/raf-high-final.html as the test animation).  I have replicated these results on both a Dell Win7 notebook, and a Dell Win81 notebook.

Out of curiosity, I ran the vsynctester.com animation on this bisect, and as expected, could not replicate on the Win7 notebook.  HOWEVER, on the Win81 notebook, I WAS able to replicate the results with the new bisect.  So something about the old bisect vs the new bisect is OS specific?

Also, this bisect does not account for 'blurbust' seeing similar issues way back in Canary 33.  However, using his animation, I HAVE replicated results using this new bisect, on my Win81 notebook, using my trigger (click on URL in omnibox).  So for now, I will just assume that he has some other trigger that showed up in earlier Chrome versions (or he was testing on systems that actually triggered higher latency issues).

So this new bisect has a lot of evidence supporting it, which is meaningless if you guys can not also replicate.  So, can someone there replicate and confirm this issue using the new bisect?

My test steps:

1) download "chrome-win32.zip" for both 302284 and 302303 from https://commondatastorage.googleapis.com/chromium-browser-snapshots/index.html?prefix=Win/
2) extract ZIPs into temp folders
3) close ALL running apps (seriously, important)
4) copy (highlight/ctrl-c) "http://www.duckware.com/test/chrome/raf-high-final.html" into the clipboard

Go into the 302284 folder from a DOS window and:

5) run chrome.exe (type 'chrome', press enter)
6) click 'ok' on a bunch of 'profile can not be used' warning messages
7) if Chrome is maximized, minimize the app
8) resize the Chrome app (drag upper right corner to make app slightly larger)
9) using the mouse, click in omnibox, then move mouse outside of Chrome window
10) paste (ctrl-v) the raf-high-final.html URL from the clipboard, press enter
11) browser window displays gray box and moving line (slight red flicker at startup is OK/normal).  If the display starts out red and stays red, try steps 15-17 to reset.
12) use the mouse and click once in the omnibox (URL is then highlighted)

If running 302284, the display stays gray (Chrome stays in "low latency mode").  Close Chrome.

Next, run steps above (5-12) using 302303.  Instead of the display staying gray, you will see:

13) test turns red, performance lines appear, inter-frame times much 'smoother', like snap.jpg attached in #1.  This is Chrome switching to "high latency mode"
14) if test does NOT turn red, you likely missed step 8

To reset Chrome 302303 back into "low latency mode", these steps work for me:

15) click inside a blank area inside the browser window until highlight from omnibox (step 12) goes away
16) click/drag in title bar, moving Chrome app window -- interestingly, a click/hold/release (no move) also works
17) display turns gray and test resets (if it stays red, maximize app, minimize app, and repeat 15-17)

Here is a video of what I see running r302303 on Win7, repeating steps 12-17 (from comment #10) several times, showing the issue:

   http://www.duckware.com/test/chrome/vid/r302303.mp4
I believe I just found a clue at to the cause of this issue?

The puzzle/contradiction for me was: If Chrome is in low latency mode, and is rendering frames 'on time' and there is no hiccup in frame production, how in the world could Chrome switch into high latency mode?  The rAF callback runs in no time (<0.1ms), and the inter-frame times are still spot (rendering on time) -- through the whole "low latency" to "high latency" event.

The huge clue comes from www.vsynctester.com.  At the exact moment this issue is triggered (eg: clicking on the URL in the omnibox), the VSYNC indicator flickers.  That 100% confirms that TO THE DISPLAY, there was a missed frame.  And we know that there is now one more frame of input latency.

Add all this evidence together and it sounds like the back end totally missed sending one frame to the display in the proper VSYNC interval (it got sent in the NEXT interval) and is now one frame behind and out of sync???

Blockedon: chromium:465819
Cc: rmcilroy@chromium.org
Owner: briander...@chromium.org
Ok. Pretty sure this isn't Ross's patch. Reassigning to myself.

There have been a lot of changes recently in the Browser (Surfaces, SingleThreadProxy Scheduler Client, vsync) that would affect the scheduling of Browser self updates like the clicking on the omnibox would trigger. Bisecting is going to be pretty hard since each of those changes have gone in and out several times each.

We need to handle multiple producer updates better by giving every producer a chance to be ready rather than triggering immediately, which throws the "losing" producers into a high latency mode. I just realized there wasn't an existing bug for this, so I opened blocking  issue 465819 .
Jerry - I think this has a lot of overlap with other issues and it's not clear how this one is different. Mind if I close it?

We are actively looking into improving vsync and latency in general and have been using your vsynctester page to test our changes. It's been very helpful =)
@briander/14: Maybe.  Is there another issue that is tracking VSYNC "phase shifts" (which we now know is ultimately caused by Chrome internally entering "high latency" mode.  There was a fix for that (that worked), but it got reverted, so the issue is now back.  Sorry, there are so many issues, maybe I missed another issue tracking this?

The key (new) metric at www.vsynctester.com is the brown line, which is the frame's offset from true (calcaulated) VSYNC.  The reason this is so much more important (now) than the green/red inter-frame times is that the inter-frame graph can hide/mask PHASE SHIFT adjustments in when VSYNC is actually called.  In the attached, the inter-frame times in the blue box look 'good', but they are actually not, since they are nearly 4ms past true VSYNC (phase shifted).

If there is another issue tracking this, then yes, close this issue, marking it as a dup of the other issue.

status.jpg
63.8 KB View Download
I must mention that staring the vsync tester, and then hovering over the currently opened tabs, causes Chrome to kick into "high latency" mode (as of Canary 44.0.2400.0).

Hovering over the link (How it works), brings back *some* of the latency in most cases, and sometimes revert it back to almost perfect (brown line little above 0ms).

Is this a known issues?
Yes, we are looking to address it with the following patches, still in review:
https://codereview.chromium.org/1133673004
https://codereview.chromium.org/1138563002
Any news on this?

This is still definitely an issue of stuttery auto scrolling on various pages, untill the browsing window gets resized and the latency is corrected.
https://codereview.chromium.org/1138563002 has landed.

I'm currently working on breaking https://codereview.chromium.org/1133673004 down into landable parts.

Comment 20 by tkent@chromium.org, Jul 15 2015

Labels: -Cr-Blink-Performance Performance Cr-Blink
Labels: -Hotlist-Scheduling Cr-Blink-Scheduler
Labels: -Cr-Blink-Scheduler Cr-Blink-Scheduling

Comment 23 by tkent@chromium.org, Oct 16 2015

Labels: -Cr-Blink
Blocking: 422000
Cc: stanisc@chromium.org
Labels: -Performance Performance-Loading
Owner: ----
Status: Available (was: Assigned)
Components: Blink>Compositing
Labels: -Pri-2 Pri-3
Components: -Blink>Compositing Internals>Compositing

Sign in to add a comment