FPS analysis on reddit.com/r/NintendoSwitch

logging patch

commit 74165c94a68cf1ef98812af68a6e3fb420b9bcca
Author: Kartikaya Gupta <kgupta@mozilla.com>
Date:   Thu Nov 2 13:25:23 2017 -0400

    Logging for perf

diff --git a/gfx/layers/wr/WebRenderBridgeParent.cpp b/gfx/layers/wr/WebRenderBridgeParent.cpp
index 32edbdb5cfa1..3b1a31b2ccb2 100644
--- a/gfx/layers/wr/WebRenderBridgeParent.cpp
+++ b/gfx/layers/wr/WebRenderBridgeParent.cpp
@@ -1128,30 +1128,51 @@ WebRenderBridgeParent::SampleAnimations(nsTArray<wr::WrOpacityProperty>& aOpacit
       } else if (value->mType == AnimatedValue::OPACITY) {
         aOpacityArray.AppendElement(
           wr::ToWrOpacityProperty(iter.Key(), value->mOpacity));
       }
     }
   }
 }
 
+static int sCompositeCount = 0;
+static int sPauseCount = 0;
+static int sBusyCount = 0;
+static TimeStamp sLastDumpTime;
+
 void
 WebRenderBridgeParent::CompositeToTarget(gfx::DrawTarget* aTarget, const gfx::IntRect* aRect)
 {
+  TimeStamp now = TimeStamp::Now();
+  if (sLastDumpTime.IsNull()) {
+    sLastDumpTime = now;
+  } else if ((now - sLastDumpTime).ToMilliseconds() >= 1000) {
+    printf_stderr("CompositeToTarget (%f ms) -> called %d times, of which %d pause, %d busy, %d GenerateFrame FPS\n",
+      (now - sLastDumpTime).ToMilliseconds(), sCompositeCount, sPauseCount,
+      sBusyCount, (sCompositeCount - sPauseCount - sBusyCount));
+    sCompositeCount = 0;
+    sPauseCount = 0;
+    sBusyCount = 0;
+    sLastDumpTime = now;
+  }
+  sCompositeCount++;
+
   AUTO_PROFILER_TRACING("Paint", "CompositeToTraget");
   if (mPaused) {
+    sPauseCount++;
     return;
   }
 
   const uint32_t maxPendingFrameCount = 1;
 
   if (!mForceRendering &&
       wr::RenderThread::Get()->GetPendingFrameCount(mApi->GetId()) >= maxPendingFrameCount) {
     // Render thread is busy, try next time.
     ScheduleComposition();
+    sBusyCount++;
     return;
   }
 
   bool scheduleComposite = false;
   nsTArray<wr::WrOpacityProperty> opacityArray;
   nsTArray<wr::WrTransformProperty> transformArray;
 
   mAsyncImageManager->SetCompositionTime(TimeStamp::Now());
diff --git a/gfx/webrender_bindings/RenderThread.cpp b/gfx/webrender_bindings/RenderThread.cpp
index baa6a4c2d39e..f12ff45cb206 100644
--- a/gfx/webrender_bindings/RenderThread.cpp
+++ b/gfx/webrender_bindings/RenderThread.cpp
@@ -198,16 +198,19 @@ NotifyDidRender(layers::CompositorBridgeParentBase* aBridge,
   wr::WrPipelineId pipeline;
   wr::WrEpoch epoch;
   while (wr_rendered_epochs_next(aEpochs, &pipeline, &epoch)) {
     aBridge->NotifyDidCompositeToPipeline(pipeline, epoch, aStart, aEnd);
   }
   wr_rendered_epochs_delete(aEpochs);
 }
 
+static int sCount = 0;
+static TimeStamp sLastDumpTime;
+
 void
 RenderThread::UpdateAndRender(wr::WindowId aWindowId)
 {
   AUTO_PROFILER_TRACING("Paint", "Composite");
   MOZ_ASSERT(IsInRenderThread());
 
   auto it = mRenderers.find(aWindowId);
   MOZ_ASSERT(it != mRenderers.end());
@@ -222,16 +225,26 @@ RenderThread::UpdateAndRender(wr::WindowId aWindowId)
 
   bool ret = renderer->Render();
   if (!ret) {
     // Render did not happen, do not call NotifyDidRender.
     return;
   }
 
   TimeStamp end = TimeStamp::Now();
+  if (sLastDumpTime.IsNull()) {
+    sLastDumpTime = end;
+  } else if ((end - sLastDumpTime).ToMilliseconds() >= 1000) {
+    printf_stderr("UpdateAndRender (%f ms) -> Render FPS: %d\n",
+      (end - sLastDumpTime).ToMilliseconds(),
+      sCount);
+    sCount = 0;
+    sLastDumpTime = end;
+  }
+  sCount++;
 
   auto epochs = renderer->FlushRenderedEpochs();
   layers::CompositorThreadHolder::Loop()->PostTask(NewRunnableFunction(
     &NotifyDidRender,
     renderer->GetCompositorBridge(),
     epochs,
     start, end
   ));

output with APZ disabled

CompositeToTarget (1001.036514 ms) -> called 48 times, of which 0 pause, 21 busy, 27 GenerateFrame FPS
UpdateAndRender (1004.787479 ms) -> Render FPS: 27
CompositeToTarget (1001.096817 ms) -> called 43 times, of which 0 pause, 17 busy, 26 GenerateFrame FPS
UpdateAndRender (1009.639527 ms) -> Render FPS: 29
CompositeToTarget (1000.783075 ms) -> called 54 times, of which 0 pause, 25 busy, 29 GenerateFrame FPS
UpdateAndRender (1004.085186 ms) -> Render FPS: 27
CompositeToTarget (1001.357652 ms) -> called 57 times, of which 0 pause, 30 busy, 27 GenerateFrame FPS
UpdateAndRender (1012.175062 ms) -> Render FPS: 29
CompositeToTarget (1000.350151 ms) -> called 58 times, of which 0 pause, 27 busy, 31 GenerateFrame FPS
UpdateAndRender (1019.464511 ms) -> Render FPS: 36
CompositeToTarget (1001.214292 ms) -> called 58 times, of which 0 pause, 25 busy, 33 GenerateFrame FPS
UpdateAndRender (1000.983892 ms) -> Render FPS: 27
CompositeToTarget (1000.469902 ms) -> called 52 times, of which 0 pause, 25 busy, 27 GenerateFrame FPS
UpdateAndRender (1004.989434 ms) -> Render FPS: 28
CompositeToTarget (1001.281990 ms) -> called 53 times, of which 0 pause, 25 busy, 28 GenerateFrame FPS
UpdateAndRender (1002.634521 ms) -> Render FPS: 28
CompositeToTarget (1016.964816 ms) -> called 61 times, of which 0 pause, 33 busy, 28 GenerateFrame FPS
UpdateAndRender (1013.814313 ms) -> Render FPS: 25
CompositeToTarget (1001.998789 ms) -> called 48 times, of which 0 pause, 23 busy, 25 GenerateFrame FPS
UpdateAndRender (1021.424616 ms) -> Render FPS: 27
CompositeToTarget (1016.461350 ms) -> called 46 times, of which 0 pause, 20 busy, 26 GenerateFrame FPS
UpdateAndRender (1013.087274 ms) -> Render FPS: 26
CompositeToTarget (1016.970505 ms) -> called 44 times, of which 0 pause, 17 busy, 27 GenerateFrame FPS
UpdateAndRender (1002.178842 ms) -> Render FPS: 27
CompositeToTarget (1017.935624 ms) -> called 46 times, of which 0 pause, 20 busy, 26 GenerateFrame FPS
UpdateAndRender (1019.779106 ms) -> Render FPS: 27
CompositeToTarget (1001.192105 ms) -> called 49 times, of which 0 pause, 23 busy, 26 GenerateFrame FPS
UpdateAndRender (1014.069460 ms) -> Render FPS: 22
CompositeToTarget (1033.562700 ms) -> called 37 times, of which 0 pause, 14 busy, 23 GenerateFrame FPS
UpdateAndRender (1027.477302 ms) -> Render FPS: 27

output with APZ enabled

CompositeToTarget (1000.376035 ms) -> called 52 times, of which 0 pause, 24 busy, 28 GenerateFrame FPS
UpdateAndRender (1272.653059 ms) -> Render FPS: 27
CompositeToTarget (1001.857136 ms) -> called 36 times, of which 0 pause, 18 busy, 18 GenerateFrame FPS
UpdateAndRender (1029.761957 ms) -> Render FPS: 31
CompositeToTarget (1016.821172 ms) -> called 60 times, of which 0 pause, 28 busy, 32 GenerateFrame FPS
UpdateAndRender (1002.181118 ms) -> Render FPS: 30
CompositeToTarget (1000.632888 ms) -> called 57 times, of which 0 pause, 28 busy, 29 GenerateFrame FPS
UpdateAndRender (1019.589667 ms) -> Render FPS: 31
CompositeToTarget (1001.344283 ms) -> called 60 times, of which 0 pause, 30 busy, 30 GenerateFrame FPS
UpdateAndRender (1032.727003 ms) -> Render FPS: 31
CompositeToTarget (1000.600746 ms) -> called 59 times, of which 0 pause, 29 busy, 30 GenerateFrame FPS
UpdateAndRender (1016.647946 ms) -> Render FPS: 31
CompositeToTarget (1000.641137 ms) -> called 59 times, of which 0 pause, 28 busy, 31 GenerateFrame FPS
UpdateAndRender (1003.087925 ms) -> Render FPS: 30
CompositeToTarget (1000.620088 ms) -> called 59 times, of which 0 pause, 29 busy, 30 GenerateFrame FPS
UpdateAndRender (1015.088054 ms) -> Render FPS: 30
CompositeToTarget (1001.257243 ms) -> called 57 times, of which 0 pause, 28 busy, 29 GenerateFrame FPS
UpdateAndRender (1003.684689 ms) -> Render FPS: 30
CompositeToTarget (1001.087714 ms) -> called 60 times, of which 0 pause, 30 busy, 30 GenerateFrame FPS
UpdateAndRender (1034.812832 ms) -> Render FPS: 31
CompositeToTarget (1000.762310 ms) -> called 59 times, of which 0 pause, 29 busy, 30 GenerateFrame FPS
UpdateAndRender (1037.105451 ms) -> Render FPS: 31
CompositeToTarget (1000.865848 ms) -> called 59 times, of which 0 pause, 29 busy, 30 GenerateFrame FPS
UpdateAndRender (1024.612096 ms) -> Render FPS: 31
CompositeToTarget (1001.146310 ms) -> called 60 times, of which 0 pause, 30 busy, 30 GenerateFrame FPS
UpdateAndRender (1005.920704 ms) -> Render FPS: 29
CompositeToTarget (1016.864123 ms) -> called 57 times, of which 0 pause, 27 busy, 30 GenerateFrame FPS
UpdateAndRender (1008.628044 ms) -> Render FPS: 30
CompositeToTarget (1000.389404 ms) -> called 60 times, of which 0 pause, 28 busy, 32 GenerateFrame FPS
UpdateAndRender (1014.062064 ms) -> Render FPS: 38
CompositeToTarget (1001.022861 ms) -> called 59 times, of which 0 pause, 24 busy, 35 GenerateFrame FPS
UpdateAndRender (1000.048071 ms) -> Render FPS: 29
CompositeToTarget (1001.056425 ms) -> called 59 times, of which 0 pause, 30 busy, 29 GenerateFrame FPS
UpdateAndRender (1016.169510 ms) -> Render FPS: 28
CompositeToTarget (1000.904248 ms) -> called 60 times, of which 0 pause, 32 busy, 28 GenerateFrame FPS
UpdateAndRender (1019.578573 ms) -> Render FPS: 29