Bug 1238040 - Update telemetry measures for checkerboarding. r=botond,vladan

gfx/layers/apz/src/AsyncPanZoomController.cpp

@@ -2871,7 +2871,7 @@ AsyncPanZoomController::RequestContentRepaint(const FrameMetrics& aFrameMetrics,
   }
 
   APZC_LOG_FM(aFrameMetrics, "%p requesting content repaint", this);
-  if (mCheckerboardEvent) {
+  if (mCheckerboardEvent && mCheckerboardEvent->IsRecordingTrace()) {
     std::stringstream info;
     info << " velocity " << aVelocity;
     std::string str = info.str();
@@ -3102,24 +3102,30 @@ AsyncPanZoomController::ReportCheckerboard(const TimeStamp& aSampleTime)
     // checkerboard once per composite though.
     return;
   }
-  uint32_t time = (aSampleTime - mLastCheckerboardReport).ToMilliseconds();
-  uint32_t magnitude = GetCheckerboardMagnitude();
-  // TODO: make this a function of velocity
-  mozilla::Telemetry::Accumulate(
-      mozilla::Telemetry::CHECKERBOARDED_CSSPIXELS_MS, magnitude * time);
   mLastCheckerboardReport = aSampleTime;
 
-  if (!mCheckerboardEvent && gfxPrefs::APZRecordCheckerboarding()) {
-    mCheckerboardEvent = MakeUnique<CheckerboardEvent>();
+  bool recordTrace = gfxPrefs::APZRecordCheckerboarding();
+  bool forTelemetry = Telemetry::CanRecordExtended();
+  if (!mCheckerboardEvent && (recordTrace || forTelemetry)) {
+    mCheckerboardEvent = MakeUnique<CheckerboardEvent>(recordTrace);
   }
-  if (mCheckerboardEvent) {
-    if (mCheckerboardEvent->RecordFrameInfo(magnitude)) {
-      // This checkerboard event is done. TODO: save the info somewhere or
-      // dispatch it to telemetry or something. For now we just print it.
+  uint32_t magnitude = GetCheckerboardMagnitude();
+  if (mCheckerboardEvent && mCheckerboardEvent->RecordFrameInfo(magnitude)) {
+    // This checkerboard event is done. Report some metrics to telemetry.
+    mozilla::Telemetry::Accumulate(mozilla::Telemetry::CHECKERBOARD_SEVERITY,
+      mCheckerboardEvent->GetSeverity());
+    mozilla::Telemetry::Accumulate(mozilla::Telemetry::CHECKERBOARD_PEAK,
+      mCheckerboardEvent->GetPeak());
+    mozilla::Telemetry::Accumulate(mozilla::Telemetry::CHECKERBOARD_DURATION,
+      (uint32_t)mCheckerboardEvent->GetDuration().ToMilliseconds());
+
+    if (recordTrace) {
+      // TODO: save the info somewhere for
+      // about:checkerboard. For now we just print it.
       std::stringstream log(mCheckerboardEvent->GetLog());
       print_stderr(log);
-      mCheckerboardEvent = nullptr;
     }
+    mCheckerboardEvent = nullptr;
   }
 }
 
@@ -3157,7 +3163,7 @@ void AsyncPanZoomController::NotifyLayersUpdated(const FrameMetrics& aLayerMetri
   APZC_LOG_FM(aLayerMetrics, "%p got a NotifyLayersUpdated with aIsFirstPaint=%d, aThisLayerTreeUpdated=%d",
     this, aIsFirstPaint, aThisLayerTreeUpdated);
 
-  if (mCheckerboardEvent) {
+  if (mCheckerboardEvent && mCheckerboardEvent->IsRecordingTrace()) {
     std::string str;
     if (aThisLayerTreeUpdated) {
       if (!aLayerMetrics.GetPaintRequestTime().IsNull()) {

gfx/layers/apz/src/CheckerboardEvent.cpp

@@ -32,8 +32,9 @@ const char* CheckerboardEvent::sColors[] = {
   "red",
 };
 
-CheckerboardEvent::CheckerboardEvent()
-  : mOriginTime(TimeStamp::Now())
+CheckerboardEvent::CheckerboardEvent(bool aRecordTrace)
+  : mRecordTrace(aRecordTrace)
+  , mOriginTime(TimeStamp::Now())
   , mCheckerboardingActive(false)
   , mLastSampleTime(mOriginTime)
   , mFrameCount(0)
@@ -43,10 +44,23 @@ CheckerboardEvent::CheckerboardEvent()
 {
 }
 
-uint64_t
+uint32_t
 CheckerboardEvent::GetSeverity()
 {
-  return mTotalPixelMs;
+  // Scale the total into a 32-bit value
+  return (uint32_t)sqrt((double)mTotalPixelMs);
+}
+
+uint32_t
+CheckerboardEvent::GetPeak()
+{
+  return mPeakPixels;
+}
+
+TimeDuration
+CheckerboardEvent::GetDuration()
+{
+  return mEndTime - mStartTime;
 }
 
 std::string
@@ -56,11 +70,20 @@ CheckerboardEvent::GetLog()
   return mRendertraceInfo.str();
 }
 
+bool
+CheckerboardEvent::IsRecordingTrace()
+{
+  return mRecordTrace;
+}
+
 void
 CheckerboardEvent::UpdateRendertraceProperty(RendertraceProperty aProperty,
                                              const CSSRect& aRect,
                                              const std::string& aExtraInfo)
 {
+  if (!mRecordTrace) {
+    return;
+  }
   MonitorAutoLock lock(mRendertraceLock);
   if (!mCheckerboardingActive) {
     mBufferedProperties[aProperty].Update(aProperty, aRect, aExtraInfo, lock);
@@ -76,6 +99,7 @@ CheckerboardEvent::LogInfo(RendertraceProperty aProperty,
                            const std::string& aExtraInfo,
                            const MonitorAutoLock& aProofOfLock)
 {
+  MOZ_ASSERT(mRecordTrace);
   if (mRendertraceInfo.tellp() >= LOG_LENGTH_LIMIT) {
     // The log is already long enough, don't put more things into it. We'll
     // append a truncation message when this event ends.
@@ -130,6 +154,9 @@ CheckerboardEvent::StartEvent()
   mCheckerboardingActive = true;
   mStartTime = TimeStamp::Now();
 
+  if (!mRecordTrace) {
+    return;
+  }
   MonitorAutoLock lock(mRendertraceLock);
   std::vector<PropertyValue> history;
   for (int i = 0; i < MAX_RendertraceProperty; i++) {
@@ -148,6 +175,9 @@ CheckerboardEvent::StopEvent()
   mCheckerboardingActive = false;
   mEndTime = TimeStamp::Now();
 
+  if (!mRecordTrace) {
+    return;
+  }
   MonitorAutoLock lock(mRendertraceLock);
   if (mRendertraceInfo.tellp() >= LOG_LENGTH_LIMIT) {
     mRendertraceInfo << "[logging aborted due to length limitations]\n";

gfx/layers/apz/src/CheckerboardEvent.h

@@ -39,14 +39,25 @@ public:
   static const char* sColors[MAX_RendertraceProperty];
 
 public:
-  CheckerboardEvent();
+  explicit CheckerboardEvent(bool aRecordTrace);
 
   /**
    * Gets the "severity" of the checkerboard event. This doesn't have units,
    * it's just useful for comparing two checkerboard events to see which one
    * is worse, for some implementation-specific definition of "worse".
    */
-  uint64_t GetSeverity();
+  uint32_t GetSeverity();
+
+  /**
+   * Gets the number of CSS pixels that were checkerboarded at the peak of the
+   * checkerboard event.
+   */
+  uint32_t GetPeak();
+
+  /**
+   * Gets the length of the checkerboard event.
+   */
+  TimeDuration GetDuration();
 
   /**
    * Gets the raw log of the checkerboard event. This can be called any time,
@@ -55,6 +66,12 @@ public:
    */
   std::string GetLog();
 
+  /**
+   * Returns true iff this event is recording a detailed trace of the event.
+   * This is the argument passed in to the constructor.
+   */
+  bool IsRecordingTrace();
+
   /**
    * Provide a new value for one of the rects that is tracked for
    * checkerboard events.
@@ -137,6 +154,12 @@ private:
   };
 
 private:
+  /**
+   * If true, we should log the various properties during the checkerboard
+   * event. If false, we only need to record things we need for telemetry
+   * measures.
+   */
+  const bool mRecordTrace;
   /**
    * A base time so that the other timestamps can be turned into durations.
    */

toolkit/components/telemetry/Histograms.json

@@ -88,14 +88,32 @@
     "kind": "boolean",
     "description": "blocklist.xml has been loaded synchronously *** No longer needed (bug 1156565). Delete histogram and accumulation code! ***"
   },
-  "CHECKERBOARDED_CSSPIXELS_MS": {
+  "CHECKERBOARD_DURATION": {
     "alert_emails": ["kgupta@mozilla.com"],
-    "bug_numbers": [1221694],
+    "bug_numbers": [1238040],
     "expires_in_version": "55",
     "kind": "exponential",
-    "high": "3840 * 2160 * 16",
+    "high": "100000",
     "n_buckets": 50,
-    "description": "Magnitude of checkerboarding in CSSPixel-milliseconds per scrollable frame per composite"
+    "description": "Duration of a checkerboard event in milliseconds"
+  },
+  "CHECKERBOARD_PEAK": {
+    "alert_emails": ["kgupta@mozilla.com"],
+    "bug_numbers": [1238040],
+    "expires_in_version": "55",
+    "kind": "exponential",
+    "high": "3840 * 2160 * 8",
+    "n_buckets": 50,
+    "description": "Peak number of CSS pixels checkerboarded during a checkerboard event (the high value is the size of a 4k display with max APZ zooming)"
+  },
+  "CHECKERBOARD_SEVERITY": {
+    "alert_emails": ["kgupta@mozilla.com"],
+    "bug_numbers": [1238040],
+    "expires_in_version": "55",
+    "kind": "exponential",
+    "high": "1073741824",
+    "n_buckets": 50,
+    "description": "Opaque measure of the severity of a checkerboard event"
   },
   "COMPOSITE_TIME" : {
     "expires_in_version": "never",