blob: a39e90e0c2aecc18c3da7f70b239e266672254ca [file] [log] [blame]
/*
* 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()
{
if ((AAudioProperty_getLogMask() & AAUDIO_LOG_CLOCK_MODEL_HISTOGRAM) != 0) {
mHistogramMicros = std::make_unique<Histogram>(kHistogramBinCount,
kHistogramBinWidthMicros);
}
update();
}
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;
mConsecutiveVeryLateCount = 0;
mDspStallCount = 0;
if (mHistogramMicros) {
mHistogramMicros->clear();
}
}
void IsochronousClockModel::stop(int64_t nanoTime) {
ALOGD("stop(nanos = %lld) max lateness = %d micros, DSP stalled %d times",
(long long) nanoTime,
(int) (mMaxMeasuredLatenessNanos / 1000),
mDspStallCount
);
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);
// Lateness relative to the start of the window.
int64_t latenessNanos = nanosDelta - expectedNanosDelta;
int32_t nextConsecutiveVeryLateCount = 0;
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)
/ AAUDIO_NANOS_PER_MICROSECOND);
ALOGD("%s() - STATE_RUNNING - #%d, %5d micros EARLY",
__func__, mTimestampCount, earlyDeltaMicros);
#endif
} else if (latenessNanos > mLatenessForJumpNanos) {
ALOGD("%s() - STATE_RUNNING - #%d, %5d micros VERY LATE, %d times",
__func__,
mTimestampCount,
(int) (latenessNanos / AAUDIO_NANOS_PER_MICROSECOND),
mConsecutiveVeryLateCount
);
// A lateness this large is probably due to a stall in the DSP.
// A pause causes a persistent lateness so we can detect it by counting
// consecutive late timestamps.
if (mConsecutiveVeryLateCount >= kVeryLateCountsNeededToTriggerJump) {
// Assume the timestamp is valid and let subsequent EARLY timestamps
// move the window quickly to the correct place.
setPositionAndTime(framePosition, nanoTime); // JUMP!
mDspStallCount++;
// Throttle the warnings but do not silence them.
// They indicate a bug that needs to be fixed!
if ((nanoTime - mLastJumpWarningTimeNanos) > AAUDIO_NANOS_PER_SECOND) {
ALOGW("%s() - STATE_RUNNING - #%d, %5d micros VERY LATE! Force window jump"
", mDspStallCount = %d",
__func__,
mTimestampCount,
(int) (latenessNanos / AAUDIO_NANOS_PER_MICROSECOND),
mDspStallCount
);
mLastJumpWarningTimeNanos = nanoTime;
}
} else {
nextConsecutiveVeryLateCount = mConsecutiveVeryLateCount + 1;
driftForward(latenessNanos, expectedNanosDelta, framePosition);
}
} else if (latenessNanos > mLatenessForDriftNanos) {
driftForward(latenessNanos, expectedNanosDelta, framePosition);
}
mConsecutiveVeryLateCount = nextConsecutiveVeryLateCount;
// 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 micros LATE",
__func__,
mTimestampCount,
(int) (latenessNanos / AAUDIO_NANOS_PER_MICROSECOND),
(int) (mMaxMeasuredLatenessNanos / AAUDIO_NANOS_PER_MICROSECOND)
);
#endif
mMaxMeasuredLatenessNanos = (int32_t) latenessNanos;
}
break;
default:
break;
}
}
// 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.
void IsochronousClockModel::driftForward(int64_t latenessNanos,
int64_t expectedNanosDelta,
int64_t framePosition) {
const int64_t driftNanos = (latenessNanos - mLatenessForDriftNanos) >> kShifterForDrift;
const int64_t minDriftNanos = std::min(driftNanos, kMaxDriftNanos);
const int64_t expectedMarkerNanoTime = mMarkerNanoTime + expectedNanosDelta;
const int64_t driftedTime = expectedMarkerNanoTime + minDriftNanos;
setPositionAndTime(framePosition, driftedTime);
#if ICM_LOG_DRIFT
ALOGD("%s() - STATE_RUNNING - #%d, %5d micros LATE, nudge window forward by %d micros",
__func__,
mTimestampCount,
(int) (latenessNanos / AAUDIO_NANOS_PER_MICROSECOND),
(int) (minDriftNanos / AAUDIO_NANOS_PER_MICROSECOND)
);
#endif
}
void IsochronousClockModel::setSampleRate(int32_t sampleRate) {
mSampleRate = sampleRate;
update();
}
void IsochronousClockModel::setFramesPerBurst(int32_t framesPerBurst) {
mFramesPerBurst = framesPerBurst;
update();
ALOGD("%s() - mFramesPerBurst = %d - mBurstPeriodNanos = %" PRId64,
__func__,
mFramesPerBurst,
mBurstPeriodNanos
);
}
// Update expected lateness based on sampleRate and framesPerBurst
void IsochronousClockModel::update() {
mBurstPeriodNanos = convertDeltaPositionToTime(mFramesPerBurst);
mLatenessForDriftNanos = mBurstPeriodNanos + kLatenessMarginForSchedulingJitter;
mLatenessForJumpNanos = mLatenessForDriftNanos * kScalerForJumpLateness;
}
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 = %" PRId64, mMarkerFramePosition);
ALOGD("mMarkerNanoTime = %" PRId64, mMarkerNanoTime);
ALOGD("mSampleRate = %6d", mSampleRate);
ALOGD("mFramesPerBurst = %6d", mFramesPerBurst);
ALOGD("mMaxMeasuredLatenessNanos = %6" PRId64, 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());
}
}