I revised this script to log the screenshot time: https://gist.github.com/paulirish/956a86b797197999cdb422f1e7be5a3e

On my mac, the performance is consistent and screenshot duration doesnt' climb above 225ms.

Deleted: Screen Shot 2017-07-12 at 11.34.36 AM.png 102 KB

	Screen Shot 2017-07-12 at 11.34.36 AM.png 102 KB View Download

Tested on a second Mac and seeing this behaviour there also.  Both I've used are latest Sierra. Timings from test script are below.

I have noticed that content of the page being rendered affects how quickly this issue begins.  

A very simple page like example.com works as expected until frame 100 or so before slowing, while an image-heavy page like https://apod.nasa.gov/apod/ap170713.html starts slowing after about 50 frames.  My use case is 100% images, which may explain why I was seeing it even earlier.


Render times for https://example.com
...
294ms. Rendered frame 96
287ms. Rendered frame 97
362ms. Rendered frame 98
346ms. Rendered frame 99
341ms. Rendered frame 100
310ms. Rendered frame 101
389ms. Rendered frame 102
1,026ms. Rendered frame 103
534ms. Rendered frame 104
5,193ms. Rendered frame 105
1,543ms. Rendered frame 106
780ms. Rendered frame 107
1,784ms. Rendered frame 108
2,008ms. Rendered frame 109
1,420ms. Rendered frame 110
1,397ms. Rendered frame 111
1,365ms. Rendered frame 112
1,367ms. Rendered frame 113
11,669ms. Rendered frame 114
8,297ms. Rendered frame 115
2,897ms. Rendered frame 116
5,420ms. Rendered frame 117
1,622ms. Rendered frame 118
12,598ms. Rendered frame 119
20,225ms. Rendered frame 120
1,410ms. Rendered frame 121
11,361ms. Rendered frame 122




Render times for https://apod.nasa.gov/apod/ap170713.html
...
541ms. Rendered frame 51
538ms. Rendered frame 52
539ms. Rendered frame 53
531ms. Rendered frame 54
552ms. Rendered frame 55
8,046ms. Rendered frame 56
3,035ms. Rendered frame 57
3,847ms. Rendered frame 58
6,064ms. Rendered frame 59
7,207ms. Rendered frame 60
5,640ms. Rendered frame 61
5,708ms. Rendered frame 62
10,695ms. Rendered frame 63
2,589ms. Rendered frame 64
5,130ms. Rendered frame 65
10,664ms. Rendered frame 66
10,682ms. Rendered frame 67
10,693ms. Rendered frame 68
10,676ms. Rendered frame 69
10,716ms. Rendered frame 70
10,653ms. Rendered frame 71
4,919ms. Rendered frame 72
5,382ms. Rendered frame 73
6,782ms. Rendered frame 74
10,689ms. Rendered frame 75
10,667ms. Rendered frame 76
5,503ms. Rendered frame 77

Quick note that I've tried this in CentOS 7 and did not see this behaviour.
Headless screenshot render times stayed consistent through several hundred iterations.

Yup, I can repro this on the APOD url:

...
550ms. Rendered frame 15
577ms. Rendered frame 16
636ms. Rendered frame 17
601ms. Rendered frame 18
564ms. Rendered frame 19
563ms. Rendered frame 20
578ms. Rendered frame 21
578ms. Rendered frame 22
602ms. Rendered frame 23
589ms. Rendered frame 24
614ms. Rendered frame 25
10,829ms. Rendered frame 26
5,806ms. Rendered frame 27
10,805ms. Rendered frame 28
10,988ms. Rendered frame 29
4,380ms. Rendered frame 30
10,732ms. Rendered frame 31
10,818ms. Rendered frame 32
10,890ms. Rendered frame 33
10,642ms. Rendered frame 34
10,858ms. Rendered frame 35
10,827ms. Rendered frame 36
8,681ms. Rendered frame 37
10,840ms. Rendered frame 38


Thanks very much for this small repro script. Super helpful.

Glad it's not just me!  My first real bug report ever :)

Thanks for the report!

I'm assuming then that this is a Mac only issue (and due how Mac headless is different to Windows/Linux)

I'll see if I can investigate

I was able to reproduce the issue on my Mac.
 
The strange thing is that if I use the headless_shell binary instead of my own compilation of chromium then rendering is consistent again. 

This is quite strange, since chrome --headless should essentially be exactly the same as running headless_shell, so I wonder if it could be a Mac specific thing in which the process gets throttled somehow

See attached a trace I took while running 100 renders.

I'm not an expert on interpreting traces. It does appear like the RendererSchedulerIdlePeriod increases over time, but not in all renders that take 10+ seconds to render.
Other than that, render time takes the usual, only that the gap between one render and the next increases suddenly

Deleted: Trace.png 176 KB

	Trace.png 176 KB View Download

David, could you share a trace file? :)

I think RendererSchedulerIdlePeriod is essentially the time between frame commit on the main thread and the next Begin(Main)Frame.

In the screenshot, it looks like the neither browser nor renderer are executing anything on their main threads during that delay period. So it seems the next frame is not delayed because of blocking work there. Can you see which event eventually triggered the next BeginFrame after the delay?

Oops, sorry I thought I had added the trace. 
It's not clear to me what triggers the BeginFrame after the idle time. I'll investigate a bit

Deleted: trace.json 8.0 MB

trace.json 8.0 MB View Download

For reference, here's a "healthy" trace using headless_shell instead of chrome --headless.

I don't see much differences other than the idle time of the previous trace starts increasing after frame ~50

Deleted: trace2.json.zip 1.0 MB

trace2.json.zip 1.0 MB Download

Seems like RenderWidgetHostImpl::WindowSnapshotReachedScreen is called VERY late for the frame that takes so long.

That get's posted here [1], with a delay of 1/6th of a second on Mac. I have no idea why that may be delayed >10s. Maybe because we don't have a window, the OS doesn't give us high enough priority and wakes us up too late?

Anyway, I don't think that delay makes sense when fromSurface is true. We don't care about OS-level animations in that case, because we are copying from the surface, not from the OS window. Let's just call WindowSnapshotReachedScreen synchronously from RWHI::OnGpuSwapBuffersCompletedInternal if fromSurface is true.

[1] https://cs.chromium.org/chromium/src/content/browser/renderer_host/render_widget_host_impl.cc?l=1851

Thanks for the insights Eric. Removing the delay does make things better (render time goes from ~500ms to ~400ms). But the increase in delay still happens.

I'm attaching a new trace.

Some notes: 
- Not sure if relevant, but I find interesting that the delay starts invariably at the 30s mark when the first screenshot is captured, both with and without removing the delay in [1]
- The render trace shows now that the CoputOutputRequest trace generated here: https://cs.chromium.org/chromium/src/cc/output/copy_output_request.cc is the one that increases over time, with the renderer sitting idle. I think this is related to copying the render bitmap to generate the screenshot data.

Deleted: trace3.json.zip 1.0 MB

trace3.json.zip 1.0 MB Download

Looks like the next vsync tick task that should be posted with a delay of about 16ms [1] is actually delayed by >10s now. I still have the feeling that this is related to the OS thinking that we're a background app and thus don't deserve to wake up too frequently.

Is there a way on OSX to manually give the chrome processes foreground priority? Just to check if it might be related to that...

[1] https://cs.chromium.org/chromium/src/cc/scheduler/delay_based_time_source.cc?l=158

FYI: https://stackoverflow.com/questions/20607290/os-x-cocoa-timer-not-fired-when-application-on-background

Here's official documentation about this feature: https://developer.apple.com/library/content/releasenotes/MacOSX/WhatsNewInOSX/Articles/MacOSX10_9.html#//apple_ref/doc/uid/TP40013207-CH100

I ran the following line in a terminal, and I believe it is a functioning workaround:

    defaults write com.google.Chrome NSAppSleepDisabled -bool YES

Thanks both for your insights, I've submitted http://crrev.com/c/582036 for review.

Confirmed that the workaround by donv42@ should work in the meantime.

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

commit 756bb3411cc85e1567b4e74f81adf100a15c5b67
Author: David Vallet <dvallet@chromium.org>
Date: Mon Jul 24 06:42:31 2017

Dissallow headless browser being backgrounded on Mac

Bug:  741689 
Change-Id: I403a263af0a52cfa4c5ea494a9bdd992b0b36b16
Reviewed-on: https://chromium-review.googlesource.com/582036
Reviewed-by: Eric Seckler <eseckler@chromium.org>
Commit-Queue: David Vallet <dvallet@chromium.org>
Cr-Commit-Position: refs/heads/master@{#488926}
[modify] https://crrev.com/756bb3411cc85e1567b4e74f81adf100a15c5b67/headless/lib/browser/headless_browser_impl_mac.mm

Confirmed this is working now on Canary. 
Thanks everybody for your help!

So is the 1/6 second delay still there when capturing from the surface?

Might be off topic now, but it seems like that is also an unnecessary slow down for capturing repeated screenshots.

I honestly don't think is worth doing the necessary plumbing to differentiate between composite and non-composite screenshot captures.
This will save the 1/6 second just in the case that you just capture screenshots continuously, but that's a very specific use case. Usually you render a page and then do the capture, so the 1/6 is relatively low compare to actual fetch/render time.

I also see this as fixed with Canary. 

Until the fix makes it to stable (in v62 in October?) is there a workaround we can use with Chrome stable? As a guess, I tried passing --disable-background-timer-throttling to Chrome on the command line, but it didn't have any impact.

Apologies - I just realised there's a workaround posted earlier in the thread:

defaults write com.google.Chrome NSAppSleepDisabled -bool YES

Still, if there were any workarounds which could be scoped to a particular Chrome process (say via CLI switch) rather than a system wide setting, I'd be glad to hear.

Indeed the workaround works. Thank you very much for this thread and the workaround. I would have lost so much time understanding what was going on without it.