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
diff --git a/services/surfaceflinger/Scheduler/SchedulerUtils.h b/services/surfaceflinger/Scheduler/SchedulerUtils.h
index d301b99..e7e73a3 100644
--- a/services/surfaceflinger/Scheduler/SchedulerUtils.h
+++ b/services/surfaceflinger/Scheduler/SchedulerUtils.h
@@ -16,6 +16,7 @@
#pragma once
+#include <utils/Timers.h>
#include <cinttypes>
#include <numeric>
#include <unordered_map>
@@ -70,6 +71,13 @@
return static_cast<int>(std::max_element(counts.begin(), counts.end(), compareCounts)->first);
}
+template <class T, size_t N>
+constexpr size_t arrayLen(T (&)[N]) {
+ return N;
+}
+
+static constexpr size_t max64print = std::numeric_limits<nsecs_t>::digits10 + 1;
+
} // namespace android::scheduler
namespace std {
diff --git a/services/surfaceflinger/Scheduler/Timer.cpp b/services/surfaceflinger/Scheduler/Timer.cpp
index fb4f315..8f81c2c 100644
--- a/services/surfaceflinger/Scheduler/Timer.cpp
+++ b/services/surfaceflinger/Scheduler/Timer.cpp
@@ -25,6 +25,7 @@
#include <chrono>
#include <cstdint>
+#include "SchedulerUtils.h"
#include "Timer.h"
namespace android::scheduler {
@@ -32,11 +33,6 @@
static constexpr size_t kReadPipe = 0;
static constexpr size_t kWritePipe = 1;
-template <class T, size_t N>
-constexpr size_t arrayLen(T (&)[N]) {
- return N;
-}
-
Timer::Timer()
: mTimerFd(timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC | TFD_NONBLOCK)),
mEpollFd(epoll_create1(EPOLL_CLOEXEC)) {
@@ -66,11 +62,8 @@
return systemTime(SYSTEM_TIME_MONOTONIC);
}
-constexpr char const* timerTraceTag = "AlarmInNs";
void Timer::alarmIn(std::function<void()> const& cb, nsecs_t fireIn) {
std::lock_guard<decltype(mMutex)> lk(mMutex);
- ATRACE_INT64(timerTraceTag, fireIn);
-
using namespace std::literals;
static constexpr int ns_per_s =
std::chrono::duration_cast<std::chrono::nanoseconds>(1s).count();
@@ -91,7 +84,6 @@
void Timer::alarmCancel() {
std::lock_guard<decltype(mMutex)> lk(mMutex);
- ATRACE_INT64(timerTraceTag, 0);
struct itimerspec old_timer;
struct itimerspec new_timer {
@@ -137,7 +129,6 @@
uint64_t iteration = 0;
char const traceNamePrefix[] = "TimerIteration #";
- static constexpr size_t max64print = std::numeric_limits<decltype(iteration)>::digits10;
static constexpr size_t maxlen = arrayLen(traceNamePrefix) + max64print;
std::array<char, maxlen> str_buffer;
auto timing = true;
diff --git a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp
index 2e5b6e9..d0f18ab 100644
--- a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp
@@ -52,6 +52,13 @@
return {mArmedInfo->mActualWakeupTime};
}
+std::optional<nsecs_t> VSyncDispatchTimerQueueEntry::targetVsync() const {
+ if (!mArmedInfo) {
+ return {};
+ }
+ return {mArmedInfo->mActualVsyncTime};
+}
+
ScheduleResult VSyncDispatchTimerQueueEntry::schedule(nsecs_t workDuration, nsecs_t earliestVsync,
VSyncTracker& tracker, nsecs_t now) {
auto nextVsyncTime =
@@ -143,9 +150,21 @@
rearmTimerSkippingUpdateFor(now, mCallbacks.end());
}
+void VSyncDispatchTimerQueue::TraceBuffer::note(std::string_view name, nsecs_t alarmIn,
+ nsecs_t vsFor) {
+ if (ATRACE_ENABLED()) {
+ snprintf(str_buffer.data(), str_buffer.size(), "%.4s%s%" PRId64 "%s%" PRId64,
+ name.substr(0, kMaxNamePrint).data(), kTraceNamePrefix, alarmIn,
+ kTraceNameSeparator, vsFor);
+ }
+ ATRACE_NAME(str_buffer.data());
+}
+
void VSyncDispatchTimerQueue::rearmTimerSkippingUpdateFor(
nsecs_t now, CallbackMap::iterator const& skipUpdateIt) {
std::optional<nsecs_t> min;
+ std::optional<nsecs_t> targetVsync;
+ std::optional<std::string_view> nextWakeupName;
for (auto it = mCallbacks.begin(); it != mCallbacks.end(); it++) {
auto& callback = it->second;
if (!callback->wakeupTime()) {
@@ -157,13 +176,19 @@
}
auto const wakeupTime = *callback->wakeupTime();
if (!min || (min && *min > wakeupTime)) {
+ nextWakeupName = callback->name();
min = wakeupTime;
+ targetVsync = callback->targetVsync();
}
}
if (min && (min < mIntendedWakeupTime)) {
+ if (targetVsync && nextWakeupName) {
+ mTraceBuffer.note(*nextWakeupName, *min - now, *targetVsync - now);
+ }
setTimer(*min, now);
} else {
+ ATRACE_NAME("cancel timer");
cancelTimer();
}
}
diff --git a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h
index 087acc7..fd0a034 100644
--- a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h
+++ b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h
@@ -17,6 +17,7 @@
#pragma once
#include <android-base/thread_annotations.h>
+#include <array>
#include <functional>
#include <memory>
#include <mutex>
@@ -24,6 +25,7 @@
#include <string_view>
#include <unordered_map>
+#include "SchedulerUtils.h"
#include "VSyncDispatch.h"
namespace android::scheduler {
@@ -54,6 +56,8 @@
// It will not update the wakeupTime.
std::optional<nsecs_t> wakeupTime() const;
+ std::optional<nsecs_t> targetVsync() const;
+
// This moves state from armed->disarmed.
void disarm();
@@ -134,6 +138,17 @@
CallbackMap mCallbacks GUARDED_BY(mMutex);
nsecs_t mIntendedWakeupTime GUARDED_BY(mMutex) = kInvalidTime;
+
+ struct TraceBuffer {
+ static constexpr char const kTraceNamePrefix[] = "-alarm in:";
+ static constexpr char const kTraceNameSeparator[] = " for vs:";
+ static constexpr size_t kMaxNamePrint = 4;
+ static constexpr size_t kNumTsPrinted = 2;
+ static constexpr size_t maxlen = kMaxNamePrint + arrayLen(kTraceNamePrefix) +
+ arrayLen(kTraceNameSeparator) - 1 + (kNumTsPrinted * max64print);
+ std::array<char, maxlen> str_buffer;
+ void note(std::string_view name, nsecs_t in, nsecs_t vs);
+ } mTraceBuffer GUARDED_BY(mMutex);
};
} // namespace android::scheduler
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;
}
diff --git a/services/surfaceflinger/Scheduler/VSyncPredictor.h b/services/surfaceflinger/Scheduler/VSyncPredictor.h
index 4210b3c..4467c71 100644
--- a/services/surfaceflinger/Scheduler/VSyncPredictor.h
+++ b/services/surfaceflinger/Scheduler/VSyncPredictor.h
@@ -20,6 +20,7 @@
#include <mutex>
#include <unordered_map>
#include <vector>
+#include "SchedulerUtils.h"
#include "VSyncTracker.h"
namespace android::scheduler {
@@ -62,6 +63,9 @@
VSyncPredictor(VSyncPredictor const&) = delete;
VSyncPredictor& operator=(VSyncPredictor const&) = delete;
+ inline void traceInt64If(const char* name, int64_t value) const;
+ bool const mTraceOn;
+
size_t const kHistorySize;
size_t const kMinimumSamplesForPrediction;
size_t const kOutlierTolerancePercent;