diff --git a/gfx/layers/ipc/CompositorBridgeParent.cpp b/gfx/layers/ipc/CompositorBridgeParent.cpp index a895edcb10be..69259d350b75 100644 --- a/gfx/layers/ipc/CompositorBridgeParent.cpp +++ b/gfx/layers/ipc/CompositorBridgeParent.cpp @@ -115,6 +115,8 @@ using namespace std; using base::ProcessId; using base::Thread; +using mozilla::Telemetry::LABELS_CONTENT_FRAME_TIME_REASON; + /// Equivalent to asserting CompositorThreadHolder::IsInCompositorThread with /// the addition that it doesn't assert if the compositor thread holder is /// already gone during late shutdown. @@ -2412,5 +2414,116 @@ mozilla::ipc::IPCResult CompositorBridgeParent::RecvAllPluginsCaptured() { #endif } +int32_t RecordContentFrameTime( + const VsyncId& aTxnId, const TimeStamp& aVsyncStart, + const TimeStamp& aTxnStart, const VsyncId& aCompositeId, + const TimeStamp& aCompositeEnd, const TimeDuration& aFullPaintTime, + const TimeDuration& aVsyncRate, bool aContainsSVGGroup, + bool aRecordUploadStats, wr::RendererStats* aStats /* = nullptr */) { + double latencyMs = (aCompositeEnd - aTxnStart).ToMilliseconds(); + double latencyNorm = latencyMs / aVsyncRate.ToMilliseconds(); + int32_t fracLatencyNorm = lround(latencyNorm * 100.0); + int32_t result = fracLatencyNorm; + +#ifdef MOZ_GECKO_PROFILER + if (profiler_is_active()) { + class ContentFramePayload : public ProfilerMarkerPayload { + public: + ContentFramePayload(const mozilla::TimeStamp& aStartTime, + const mozilla::TimeStamp& aEndTime) + : ProfilerMarkerPayload(aStartTime, aEndTime) {} + virtual void StreamPayload(SpliceableJSONWriter& aWriter, + const TimeStamp& aProcessStartTime, + UniqueStacks& aUniqueStacks) override { + StreamCommonProps("CONTENT_FRAME_TIME", aWriter, aProcessStartTime, + aUniqueStacks); + } + }; + profiler_add_marker_for_thread( + profiler_current_thread_id(), "CONTENT_FRAME_TIME", + MakeUnique(aTxnStart, aCompositeEnd)); + } +#endif + + Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME, fracLatencyNorm); + if (aContainsSVGGroup) { + Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME_WITH_SVG, + fracLatencyNorm); + } + + if (aRecordUploadStats) { + if (aStats) { + latencyMs -= (double(aStats->resource_upload_time) / 1000000.0); + latencyNorm = latencyMs / aVsyncRate.ToMilliseconds(); + fracLatencyNorm = lround(latencyNorm * 100.0); + } + Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME_WITHOUT_RESOURCE_UPLOAD, + fracLatencyNorm); + + if (aStats) { + latencyMs -= (double(aStats->gpu_cache_upload_time) / 1000000.0); + latencyNorm = latencyMs / aVsyncRate.ToMilliseconds(); + fracLatencyNorm = lround(latencyNorm * 100.0); + } + Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME_WITHOUT_UPLOAD, + fracLatencyNorm); + } + + if (!(aTxnId == VsyncId()) && aVsyncStart) { + latencyMs = (aCompositeEnd - aVsyncStart).ToMilliseconds(); + latencyNorm = latencyMs / aVsyncRate.ToMilliseconds(); + fracLatencyNorm = lround(latencyNorm * 100.0); + Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME_VSYNC, fracLatencyNorm); + + // Record CONTENT_FRAME_TIME_REASON. + // + // Also of note is that when the root WebRenderBridgeParent decides to + // skip a composite (due to the Renderer being busy), that won't notify + // child WebRenderBridgeParents. That failure will show up as the + // composite starting late (since it did), but it's really a fault of a + // slow composite on the previous frame, not a slow + // CONTENT_FULL_PAINT_TIME. It would be nice to have a separate bucket for + // this category (scene was ready on the next vsync, but we chose not to + // composite), but I can't find a way to locate the right child + // WebRenderBridgeParents from the root. WebRender notifies us of the + // child pipelines contained within a render, after it finishes, but I + // can't see how to query what child pipeline would have been rendered, + // when we choose to not do it. + if (fracLatencyNorm < 200) { + // Success + Telemetry::AccumulateCategorical( + LABELS_CONTENT_FRAME_TIME_REASON::OnTime); + } else { + if (aCompositeId == VsyncId() || aTxnId >= aCompositeId) { + // Vsync ids are nonsensical, possibly something got trigged from + // outside vsync? + Telemetry::AccumulateCategorical( + LABELS_CONTENT_FRAME_TIME_REASON::NoVsync); + } else if (aCompositeId - aTxnId > 1) { + // Composite started late (and maybe took too long as well) + if (aFullPaintTime >= TimeDuration::FromMilliseconds(20)) { + Telemetry::AccumulateCategorical( + LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeLong); + } else if (aFullPaintTime >= TimeDuration::FromMilliseconds(10)) { + Telemetry::AccumulateCategorical( + LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeMid); + } else if (aFullPaintTime >= TimeDuration::FromMilliseconds(5)) { + Telemetry::AccumulateCategorical( + LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeLow); + } else { + Telemetry::AccumulateCategorical( + LABELS_CONTENT_FRAME_TIME_REASON::MissedComposite); + } + } else { + // Composite started on time, but must have taken too long. + Telemetry::AccumulateCategorical( + LABELS_CONTENT_FRAME_TIME_REASON::SlowComposite); + } + } + } + + return result; +} + } // namespace layers } // namespace mozilla diff --git a/gfx/layers/ipc/CompositorBridgeParent.h b/gfx/layers/ipc/CompositorBridgeParent.h index 36861d93ec34..f2719f7e9e40 100644 --- a/gfx/layers/ipc/CompositorBridgeParent.h +++ b/gfx/layers/ipc/CompositorBridgeParent.h @@ -704,6 +704,13 @@ class CompositorBridgeParent final : public CompositorBridgeParentBase, DISALLOW_EVIL_CONSTRUCTORS(CompositorBridgeParent); }; +int32_t RecordContentFrameTime( + const VsyncId& aTxnId, const TimeStamp& aVsyncStart, + const TimeStamp& aTxnStart, const VsyncId& aCompositeId, + const TimeStamp& aCompositeEnd, const TimeDuration& aFullPaintTime, + const TimeDuration& aVsyncRate, bool aContainsSVGGroup, + bool aRecordUploadStats, wr::RendererStats* aStats = nullptr); + } // namespace layers } // namespace mozilla diff --git a/gfx/layers/wr/WebRenderBridgeParent.cpp b/gfx/layers/wr/WebRenderBridgeParent.cpp index a8963626138a..1ae65e7bd606 100644 --- a/gfx/layers/wr/WebRenderBridgeParent.cpp +++ b/gfx/layers/wr/WebRenderBridgeParent.cpp @@ -40,8 +40,6 @@ #include "dwrite.h" #endif -using mozilla::Telemetry::LABELS_CONTENT_FRAME_TIME_REASON; - #ifdef MOZ_GECKO_PROFILER #include "ProfilerMarkerPayload.h" #endif @@ -1916,129 +1914,28 @@ TransactionId WebRenderBridgeParent::FlushTransactionIdsForEpoch( if (!IsRootWebRenderBridgeParent() && !mVsyncRate.IsZero() && transactionId.mUseForTelemetry) { - double latencyMs = - (aEndTime - transactionId.mTxnStartTime).ToMilliseconds(); - double latencyNorm = latencyMs / mVsyncRate.ToMilliseconds(); - int32_t fracLatencyNorm = lround(latencyNorm * 100.0); + auto fullPaintTime = + transactionId.mSceneBuiltTime + ? transactionId.mSceneBuiltTime - transactionId.mTxnStartTime + : TimeDuration::FromMilliseconds(0); -#ifdef MOZ_GECKO_PROFILER - if (profiler_is_active()) { - class ContentFramePayload : public ProfilerMarkerPayload { - public: - ContentFramePayload(const mozilla::TimeStamp& aStartTime, - const mozilla::TimeStamp& aEndTime) - : ProfilerMarkerPayload(aStartTime, aEndTime) {} - virtual void StreamPayload(SpliceableJSONWriter& aWriter, - const TimeStamp& aProcessStartTime, - UniqueStacks& aUniqueStacks) override { - StreamCommonProps("CONTENT_FRAME_TIME", aWriter, aProcessStartTime, - aUniqueStacks); - } - }; - profiler_add_marker_for_thread( - profiler_current_thread_id(), "CONTENT_FRAME_TIME", - MakeUnique(transactionId.mTxnStartTime, - aEndTime)); - } -#endif - - if (fracLatencyNorm > 200) { + int32_t contentFrameTime = RecordContentFrameTime( + transactionId.mVsyncId, transactionId.mVsyncStartTime, + transactionId.mTxnStartTime, aCompositeStartId, aEndTime, + fullPaintTime, mVsyncRate, transactionId.mContainsSVGGroup, true, + aStats); + if (contentFrameTime > 200) { aOutputStats->AppendElement(FrameStats( transactionId.mId, aCompositeStartTime, aRenderStartTime, aEndTime, - fracLatencyNorm, + contentFrameTime, aStats ? (double(aStats->resource_upload_time) / 1000000.0) : 0.0, aStats ? (double(aStats->gpu_cache_upload_time) / 1000000.0) : 0.0, transactionId.mTxnStartTime, transactionId.mRefreshStartTime, transactionId.mFwdTime, transactionId.mSceneBuiltTime, transactionId.mSkippedComposites, transactionId.mTxnURL)); - } - Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME, fracLatencyNorm); - if (fracLatencyNorm > 200) { wr::RenderThread::Get()->NotifySlowFrame(mApi->GetId()); } - if (transactionId.mContainsSVGGroup) { - Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME_WITH_SVG, - fracLatencyNorm); - } - - if (aStats) { - latencyMs -= (double(aStats->resource_upload_time) / 1000000.0); - latencyNorm = latencyMs / mVsyncRate.ToMilliseconds(); - fracLatencyNorm = lround(latencyNorm * 100.0); - } - Telemetry::Accumulate( - Telemetry::CONTENT_FRAME_TIME_WITHOUT_RESOURCE_UPLOAD, - fracLatencyNorm); - - if (aStats) { - latencyMs -= (double(aStats->gpu_cache_upload_time) / 1000000.0); - latencyNorm = latencyMs / mVsyncRate.ToMilliseconds(); - fracLatencyNorm = lround(latencyNorm * 100.0); - } - Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME_WITHOUT_UPLOAD, - fracLatencyNorm); - - if (!(transactionId.mVsyncId == VsyncId()) && - transactionId.mVsyncStartTime) { - latencyMs = (aEndTime - transactionId.mVsyncStartTime).ToMilliseconds(); - latencyNorm = latencyMs / mVsyncRate.ToMilliseconds(); - fracLatencyNorm = lround(latencyNorm * 100.0); - Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME_VSYNC, - fracLatencyNorm); - - // Record CONTENT_FRAME_TIME_REASON. - // - // Also of note is that when the root WebRenderBridgeParent decides to - // skip a composite (due to the Renderer being busy), that won't notify - // child WebRenderBridgeParents. That failure will show up as the - // composite starting late (since it did), but it's really a fault of a - // slow composite on the previous frame, not a slow - // CONTENT_FULL_PAINT_TIME. It would be nice to have a separate bucket for - // this category (scene was ready on the next vsync, but we chose not to - // composite), but I can't find a way to locate the right child - // WebRenderBridgeParents from the root. WebRender notifies us of the - // child pipelines contained within a render, after it finishes, but I - // can't see how to query what child pipeline would have been rendered, - // when we choose to not do it. - if (fracLatencyNorm < 200) { - // Success - Telemetry::AccumulateCategorical( - LABELS_CONTENT_FRAME_TIME_REASON::OnTime); - } else { - if (transactionId.mVsyncId == VsyncId() || - aCompositeStartId == VsyncId() || - transactionId.mVsyncId >= aCompositeStartId) { - // Vsync ids are nonsensical, possibly something got trigged from - // outside vsync? - Telemetry::AccumulateCategorical( - LABELS_CONTENT_FRAME_TIME_REASON::NoVsync); - } else if (aCompositeStartId - transactionId.mVsyncId > 1) { - auto fullPaintTime = - transactionId.mSceneBuiltTime - ? transactionId.mSceneBuiltTime - transactionId.mTxnStartTime - : TimeDuration::FromMilliseconds(0); - // Composite started late (and maybe took too long as well) - if (fullPaintTime >= TimeDuration::FromMilliseconds(20)) { - Telemetry::AccumulateCategorical( - LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeLong); - } else if (fullPaintTime >= TimeDuration::FromMilliseconds(10)) { - Telemetry::AccumulateCategorical( - LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeMid); - } else if (fullPaintTime >= TimeDuration::FromMilliseconds(5)) { - Telemetry::AccumulateCategorical( - LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeLow); - } else { - Telemetry::AccumulateCategorical( - LABELS_CONTENT_FRAME_TIME_REASON::MissedComposite); - } - } else { - // Composite start on time, but must have taken too long. - Telemetry::AccumulateCategorical( - LABELS_CONTENT_FRAME_TIME_REASON::SlowComposite); - } - } - } } #if defined(ENABLE_FRAME_LATENCY_LOG)