Bug 1923263 - Add log around RenderThread::PostEvent() and RendererEvent r=gfx-reviewers,lsalzman

The log helps to understand how time was spent around RenderThread::PostEvent() and RendererEvent.

Differential Revision: https://phabricator.services.mozilla.com/D224897

gfx/webrender_bindings/RenderThread.cpp

@@ -579,7 +579,7 @@ void RenderThread::WrNotifierEvent_HandleExternalEvent(
     wr::WindowId aWindowId, UniquePtr<RendererEvent> aRendererEvent) {
   MOZ_ASSERT(IsInRenderThread());
 
-  RunEvent(aWindowId, std::move(aRendererEvent));
+  RunEvent(aWindowId, std::move(aRendererEvent), /* aViaWebRender */ true);
 }
 
 void RenderThread::BeginRecordingForWindow(wr::WindowId aWindowId,
@@ -727,17 +727,40 @@ void RenderThread::SetProfilerUI(wr::WindowId aWindowId,
 
 void RenderThread::PostEvent(wr::WindowId aWindowId,
                              UniquePtr<RendererEvent> aEvent) {
-  PostRunnable(NewRunnableMethod<wr::WindowId, UniquePtr<RendererEvent>&&>(
-      "wr::RenderThread::PostEvent", this, &RenderThread::RunEvent, aWindowId,
-      std::move(aEvent)));
+  PostRunnable(
+      NewRunnableMethod<wr::WindowId, UniquePtr<RendererEvent>&&, bool>(
+          "wr::RenderThread::PostEvent", this, &RenderThread::RunEvent,
+          aWindowId, std::move(aEvent), /* aViaWebRender */ false));
 }
 
 void RenderThread::RunEvent(wr::WindowId aWindowId,
-                            UniquePtr<RendererEvent> aEvent) {
+                            UniquePtr<RendererEvent> aEvent,
+                            bool aViaWebRender) {
   MOZ_ASSERT(IsInRenderThread());
 
+#ifndef DEBUG
+  const auto maxDurationMs = 2 * 1000;
+  const auto start = TimeStamp::Now();
+  const auto delayMs = static_cast<uint32_t>(
+      (start - aEvent->mCreationTimeStamp).ToMilliseconds());
+  // Check for the delay only if RendererEvent is delivered without using
+  // WebRender. Its delivery via WebRender can be very slow.
+  if (aViaWebRender && (delayMs > maxDurationMs)) {
+    gfxCriticalNote << "Calling " << aEvent->Name()
+                    << "::Run: is delayed: " << delayMs;
+  }
+#endif
+
   aEvent->Run(*this, aWindowId);
   aEvent = nullptr;
+
+#ifndef DEBUG
+  const auto end = TimeStamp::Now();
+  const auto durationMs = static_cast<uint32_t>((end - start).ToMilliseconds());
+  if (durationMs > maxDurationMs) {
+    gfxCriticalNote << "NewRenderer::Run is slow: " << durationMs;
+  }
+#endif
 }
 
 static void NotifyDidRender(layers::CompositorBridgeParent* aBridge,
@@ -1241,6 +1264,8 @@ void RenderThread::InitDeviceTask() {
   MOZ_ASSERT(!mSingletonGL);
   LOG("RenderThread::InitDeviceTask()");
 
+  const auto start = TimeStamp::Now();
+
   if (gfx::gfxVars::UseSoftwareWebRender()) {
     // Ensure we don't instantiate any shared GL context when SW-WR is used.
     return;
@@ -1254,6 +1279,14 @@ void RenderThread::InitDeviceTask() {
   // Query the shared GL context to force the
   // lazy initialization to happen now.
   SingletonGL();
+
+  const auto maxDurationMs = 3 * 1000;
+  const auto end = TimeStamp::Now();
+  const auto durationMs = static_cast<uint32_t>((end - start).ToMilliseconds());
+  if (durationMs > maxDurationMs) {
+    gfxCriticalNoteOnce << "RenderThread::InitDeviceTask is slow: "
+                        << durationMs;
+  }
 }
 
 void RenderThread::PostRunnable(already_AddRefed<nsIRunnable> aRunnable) {

gfx/webrender_bindings/RenderThread.h

@@ -128,8 +128,12 @@ class WebRenderPipelineInfo final {
 /// messages to preserve ordering.
 class RendererEvent {
  public:
+  RendererEvent() : mCreationTimeStamp(TimeStamp::Now()) {}
   virtual ~RendererEvent() = default;
   virtual void Run(RenderThread& aRenderThread, wr::WindowId aWindow) = 0;
+  virtual const char* Name() = 0;
+
+  const TimeStamp mCreationTimeStamp;
 };
 
 /// The render thread is where WebRender issues all of its GPU work, and as much
@@ -433,7 +437,8 @@ class RenderThread final {
   void InitDeviceTask();
   void HandleFrameOneDoc(wr::WindowId aWindowId, bool aRender,
                          bool aTrackedFrame, Maybe<FramePublishId> aPublishId);
-  void RunEvent(wr::WindowId aWindowId, UniquePtr<RendererEvent> aEvent);
+  void RunEvent(wr::WindowId aWindowId, UniquePtr<RendererEvent> aEvent,
+                bool aViaWebRender);
   void PostRunnable(already_AddRefed<nsIRunnable> aRunnable);
 
   void DoAccumulateMemoryReport(MemoryReport,

gfx/webrender_bindings/WebRenderAPI.cpp

@@ -179,6 +179,8 @@ class NewRenderer : public RendererEvent {
     aRenderThread.AddRenderer(aWindowId, std::move(renderer));
   }
 
+  const char* Name() override { return "NewRenderer"; }
+
  private:
   wr::DocumentHandle** mDocHandle;
   WebRenderBackend* mBackend;
@@ -210,6 +212,8 @@ class RemoveRenderer : public RendererEvent {
     layers::AutoCompleteTask complete(mTask);
   }
 
+  const char* Name() override { return "RemoveRenderer"; }
+
  private:
   layers::SynchronousTask* mTask;
 };
@@ -703,6 +707,9 @@ void WebRenderAPI::Readback(const TimeStamp& aStartTime, gfx::IntSize size,
       layers::AutoCompleteTask complete(mTask);
     }
 
+    const char* Name() override { return "Readback"; }
+
+   private:
     layers::SynchronousTask* mTask;
     TimeStamp mStartTime;
     gfx::IntSize mSize;
@@ -772,6 +779,9 @@ void WebRenderAPI::Pause() {
       layers::AutoCompleteTask complete(mTask);
     }
 
+    const char* Name() override { return "PauseEvent"; }
+
+   private:
     layers::SynchronousTask* mTask;
   };
 
@@ -797,6 +807,9 @@ bool WebRenderAPI::Resume() {
       layers::AutoCompleteTask complete(mTask);
     }
 
+    const char* Name() override { return "ResumeEvent"; }
+
+   private:
     layers::SynchronousTask* mTask;
     bool* mResult;
   };
@@ -838,6 +851,9 @@ void WebRenderAPI::WaitFlushed() {
       layers::AutoCompleteTask complete(mTask);
     }
 
+    const char* Name() override { return "WaitFlushedEvent"; }
+
+   private:
     layers::SynchronousTask* mTask;
   };
 
@@ -896,6 +912,8 @@ void WebRenderAPI::BeginRecording(const TimeStamp& aRecordingStart,
                                             mRootPipelineId);
     }
 
+    const char* Name() override { return "BeginRecordingEvent"; }
+
    private:
     TimeStamp mRecordingStart;
     wr::PipelineId mRootPipelineId;
@@ -928,6 +946,8 @@ RefPtr<WebRenderAPI::EndRecordingPromise> WebRenderAPI::EndRecording() {
       return mPromise.Ensure(__func__);
     }
 
+    const char* Name() override { return "EndRecordingEvent"; }
+
    private:
     MozPromiseHolder<WebRenderAPI::EndRecordingPromise> mPromise;
   };
@@ -1088,6 +1108,8 @@ class FrameStartTime : public RendererEvent {
     }
   }
 
+  const char* Name() override { return "FrameStartTime"; }
+
  private:
   TimeStamp mTime;
 };