Kai, could you take a look?

FYI, I posted a question about this on the Qualcomm developer forum: https://developer.qualcomm.com/forum/qdn-forums/software/adreno-gpu-sdk/34573

Been discussing this issue with Klaus on chat.

Sunny, Brian, you might know about this. Klaus asked if it's possible to add some kind of performance assertion that some section of code will be "fast", e.g. the glGetQueryObject(GL_QUERY_RESULT_AVAILABLE) calls in question, so that we could (1) get more info on this issue and (2) protect against it in the future.

We should file an internal bug against Qualcomm. This query's being made directly against the OpenGL ES driver and there is no reason that it should block. Kai, could you take care of doing this and mark it reasonably high priority so that it gets triaged?

+aelias and boliu because they're experts on the Android driver side.

kbr: Unfortunately this is currently hard to send a repro case for - it requires an unlanded patch to trigger it plus additional tracing to detect. Maybe we can wait until https://crrev.com/c/592249 lands, and maybe we can also land a little bit of extra tracing code to make it detectable. WDYT?

I've hacked in a "SLOW_WARNING" message for this call taking >10ms and ran a debug build with --enable-gpu-service-logging added to the command line to get some context for the command stream.

This may well be a red herring due to the debug build slowing things down, but I do see slow calls in the ~20ms range even before entering VR for the sketchfab site. After entering VR, there's fairly frequent ~50ms calls, and this seems to happen fairly often after glInvalidateFramebuffer calls.

08-07 18:17:07.571 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(11603)] glTexImage2D(GL_TEXTURE_2D, 0, 6407, 1490, 874, 0, GL_RGB, GL_UNSIGNED_BYTE, 0)
08-07 18:17:07.571 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(9686)] glGetError()
08-07 18:17:07.572 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(9689)] GL_RESULT: GL_NONE
08-07 18:17:07.572 22089 22112 E chromium: [ERROR:gles2_cmd_decoder.cc(5273)] [.Offscreen-For-WebGL-0xbf5a2400]cmd: kBindTexture
08-07 18:17:07.572 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(8355)] glBindTexture(GL_TEXTURE_2D, 338)
08-07 18:17:07.572 22089 22112 E chromium: [ERROR:gles2_cmd_decoder.cc(5273)] [.Offscreen-For-WebGL-0xbf5a2400]cmd: kFramebufferTexture2D
08-07 18:17:07.572 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(9686)] glGetError()
08-07 18:17:07.572 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(9689)] GL_RESULT: GL_NONE
08-07 18:17:07.572 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(9338)] glFramebufferTexture2DEXT(GL_FRAMEBUFFER, GL_COLOR_ATTACHMENT0, GL_TEXTURE_2D, 338, 0)
08-07 18:17:07.572 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(9686)] glGetError()
08-07 18:17:07.572 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(9689)] GL_RESULT: GL_NONE
08-07 18:17:07.572 22089 22112 E chromium: [ERROR:gles2_cmd_decoder.cc(5273)] [.Offscreen-For-WebGL-0xbf5a2400]cmd: kDiscardFramebufferEXTImmediate
08-07 18:17:07.573 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(10753)] glInvalidateFramebuffer(GL_FRAMEBUFFER, 3, 0xbdfbe920)
08-07 18:17:07.573 22089 22112 E chromium: [ERROR:gles2_cmd_decoder.cc(5273)] [.Offscreen-For-WebGL-0xbf5a2400]cmd: kProduceTextureDirectCHROMIUMImmediate
08-07 18:17:07.573 22089 22112 E chromium: [ERROR:gles2_cmd_decoder.cc(5273)] [.Offscreen-For-WebGL-0xbf5a2400]cmd: kInsertFenceSyncCHROMIUM
08-07 18:17:07.573 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(10193)] glGetQueryObjectuiv(1, GL_QUERY_RESULT_AVAILABLE_EXT, 0xcab94964)
08-07 18:17:07.630 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(10198)] glGetQueryObjectuivFn;;; SLOW_WARNING call took 56.198ms
08-07 18:17:07.630 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(10193)] glGetQueryObjectuiv(2, GL_QUERY_RESULT_AVAILABLE_EXT, 0xcab94964)
08-07 18:17:07.630 22089 22112 I chromium: [INFO:gl_bindings_autogen_gl.cc(10193)] glGetQueryObjectuiv(3, GL_QUERY_RESULT_AVAILABLE_EXT, 0xcab94964)

Deleted: slow-commands-full.txt.gz 841 KB

slow-commands-full.txt.gz 841 KB Download

One more thing - the sequence seems to be:

glGetError() -> GL_NONE
glInvalidateFramebuffer()
lGetQueryObjectuiv(..., GL_QUERY_RESULT_AVAILABLE_EXT)

As far as I understand glGetError() includes an implicit driver flush, so this would seem to be a hint that the glInvalidateFramebuffer() call itself is what makes the next call slow. Does that sound plausible? Is the driver delaying further calls on this context until the invalidation finishes and the underlying commands have completed?

Yes, the glGetError call should flush previous commands to the GPU. The glInvalidateFramebuffer call is optional, and just an optimization; have you tried taking it out?

Thinking about it more, if the issue is that the call to glGetQueryObjectuiv is synchronizing the GL client and server in order to provide an accurate answer, and the GPU is busy, that would explain the behavior.

klausw@, if you can reproduce this in a standalone Android app that would help if we file a bug against Qualcomm.

klausw@, also: please try adding a driver bug workaround src/gpu/config/gpu_driver_bug_list.json disabling the GL_EXT_disjoint_timer_query extension on your affected device. If the app then runs at an acceptable rate, then we may need to disable that extension when WebGL is used in the context of WebVR (do we know that at WebGL context creation time at this point?).

For the record, I've also tried the sketchfab site without --enable-gpu-service-logging, and am seeing slow glGetQueryObjectuiv calls both before and after entering VR. I've updated https://chromium-review.googlesource.com/592011 to show the temporary logging I added.

The slow calls seem to happen in other places also, not just after glInvalidateFramebuffer, but the correlation seemed suspicious. I didn't see an obvious pattern for the other cases, this includes calls such as glUniform1i, glBindTexture, and even glGetString(GL_RENDERER). See the attachment:

$ zcat slow-commands-full.txt.gz | grep gl_bindings | grep -B 5 SLOW_WARNING > slow-context.txt

Since the issue also appears to happen before entering VR, even though less frequently, it seems unrelated to the pending change https://crrev.com/c/592249 since that code is only active during VR presentation. 

I'm currently making a build with just the SLOW_WARNING and trace_event changes from https://chromium-review.googlesource.com/592011 to confirm this.

Deleted: slow-context.txt 29.3 KB

slow-context.txt 29.3 KB View Download

Klaus: since you're working on this, reassigning to you; please assign it back to me if you need me to file a Qualcomm bug or anything else.

Reassigning to kainino@ - is this enough information to file a Qualcomm bug? Can you try to repro on a different Pixel XL on Android O to confirm? I'm on the Aug 5 2017 Android security patch level, marlin-userdebug 8.0.0 OPR1.170623.011 .

I've uploaded a build MonochromePublic_SLOW_WARNING_20170807a.apk from an older ToT 9f6c443975f0e26625e8177755cfdfaa9b6368bb (Fri Aug 4 18:10:26 2017 +0000) + the debugging changes from https://chromium-review.googlesource.com/c/592011 :

https://drive.google.com/drive/folders/0B8dt3TGgfXfiVDd5eTZaTWhCR28?usp=sharing

I've enabled "anyone with the link" sharing for this folder.

For reference, the args.gn for this was:

is_debug = true
enable_vr = true
target_os = "android"
target_cpu = "arm"
use_goma = true
proprietary_codecs = true
ffmpeg_branding = "Chrome"
use_unpublished_apis = true

To reproduce, open https://sketchfab.com/models/uFqGJrS9ZjVr9Myk9kg4fubPNPz , wait for the model to load, and use finger drag to rotate the model around. (It stops updating while idle.) This should produce logcat entries such as:

08-07 19:11:54.609 19391 19421 I chromium: [INFO:gl_bindings_autogen_gl.cc(3763)] glGetQueryObjectuivFn;;; SLOW_WARNING call took 21.904ms

Entering VR is *not* necessary for this. I expect it should be independent of the Google VR services version that's installed, though I haven't tested that.

Thanks, will look into this soon. Just checking, did you determine that your patch https://crrev.com/c/592249/ was not necessary for this issue to reproduce?

FWIW, the build from comment #15 doesn't emit the SLOW_WARNING in all code paths, I added it to GLApiBase (normal operation) and DebugGLApi (when --enable-gpu-service-logging is set on the command line).

Other variations aren't covered, for example I expect the warning to disappear when using event tracing, though in that case the TRACE_EVENT0("gpu", "glGetQueryObject_GL_QUERY_RESULT_AVAILABLE") entries should provide sufficient visibility.

kbr@, re comment #11: 

> klausw@, also: please try adding a driver bug workaround src/gpu/config/gpu_driver_bug_list.json disabling the GL_EXT_disjoint_timer_query extension on your affected device. If the app then runs at an acceptable rate, then we may need to disable that extension when WebGL is used in the context of WebVR (do we know that at WebGL context creation time at this point?).

This is a bit tricky. Core problem is that we don't know at WebGL context creation time that it'll be used for WebVR. Potentially, any WebGL canvas could be used for VR presentation at any time. In theory, since WebVR is still experimental, we could apply the workaround for sites participating in the WebVR origin trial or for people who have the WebVR flag enabled manually. However, would this require creating a different context outside the shared virtualized context? If yes, this would run into the same problem we had for issue 690106 where this conditional context change broke non-WebVR GL rendering. Apparently we *have* to use virtualized contexts for correctness on Qualcomm GPUs.

The other potential problem is that AFAIK Sketchfab uses the timer queries to do dynamic quality scaling, so it's possible that disabling the extension could indirectly affect performance due to changing application behavior when it's not present.

Anyway, I tried adding the blacklist entry to disable GL_EXT_disjoint_timer_query, and it appears that this significantly reduces the time spent in CrGpuMain, and now GPU rendering itself appears to be the bottleneck. So it does seem to help, but I don't know if this is feasible as a workaround.

re comment 16 by kainino@:

yes, it repros outside VR without https://crrev.com/c/592249/ , the build from comment #15 does not include that patch.

klausw@: good to know that disabling the GL_EXT_disjoint_timer_query extension addresses the immediate performance problem.

Note that I wasn't able to reproduce any hiccups with a current Chrome Dev Channel build on Android on a Pixel phone running Android N, spinning around https://sketchfab.com/models/uFqGJrS9ZjVr9Myk9kg4fubPNPz (not using VR mode).

Is it possible this is a regression in the Android O driver?

Basically -- I think we should file an internal bug against Qualcomm and give them an easy-to-reproduce test case -- perhaps two ChromePublic.apk builds, one which disables the extension as a driver bug workaround, and one which doesn't. I would tentatively support disabling that extension on the affected hardware as long as the bug's been filed and there's an indication that it'll be picked up.

I've done some additional testing, all with queries enabled. (No blacklist.) 

On Pixel (non-XL) on Android N, I do get SLOW_WARNING messages there too. In one test I got two at the start of rendering before entering VR, but no more after that while I was dragging the model around. After entering VR, I got one every 10 seconds or so.

That's a much lower warning rate than when using Pixel XL on Android O, there I got this warning about once per second both outside VR and in VR.

One more complication is that on Android O I see the issue when using the debug build configuration from comment #15 while in VR without the timing change from https://crrev.com/c/592249. A production build without the timing change emits SLOW_WARNING while outside VR, but the messages stop appearing while in VR, but the framerate also drops to 14fps (compared to 29fps for Pixel on N for the same build) due to the slow/fast render timing from  issue 747159 . 

So in summary I think that the GL_QUERY_RESULT_AVAILABLE issue is not completely specific to the Android O driver, but it appears to be much more severe there. The slow/fast timing as of  issue 747159  does seem to be Android O specific, and the resulting change in timing makes it a bit trickier to isolate the GL_QUERY_RESULT_AVAILABLE problem.

I had talked separately to +bajones@, since timing queries are part of the WebGL 2 spec, it sounds as if we'd need to unadvertise WebGL 2 support on affected devices if we do end up blacklisting the timer queries. Or would there be a way to use them just from WebGL 2.0 contexts (accepting the performance hit) while keeping them disabled for other contexts that share the same underlying virtualized context?

Timer queries are an extension in WebGL 2.0, as they are in WebGL 1.0. https://www.khronos.org/registry/webgl/extensions/EXT_disjoint_timer_query_webgl2/

It would be feasible to add a blacklist entry just for the Pixel XL running Android O, for example.

I'm confused. https://crrev.com/c/592249 is now submitted and merged as r492707, but now I'm seeing sketchfab's framerate cut in half on the Android N Pixel from ~29fps to ~14fps, and this slowdown remains even when blacklisting disjoint timer queries and also when I roll back r492707 locally. Not sure if it's a change on the Sketchfab site or an unrelated regression on ToT between 9f6c443975f0e26625e8177755cfdfaa9b6368bb (Fri Aug 4 18:10:26 2017 +0000) and 8fdcb934eebce9cc880e3d4b99b66951e2232499 (Tue Aug 8 18:48:44 2017 +0000). Will need to run some more experiments, there's rather many variables involved here :-/

(Deleted and reposted to clarify that this test was on the Android N Pixel.)

Framerate continued dropping to ~9fps on Pixel/Android N, and stayed there when I went back to 9f6c443975f0e26625e8177755cfdfaa9b6368bb for bisecting, so it doesn't seem to be a ToT regression. Framerate went back to ~29fps on the same test build after rebooting.

So there seems to be a separate performance issue related to prolonged use which we should look into separately, for now I'll try to make sure to reboot frequently while doing performance testing.

I filed b/64534470 against Qualcomm about this problem since it's not clear whether it's a known issue. Klaus, in the future, it would have been helpful if you could have filed a ticket like this one.

Apologies for not filing the Qualcomm bug sooner. Since it's filed, assigning back to Klaus and marking ExternalDependency until we have more info.

Qualcomm responded on b/64534470, looks like this indeed was a driver bug and it will be fixed in an upcoming version, but we'll have to live with the bug for a while. Should we proceed with blacklisting it?  I'm following up in the bug to see if we can narrow it down to specific gl_renderer versions such as "Adreno \\(TM\\) 530" or if it needs to be broader.

As far as impact is concerned, the issue doesn't appear to be inherently WebVR specific, but it's possible that other WebGL content wasn't affected noticeably. Triggering the issue may depend on specific timing or other circumstances, and the impact wasn't really obvious without extra instrumentation.

If we do want to blacklist, it would be nice to do so in M62.

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

commit 93e280e077b39694576ab96956c41b75f0c781d7
Author: Klaus Weidner <klausw@chromium.org>
Date: Wed Aug 30 20:14:41 2017

Blacklist timer query objects on Adreno 530 (Pixel)

glGetQueryObject(GL_QUERY_RESULT_AVAILABLE) blocks unexpectedly on
Adreno chipsets, causing slowdown in WebVR applications such as 
Sketchfab. As a workaround, disable the EXT_disjoint_timer_query
extension on affected chipsets. (The range of affected chipsets
may need to be broadened based on further testing.)

BUG= 750306 

Cq-Include-Trybots: master.tryserver.chromium.android:android_optional_gpu_tests_rel;master.tryserver.chromium.linux:linux_optional_gpu_tests_rel;master.tryserver.chromium.mac:mac_optional_gpu_tests_rel;master.tryserver.chromium.win:win_optional_gpu_tests_rel
Change-Id: Id3dafe760856174366eb167f8ddf1266db8f6ae0
Reviewed-on: https://chromium-review.googlesource.com/643043
Reviewed-by: Kenneth Russell <kbr@chromium.org>
Commit-Queue: Klaus Weidner <klausw@chromium.org>
Cr-Commit-Position: refs/heads/master@{#498587}
[modify] https://crrev.com/93e280e077b39694576ab96956c41b75f0c781d7/gpu/config/gpu_driver_bug_list.json

See followup in  issue 764526 , apparently this affects "all A4x (or newer) chips" which includes the Adreno 540 as used in Daydream ready devices such as the Samsung Galaxy S8.

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

commit dfcd205695a30d57bbea2cd97aba08853f0b0a00
Author: Klaus Weidner <klausw@chromium.org>
Date: Wed Sep 13 00:02:11 2017

Add Adreno 540 to disjoint_timer_query blacklist

According to Qualcomm the unexpected blocking issue likely affects
"all A4x (or newer) chips", though the specific effect only seems
to be noticeable for WebVR on Daydream-ready devices which are 
currently limited to Adreno 530 and 540.

BUG= 750306 , 764526 
R=kbr

Cq-Include-Trybots: master.tryserver.chromium.android:android_optional_gpu_tests_rel;master.tryserver.chromium.linux:linux_optional_gpu_tests_rel;master.tryserver.chromium.mac:mac_optional_gpu_tests_rel;master.tryserver.chromium.win:win_optional_gpu_tests_rel
Change-Id: Ifb95ed9a59f58fb7b4a3c91e3745f5def6b51d21
Reviewed-on: https://chromium-review.googlesource.com/662903
Reviewed-by: Kenneth Russell <kbr@chromium.org>
Commit-Queue: Klaus Weidner <klausw@chromium.org>
Cr-Commit-Position: refs/heads/master@{#501463}
[modify] https://crrev.com/dfcd205695a30d57bbea2cd97aba08853f0b0a00/gpu/config/gpu_driver_bug_list.json

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

commit a3a68de4bf635187625dcbb7e3691f24e33ca491
Author: Klaus Weidner <klausw@chromium.org>
Date: Fri Sep 15 20:43:45 2017

Add Adreno 540 to disjoint_timer_query blacklist

According to Qualcomm the unexpected blocking issue likely affects
"all A4x (or newer) chips", though the specific effect only seems
to be noticeable for WebVR on Daydream-ready devices which are
currently limited to Adreno 530 and 540.

(cherry picked from commit dfcd205695a30d57bbea2cd97aba08853f0b0a00)

BUG= 750306 , 764526 
R=kbr

Cq-Include-Trybots: master.tryserver.chromium.android:android_optional_gpu_tests_rel;master.tryserver.chromium.linux:linux_optional_gpu_tests_rel;master.tryserver.chromium.mac:mac_optional_gpu_tests_rel;master.tryserver.chromium.win:win_optional_gpu_tests_rel
Change-Id: Ifb95ed9a59f58fb7b4a3c91e3745f5def6b51d21
Reviewed-on: https://chromium-review.googlesource.com/662903
Reviewed-by: Kenneth Russell <kbr@chromium.org>
Commit-Queue: Klaus Weidner <klausw@chromium.org>
Cr-Original-Commit-Position: refs/heads/master@{#501463}
Reviewed-on: https://chromium-review.googlesource.com/669528
Reviewed-by: David Dorwin <ddorwin@chromium.org>
Cr-Commit-Position: refs/branch-heads/3202@{#260}
Cr-Branched-From: fa6a5d87adff761bc16afc5498c3f5944c1daa68-refs/heads/master@{#499098}
[modify] https://crrev.com/a3a68de4bf635187625dcbb7e3691f24e33ca491/gpu/config/gpu_driver_bug_list.json

This is reported as fixed in
msm8996: O15 release of Adreno ESX driver with GCC
msm8994: O15 release of Adreno ESX driver with GCC

If/once we are able to test that build, we should verify the bug is fixed.

Have we had a chance to verify the fix?

If it works then I guess we need to update the blacklist.

klausw@, friendly ping.

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

commit e152ac2a485d8e9782b88e4d0c96246e20bceb8e
Author: Peng Huang <penghuang@chromium.org>
Date: Wed Jan 31 17:21:11 2018

Disable GL_EXT_disjoint_timer_query for Nexus5 and Nexus7v2

Disable GL_EXT_disjoint_timer_query for Nexus5 and Nexus7v2, because
glGetQueryObject(GL_QUERY_RESULT_AVAILABLE) blocks unexpectedly.

Bug:  750306 ,  764526 
Cq-Include-Trybots: master.tryserver.chromium.android:android_optional_gpu_tests_rel;master.tryserver.chromium.linux:linux_optional_gpu_tests_rel;master.tryserver.chromium.mac:mac_optional_gpu_tests_rel;master.tryserver.chromium.win:win_optional_gpu_tests_rel
Change-Id: I752d51c05c26203a759b6c2ded961a84a90cc4cd
Reviewed-on: https://chromium-review.googlesource.com/895246
Reviewed-by: Antoine Labour <piman@chromium.org>
Commit-Queue: Peng Huang <penghuang@chromium.org>
Cr-Commit-Position: refs/heads/master@{#533307}
[modify] https://crrev.com/e152ac2a485d8e9782b88e4d0c96246e20bceb8e/gpu/config/gpu_driver_bug_list.json

didn't make it for M64, moved to 65

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

commit 03d9c2d401e533a51b61543d85ed7c80273bff2d
Author: Klaus Weidner <klausw@chromium.org>
Date: Thu Mar 01 22:26:58 2018

Update Adreno GL_EXT_disjoint_timer blacklists

The "glGetQueryObject(GL_QUERY_RESULT_AVAILABLE) blocks unexpectedly on
Adreno" issue is fixed in Android 8.1, un-blacklist it on that version.

According to Qualcomm, the issue affected Adreno 4xx and newer, and
penghuang@ also saw it on Adreno 3xx on Android K (4.x). The extension
is separately blacklisted by entry id=112 for Adreno 3xx, but only on
Android 5.0 and up, so it seems cleanest to apply the blacklist to
all of Adreno 3xx/4xx/5xx for the blocking issue.

For consistency, also disable GL_EXT_disjoint_timer_query_webgl2 for the
pre-existing Adreno blacklist entries. If the underlying calls are
broken, this is expected to affect both variants.

BUG= 477514 , 750306 , 764526 

Cq-Include-Trybots: master.tryserver.chromium.android:android_optional_gpu_tests_rel;master.tryserver.chromium.linux:linux_optional_gpu_tests_rel;master.tryserver.chromium.mac:mac_optional_gpu_tests_rel;master.tryserver.chromium.win:win_optional_gpu_tests_rel
Change-Id: Iace887cb6e168d691329ff5aaf29634e509ab5c0
Reviewed-on: https://chromium-review.googlesource.com/941549
Reviewed-by: Antoine Labour <piman@chromium.org>
Commit-Queue: Klaus Weidner <klausw@chromium.org>
Cr-Commit-Position: refs/heads/master@{#540307}
[modify] https://crrev.com/03d9c2d401e533a51b61543d85ed7c80273bff2d/gpu/config/gpu_driver_bug_list.json

To clarify, the disjoint_timer_query extensions continue to be disabled for Adreno 3xx/4xx/5xx for Android versions < 8.1, but are now kept enabled for >= 8.1.

However, the separate blacklist entry id=256 currently prevents the extensions from being visible even for >= 8.1 due to the separate  issue 808744 , it should start working once that's resolved. There are also separate blacklists for Adreno 3xx and 4xx which remain in effect.