All graphs for this bug:
  https://chromeperf.appspot.com/group_report?bug_id=797426

(For debugging:) Original alerts at time of bug-filing:
  https://chromeperf.appspot.com/group_report?sid=e233659d18e7a566f3c0df4cfbbe699fd465c78ecd387b01d8ffac2249aa70d8


Bot(s) for this bug's original alert(s):

android-nexus6

Started bisect job https://chromeperf.appspot.com/buildbucket_job_status/8959470443338019968

=== Auto-CCing suspected CL author jamwalla@chromium.org ===

Hi jamwalla@chromium.org, the bisect results pointed to your CL, please take a look at the
results.


=== BISECT JOB RESULTS ===
Perf regression found with culprit

Suspected Commit
  Author : James Wallace-Lee
  Commit : aefa586e7c8a20173fac5a4b8dfa301f8460e852
  Date   : Thu Dec 21 16:40:07 2017
  Subject: cc: don't ProcessScheduledActions inside BeginImplFrame

Bisect Details
  Configuration: android_nexus6_perf_bisect
  Benchmark    : smoothness.gpu_rasterization.top_25_smooth
  Metric       : frame_times/http___techcrunch.com
  Change       : 1.88% | 16.8400807057 -> 17.1563309643

Revision             Result                     N
chromium@525689      16.8401 +- 0.0437854       6      good
chromium@525710      16.8523 +- 0.0548481       6      good
chromium@525712      16.8323 +- 0.00630779      6      good
chromium@525713      17.1146 +- 0.182796        6      bad       <--
chromium@525716      17.141 +- 0.156131         6      bad
chromium@525721      17.1766 +- 0.244722        6      bad
chromium@525731      17.1563 +- 0.133116        6      bad

To Run This Test
  src/tools/perf/run_benchmark -v --browser=android-chromium --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=http...techcrunch.com smoothness.gpu_rasterization.top_25_smooth

More information on addressing performance regressions:
  http://g.co/ChromePerformanceRegressions

Debug information about this bisect:
  https://chromeperf.appspot.com/buildbucket_job_status/8959470443338019968


For feedback, file a bug with component Speed>Bisection

 Issue 797425  has been merged into this issue.

 Issue 797424  has been merged into this issue.

 Issue 798339  has been merged into this issue.

perf bots produce traces, which generally should provide a clue. I'll take a look later today.

this appears to have broken deadline scheduler. the deadline now happens before begin main frame, which I assume usually shouldn't happen. see attached screenshots of the traces produced by perf bot

Deleted: before.png 149 KB

	before.png 149 KB View Download

Deleted: after.png 150 KB

	after.png 150 KB View Download

I can't tell by staring at the CL what caused the behavior change. jamwalla is investigating with a device now

scratch #8. That's just whether input needs to go to main thread, and I wasn't reading the traces carefully, so total red herring.

I think it's a *lot* more subtle, but can still see it in the trace. I see dropped frames, that the deadline never happens for whatever reason in some cases. It's easier to see with flow events turned on, but see that gap near the slightly left of center in this screenshot, which is a missing deadline event for whatever reason. I don't think I see that in the before trace.

It seem to happen when unbuffered input arrives immediately after a begin frame, which honestly means input just missed that frame. So on the surface, this kind of makes sense, and I'm more curious what it was triggering drawing before this change, because there was no input to cause damage.. I have a feeling this might be a intended change. :/

Kind of disturbing to see *unbuffered* input isn't aligned to frames at all, but shifts slightly throughout. I don't know if this is due to synthetic input not having a super precise clock, or this particular device actually does this?. +dtapuska, do you know?

Attached the traces as well this time. Need to go to chrome://tracing, the click on load and then select the html file.

Deleted: Screenshot from 2018-01-05 11:40:26.png 209 KB

	Screenshot from 2018-01-05 11:40:26.png 209 KB View Download

Deleted: r525698.html 3.8 MB

r525698.html 3.8 MB View Download

Deleted: r525797.html 3.8 MB

r525797.html 3.8 MB View Download

> I'm more curious what it was triggering drawing before this change, because there was no input to cause damage..

And of course I'm confusing webview and clank. In clank, begin frame should pretty much always trigger a deadline, and the damage check happens in the deadline, and draw is skipped if so. Ok, so missing deadline there appears to be the problem, at least to me.

Synthetic input isn't aligned to a clock at all (it was previously but was removed for viz, because these are all IPCs and they race between the processes).

Fundamentally synthetic input should be firing at a race higher than the display rate since that is how it actually occurs.. I believe Victor was experimenting with that in this change: https://chromium-review.googlesource.com/c/chromium/src/+/761265

Why does in the telemetry trace there only appear 3 frames in the frametimes? Shouldn't there be a whole lot more frame times?

For the record I was looking at the traces here: https://chromeperf.appspot.com/report?sid=2d0370d996a49f2f9b191d1073e299431300664b4e52381f6130500d2854953f&rev=525731

but even before/after the change they seem to only have 3 frames and that could certainly change the average which so few data points.

Err, how does one look up the "frame times" in the trace?

Right hand side of the window, click input latency.

Discussed this with boliu. It looks like frames are being dropped because the synthetic input is on a timer that's slightly slower than vsync. So, input comes later and later in the frame until we eventually drop a frame.

I couldn't reproduce this with manual scrolling, but it's still worth figuring out why this changed behavior at all.

Attached is a screenshot of the behavior change. Looking at the behavior of Scheduler::BeginImplFrame in low latency mode (the latter part of the trace):

- Before this CL, ThreadProxy::ScheduledActionSendBeginMainFrame happened before the scheduler received input (LatencyInfo.Flow: "Main thread scroll update").
- After this CL, the scheduler receives input before sending the BeginMainFrame.
- The scheduler now does not draw if there is no input event in BeginImplFrame.

Possibly this is because Scheduler::BeginImplFrame is now not reentrant: 
https://chromium-review.googlesource.com/c/chromium/src/+/806642/14/cc/scheduler/scheduler.cc#546

BeginImplFrame calls LayerTreeHostImpl::WillBeginImplFrame, which calls InputHandlerClient::DeliverInputForBeginFrame.

I'll play with this tomorrow -- but this new behavior seems sensible (?)

Also note to self that chrome://tracing and the perf charts only show a handful of frame times, but many more are recorded in results-chart.json.

Deleted: before.png 20.8 KB

	before.png 20.8 KB View Download

Deleted: after.png 21.4 KB

	after.png 21.4 KB View Download

Deleted: before (draws).png 53.7 KB

	before (draws).png 53.7 KB View Download

Deleted: after (doesn't draw).png 35.8 KB

	after (doesn't draw).png 35.8 KB View Download

Adding my summary here as well. Mostly same info as above, with different emphasis.

BeginImplFrame used to deliver input *after* SendBeginMainFrame. That feels super bad, because main thread scroll update is potentially frame late? (Although I don't know scroll updates in detail)

Given that the synthetic input is period is slightly longer than a vsync period (easily seen in trace), it actually makes no sense that chrome was drawing every single frame previously (frame time average almost exactly 16.7ms). I think it's totally expected that chrome skips a frame once in awhile when the synthetic input skips a frame, hence this "regression". Haven't worked out exactly what caused this though, but I'm guessing it might have to do with input and begin main frame ordering above.

If I comment out the mark_inside in BeginImplFrame (https://cs.chromium.org/chromium/src/cc/scheduler/scheduler.cc?l=547&rcl=b42c8c63669fd9128aa6354abc62aed0a569e1ae), the trace goes back to the original behavior (BeginMainFrame before input) and the mean frame time goes back down to around 16.8ms (testing locally on a nexus 6p).

So, I think we're right that not allowing BeginImplFrame to be reentrant caused this regression.

that sounds like a wontfix to me

Justification is in #20, that this only happens with synthetic input