1302713 - [GFX1-]: Refresh driver waiting for the compositor for1.36667 seconds.

Status: RESOLVED FIXED

(Core :: Graphics: Layers, defect)

Description

[Gary [:streetwolf52]]

Attachment: My about:support information

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:51.0) Gecko/20100101 Firefox/51.0
Build ID: 20160914003026

Steps to reproduce:

Make sure patch 1298085 is installed.

Run Fx51.


Actual results:

Getting error messages regarding the compositor.


Expected results:

No error messages unless something is wrong on my end.

Comment 1

[Gary [:streetwolf52]]

Both safe mode a new empty profile give me the same type of errors.

Comment 2

[Kartikaya Gupta (email:[e-mail])]

I can pretty easily get a bunch of these errors by running (on current m-c, local Linux debug build):

xr ./mach mochitest -f plain gfx/layers/apz/test/mochitest/test_bug1285070.html --keep-open=false --debugger=rrh

(where xr is basically xvfb-run [1] and rrh is rr with chaos recording [2]).

[1] https://github.com/staktrace/moz-scripts/blob/master/xr
[2] https://github.com/staktrace/moz-scripts/blob/master/rrh

Comment 3

[Gary [:streetwolf52]]

What are these errors telling me?  Is there something that I need to do so I don't get them?

Comment 4

[Dana Keeler (she/her) (use needinfo) [:keeler]]

I'm seeing this a ton on Fedora linux. No special setup - just running a locally-compiled mozilla-central from the terminal.

Comment 5

[Jonathan Kingston [:jkt] he/him]

Standard Mozilla w550s laptop on Ubuntu 16.04 I get this filling my logs on central local build too.

Comment 6

[Jim Jeffery not reading bug-mail 1/2/11]

I see those on latest win32 m-c hourly build as well.

Setting to NEW

Comment 7

[Jorg K (CEST = GMT+2)]

I'm seeing this an *awful* lot in my debug console. It really messes up the debug console to the point where you can't find the debug you're looking for. *Real* example below, no, I didn't paste it repeatedly.

Windows 10, local Thunderbird 32-bit build.

The Troubleshooting Information is also full of these errors.

Also ugly: There is a space missing.

Crash Annotation GraphicsCriticalError: |[0][GFX1-]: Refresh driver waiting for the compositor for1.75619 seconds. (t=89.898) |[31][GFX1-]: Refresh driver waiting for the compositor for120.56 seconds. (t=14392) |[17][GFX1-]: Refresh driver waiting for the compositor for4.96477 seconds. (t=510.265) |[18][GFX1-]: Refresh driver waiting for the compositor for16.495 seconds. (t=746.301) |[19][GFX1-]: Refresh driver waiting for the compositor for1.66581 seconds. (t=770.241) |[20][GFX1-]: Refresh driver waiting for the compositor for1.31814 seconds. (t=793.049) |[21][GFX1-]: Refresh driver waiting for the compositor for28.8237 seconds. (t=844.509) |[22][GFX1-]: Refresh driver waiting for the compositor for3.39883 seconds. (t=846.743) |[23][GFX1-]: Refresh driver waiting for the compositor for3.39883 seconds. (t=849.205) |[24][GFX1-]: Refresh driver waiting for the compositor for59.8637 seconds. (t=1715.24) |[25][GFX1-]: Refresh driver waiting for the compositor for60.4476 seconds. (t=1723.73) |[26][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2811.03) |[27][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2813.49) |[28][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2815.95) |[29][GFX1-]: Refresh driver waiting for the compositor for685.54 seconds. (t=12638.9) |[30][GFX1-]: Refresh driver waiting for the compositor for7.6748 seconds. (t=12806.5) [GFX1-]: Refresh driver waiting for the compositor for120.56 seconds.
Crash Annotation GraphicsCriticalError: |[0][GFX1-]: Refresh driver waiting for the compositor for1.75619 seconds. (t=89.898) |[31][GFX1-]: Refresh driver waiting for the compositor for120.56 seconds. (t=14392) |[32][GFX1-]: Refresh driver waiting for the compositor for114.236 seconds. (t=16039.2) |[18][GFX1-]: Refresh driver waiting for the compositor for16.495 seconds. (t=746.301) |[19][GFX1-]: Refresh driver waiting for the compositor for1.66581 seconds. (t=770.241) |[20][GFX1-]: Refresh driver waiting for the compositor for1.31814 seconds. (t=793.049) |[21][GFX1-]: Refresh driver waiting for the compositor for28.8237 seconds. (t=844.509) |[22][GFX1-]: Refresh driver waiting for the compositor for3.39883 seconds. (t=846.743) |[23][GFX1-]: Refresh driver waiting for the compositor for3.39883 seconds. (t=849.205) |[24][GFX1-]: Refresh driver waiting for the compositor for59.8637 seconds. (t=1715.24) |[25][GFX1-]: Refresh driver waiting for the compositor for60.4476 seconds. (t=1723.73) |[26][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2811.03) |[27][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2813.49) |[28][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2815.95) |[29][GFX1-]: Refresh driver waiting for the compositor for685.54 seconds. (t=12638.9) |[30][GFX1-]: Refresh driver waiting for the compositor for7.6748 seconds. (t=12806.5) [GFX1-]: Refresh driver waiting for the compositor for114.236 seconds.
Crash Annotation GraphicsCriticalError: |[0][GFX1-]: Refresh driver waiting for the compositor for1.75619 seconds. (t=89.898) |[31][GFX1-]: Refresh driver waiting for the compositor for120.56 seconds. (t=14392) |[32][GFX1-]: Refresh driver waiting for the compositor for114.236 seconds. (t=16039.2) |[33][GFX1-]: Refresh driver waiting for the compositor for66.3949 seconds. (t=16993.2) |[19][GFX1-]: Refresh driver waiting for the compositor for1.66581 seconds. (t=770.241) |[20][GFX1-]: Refresh driver waiting for the compositor for1.31814 seconds. (t=793.049) |[21][GFX1-]: Refresh driver waiting for the compositor for28.8237 seconds. (t=844.509) |[22][GFX1-]: Refresh driver waiting for the compositor for3.39883 seconds. (t=846.743) |[23][GFX1-]: Refresh driver waiting for the compositor for3.39883 seconds. (t=849.205) |[24][GFX1-]: Refresh driver waiting for the compositor for59.8637 seconds. (t=1715.24) |[25][GFX1-]: Refresh driver waiting for the compositor for60.4476 seconds. (t=1723.73) |[26][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2811.03) |[27][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2813.49) |[28][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2815.95) |[29][GFX1-]: Refresh driver waiting for the compositor for685.54 seconds. (t=12638.9) |[30][GFX1-]: Refresh driver waiting for the compositor for7.6748 seconds. (t=12806.5) [GFX1-]: Refresh driver waiting for the compositor for66.3949 seconds.
Crash Annotation GraphicsCriticalError: |[0][GFX1-]: Refresh driver waiting for the compositor for1.75619 seconds. (t=89.898) |[31][GFX1-]: Refresh driver waiting for the compositor for120.56 seconds. (t=14392) |[32][GFX1-]: Refresh driver waiting for the compositor for114.236 seconds. (t=16039.2) |[33][GFX1-]: Refresh driver waiting for the compositor for66.3949 seconds. (t=16993.2) |[34][GFX1-]: Refresh driver waiting for the compositor for18.2091 seconds. (t=17258.3) |[20][GFX1-]: Refresh driver waiting for the compositor for1.31814 seconds. (t=793.049) |[21][GFX1-]: Refresh driver waiting for the compositor for28.8237 seconds. (t=844.509) |[22][GFX1-]: Refresh driver waiting for the compositor for3.39883 seconds. (t=846.743) |[23][GFX1-]: Refresh driver waiting for the compositor for3.39883 seconds. (t=849.205) |[24][GFX1-]: Refresh driver waiting for the compositor for59.8637 seconds. (t=1715.24) |[25][GFX1-]: Refresh driver waiting for the compositor for60.4476 seconds. (t=1723.73) |[26][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2811.03) |[27][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2813.49) |[28][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2815.95) |[29][GFX1-]: Refresh driver waiting for the compositor for685.54 seconds. (t=12638.9) |[30][GFX1-]: Refresh driver waiting for the compositor for7.6748 seconds. (t=12806.5) [GFX1-]: Refresh driver waiting for the compositor for18.2091 seconds.
GetDiskSpaceAvailable returned: 36862955520 bytes
Crash Annotation GraphicsCriticalError: |[0][GFX1-]: Refresh driver waiting for the compositor for1.75619 seconds. (t=89.898) |[31][GFX1-]: Refresh driver waiting for the compositor for120.56 seconds. (t=14392) |[32][GFX1-]: Refresh driver waiting for the compositor for114.236 seconds. (t=16039.2) |[33][GFX1-]: Refresh driver waiting for the compositor for66.3949 seconds. (t=16993.2) |[34][GFX1-]: Refresh driver waiting for the compositor for18.2091 seconds. (t=17258.3) |[35][GFX1-]: Refresh driver waiting for the compositor for30.3566 seconds. (t=17696.1) |[21][GFX1-]: Refresh driver waiting for the compositor for28.8237 seconds. (t=844.509) |[22][GFX1-]: Refresh driver waiting for the compositor for3.39883 seconds. (t=846.743) |[23][GFX1-]: Refresh driver waiting for the compositor for3.39883 seconds. (t=849.205) |[24][GFX1-]: Refresh driver waiting for the compositor for59.8637 seconds. (t=1715.24) |[25][GFX1-]: Refresh driver waiting for the compositor for60.4476 seconds. (t=1723.73) |[26][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2811.03) |[27][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2813.49) |[28][GFX1-]: Refresh driver waiting for the compositor for75.9419 seconds. (t=2815.95) |[29][GFX1-]: Refresh driver waiting for the compositor for685.54 seconds. (t=12638.9) |[30][GFX1-]: Refresh driver waiting for the compositor for7.6748 seconds. (t=12806.5) [GFX1-]: Refresh driver waiting for the compositor for30.3566 seconds.

Comment 8

[Daniel Holbert [:dholbert]]

(Side note: I filed Bug 1302922 on the fact that this logging is missing a space between "for" and the number of seconds.)

Comment 9

[Julian Seward [:jseward]]

I see this too, having just updated my m-c tree.  Please, can this get
fixed as a matter of urgency?

Comment 10

[Nicolas Silva [:nical]]

Attachment: Reduce the amount of false positives

This patch makes sure we only log if we already noticed that we skipped frames, this should make a big difference. I think that the current code also logs if the refresh driver has not ticked for a while regardless of whether the compositor is at fault (minimized or unfocused window, screen locked, that kind of things).

Comment 11

[Nicolas Silva [:nical]]

Attachment: use different time threshold with valgrind, debug and release builds

The numbers are arbitrary, don't hesitate to propose adjustments.

With this patch we'll start logging:
 - In valgrind builds: if we skipped frames for 10 seconds.
 - In debug and/or asan builds: if we skipped frames for 5 seconds.
 - Else (release builds): if we skipped frames for 1 second.

Comment 12

[Gary [:streetwolf52]]

Nicolas.... What exactly do the messages mean as far as the user is concerned?  I'm sure once these messages are released in the wild people are going to react to them as if something is wrong with their setup.

Comment 13

[Mason Chang [Inactive] [:mchang]]

(In reply to Gary [:streetwolf] from comment #12)
> Nicolas.... What exactly do the messages mean as far as the user is
> concerned?  I'm sure once these messages are released in the wild people are
> going to react to them as if something is wrong with their setup.

I don't think the user actually sees this until they go to about:Support or are in a diagnostic setting right? So from the users perspective, they won't see this. Unless you mean developers or something else?

What it means is that the compositor is blocked for some reason, and we don't know why.

Comment 14

[Daniel Holbert [:dholbert]]

Incorrect -- I'm absolutely seeing this message spammed to my terminal (in current Nightly, fresh profile).

Comment 15

[Daniel Holbert [:dholbert]]

e.g. I see some of this logging (on latest Linux Nightly) if I do:
  mkdir /tmp/foo65; firefox -no-remote -profile /tmp/foo65 http://www.flightarcade.com/missions/tin/play

...and just wait 10-20 seconds.

Comment 16

[Nicolas Silva [:nical]]

The tree is closed and it's getting late here. I'll land the patches tomorrow, unless someone wants to do it in the mean time whenever inbound reopens. With these two patches we shouldn't have this amount of log spam anymore unless something bad is really happening.

Comment 17

[Gary [:streetwolf52]]

Is it normal to get these messages just starting Fx51?  I usually get 3 or 4 without doing anything.  Yes, the errors are only visible in about:support.  I have no idea if a 'normal' user ever gets into about:support.

Comment 18

[Gary [:streetwolf52]]

Isn't the browser console a better place for these messages to go?

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/8f6e1f5e7747
Reduce the amount of false positive in the refresh driver warnings. r=mchang
https://hg.mozilla.org/integration/mozilla-inbound/rev/d30c5b875098
Adapt the refresh driver warning threshold to the build target.

Comment 20

[Nicolas Silva [:nical]]

(In reply to Gary [:streetwolf] from comment #18)
> Isn't the browser console a better place for these messages to go?

No, this log is intended to highlight abyssal compositor responsiveness issues which is a platform thing. There was an issue with the logging logic causing false-positives to spam the log which should be addressed by the patches I just landed.
This is useful for us to have this information in about:support and crash reports. If a user reports 1sec+ freezes we can ask him if this log is present in about:support and know if the problem is in the content or compositor process.

Comment 21

[Gary [:streetwolf52]]

If I get messages after the new patch do I open up a bug report about the ones I get?  I often see 10+ seconds in the messages now.  If this indicates a problem there needs to be a way to let you guys know about it.

Comment 22

[Gary [:streetwolf52]]

The new patch is looking good so far.  No Failure Log messages.

Comment 23

[Nicolas Silva [:nical]]

(In reply to Gary [:streetwolf] from comment #21)
> If I get messages after the new patch do I open up a bug report about the
> ones I get?  I often see 10+ seconds in the messages now.  If this indicates
> a problem there needs to be a way to let you guys know about it.

Yes, please do file bugs if this message shows up again. We are supposed to see this log only in very bad cases so we should know about it.

Comment 24

[Jorg K (CEST = GMT+2)]

(In reply to Gary [:streetwolf] from comment #22)
> The new patch is looking good so far.  No Failure Log messages.
Same here, thanks a lot.

Comment 25

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/8f6e1f5e7747
https://hg.mozilla.org/mozilla-central/rev/d30c5b875098

Comment 26

[George R. Goffe]

Hi,

I just updated "my" Nightly on a Fedora 23 x86_64 system and am STILL seeing these messages.

What would you like me to do? Wait for more updates? Needinfo?

THANKS for all the WAY COOL CODE!

George...

Comment 27

[Nicolas Silva [:nical]]

(In reply to George R. Goffe from comment #26)
> I just updated "my" Nightly on a Fedora 23 x86_64 system and am STILL seeing
> these messages.

What is the build id shown in the about:support page? When you see this in the log, does it happen after the page froze for a second or more, or does the browser feel responsive? Thanks!

Comment 28

[George R. Goffe]

Nicolas,

"current" build id is: 20160918030408

I start FF Nightly from the "Konsole" command line. This is where the messages come out.

I didn't notice any abnormal pauses although it's possible. FF Nightly has been up for about half an hour and now I'm getting the "Refresh" messages. No specific web site as far as I can tell.

Thanks!

George...