New issue
Advanced search Search tips

Issue 881949 link

Starred by 1 user

Issue metadata

Status: Available
Owner: ----
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment

Frame Processing order

Project Member Reported by yiyix@chromium.org, Sep 7

Issue description

I ran into the following behavior for frame submission:

Frame A arrives in OnBeginFrame
Frame B arrives in OnBeginFrame
Frame B ends in DidNotProduceFrame through Scheduler::SendBeginFrameAck
Frame A ends in SubmitCompositorFrame

Is it a bug that Frame A and B are processed at different order as they arrive?

More info:
experiment cl: https://chromium-review.googlesource.com/c/chromium/src/+/1159167

observed crash in:
https://chromium-review.googlesource.com/c/chromium/src/+/1159167/14 && https://chromium-review.googlesource.com/c/chromium/src/+/1159167/13 

Log:
[204030:204030:0906/172501.691866:ERROR:async_layer_tree_frame_sink.cc(263)] ++++++++++++++++++++4294967361
[204030:204030:0906/172501.691941:ERROR:scheduler.cc(759)] process scheduled action: 4294967360
[204030:204030:0906/172501.692059:ERROR:async_layer_tree_frame_sink.cc(263)] ++++++++++++++++++++4294967362
[204030:204030:0906/172501.692115:ERROR:scheduler.cc(565)] go to Scheduler::SendBeginFrameAck: 4294967361
[204030:204030:0906/172501.692155:ERROR:async_layer_tree_frame_sink.cc(221)] ------------------------actual: 4294967361
[204030:204030:0906/172501.692199:ERROR:async_layer_tree_frame_sink.cc(222)] ------------------------we think: 4294967360
[204030:204030:0906/172501.692306:ERROR:scheduler.cc(759)] process scheduled action: 4294967360
[204030:204030:0906/172501.692399:ERROR:async_layer_tree_frame_sink.cc(263)] ++++++++++++++++++++4294967363
[204030:204030:0906/172501.692455:ERROR:scheduler.cc(565)] go to Scheduler::SendBeginFrameAck: 4294967362
[204030:204030:0906/172501.692491:ERROR:async_layer_tree_frame_sink.cc(221)] ------------------------actual: 4294967362
[204030:204030:0906/172501.692527:ERROR:async_layer_tree_frame_sink.cc(222)] ------------------------we think: 4294967361
[204030:204030:0906/172501.692625:ERROR:scheduler.cc(759)] process scheduled action: 4294967360
[204030:204030:0906/172501.692724:ERROR:async_layer_tree_frame_sink.cc(263)] ++++++++++++++++++++4294967364
[204030:204030:0906/172501.692781:ERROR:scheduler.cc(565)] go to Scheduler::SendBeginFrameAck: 4294967363
[204030:204030:0906/172501.692818:ERROR:async_layer_tree_frame_sink.cc(221)] ------------------------actual: 4294967363
[204030:204030:0906/172501.692862:ERROR:async_layer_tree_frame_sink.cc(222)] ------------------------we think: 4294967362
[204030:204030:0906/172501.692986:ERROR:scheduler.cc(759)] process scheduled action: 4294967360
[204030:204030:0906/172501.693954:ERROR:scheduler.cc(759)] process scheduled action: 4294967360
[204030:204030:0906/172501.694099:ERROR:scheduler.cc(759)] process scheduled action: 4294967360
[204030:204030:0906/172501.694328:ERROR:scheduler.cc(759)] process scheduled action: 4294967360
[204030:204030:0906/172501.694462:ERROR:scheduler.cc(759)] process scheduled action: 4294967360
[204030:204030:0906/172501.694529:ERROR:scheduler.cc(759)] process scheduled action: 4294967360
[204030:204030:0906/172501.696092:ERROR:async_layer_tree_frame_sink.cc(157)] ------------------------4294967360
[204030:204030:0906/172501.696157:ERROR:async_layer_tree_frame_sink.cc(159)] trace_id is different: 4294967363 : 4294967360
[204030:204030:0906/172501.696204:ERROR:async_layer_tree_frame_sink.cc(160)] client_name: Browser
 
Consider:

1. Compositor thread is busy
2. BeginFrame A arrives
3. BeginFrame B arrives
4. Compositor thread wakes
5. Compositor thread starts BeginFrame A
6. While still in that same vsync it sees BeginFrame B. It's not going to service both so it aborts B.
7. Compositor thread sends a frame for A.
I have very similar assumption. 

@fsamuel suggested to do the following:
1. Compositor thread is busy
2. BeginFrame A arrives
3. BeginFrame B arrives
4. Compositor thread wakes
5. Compositor thread starts BeginFrame A
6. Set BeginFrame B to Abort state and do not process the abortion.
7. Compositor thread sends a frame for A.
8. Abort BeginFrame B. 

What do you think?
Stepping back a bit, what is the problem with sending the ack for B immediately?
I suppose maybe there's nothing wrong assuming Viz can handle out of order ACKs. Certainly, I was under the impression that with the introduction of BeginFrameAcks, that the following statements are true:

1. For every BeginFrame, there is one and only one BeginFrameAck via SubmitCompositorFrame or DidNotProduceFrame.

2. BeginFrameAcks get sent back to Viz in order.

Is it worth making these invariants true if they're not already true?

Measuring the graphics pipeline becomes a bit trickier because we only care about BeginFrames that have corresponding CompositorFrames, but we need to track BeginFrames in any order (can't necessarily use a queue).

Maybe we should just use a flat_map then?
What are we tracking state-wise in the browser? Could we reconstruct it from what the renderer sends?
Do we process a BeginFrame that is past its deadline? I don't understand why cc starts working on BeginFrame A instead of discarding it.
Cc: sunn...@chromium.org
I just found another bug: DidNotProduceFrame may issue twice for the same frame from function Scheduler::SendBeginFrameAck.

patch:
https://chromium-review.googlesource.com/c/chromium/src/+/1159167/16

output:
[246217:246217:0910/163328.223497:ERROR:async_layer_tree_frame_sink.cc(256)] adding...: 4294967336
[246217:246217:0910/163328.223598:ERROR:scheduler.cc(565)] go to Scheduler::SendBeginFrameAck: 4294967336
[246217:246217:0910/163328.223665:ERROR:async_layer_tree_frame_sink.cc(217)] Removing...: 4294967336
[246217:246217:0910/163328.231173:ERROR:scheduler.cc(565)] go to Scheduler::SendBeginFrameAck: 4294967335
[246217:246217:0910/163328.231243:ERROR:async_layer_tree_frame_sink.cc(217)] Removing...: 4294967335
[1:8:0910/163328.233322:ERROR:scheduler.cc(565)] go to Scheduler::SendBeginFrameAck: 1407387768455188
[1:8:0910/163328.233523:ERROR:async_layer_tree_frame_sink.cc(217)] Removing...: 1407387768455188
[1:8:0910/163328.233869:ERROR:async_layer_tree_frame_sink.cc(256)] adding...: 1407387768455189
[1:8:0910/163328.250055:ERROR:scheduler.cc(565)] go to Scheduler::SendBeginFrameAck: 1407387768455189
[1:8:0910/163328.250373:ERROR:async_layer_tree_frame_sink.cc(217)] Removing...: 1407387768455189
[1:8:0910/163328.250740:ERROR:async_layer_tree_frame_sink.cc(256)] adding...: 1407387768455190
[246217:246217:0910/163328.264028:ERROR:async_layer_tree_frame_sink.cc(256)] adding...: 4294967337
[246217:246217:0910/163328.264164:ERROR:scheduler.cc(565)] go to Scheduler::SendBeginFrameAck: 4294967336
[246217:246217:0910/163328.264233:ERROR:async_layer_tree_frame_sink.cc(217)] Removing...: 4294967336

Frame 4294967336 is the one get to DidNotProduceFrame twice.


This is icky. Ideally we'd ACK once and ACKs would be sent in the order BeginFrames arrive but that is not the case. The BeginFrame protocol is more complicated than I initially thought. :(
Owner: ----
Status: Available (was: Assigned)
I don't think i will fix this, removing myself from the owner.

Sign in to add a comment