Closed Bug 1075096 Opened 10 years ago Closed 10 years ago

Composite Times are inaccurate in the SPS Profiler

Categories

(Core :: Gecko Profiler, defect)

ARM
Gonk (Firefox OS)
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla35

People

(Reporter: mchang, Assigned: mchang)

References

Details

Attachments

(8 files, 3 obsolete files)

Attached image screenshot.png
+++ This bug was initially created as a clone of Bug #1073545 +++

Once I added vsync markers, I noticed that composite times were always overlapping vsync times, even with silk. I measured composite times start - http://dxr.mozilla.org/mozilla-central/source/gfx/layers/ipc/CompositorParent.cpp?from=CompositorParent.cpp&case=true#648 to end here - http://dxr.mozilla.org/mozilla-central/source/gfx/layers/ipc/CompositorParent.cpp?from=CompositorParent.cpp&case=true#736.

Even if the composites were 5 ms, the SPS profiler showed composite times as 15 ms as show in the screenshot. Find out why this is happening.
Summary: Add Vsync Markers to SPS Profiler → Composite Times are inaccurate in the SPS Profiler
What we could be seeing is that there's non trivial machinery between glSwapBuffers and the driver's display thread. We should try to understand what this is and why it doesn't line up with VSync. Note that on its own it's not necessarily bad. Especially if we see a VSync per Composite.
Attached file Sample JSON of Error
Turns out the problem was that we were generating two start composite traces in the profiler. One at CompositorParent::CompositeToTarget and at LayerTransactionParent::RecvUpdate (http://dxr.mozilla.org/mozilla-central/source/gfx/layers/ipc/LayerTransactionParent.cpp#206). The LayerTransactionParent::RecvUpdate case doesn't have a TRACING_INTERVAL_END. Thus, we would have two composite starts in the profiler for every single composite end, which extended the compositor length in the profiler. Sample JSON is attached.
Deletes the TRACING_INTERVAL_START at http://dxr.mozilla.org/mozilla-central/source/gfx/layers/ipc/LayerTransactionParent.cpp#206 so that we have only one place where we measure composite times.
Attachment #8497802 - Flags: review?(bgirard)
Cleopatra would not update composite start times until it reached an end. Thus if two composite starts are in the same interval, it would use the earliest composite as a start time. This change uses the last composite start until the end. In practice, this doesn't make a difference as we should always have one corresponding composite start / end.
Attachment #8497805 - Flags: review?(bgirard)
We still have vsync overlapping composites, which may be from comment 1.
Attached image OMTA screenshot of Silk
Nice verification of Silk. Composite times are down from ~15ms on master to ~5ms on silk. Should still find out why master is 15 ms but silk is 5 ms.
Comment on attachment 8497802 [details] [diff] [review]
Correct SPS Profiler Labels for Composites

Review of attachment 8497802 [details] [diff] [review]:
-----------------------------------------------------------------

This is by design. When we receive a transaction we charge the processing of that transaction against the composite. The UI building code should look at the first START and ignore other START that happen later until its seen an END.

This means for main thread transaction we include the processing time of the transaction update.
For async transaction we only hit the 'CompositeToTarget' path and start counting from there.

For the purposes of silk we want to be looking at where the 'Composite' ends which is when the driver has acknowledged the frame from glSwapBuffers.
Attachment #8497802 - Flags: review?(bgirard) → review-
Hmm, but aren't CompositeToTarget and LayerTransactions independent? A Layer Transaction may schedule a composite, but the update will until a composite occurs, so aren't they two separate things? If they are two separate things, maybe we should paint them as two separate boxes instead in cleopatra?
Flags: needinfo?(bgirard)
Yes, breaking them down into two events isn't a bad idea TBH.

They are separate events but it's a decent approximation as-is. Feel free to split it up if you'd like.
Flags: needinfo?(bgirard)
Comment on attachment 8497809 [details]
OMTA screenshot of Silk

That's very nice looking :D
Create a new SyncLayerTransaction profile label.
Attachment #8497802 - Attachment is obsolete: true
Attachment #8498335 - Flags: review?(bgirard)
Attachment #8497805 - Attachment is obsolete: true
Attachment #8497805 - Flags: review?(bgirard)
Attachment #8498341 - Flags: review?(bgirard)
Comment on attachment 8498335 [details] [diff] [review]
Separate SyncLayerTransaction labels in profiler

Review of attachment 8498335 [details] [diff] [review]:
-----------------------------------------------------------------

::: gfx/layers/ipc/LayerTransactionParent.cpp
@@ +202,5 @@
>                                     const bool& isRepeatTransaction,
>                                     const mozilla::TimeStamp& aTransactionStart,
>                                     InfallibleTArray<EditReply>* reply)
>  {
> +  profiler_tracing("Paint", "SyncLayerTransaction", TRACING_INTERVAL_START);

The async path calls into the sync path and asserts that reply is empty. Sync is thus incorrect for this marker. Drop the preffix.
Attachment #8498335 - Flags: review?(bgirard) → review+
Carrying r+. Formatted for proper commit guidelines. Try: https://tbpl.mozilla.org/?tree=Try&rev=5c852810f80e
Attachment #8498335 - Attachment is obsolete: true
Attachment #8498361 - Flags: review+
Comment on attachment 8498341 [details] [review]
Cleopatra Front End to read SyncLayerTransaction Labels

Landed on Cleopatra Front End
Attachment #8498341 - Flags: review?(bgirard)
Pushing to try again due to OS X 10.8 try issues - https://tbpl.mozilla.org/?tree=Try&rev=9911669c2e44
Successful try - https://tbpl.mozilla.org/?tree=Try&rev=5c852810f80e - 2 day turn around time for OS X 10.8 :/. Added checkin-needed
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/264cf0a35e48
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla35
You need to log in before you can comment on or make changes to this bug.