Managed to get a trace while this was happening. The Aquarium tab hung while gathering the trace. Clicking "Stop" caused both views to resume rendering. I don't see anything obviously suspicious in the trace. Will try to make this happen again but this time wait longer while both tabs aren't rendering.

Deleted: trace_aquarium-hang.json.gz 1.7 MB

trace_aquarium-hang.json.gz 1.7 MB Download

Another trace where rendering stopped for ~10 seconds before grabbing the trace. The hang doesn't seem to show up in the trace.

Deleted: trace_aquarium-hang-10s.json.gz 4.5 MB

trace_aquarium-hang-10s.json.gz 4.5 MB Download

piman@ looked at the second trace in detail and found that at 1,884,400 µs there's a MessageLoop::RunTask call from here:

src_file	"../../extensions/browser/process_manager.cc"
src_func	"OnSuspendAck"

In response to that there is a trace event clearly showing the browser compositor being torn down:

Compositor::destructor	
LayerTreeHostInProcess::~LayerTreeHostInProcess	
SingleThreadProxy::stop	
LayerTreeHostImpl::ReleaseLayerTreeFrameSink	
GLES2::Finish	
CommandBufferHelper::Finish	
CommandBufferProxyImpl::WaitForGetOffset

I was able to reproduce this on 10.12 as well with a fresh user profile:

1. Start Chrome with --user-data-dir=/tmp/t1 (or some new user data dir)
2. Quickly navigate to the WebGL Aquarium and select 25,000 fish.
3. Try to open the Task Manager so you can watch the built-in extensions and background pages time out and exit after several seconds.

What seems to happen is that when a built-in extension exits, if the Aquarium is running with a lot of fish and therefore chewing up a lot of GPU time, a race condition is triggered and the browser's compositor is town down. I've seen this happen with the Chrome Web Store Payments Background Page and Chrome Media Router Extension. On 10.12 this happens intermittently but on 10.13 it happens frequently.

This happens with top-of-tree Chromium as well as Chrome, when the built-in CryptoTokenExtension exits. That extension only seems to launch the first time a user profile is created, so it's necessary to specify --user-data-dir=/tmp/[new dir] every time to try to reproduce the bug. Navigate to the Aquarium, quickly select 25,000 fish, and see if the renderer hangs when that extension exits.

sounds similar to issue 781714 which is about a hang during browser shutdown in CommandBufferProxyImpl dtor.

Nvm my above comment. This seems to be because of the SetDeferCommits(true) call. It means that we stop updating ui compositor via begin main frame.

Chris, you mentioned you could look into this if it were reproducible with Chromium; can I assign this to you?

Note that I'm having difficulty reproducing this on 10.12. Steps were:

1) Check out https://github.com/WebGLSamples/WebGLSamples.github.io/
2) From the checked-out directory, run:  python -m SimpleHTTPServer
3) Run:
rm -rf /tmp/t1 ; ./chrome-mac-515287/Chromium.app/Contents/MacOS/Chromium --user-data-dir=/tmp/t1 http://localhost:8000/aquarium/aquarium.html

When the CryptoTokenExtension exits, it doesn't seem to cause the aquarium to hang.

From offline discussion with kbr and ccameron, SetDeferCommits(true) is expected because the extension's ui compositor is suspended so that it can be recycled. We acquire a compositor lock on that ui compositor to prevent updates until it's recycled.

I see that the browser is continuing to call GLRenderer::SwapBuffers, so it looks as though it's not a scheduling bug.

To be 100% certain, we could enable tracing of ui and ensure that ui::AcceleratedWidgetMac::GotCALayerFrame or ui::AcceleratedWidgetMac::GotIOSurfaceFrame is being called after each swap.

If that call is not being made, then there may be a bug wherein GpuOutputSurfaceMac::OnGpuSwapBuffersCompleted thinks that it should not draw.

After rebooting the machine, this problem seemed to disappear, and I had some difficulty getting it to happen again. The reproduction steps above don't work reliably. Here are some which work almost 100% of the time. They have been tested on MacBook Pros with both AMD and NVIDIA GPUs on 10.12, so this issue isn't GPU dependent nor macOS 10.13 dependent.

0. Download this Chromium build, or use your own:
https://commondatastorage.googleapis.com/chromium-browser-snapshots/index.html?prefix=Mac/515287/

1. Copy the URL into the clipboard:
https://webglsamples.org/aquarium/aquarium.html
2. Run Chrome/Chromium from the command line with a fresh user data directory, e.g.:
rm -rf /tmp/t1 ; ./chrome-mac-515287/Chromium.app/Contents/MacOS/Chromium --user-data-dir=/tmp/t1
3. Quickly paste the URL into the Omnibox.
4. As soon as the Aquarium loads, click the text for 30,000 fish.
5. Quickly open the Task Manager.
6. Wait for the CryptoTokenExtension to exit.

As soon as the CryptoTokenExtension exits, the window will frequently stop rendering. A locally hosted copy of the Aquarium would work too.

Passing the URL on the command line seems to cause the renderer for the Aquarium to initialize before those for the extensions, and when the extensions exit, the destruction of their compositors doesn't break the presentation of the Aquarium's frames.

Here is a trace gathered via the following command line options:

rm -rf /tmp/t1 ; ./chrome-mac-515287/Chromium.app/Contents/MacOS/Chromium --user-data-dir=/tmp/t1 --trace-startup=blink,cc,gpu,renderer.scheduler,ui,v8,toplevel --trace-startup-duration=20 --trace-startup-file=aquarium-hang.json

and following the steps above.

The MessageLoop::RunTask event posted which seems to trigger SingleThreadProxy::SetDeferCommits, and the destruction of the LayerTreeHostInProcess, happens at 15,443.794 ms.

Deleted: aquarium-hang.json.gz 5.5 MB

aquarium-hang.json.gz 5.5 MB Download

We're continuing to get GLRenderer::SwapBuffers and ui::AcceleratedWidgetMac::GotCALayerFrame calls.

This indicates that everything is working perfectly in terms of compositor and scheduling -- frames are being produced and the browser is being told to put them on-screen.

I would guess this to be remote CoreAnimation hiccuping.

It seems more likely to me to be a compositor bookkeeping bug in Chrome. Starting the browser with the URL as argument seems to make the bug reliably go away. In this situation I think the renderer for the page is racily starting before the extensions' renderers, and when the extensions' renderers shut down, they aren't having the same effect on the UI compositor as when they start before the page's renderer.

Can we confirm or refute this hypothesis?

I tried running with various combinations of the flags:

--disable-remote-core-animation --disable-mac-overlays --disable-features=WebGLImageChromium

but the browser window renders black with --disable-remote-core-animation specified. Is there another way to confirm that the bug's related to usage of remote CA?

Looks like I broke --disable-remote-core-animation recently (oops, need to fix that).

I went back to 62.0.3202.94, where --disable-remote-core-animation still works and:
- this reproduces without --disable-remote-core-animation
- this does not reproduce with --disable-remote-core-animation

I'll go see if just re-creating our CALayerHost takes care of this.

One of my experiments here was to re-create the CALayerHost in the browser periodically. That did nothing.

Next experiment was to re-create the CAContext in the GPU process periodically. When I do that, the screen just turns black.

My feeling here is that the aquarium WebGL context is starving the ability of the GPU process to send new frames to the WindowServer.

The reason that the non-remote-layer path works, in this case, would be because it is the browser process that is sending new frames to the WindowServer (and is thus exempt from whatever throttling is being done).

My next experiment was to glFinish all GLContextCGLs whenever create or destroy a CAContext ... that didn't work.

Next attempt was to glFinish all GLContextCGLs every single frame ... that still doesn't fix anything.

It seems that this needs lots of breathing room. Of note is that clicking on any of the fish levels that brings the framerate back to 60hz fixes this immediately.

Thanks Chris for investigating this. Interesting that it really does seem to be in the Core Animation internals.

Right now DrawingBuffer calls DescheduleUntilFinishedCHROMIUM. Do you think it'd be feasible to plumb some signal through to prevent that from unblocking the WebGL context until say the first frame of a newly created UI compositor has hit the screen, or similar?

Have you figured out why this behavior's tied to the teardown of an extension?

> Have you figured out why this behavior's tied to the teardown of an extension?

Not yet. I've tried keeping the CAContexts and CALayers alive indefinitely on the GPU side, but the hang still occurs.

I've also just put a "glFinish the do a sleep for 10 msec" inside DescheduleUntilFinishedCHROMIUM, without luck.

So, I have a hunch that we're starving Cocoa's message loop here. Lemme see where I can get with that.

This is 100% a CPU-side scheduling/starvation issue.

I added a patch we make Scheduler::RunNextTask post its next task with a 1msec delay after every HandleDescheduleUntilFinishedCHROMIUM (coordinated just by a global variable).

With that change, the issue completely vanishes.

Ultimately we need the GPU scheduler to be running at a less-important priority than Cocoa. Cocoa has very few messages it runs in the GPU process, but it's important that they run with the most-important priority, because they are necessary to getting anything on-screen.

(this is the patch, btw)

diff --git a/gpu/command_buffer/service/gles2_cmd_decoder.cc b/gpu/command_buffer/service/gles2_cmd_decoder.cc
index 0a583f61ad66..97d19e953710 100644
--- a/gpu/command_buffer/service/gles2_cmd_decoder.cc
+++ b/gpu/command_buffer/service/gles2_cmd_decoder.cc
@@ -98,6 +98,8 @@
 #include "ui/gl/gpu_timing.h"
 #include "ui/gl/init/create_gr_gl_interface.h"
 
+bool g_let_me_breathe = false;
 #if defined(OS_MACOSX)
 #include <IOSurface/IOSurface.h>
 // Note that this must be included after gl_bindings.h to avoid conflicts.
@@ -16392,6 +16394,7 @@ bool GLES2DecoderImpl::CheckResetStatus() {
 error::Error GLES2DecoderImpl::HandleDescheduleUntilFinishedCHROMIUM(
     uint32_t immediate_data_size,
     const volatile void* cmd_data) {
+  g_let_me_breathe = true;
   if (!gl::GLFence::IsSupported())
     return error::kNoError;
   std::unique_ptr<gl::GLFence> fence(gl::GLFence::Create());
diff --git a/gpu/command_buffer/service/scheduler.cc b/gpu/command_buffer/service/scheduler.cc
index 1c75957e91d3..ac565c408655 100644
--- a/gpu/command_buffer/service/scheduler.cc
+++ b/gpu/command_buffer/service/scheduler.cc
@@ -15,6 +15,9 @@
 #include "base/trace_event/trace_event_argument.h"
 #include "gpu/command_buffer/service/sync_point_manager.h"
 
+extern bool g_let_me_breathe;
 namespace gpu {
 
 class Scheduler::Sequence {
@@ -560,8 +563,16 @@ void Scheduler::RunNextTask() {
     }
   }
 
-  task_runner_->PostTask(FROM_HERE, base::Bind(&Scheduler::RunNextTask,
-                                               weak_factory_.GetWeakPtr()));
+  if (g_let_me_breathe) {
+    g_let_me_breathe = false;
+    task_runner_->PostDelayedTask(FROM_HERE,
+        base::Bind(&Scheduler::RunNextTask, weak_factory_.GetWeakPtr()),
+        base::TimeDelta::FromMilliseconds(1));
+  } else {
+    task_runner_->PostTask(FROM_HERE, base::Bind(&Scheduler::RunNextTask,
+                                                 weak_factory_.GetWeakPtr()));
+  }
+
 }
 
 }  // namespace gpu

Fortunately, rsesek has an explanation for this bug (thanks!):
https://bugs.chromium.org/p/chromium/issues/detail?id=312462#c51

> For context, on OS X there are four options for the main thread MessagePump:
> 1. Default
> 2. CFRunLoop
> 3. NSRunLoop
> 4. NSApplication
> 
> You may be able to get away with (2) if nothing requires NSTimer or
> -[NSObject performSelector:afterDelay:withObject:]. This was not the case in the renderers
> (scrollbars use NSTimer), so that's why renderer_main.cc allocates (3).

What we're running up against is consistent with remote CoreAnimation using one of those sorts of calls.

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

commit 1732f2b0b33337ace603d3ec12f28cd3afaecda4
Author: Christopher Cameron <ccameron@chromium.org>
Date: Fri Nov 17 10:56:50 2017

Use a NSRunLoop instead of a CFRunLoop in GpuMain

Under heavy CPU load, the GPU main thread was starving out messages
required by CoreAnimation.

Bug:  783298 
Change-Id: If3604b47e479e93b6351b816c17c7f570589ac22
Reviewed-on: https://chromium-review.googlesource.com/775621
Reviewed-by: Kenneth Russell <kbr@chromium.org>
Commit-Queue: ccameron <ccameron@chromium.org>
Cr-Commit-Position: refs/heads/master@{#517365}
[modify] https://crrev.com/1732f2b0b33337ace603d3ec12f28cd3afaecda4/content/gpu/gpu_main.cc

Do you know what specific work was being starved by CFRunLoop? If you have a stack from the CoreAnimation work that wasn't getting processed but is after that change, I'd be curious.

Sending frames to the WindowServer was working fine (probably doesn't involve posting tasks) -- it seemed to be something related to destroying or disconnecting a CAContext in the browser process.