1 /*
2 * Copyright (C) 2016 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #define LOG_TAG "IsochronousClockModel"
18 //#define LOG_NDEBUG 0
19 #include <log/log.h>
20
21 #define __STDC_FORMAT_MACROS
22 #include <inttypes.h>
23 #include <stdint.h>
24 #include <algorithm>
25
26 #include "utility/AudioClock.h"
27 #include "utility/AAudioUtilities.h"
28 #include "IsochronousClockModel.h"
29
30 using namespace aaudio;
31
32 using namespace android::audio_utils;
33
34 #ifndef ICM_LOG_DRIFT
35 #define ICM_LOG_DRIFT 0
36 #endif // ICM_LOG_DRIFT
37
38 // To enable the timestamp histogram, enter this before opening the stream:
39 // adb root
40 // adb shell setprop aaudio.log_mask 1
41 // A histogram of the lateness of the timestamps will be cleared when the stream is started.
42 // It will be updated when the model is stable and receives a timestamp,
43 // and dumped to the log when the stream is stopped.
44
IsochronousClockModel()45 IsochronousClockModel::IsochronousClockModel()
46 : mMarkerFramePosition(0)
47 , mMarkerNanoTime(0)
48 , mSampleRate(48000)
49 , mFramesPerBurst(48)
50 , mBurstPeriodNanos(0) // this will be updated before use
51 , mMaxMeasuredLatenessNanos(0)
52 , mLatenessForDriftNanos(kInitialLatenessForDriftNanos)
53 , mState(STATE_STOPPED)
54 {
55 if ((AAudioProperty_getLogMask() & AAUDIO_LOG_CLOCK_MODEL_HISTOGRAM) != 0) {
56 mHistogramMicros = std::make_unique<Histogram>(kHistogramBinCount,
57 kHistogramBinWidthMicros);
58 }
59 }
60
setPositionAndTime(int64_t framePosition,int64_t nanoTime)61 void IsochronousClockModel::setPositionAndTime(int64_t framePosition, int64_t nanoTime) {
62 ALOGV("setPositionAndTime, %lld, %lld", (long long) framePosition, (long long) nanoTime);
63 mMarkerFramePosition = framePosition;
64 mMarkerNanoTime = nanoTime;
65 }
66
start(int64_t nanoTime)67 void IsochronousClockModel::start(int64_t nanoTime) {
68 ALOGV("start(nanos = %lld)\n", (long long) nanoTime);
69 mMarkerNanoTime = nanoTime;
70 mState = STATE_STARTING;
71 if (mHistogramMicros) {
72 mHistogramMicros->clear();
73 }
74 }
75
stop(int64_t nanoTime)76 void IsochronousClockModel::stop(int64_t nanoTime) {
77 ALOGD("stop(nanos = %lld) max lateness = %d micros\n",
78 (long long) nanoTime,
79 (int) (mMaxMeasuredLatenessNanos / 1000));
80 setPositionAndTime(convertTimeToPosition(nanoTime), nanoTime);
81 // TODO should we set position?
82 mState = STATE_STOPPED;
83 if (mHistogramMicros) {
84 dumpHistogram();
85 }
86 }
87
isStarting() const88 bool IsochronousClockModel::isStarting() const {
89 return mState == STATE_STARTING;
90 }
91
isRunning() const92 bool IsochronousClockModel::isRunning() const {
93 return mState == STATE_RUNNING;
94 }
95
processTimestamp(int64_t framePosition,int64_t nanoTime)96 void IsochronousClockModel::processTimestamp(int64_t framePosition, int64_t nanoTime) {
97 mTimestampCount++;
98 // Log position and time in CSV format so we can import it easily into spreadsheets.
99 //ALOGD("%s() CSV, %d, %lld, %lld", __func__,
100 //mTimestampCount, (long long)framePosition, (long long)nanoTime);
101 int64_t framesDelta = framePosition - mMarkerFramePosition;
102 int64_t nanosDelta = nanoTime - mMarkerNanoTime;
103 if (nanosDelta < 1000) {
104 return;
105 }
106
107 // ALOGD("processTimestamp() - mMarkerFramePosition = %lld at mMarkerNanoTime %llu",
108 // (long long)mMarkerFramePosition,
109 // (long long)mMarkerNanoTime);
110
111 int64_t expectedNanosDelta = convertDeltaPositionToTime(framesDelta);
112 // ALOGD("processTimestamp() - expectedNanosDelta = %lld, nanosDelta = %llu",
113 // (long long)expectedNanosDelta,
114 // (long long)nanosDelta);
115
116 // ALOGD("processTimestamp() - mSampleRate = %d", mSampleRate);
117 // ALOGD("processTimestamp() - mState = %d", mState);
118 int64_t latenessNanos = nanosDelta - expectedNanosDelta;
119 switch (mState) {
120 case STATE_STOPPED:
121 break;
122 case STATE_STARTING:
123 setPositionAndTime(framePosition, nanoTime);
124 mState = STATE_SYNCING;
125 break;
126 case STATE_SYNCING:
127 // This will handle a burst of rapid transfer at the beginning.
128 if (latenessNanos < 0) {
129 setPositionAndTime(framePosition, nanoTime);
130 } else {
131 // ALOGD("processTimestamp() - advance to STATE_RUNNING");
132 mState = STATE_RUNNING;
133 }
134 break;
135 case STATE_RUNNING:
136 if (mHistogramMicros) {
137 mHistogramMicros->add(latenessNanos / AAUDIO_NANOS_PER_MICROSECOND);
138 }
139 // Modify estimated position based on lateness.
140 // This affects the "early" side of the window, which controls output glitches.
141 if (latenessNanos < 0) {
142 // Earlier than expected timestamp.
143 // This data is probably more accurate, so use it.
144 // Or we may be drifting due to a fast HW clock.
145 setPositionAndTime(framePosition, nanoTime);
146 #if ICM_LOG_DRIFT
147 int earlyDeltaMicros = (int) ((expectedNanosDelta - nanosDelta)/ 1000);
148 ALOGD("%s() - STATE_RUNNING - #%d, %4d micros EARLY",
149 __func__, mTimestampCount, earlyDeltaMicros);
150 #endif
151 } else if (latenessNanos > mLatenessForDriftNanos) {
152 // When we are on the late side, it may be because of preemption in the kernel,
153 // or timing jitter caused by resampling in the DSP,
154 // or we may be drifting due to a slow HW clock.
155 // We add slight drift value just in case there is actual long term drift
156 // forward caused by a slower clock.
157 // If the clock is faster than the model will get pushed earlier
158 // by the code in the earlier branch.
159 // The two opposing forces should allow the model to track the real clock
160 // over a long time.
161 int64_t driftingTime = mMarkerNanoTime + expectedNanosDelta + kDriftNanos;
162 setPositionAndTime(framePosition, driftingTime);
163 #if ICM_LOG_DRIFT
164 ALOGD("%s() - STATE_RUNNING - #%d, DRIFT, lateness = %d micros",
165 __func__,
166 mTimestampCount,
167 (int) (latenessNanos / 1000));
168 #endif
169 }
170
171 // Modify mMaxMeasuredLatenessNanos.
172 // This affects the "late" side of the window, which controls input glitches.
173 if (latenessNanos > mMaxMeasuredLatenessNanos) { // increase
174 #if ICM_LOG_DRIFT
175 ALOGD("%s() - STATE_RUNNING - #%d, newmax %d - oldmax %d = %4d micros LATE",
176 __func__,
177 mTimestampCount,
178 (int) (latenessNanos / 1000),
179 mMaxMeasuredLatenessNanos / 1000,
180 (int) ((latenessNanos - mMaxMeasuredLatenessNanos) / 1000)
181 );
182 #endif
183 mMaxMeasuredLatenessNanos = (int32_t) latenessNanos;
184 // Calculate upper region that will trigger a drift forwards.
185 mLatenessForDriftNanos = mMaxMeasuredLatenessNanos - (mMaxMeasuredLatenessNanos >> 4);
186 } else { // decrease
187 // If this is an outlier in lateness then mMaxMeasuredLatenessNanos can go high
188 // and stay there. So we slowly reduce mMaxMeasuredLatenessNanos for better
189 // long term stability. The two opposing forces will keep mMaxMeasuredLatenessNanos
190 // within a reasonable range.
191 mMaxMeasuredLatenessNanos -= kDriftNanos;
192 }
193 break;
194 default:
195 break;
196 }
197 }
198
setSampleRate(int32_t sampleRate)199 void IsochronousClockModel::setSampleRate(int32_t sampleRate) {
200 mSampleRate = sampleRate;
201 update();
202 }
203
setFramesPerBurst(int32_t framesPerBurst)204 void IsochronousClockModel::setFramesPerBurst(int32_t framesPerBurst) {
205 mFramesPerBurst = framesPerBurst;
206 update();
207 }
208
209 // Update expected lateness based on sampleRate and framesPerBurst
update()210 void IsochronousClockModel::update() {
211 mBurstPeriodNanos = convertDeltaPositionToTime(mFramesPerBurst); // uses mSampleRate
212 }
213
convertDeltaPositionToTime(int64_t framesDelta) const214 int64_t IsochronousClockModel::convertDeltaPositionToTime(int64_t framesDelta) const {
215 return (AAUDIO_NANOS_PER_SECOND * framesDelta) / mSampleRate;
216 }
217
convertDeltaTimeToPosition(int64_t nanosDelta) const218 int64_t IsochronousClockModel::convertDeltaTimeToPosition(int64_t nanosDelta) const {
219 return (mSampleRate * nanosDelta) / AAUDIO_NANOS_PER_SECOND;
220 }
221
convertPositionToTime(int64_t framePosition) const222 int64_t IsochronousClockModel::convertPositionToTime(int64_t framePosition) const {
223 if (mState == STATE_STOPPED) {
224 return mMarkerNanoTime;
225 }
226 int64_t nextBurstIndex = (framePosition + mFramesPerBurst - 1) / mFramesPerBurst;
227 int64_t nextBurstPosition = mFramesPerBurst * nextBurstIndex;
228 int64_t framesDelta = nextBurstPosition - mMarkerFramePosition;
229 int64_t nanosDelta = convertDeltaPositionToTime(framesDelta);
230 int64_t time = mMarkerNanoTime + nanosDelta;
231 // ALOGD("convertPositionToTime: pos = %llu --> time = %llu",
232 // (unsigned long long)framePosition,
233 // (unsigned long long)time);
234 return time;
235 }
236
convertTimeToPosition(int64_t nanoTime) const237 int64_t IsochronousClockModel::convertTimeToPosition(int64_t nanoTime) const {
238 if (mState == STATE_STOPPED) {
239 return mMarkerFramePosition;
240 }
241 int64_t nanosDelta = nanoTime - mMarkerNanoTime;
242 int64_t framesDelta = convertDeltaTimeToPosition(nanosDelta);
243 int64_t nextBurstPosition = mMarkerFramePosition + framesDelta;
244 int64_t nextBurstIndex = nextBurstPosition / mFramesPerBurst;
245 int64_t position = nextBurstIndex * mFramesPerBurst;
246 // ALOGD("convertTimeToPosition: time = %llu --> pos = %llu",
247 // (unsigned long long)nanoTime,
248 // (unsigned long long)position);
249 // ALOGD("convertTimeToPosition: framesDelta = %llu, mFramesPerBurst = %d",
250 // (long long) framesDelta, mFramesPerBurst);
251 return position;
252 }
253
getLateTimeOffsetNanos() const254 int32_t IsochronousClockModel::getLateTimeOffsetNanos() const {
255 return mMaxMeasuredLatenessNanos + kExtraLatenessNanos;
256 }
257
convertPositionToLatestTime(int64_t framePosition) const258 int64_t IsochronousClockModel::convertPositionToLatestTime(int64_t framePosition) const {
259 return convertPositionToTime(framePosition) + getLateTimeOffsetNanos();
260 }
261
convertLatestTimeToPosition(int64_t nanoTime) const262 int64_t IsochronousClockModel::convertLatestTimeToPosition(int64_t nanoTime) const {
263 return convertTimeToPosition(nanoTime - getLateTimeOffsetNanos());
264 }
265
dump() const266 void IsochronousClockModel::dump() const {
267 ALOGD("mMarkerFramePosition = %" PRIu64, mMarkerFramePosition);
268 ALOGD("mMarkerNanoTime = %" PRIu64, mMarkerNanoTime);
269 ALOGD("mSampleRate = %6d", mSampleRate);
270 ALOGD("mFramesPerBurst = %6d", mFramesPerBurst);
271 ALOGD("mMaxMeasuredLatenessNanos = %6d", mMaxMeasuredLatenessNanos);
272 ALOGD("mState = %6d", mState);
273 }
274
dumpHistogram() const275 void IsochronousClockModel::dumpHistogram() const {
276 if (!mHistogramMicros) return;
277 std::istringstream istr(mHistogramMicros->dump());
278 std::string line;
279 while (std::getline(istr, line)) {
280 ALOGD("lateness, %s", line.c_str());
281 }
282 }
283