media/libaaudio/src/client/IsochronousClockModel.cpp - LeafOS-Project/android_frameworks_av - Gitiles

 /*
  * Copyright (C) 2016 The Android Open Source Project
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
  * You may obtain a copy of the License at
  *
  *      http://www.apache.org/licenses/LICENSE-2.0
  *
  * Unless required by applicable law or agreed to in writing, software
  * distributed under the License is distributed on an "AS IS" BASIS,
  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */

 #define LOG_TAG "IsochronousClockModel"
 //#define LOG_NDEBUG 0
 #include <log/log.h>

 #define __STDC_FORMAT_MACROS
 #include <inttypes.h>
 #include <stdint.h>
 #include <algorithm>

 #include "utility/AudioClock.h"
 #include "utility/AAudioUtilities.h"
 #include "IsochronousClockModel.h"

 using namespace aaudio;

 using namespace android::audio_utils;

 #ifndef ICM_LOG_DRIFT
 #define ICM_LOG_DRIFT   0
 #endif // ICM_LOG_DRIFT

 // To enable the timestamp histogram, enter this before opening the stream:
 //    adb root
 //    adb shell setprop aaudio.log_mask 1
 // A histogram of the lateness of the timestamps will be cleared when the stream is started.
 // It will be updated when the model is stable and receives a timestamp,
 // and dumped to the log when the stream is stopped.

 IsochronousClockModel::IsochronousClockModel()
         : mMarkerFramePosition(0)
         , mMarkerNanoTime(0)
         , mSampleRate(48000)
         , mFramesPerBurst(48)
         , mMaxMeasuredLatenessNanos(0)
         , mLatenessForDriftNanos(kInitialLatenessForDriftNanos)
         , mState(STATE_STOPPED)
 {
     if ((AAudioProperty_getLogMask() & AAUDIO_LOG_CLOCK_MODEL_HISTOGRAM) != 0) {
         mHistogramMicros = std::make_unique<Histogram>(kHistogramBinCount,
                 kHistogramBinWidthMicros);
     }
 }

 IsochronousClockModel::~IsochronousClockModel() {
 }

 void IsochronousClockModel::setPositionAndTime(int64_t framePosition, int64_t nanoTime) {
     ALOGV("setPositionAndTime, %lld, %lld", (long long) framePosition, (long long) nanoTime);
     mMarkerFramePosition = framePosition;
     mMarkerNanoTime = nanoTime;
 }

 void IsochronousClockModel::start(int64_t nanoTime) {
     ALOGV("start(nanos = %lld)\n", (long long) nanoTime);
     mMarkerNanoTime = nanoTime;
     mState = STATE_STARTING;
     if (mHistogramMicros) {
         mHistogramMicros->clear();
     }
 }

 void IsochronousClockModel::stop(int64_t nanoTime) {
     ALOGD("stop(nanos = %lld) max lateness = %d micros\n",
         (long long) nanoTime,
         (int) (mMaxMeasuredLatenessNanos / 1000));
     setPositionAndTime(convertTimeToPosition(nanoTime), nanoTime);
     // TODO should we set position?
     mState = STATE_STOPPED;
     if (mHistogramMicros) {
         dumpHistogram();
     }
 }

 bool IsochronousClockModel::isStarting() const {
     return mState == STATE_STARTING;
 }

 bool IsochronousClockModel::isRunning() const {
     return mState == STATE_RUNNING;
 }

 void IsochronousClockModel::processTimestamp(int64_t framePosition, int64_t nanoTime) {
     mTimestampCount++;
 // Log position and time in CSV format so we can import it easily into spreadsheets.
     //ALOGD("%s() CSV, %d, %lld, %lld", __func__,
           //mTimestampCount, (long long)framePosition, (long long)nanoTime);
     int64_t framesDelta = framePosition - mMarkerFramePosition;
     int64_t nanosDelta = nanoTime - mMarkerNanoTime;
     if (nanosDelta < 1000) {
         return;
     }

 //    ALOGD("processTimestamp() - mMarkerFramePosition = %lld at mMarkerNanoTime %llu",
 //         (long long)mMarkerFramePosition,
 //         (long long)mMarkerNanoTime);

     int64_t expectedNanosDelta = convertDeltaPositionToTime(framesDelta);
 //    ALOGD("processTimestamp() - expectedNanosDelta = %lld, nanosDelta = %llu",
 //         (long long)expectedNanosDelta,
 //         (long long)nanosDelta);

 //    ALOGD("processTimestamp() - mSampleRate = %d", mSampleRate);
 //    ALOGD("processTimestamp() - mState = %d", mState);
     int64_t latenessNanos = nanosDelta - expectedNanosDelta;
     switch (mState) {
     case STATE_STOPPED:
         break;
     case STATE_STARTING:
         setPositionAndTime(framePosition, nanoTime);
         mState = STATE_SYNCING;
         break;
     case STATE_SYNCING:
         // This will handle a burst of rapid transfer at the beginning.
         if (latenessNanos < 0) {
             setPositionAndTime(framePosition, nanoTime);
         } else {
 //            ALOGD("processTimestamp() - advance to STATE_RUNNING");
             mState = STATE_RUNNING;
         }
         break;
     case STATE_RUNNING:
         if (mHistogramMicros) {
             mHistogramMicros->add(latenessNanos / AAUDIO_NANOS_PER_MICROSECOND);
         }
         // Modify estimated position based on lateness.
         // This affects the "early" side of the window, which controls output glitches.
         if (latenessNanos < 0) {
             // Earlier than expected timestamp.
             // This data is probably more accurate, so use it.
             // Or we may be drifting due to a fast HW clock.
             setPositionAndTime(framePosition, nanoTime);
 #if ICM_LOG_DRIFT
             int earlyDeltaMicros = (int) ((expectedNanosDelta - nanosDelta)/ 1000);
             ALOGD("%s() - STATE_RUNNING - #%d, %4d micros EARLY",
                 __func__, mTimestampCount, earlyDeltaMicros);
 #endif
         } else if (latenessNanos > mLatenessForDriftNanos) {
             // When we are on the late side, it may be because of preemption in the kernel,
             // or timing jitter caused by resampling in the DSP,
             // or we may be drifting due to a slow HW clock.
             // We add slight drift value just in case there is actual long term drift
             // forward caused by a slower clock.
             // If the clock is faster than the model will get pushed earlier
             // by the code in the earlier branch.
             // The two opposing forces should allow the model to track the real clock
             // over a long time.
             int64_t driftingTime = mMarkerNanoTime + expectedNanosDelta + kDriftNanos;
             setPositionAndTime(framePosition,  driftingTime);
 #if ICM_LOG_DRIFT
             ALOGD("%s() - STATE_RUNNING - #%d, DRIFT, lateness = %d micros",
                   __func__,
                   mTimestampCount,
                   (int) (latenessNanos / 1000));
 #endif
         }

         // Modify mMaxMeasuredLatenessNanos.
         // This affects the "late" side of the window, which controls input glitches.
         if (latenessNanos > mMaxMeasuredLatenessNanos) { // increase
 #if ICM_LOG_DRIFT
             ALOGD("%s() - STATE_RUNNING - #%d, newmax %d - oldmax %d = %4d micros LATE",
                     __func__,
                     mTimestampCount,
                     (int) (latenessNanos / 1000),
                     mMaxMeasuredLatenessNanos / 1000,
                     (int) ((latenessNanos - mMaxMeasuredLatenessNanos) / 1000)
                     );
 #endif
             mMaxMeasuredLatenessNanos = (int32_t) latenessNanos;
             // Calculate upper region that will trigger a drift forwards.
             mLatenessForDriftNanos = mMaxMeasuredLatenessNanos - (mMaxMeasuredLatenessNanos >> 4);
         } else { // decrease
             // If these is an outlier in lateness then mMaxMeasuredLatenessNanos can go high
             // and stay there. So we slowly reduce mMaxMeasuredLatenessNanos for better
             // long term stability. The two opposing forces will keep mMaxMeasuredLatenessNanos
             // within a reasonable range.
             mMaxMeasuredLatenessNanos -= kDriftNanos;
         }
         break;
     default:
         break;
     }
 }

 void IsochronousClockModel::setSampleRate(int32_t sampleRate) {
     mSampleRate = sampleRate;
     update();
 }

 void IsochronousClockModel::setFramesPerBurst(int32_t framesPerBurst) {
     mFramesPerBurst = framesPerBurst;
     update();
 }

 // Update expected lateness based on sampleRate and framesPerBurst
 void IsochronousClockModel::update() {
     mBurstPeriodNanos = convertDeltaPositionToTime(mFramesPerBurst); // uses mSampleRate
 }

 int64_t IsochronousClockModel::convertDeltaPositionToTime(int64_t framesDelta) const {
     return (AAUDIO_NANOS_PER_SECOND * framesDelta) / mSampleRate;
 }

 int64_t IsochronousClockModel::convertDeltaTimeToPosition(int64_t nanosDelta) const {
     return (mSampleRate * nanosDelta) / AAUDIO_NANOS_PER_SECOND;
 }

 int64_t IsochronousClockModel::convertPositionToTime(int64_t framePosition) const {
     if (mState == STATE_STOPPED) {
         return mMarkerNanoTime;
     }
     int64_t nextBurstIndex = (framePosition + mFramesPerBurst - 1) / mFramesPerBurst;
     int64_t nextBurstPosition = mFramesPerBurst * nextBurstIndex;
     int64_t framesDelta = nextBurstPosition - mMarkerFramePosition;
     int64_t nanosDelta = convertDeltaPositionToTime(framesDelta);
     int64_t time = mMarkerNanoTime + nanosDelta;
 //    ALOGD("convertPositionToTime: pos = %llu --> time = %llu",
 //         (unsigned long long)framePosition,
 //         (unsigned long long)time);
     return time;
 }

 int64_t IsochronousClockModel::convertTimeToPosition(int64_t nanoTime) const {
     if (mState == STATE_STOPPED) {
         return mMarkerFramePosition;
     }
     int64_t nanosDelta = nanoTime - mMarkerNanoTime;
     int64_t framesDelta = convertDeltaTimeToPosition(nanosDelta);
     int64_t nextBurstPosition = mMarkerFramePosition + framesDelta;
     int64_t nextBurstIndex = nextBurstPosition / mFramesPerBurst;
     int64_t position = nextBurstIndex * mFramesPerBurst;
 //    ALOGD("convertTimeToPosition: time = %llu --> pos = %llu",
 //         (unsigned long long)nanoTime,
 //         (unsigned long long)position);
 //    ALOGD("convertTimeToPosition: framesDelta = %llu, mFramesPerBurst = %d",
 //         (long long) framesDelta, mFramesPerBurst);
     return position;
 }

 int32_t IsochronousClockModel::getLateTimeOffsetNanos() const {
     return mMaxMeasuredLatenessNanos + kExtraLatenessNanos;
 }

 int64_t IsochronousClockModel::convertPositionToLatestTime(int64_t framePosition) const {
     return convertPositionToTime(framePosition) + getLateTimeOffsetNanos();
 }

 int64_t IsochronousClockModel::convertLatestTimeToPosition(int64_t nanoTime) const {
     return convertTimeToPosition(nanoTime - getLateTimeOffsetNanos());
 }

 void IsochronousClockModel::dump() const {
     ALOGD("mMarkerFramePosition = %" PRIu64, mMarkerFramePosition);
     ALOGD("mMarkerNanoTime      = %" PRIu64, mMarkerNanoTime);
     ALOGD("mSampleRate          = %6d", mSampleRate);
     ALOGD("mFramesPerBurst      = %6d", mFramesPerBurst);
     ALOGD("mMaxMeasuredLatenessNanos = %6d", mMaxMeasuredLatenessNanos);
     ALOGD("mState               = %6d", mState);
 }

 void IsochronousClockModel::dumpHistogram() const {
     if (!mHistogramMicros) return;
     std::istringstream istr(mHistogramMicros->dump());
     std::string line;
     while (std::getline(istr, line)) {
         ALOGD("lateness, %s", line.c_str());
     }
 }
	/*
	* Copyright (C) 2016 The Android Open Source Project
	*
	* Licensed under the Apache License, Version 2.0 (the "License");
	* you may not use this file except in compliance with the License.
	* You may obtain a copy of the License at
	*
	* http://www.apache.org/licenses/LICENSE-2.0
	*
	* Unless required by applicable law or agreed to in writing, software
	* distributed under the License is distributed on an "AS IS" BASIS,
	* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
	* See the License for the specific language governing permissions and
	* limitations under the License.
	*/

	#define LOG_TAG "IsochronousClockModel"
	//#define LOG_NDEBUG 0
	#include <log/log.h>

	#define __STDC_FORMAT_MACROS
	#include <inttypes.h>
	#include <stdint.h>
	#include <algorithm>

	#include "utility/AudioClock.h"
	#include "utility/AAudioUtilities.h"
	#include "IsochronousClockModel.h"

	using namespace aaudio;

	using namespace android::audio_utils;

	#ifndef ICM_LOG_DRIFT
	#define ICM_LOG_DRIFT 0
	#endif // ICM_LOG_DRIFT

	// To enable the timestamp histogram, enter this before opening the stream:
	// adb root
	// adb shell setprop aaudio.log_mask 1
	// A histogram of the lateness of the timestamps will be cleared when the stream is started.
	// It will be updated when the model is stable and receives a timestamp,
	// and dumped to the log when the stream is stopped.

	IsochronousClockModel::IsochronousClockModel()
	: mMarkerFramePosition(0)
	, mMarkerNanoTime(0)
	, mSampleRate(48000)
	, mFramesPerBurst(48)
	, mMaxMeasuredLatenessNanos(0)
	, mLatenessForDriftNanos(kInitialLatenessForDriftNanos)
	, mState(STATE_STOPPED)
	{
	if ((AAudioProperty_getLogMask() & AAUDIO_LOG_CLOCK_MODEL_HISTOGRAM) != 0) {
	mHistogramMicros = std::make_unique<Histogram>(kHistogramBinCount,
	kHistogramBinWidthMicros);
	}
	}

	IsochronousClockModel::~IsochronousClockModel() {
	}

	void IsochronousClockModel::setPositionAndTime(int64_t framePosition, int64_t nanoTime) {
	ALOGV("setPositionAndTime, %lld, %lld", (long long) framePosition, (long long) nanoTime);
	mMarkerFramePosition = framePosition;
	mMarkerNanoTime = nanoTime;
	}

	void IsochronousClockModel::start(int64_t nanoTime) {
	ALOGV("start(nanos = %lld)\n", (long long) nanoTime);
	mMarkerNanoTime = nanoTime;
	mState = STATE_STARTING;
	if (mHistogramMicros) {
	mHistogramMicros->clear();
	}
	}

	void IsochronousClockModel::stop(int64_t nanoTime) {
	ALOGD("stop(nanos = %lld) max lateness = %d micros\n",
	(long long) nanoTime,
	(int) (mMaxMeasuredLatenessNanos / 1000));
	setPositionAndTime(convertTimeToPosition(nanoTime), nanoTime);
	// TODO should we set position?
	mState = STATE_STOPPED;
	if (mHistogramMicros) {
	dumpHistogram();
	}
	}

	bool IsochronousClockModel::isStarting() const {
	return mState == STATE_STARTING;
	}

	bool IsochronousClockModel::isRunning() const {
	return mState == STATE_RUNNING;
	}

	void IsochronousClockModel::processTimestamp(int64_t framePosition, int64_t nanoTime) {
	mTimestampCount++;
	// Log position and time in CSV format so we can import it easily into spreadsheets.
	//ALOGD("%s() CSV, %d, %lld, %lld", __func__,
	//mTimestampCount, (long long)framePosition, (long long)nanoTime);
	int64_t framesDelta = framePosition - mMarkerFramePosition;
	int64_t nanosDelta = nanoTime - mMarkerNanoTime;
	if (nanosDelta < 1000) {
	return;
	}

	// ALOGD("processTimestamp() - mMarkerFramePosition = %lld at mMarkerNanoTime %llu",
	// (long long)mMarkerFramePosition,
	// (long long)mMarkerNanoTime);

	int64_t expectedNanosDelta = convertDeltaPositionToTime(framesDelta);
	// ALOGD("processTimestamp() - expectedNanosDelta = %lld, nanosDelta = %llu",
	// (long long)expectedNanosDelta,
	// (long long)nanosDelta);

	// ALOGD("processTimestamp() - mSampleRate = %d", mSampleRate);
	// ALOGD("processTimestamp() - mState = %d", mState);
	int64_t latenessNanos = nanosDelta - expectedNanosDelta;
	switch (mState) {
	case STATE_STOPPED:
	break;
	case STATE_STARTING:
	setPositionAndTime(framePosition, nanoTime);
	mState = STATE_SYNCING;
	break;
	case STATE_SYNCING:
	// This will handle a burst of rapid transfer at the beginning.
	if (latenessNanos < 0) {
	setPositionAndTime(framePosition, nanoTime);
	} else {
	// ALOGD("processTimestamp() - advance to STATE_RUNNING");
	mState = STATE_RUNNING;
	}
	break;
	case STATE_RUNNING:
	if (mHistogramMicros) {
	mHistogramMicros->add(latenessNanos / AAUDIO_NANOS_PER_MICROSECOND);
	}
	// Modify estimated position based on lateness.
	// This affects the "early" side of the window, which controls output glitches.
	if (latenessNanos < 0) {
	// Earlier than expected timestamp.
	// This data is probably more accurate, so use it.
	// Or we may be drifting due to a fast HW clock.
	setPositionAndTime(framePosition, nanoTime);
	#if ICM_LOG_DRIFT
	int earlyDeltaMicros = (int) ((expectedNanosDelta - nanosDelta)/ 1000);
	ALOGD("%s() - STATE_RUNNING - #%d, %4d micros EARLY",
	__func__, mTimestampCount, earlyDeltaMicros);
	#endif
	} else if (latenessNanos > mLatenessForDriftNanos) {
	// When we are on the late side, it may be because of preemption in the kernel,
	// or timing jitter caused by resampling in the DSP,
	// or we may be drifting due to a slow HW clock.
	// We add slight drift value just in case there is actual long term drift
	// forward caused by a slower clock.
	// If the clock is faster than the model will get pushed earlier
	// by the code in the earlier branch.
	// The two opposing forces should allow the model to track the real clock
	// over a long time.
	int64_t driftingTime = mMarkerNanoTime + expectedNanosDelta + kDriftNanos;
	setPositionAndTime(framePosition, driftingTime);
	#if ICM_LOG_DRIFT
	ALOGD("%s() - STATE_RUNNING - #%d, DRIFT, lateness = %d micros",
	__func__,
	mTimestampCount,
	(int) (latenessNanos / 1000));
	#endif
	}

	// Modify mMaxMeasuredLatenessNanos.
	// This affects the "late" side of the window, which controls input glitches.
	if (latenessNanos > mMaxMeasuredLatenessNanos) { // increase
	#if ICM_LOG_DRIFT
	ALOGD("%s() - STATE_RUNNING - #%d, newmax %d - oldmax %d = %4d micros LATE",
	__func__,
	mTimestampCount,
	(int) (latenessNanos / 1000),
	mMaxMeasuredLatenessNanos / 1000,
	(int) ((latenessNanos - mMaxMeasuredLatenessNanos) / 1000)
	);
	#endif
	mMaxMeasuredLatenessNanos = (int32_t) latenessNanos;
	// Calculate upper region that will trigger a drift forwards.
	mLatenessForDriftNanos = mMaxMeasuredLatenessNanos - (mMaxMeasuredLatenessNanos >> 4);
	} else { // decrease
	// If these is an outlier in lateness then mMaxMeasuredLatenessNanos can go high
	// and stay there. So we slowly reduce mMaxMeasuredLatenessNanos for better
	// long term stability. The two opposing forces will keep mMaxMeasuredLatenessNanos
	// within a reasonable range.
	mMaxMeasuredLatenessNanos -= kDriftNanos;
	}
	break;
	default:
	break;
	}
	}

	void IsochronousClockModel::setSampleRate(int32_t sampleRate) {
	mSampleRate = sampleRate;
	update();
	}

	void IsochronousClockModel::setFramesPerBurst(int32_t framesPerBurst) {
	mFramesPerBurst = framesPerBurst;
	update();
	}

	// Update expected lateness based on sampleRate and framesPerBurst
	void IsochronousClockModel::update() {
	mBurstPeriodNanos = convertDeltaPositionToTime(mFramesPerBurst); // uses mSampleRate
	}

	int64_t IsochronousClockModel::convertDeltaPositionToTime(int64_t framesDelta) const {
	return (AAUDIO_NANOS_PER_SECOND * framesDelta) / mSampleRate;
	}

	int64_t IsochronousClockModel::convertDeltaTimeToPosition(int64_t nanosDelta) const {
	return (mSampleRate * nanosDelta) / AAUDIO_NANOS_PER_SECOND;
	}

	int64_t IsochronousClockModel::convertPositionToTime(int64_t framePosition) const {
	if (mState == STATE_STOPPED) {
	return mMarkerNanoTime;
	}
	int64_t nextBurstIndex = (framePosition + mFramesPerBurst - 1) / mFramesPerBurst;
	int64_t nextBurstPosition = mFramesPerBurst * nextBurstIndex;
	int64_t framesDelta = nextBurstPosition - mMarkerFramePosition;
	int64_t nanosDelta = convertDeltaPositionToTime(framesDelta);
	int64_t time = mMarkerNanoTime + nanosDelta;
	// ALOGD("convertPositionToTime: pos = %llu --> time = %llu",
	// (unsigned long long)framePosition,
	// (unsigned long long)time);
	return time;
	}

	int64_t IsochronousClockModel::convertTimeToPosition(int64_t nanoTime) const {
	if (mState == STATE_STOPPED) {
	return mMarkerFramePosition;
	}
	int64_t nanosDelta = nanoTime - mMarkerNanoTime;
	int64_t framesDelta = convertDeltaTimeToPosition(nanosDelta);
	int64_t nextBurstPosition = mMarkerFramePosition + framesDelta;
	int64_t nextBurstIndex = nextBurstPosition / mFramesPerBurst;
	int64_t position = nextBurstIndex * mFramesPerBurst;
	// ALOGD("convertTimeToPosition: time = %llu --> pos = %llu",
	// (unsigned long long)nanoTime,
	// (unsigned long long)position);
	// ALOGD("convertTimeToPosition: framesDelta = %llu, mFramesPerBurst = %d",
	// (long long) framesDelta, mFramesPerBurst);
	return position;
	}

	int32_t IsochronousClockModel::getLateTimeOffsetNanos() const {
	return mMaxMeasuredLatenessNanos + kExtraLatenessNanos;
	}

	int64_t IsochronousClockModel::convertPositionToLatestTime(int64_t framePosition) const {
	return convertPositionToTime(framePosition) + getLateTimeOffsetNanos();
	}

	int64_t IsochronousClockModel::convertLatestTimeToPosition(int64_t nanoTime) const {
	return convertTimeToPosition(nanoTime - getLateTimeOffsetNanos());
	}

	void IsochronousClockModel::dump() const {
	ALOGD("mMarkerFramePosition = %" PRIu64, mMarkerFramePosition);
	ALOGD("mMarkerNanoTime = %" PRIu64, mMarkerNanoTime);
	ALOGD("mSampleRate = %6d", mSampleRate);
	ALOGD("mFramesPerBurst = %6d", mFramesPerBurst);
	ALOGD("mMaxMeasuredLatenessNanos = %6d", mMaxMeasuredLatenessNanos);
	ALOGD("mState = %6d", mState);
	}

	void IsochronousClockModel::dumpHistogram() const {
	if (!mHistogramMicros) return;
	std::istringstream istr(mHistogramMicros->dump());
	std::string line;
	while (std::getline(istr, line)) {
	ALOGD("lateness, %s", line.c_str());
	}
	}