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

Commit 6292112e authored by Andy Hung's avatar Andy Hung
Browse files

Tracks: Stabilize the latency/startup metrics for BT 

Use kernel timestamps instead of server timestamps.
Postpone latency / startup collection until later
to ensure BT is stabilized.

Test: adb shell dumpsys media.metrics
Bug: 149850236
Change-Id: Ie4e0658cedec13000f7b713407630e273df391b7
parent b4a3b65d

services/audioflinger/TrackBase.h

+9 −4
Original line number Diff line number Diff line
@@ -373,10 +373,15 @@ protected: 
    bool                mIsInvalid; // non-resettable latch, set by invalidate()



    // It typically takes 5 threadloop mix iterations for latency to stabilize.

    static inline constexpr int32_t LOG_START_COUNTDOWN = 8;

    int32_t             mLogStartCountdown = 0;

    int64_t             mLogStartTimeNs = 0;

    int64_t             mLogStartFrames = 0;

    // However, this can be 12+ iterations for BT.

    // To be sure, we wait for latency to dip (it usually increases at the start)

    // to assess stability and then log to MediaMetrics.

    // Rapid start / pause calls may cause inaccurate numbers.

    static inline constexpr int32_t LOG_START_COUNTDOWN = 12;

    int32_t             mLogStartCountdown = 0; // Mixer period countdown

    int64_t             mLogStartTimeNs = 0;    // Monotonic time at start()

    int64_t             mLogStartFrames = 0;    // Timestamp frames at start()

    double              mLogLatencyMs = 0.;     // Track the last log latency



    TrackMetrics        mTrackMetrics;

services/audioflinger/Tracks.cpp

+20 −11
Original line number Diff line number Diff line
@@ -978,7 +978,8 @@ status_t AudioFlinger::PlaybackThread::Track::start(AudioSystem::sync_event_t ev 
            mLogStartCountdown = LOG_START_COUNTDOWN;

            mLogStartTimeNs = systemTime();

            mLogStartFrames = mAudioTrackServerProxy->getTimestamp()

                    .mPosition[ExtendedTimestamp::LOCATION_SERVER];

                    .mPosition[ExtendedTimestamp::LOCATION_KERNEL];

            mLogLatencyMs = 0.;

        }



        if (status == NO_ERROR || status == ALREADY_EXISTS) {
@@ -1514,23 +1515,31 @@ void AudioFlinger::PlaybackThread::Track::updateTrackFrameInfo( 
    mServerLatencyFromTrack.store(useTrackTimestamp);

    mServerLatencyMs.store(latencyMs);



    if (mLogStartCountdown > 0) {

        if (--mLogStartCountdown == 0) {

    if (mLogStartCountdown > 0

            && local.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] > 0

            && local.mPosition[ExtendedTimestamp::LOCATION_KERNEL] > 0)

    {

        if (mLogStartCountdown > 1) {

            --mLogStartCountdown;

        } else if (latencyMs < mLogLatencyMs) { // wait for latency to stabilize (dip)

            mLogStartCountdown = 0;

            // startup is the difference in times for the current timestamp and our start

            double startUpMs =

                    (local.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] - mLogStartTimeNs) * 1e-6;

                    (local.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] - mLogStartTimeNs) * 1e-6;

            // adjust for frames played.

            startUpMs -= (local.mPosition[ExtendedTimestamp::LOCATION_SERVER] - mLogStartFrames)

            startUpMs -= (local.mPosition[ExtendedTimestamp::LOCATION_KERNEL] - mLogStartFrames)

                    * 1e3 / mSampleRate;

            ALOGV("%s: logging localTime:%lld, startTime:%lld"

                  "  localPosition:%lld, startPosition:%lld",

                    __func__,

                    (long long)local.mTimeNs[ExtendedTimestamp::LOCATION_SERVER],

            ALOGV("%s: latencyMs:%lf startUpMs:%lf"

                    " localTime:%lld startTime:%lld"

                    " localPosition:%lld startPosition:%lld",

                    __func__, latencyMs, startUpMs,

                    (long long)local.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL],

                    (long long)mLogStartTimeNs,

                    (long long)local.mPosition[ExtendedTimestamp::LOCATION_SERVER],

                    (long long)local.mPosition[ExtendedTimestamp::LOCATION_KERNEL],

                    (long long)mLogStartFrames);

            mTrackMetrics.logLatencyAndStartup(latencyMs, startUpMs);

        }

        mLogLatencyMs = latencyMs;

    }

}