commit ecb1f0d33ca88017aec1161afdeb96245bfb27d2
author Kevin DuBois <kevindubois@google.com> Thu Dec 12 10:47:41 2019 -0800
committer Kevin DuBois <kevindubois@google.com> Tue Jan 21 13:39:35 2020 -0800
tree 2ecb109c8be0d40003d112444c16474f899c8898
parent 32af59a56d5304ff6281a8ecdb44bc5d331b9a16

SF: add trace points for dispatcher system

Adds initial tracing points for the dispatcher and predictor vsync
signal dispatch system, along with some helper classes to turn traces
on and off based on system properties.

Verbose tracing can be turned on with 'setprop debug.sf.vsp_trace 1'

Test: boot with tracepoints on, see intended traces
Bug: 144927823

Change-Id: Ib6764404b77881887f338a41a25daa1d7068dc1f

services/surfaceflinger/Scheduler/VSyncPredictor.cpp

diff --git a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
index 9154191..cee5f45 100644
--- a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
@@ -23,28 +23,35 @@
 #include "VSyncPredictor.h"
 #include <android-base/logging.h>
 #include <cutils/compiler.h>
+#include <cutils/properties.h>
 #include <utils/Log.h>
 #include <utils/Trace.h>
 #include <algorithm>
 #include <chrono>
 #include <sstream>
-#include "SchedulerUtils.h"
 
 namespace android::scheduler {
-static auto constexpr kNeedsSamplesTag = "SamplesRequested";
+
 static auto constexpr kMaxPercent = 100u;
 
 VSyncPredictor::~VSyncPredictor() = default;
 
 VSyncPredictor::VSyncPredictor(nsecs_t idealPeriod, size_t historySize,
                                size_t minimumSamplesForPrediction, uint32_t outlierTolerancePercent)
-      : kHistorySize(historySize),
+      : mTraceOn(property_get_bool("debug.sf.vsp_trace", false)),
+        kHistorySize(historySize),
         kMinimumSamplesForPrediction(minimumSamplesForPrediction),
         kOutlierTolerancePercent(std::min(outlierTolerancePercent, kMaxPercent)),
         mIdealPeriod(idealPeriod) {
     mRateMap[mIdealPeriod] = {idealPeriod, 0};
 }
 
+inline void VSyncPredictor::traceInt64If(const char* name, int64_t value) const {
+    if (CC_UNLIKELY(mTraceOn)) {
+        ATRACE_INT64(name, value);
+    }
+}
+
 inline size_t VSyncPredictor::next(int i) const {
     return (i + 1) % timestamps.size();
 }
@@ -68,7 +75,7 @@
     std::lock_guard<std::mutex> lk(mMutex);
 
     if (!validate(timestamp)) {
-        ALOGW("timestamp was too far off the last known timestamp");
+        ALOGV("timestamp was too far off the last known timestamp");
         return;
     }
 
@@ -114,6 +121,8 @@
     static constexpr int kScalingFactor = 10;
 
     for (auto i = 0u; i < timestamps.size(); i++) {
+        traceInt64If("VSP-ts", timestamps[i]);
+
         vsyncTS[i] = timestamps[i] - oldest_ts;
         ordinals[i] = ((vsyncTS[i] + (currentPeriod / 2)) / currentPeriod) * kScalingFactor;
     }
@@ -140,6 +149,9 @@
     nsecs_t const anticipatedPeriod = top / bottom * kScalingFactor;
     nsecs_t const intercept = meanTS - (anticipatedPeriod * meanOrdinal / kScalingFactor);
 
+    traceInt64If("VSP-period", anticipatedPeriod);
+    traceInt64If("VSP-intercept", intercept);
+
     it->second = {anticipatedPeriod, intercept};
 
     ALOGV("model update ts: %" PRId64 " slope: %" PRId64 " intercept: %" PRId64, timestamp,
@@ -152,6 +164,7 @@
     auto const [slope, intercept] = getVSyncPredictionModel(lk);
 
     if (timestamps.empty()) {
+        traceInt64If("VSP-mode", 1);
         auto const knownTimestamp = mKnownTimestamp ? *mKnownTimestamp : timePoint;
         auto const numPeriodsOut = ((timePoint - knownTimestamp) / mIdealPeriod) + 1;
         return knownTimestamp + numPeriodsOut * mIdealPeriod;
@@ -164,6 +177,10 @@
     auto const ordinalRequest = (timePoint - zeroPoint + slope) / slope;
     auto const prediction = (ordinalRequest * slope) + intercept + oldest;
 
+    traceInt64If("VSP-mode", 0);
+    traceInt64If("VSP-timePoint", timePoint);
+    traceInt64If("VSP-prediction", prediction);
+
     auto const printer = [&, slope = slope, intercept = intercept] {
         std::stringstream str;
         str << "prediction made from: " << timePoint << "prediction: " << prediction << " (+"
@@ -223,7 +240,7 @@
         }
     }
 
-    ATRACE_INT(kNeedsSamplesTag, needsMoreSamples);
+    ATRACE_INT("VSP-moreSamples", needsMoreSamples);
     return needsMoreSamples;
 }