Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit ecb1f0d3 authored by Kevin DuBois's avatar Kevin DuBois
Browse files

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
parent 32af59a5

services/surfaceflinger/Scheduler/SchedulerUtils.h

+8 −0
Original line number Diff line number Diff line
@@ -16,6 +16,7 @@ 


#pragma once



#include <utils/Timers.h>

#include <cinttypes>

#include <numeric>

#include <unordered_map>
@@ -70,6 +71,13 @@ auto calculate_mode(const T& v) { 
    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 {

services/surfaceflinger/Scheduler/Timer.cpp

+1 −10
Original line number Diff line number Diff line
@@ -25,6 +25,7 @@ 
#include <chrono>

#include <cstdint>



#include "SchedulerUtils.h"

#include "Timer.h"



namespace android::scheduler {
@@ -32,11 +33,6 @@ namespace android::scheduler { 
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 @@ nsecs_t Timer::now() const { 
    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::alarmIn(std::function<void()> const& cb, nsecs_t fireIn) { 


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 @@ void Timer::dispatch() { 


    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;

services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp

+25 −0
Original line number Diff line number Diff line
@@ -52,6 +52,13 @@ std::optional<nsecs_t> VSyncDispatchTimerQueueEntry::wakeupTime() const { 
    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 @@ void VSyncDispatchTimerQueue::rearmTimer(nsecs_t now) { 
    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 @@ void VSyncDispatchTimerQueue::rearmTimerSkippingUpdateFor( 
        }

        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();

    }

}

services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h

+15 −0
Original line number Diff line number Diff line
@@ -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 @@ public: 
    // 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 @@ private: 


    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

services/surfaceflinger/Scheduler/VSyncPredictor.cpp

+22 −5
Original line number Diff line number Diff line
@@ -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 @@ void VSyncPredictor::addVsyncTimestamp(nsecs_t timestamp) { 
    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 @@ void VSyncPredictor::addVsyncTimestamp(nsecs_t timestamp) { 
    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 @@ void VSyncPredictor::addVsyncTimestamp(nsecs_t timestamp) { 
    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 @@ nsecs_t VSyncPredictor::nextAnticipatedVSyncTimeFrom(nsecs_t timePoint) const { 
    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 @@ nsecs_t VSyncPredictor::nextAnticipatedVSyncTimeFrom(nsecs_t timePoint) const { 
    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 @@ bool VSyncPredictor::needsMoreSamples(nsecs_t now) const { 
        }

    }



    ATRACE_INT(kNeedsSamplesTag, needsMoreSamples);

    ATRACE_INT("VSP-moreSamples", needsMoreSamples);

    return needsMoreSamples;

}