Merge "SF: add trace points for dispatcher system"
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 e8c47a5..ac32633 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) {
resetModel();
}
+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 << " (+"
@@ -227,7 +244,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 41e5469..e366555 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 {
@@ -64,6 +65,9 @@
VSyncPredictor& operator=(VSyncPredictor const&) = delete;
void clearTimestamps() REQUIRES(mMutex);
+ 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;