blob: 3fe50dcf9b79b0fdbc49e144ecb6a66a6af36664 [file] [log] [blame]
Glenn Kasten97b5d0d2012-03-23 18:54:19 -07001/*
2 * Copyright (C) 2012 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 "FastMixer"
18//#define LOG_NDEBUG 0
19
20#include <sys/atomics.h>
21#include <time.h>
22#include <utils/Log.h>
Glenn Kastend8e6fd32012-05-07 11:07:57 -070023#include <utils/Trace.h>
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070024#include <system/audio.h>
25#ifdef FAST_MIXER_STATISTICS
26#include <cpustats/CentralTendencyStatistics.h>
Glenn Kasten42d45cf2012-05-02 10:34:47 -070027#include <cpustats/ThreadCpuUsage.h>
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070028#endif
29#include "AudioMixer.h"
30#include "FastMixer.h"
31
32#define FAST_HOT_IDLE_NS 1000000L // 1 ms: time to sleep while hot idling
33#define FAST_DEFAULT_NS 999999999L // ~1 sec: default time to sleep
Glenn Kasten288ed212012-04-25 17:52:27 -070034#define MAX_WARMUP_CYCLES 10 // maximum number of loop cycles to wait for warmup
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070035
36namespace android {
37
38// Fast mixer thread
39bool FastMixer::threadLoop()
40{
41 static const FastMixerState initial;
42 const FastMixerState *previous = &initial, *current = &initial;
43 FastMixerState preIdle; // copy of state before we went into idle
44 struct timespec oldTs = {0, 0};
45 bool oldTsValid = false;
46 long slopNs = 0; // accumulated time we've woken up too early (> 0) or too late (< 0)
47 long sleepNs = -1; // -1: busy wait, 0: sched_yield, > 0: nanosleep
48 int fastTrackNames[FastMixerState::kMaxFastTracks]; // handles used by mixer to identify tracks
49 int generations[FastMixerState::kMaxFastTracks]; // last observed mFastTracks[i].mGeneration
50 unsigned i;
51 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
52 fastTrackNames[i] = -1;
53 generations[i] = 0;
54 }
55 NBAIO_Sink *outputSink = NULL;
56 int outputSinkGen = 0;
57 AudioMixer* mixer = NULL;
58 short *mixBuffer = NULL;
59 enum {UNDEFINED, MIXED, ZEROED} mixBufferState = UNDEFINED;
60 NBAIO_Format format = Format_Invalid;
61 unsigned sampleRate = 0;
62 int fastTracksGen = 0;
63 long periodNs = 0; // expected period; the time required to render one mix buffer
Glenn Kasten288ed212012-04-25 17:52:27 -070064 long underrunNs = 0; // underrun likely when write cycle is greater than this value
65 long overrunNs = 0; // overrun likely when write cycle is less than this value
66 long warmupNs = 0; // warmup complete when write cycle is greater than to this value
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070067 FastMixerDumpState dummyDumpState, *dumpState = &dummyDumpState;
68 bool ignoreNextOverrun = true; // used to ignore initial overrun and first after an underrun
69#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070070 struct timespec oldLoad = {0, 0}; // previous value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
71 bool oldLoadValid = false; // whether oldLoad is valid
72 uint32_t bounds = 0;
73 bool full = false; // whether we have collected at least kSamplingN samples
74 ThreadCpuUsage tcu; // for reading the current CPU clock frequency in kHz
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070075#endif
76 unsigned coldGen = 0; // last observed mColdGen
Glenn Kasten288ed212012-04-25 17:52:27 -070077 bool isWarm = false; // true means ready to mix, false means wait for warmup before mixing
78 struct timespec measuredWarmupTs = {0, 0}; // how long did it take for warmup to complete
79 uint32_t warmupCycles = 0; // counter of number of loop cycles required to warmup
Glenn Kastenfbae5da2012-05-21 09:17:20 -070080 NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070081
82 for (;;) {
83
84 // either nanosleep, sched_yield, or busy wait
85 if (sleepNs >= 0) {
86 if (sleepNs > 0) {
87 ALOG_ASSERT(sleepNs < 1000000000);
88 const struct timespec req = {0, sleepNs};
89 nanosleep(&req, NULL);
90 } else {
91 sched_yield();
92 }
93 }
94 // default to long sleep for next cycle
95 sleepNs = FAST_DEFAULT_NS;
96
97 // poll for state change
98 const FastMixerState *next = mSQ.poll();
99 if (next == NULL) {
100 // continue to use the default initial state until a real state is available
101 ALOG_ASSERT(current == &initial && previous == &initial);
102 next = current;
103 }
104
105 FastMixerState::Command command = next->mCommand;
106 if (next != current) {
107
108 // As soon as possible of learning of a new dump area, start using it
109 dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
Glenn Kastenfbae5da2012-05-21 09:17:20 -0700110 teeSink = next->mTeeSink;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700111
112 // We want to always have a valid reference to the previous (non-idle) state.
113 // However, the state queue only guarantees access to current and previous states.
114 // So when there is a transition from a non-idle state into an idle state, we make a
115 // copy of the last known non-idle state so it is still available on return from idle.
116 // The possible transitions are:
117 // non-idle -> non-idle update previous from current in-place
118 // non-idle -> idle update previous from copy of current
119 // idle -> idle don't update previous
120 // idle -> non-idle don't update previous
121 if (!(current->mCommand & FastMixerState::IDLE)) {
122 if (command & FastMixerState::IDLE) {
123 preIdle = *current;
124 current = &preIdle;
125 oldTsValid = false;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700126 oldLoadValid = false;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700127 ignoreNextOverrun = true;
128 }
129 previous = current;
130 }
131 current = next;
132 }
133#if !LOG_NDEBUG
134 next = NULL; // not referenced again
135#endif
136
137 dumpState->mCommand = command;
138
139 switch (command) {
140 case FastMixerState::INITIAL:
141 case FastMixerState::HOT_IDLE:
142 sleepNs = FAST_HOT_IDLE_NS;
143 continue;
144 case FastMixerState::COLD_IDLE:
145 // only perform a cold idle command once
Glenn Kasten21e8c502012-04-12 09:39:42 -0700146 // FIXME consider checking previous state and only perform if previous != COLD_IDLE
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700147 if (current->mColdGen != coldGen) {
148 int32_t *coldFutexAddr = current->mColdFutexAddr;
149 ALOG_ASSERT(coldFutexAddr != NULL);
150 int32_t old = android_atomic_dec(coldFutexAddr);
151 if (old <= 0) {
152 __futex_syscall4(coldFutexAddr, FUTEX_WAIT_PRIVATE, old - 1, NULL);
153 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700154 // This may be overly conservative; there could be times that the normal mixer
155 // requests such a brief cold idle that it doesn't require resetting this flag.
156 isWarm = false;
157 measuredWarmupTs.tv_sec = 0;
158 measuredWarmupTs.tv_nsec = 0;
159 warmupCycles = 0;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700160 sleepNs = -1;
161 coldGen = current->mColdGen;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700162 bounds = 0;
163 full = false;
Glenn Kasten04a4ca42012-06-01 10:49:51 -0700164 oldTsValid = !clock_gettime(CLOCK_MONOTONIC, &oldTs);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700165 } else {
166 sleepNs = FAST_HOT_IDLE_NS;
167 }
168 continue;
169 case FastMixerState::EXIT:
170 delete mixer;
171 delete[] mixBuffer;
172 return false;
173 case FastMixerState::MIX:
174 case FastMixerState::WRITE:
175 case FastMixerState::MIX_WRITE:
176 break;
177 default:
178 LOG_FATAL("bad command %d", command);
179 }
180
181 // there is a non-idle state available to us; did the state change?
182 size_t frameCount = current->mFrameCount;
183 if (current != previous) {
184
185 // handle state change here, but since we want to diff the state,
186 // we're prepared for previous == &initial the first time through
187 unsigned previousTrackMask;
188
189 // check for change in output HAL configuration
190 NBAIO_Format previousFormat = format;
191 if (current->mOutputSinkGen != outputSinkGen) {
192 outputSink = current->mOutputSink;
193 outputSinkGen = current->mOutputSinkGen;
194 if (outputSink == NULL) {
195 format = Format_Invalid;
196 sampleRate = 0;
197 } else {
198 format = outputSink->format();
199 sampleRate = Format_sampleRate(format);
200 ALOG_ASSERT(Format_channelCount(format) == 2);
201 }
Glenn Kasten21e8c502012-04-12 09:39:42 -0700202 dumpState->mSampleRate = sampleRate;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700203 }
204
205 if ((format != previousFormat) || (frameCount != previous->mFrameCount)) {
206 // FIXME to avoid priority inversion, don't delete here
207 delete mixer;
208 mixer = NULL;
209 delete[] mixBuffer;
210 mixBuffer = NULL;
211 if (frameCount > 0 && sampleRate > 0) {
212 // FIXME new may block for unbounded time at internal mutex of the heap
213 // implementation; it would be better to have normal mixer allocate for us
214 // to avoid blocking here and to prevent possible priority inversion
215 mixer = new AudioMixer(frameCount, sampleRate, FastMixerState::kMaxFastTracks);
216 mixBuffer = new short[frameCount * 2];
217 periodNs = (frameCount * 1000000000LL) / sampleRate; // 1.00
218 underrunNs = (frameCount * 1750000000LL) / sampleRate; // 1.75
219 overrunNs = (frameCount * 250000000LL) / sampleRate; // 0.25
Glenn Kasten288ed212012-04-25 17:52:27 -0700220 warmupNs = (frameCount * 500000000LL) / sampleRate; // 0.50
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700221 } else {
222 periodNs = 0;
223 underrunNs = 0;
224 overrunNs = 0;
225 }
226 mixBufferState = UNDEFINED;
227#if !LOG_NDEBUG
228 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
229 fastTrackNames[i] = -1;
230 }
231#endif
232 // we need to reconfigure all active tracks
233 previousTrackMask = 0;
234 fastTracksGen = current->mFastTracksGen - 1;
Glenn Kasten21e8c502012-04-12 09:39:42 -0700235 dumpState->mFrameCount = frameCount;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700236 } else {
237 previousTrackMask = previous->mTrackMask;
238 }
239
240 // check for change in active track set
241 unsigned currentTrackMask = current->mTrackMask;
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700242 dumpState->mTrackMask = currentTrackMask;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700243 if (current->mFastTracksGen != fastTracksGen) {
244 ALOG_ASSERT(mixBuffer != NULL);
245 int name;
246
247 // process removed tracks first to avoid running out of track names
248 unsigned removedTracks = previousTrackMask & ~currentTrackMask;
249 while (removedTracks != 0) {
250 i = __builtin_ctz(removedTracks);
251 removedTracks &= ~(1 << i);
252 const FastTrack* fastTrack = &current->mFastTracks[i];
Glenn Kasten288ed212012-04-25 17:52:27 -0700253 ALOG_ASSERT(fastTrack->mBufferProvider == NULL);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700254 if (mixer != NULL) {
255 name = fastTrackNames[i];
256 ALOG_ASSERT(name >= 0);
257 mixer->deleteTrackName(name);
258 }
259#if !LOG_NDEBUG
260 fastTrackNames[i] = -1;
261#endif
Glenn Kasten288ed212012-04-25 17:52:27 -0700262 // don't reset track dump state, since other side is ignoring it
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700263 generations[i] = fastTrack->mGeneration;
264 }
265
266 // now process added tracks
267 unsigned addedTracks = currentTrackMask & ~previousTrackMask;
268 while (addedTracks != 0) {
269 i = __builtin_ctz(addedTracks);
270 addedTracks &= ~(1 << i);
271 const FastTrack* fastTrack = &current->mFastTracks[i];
272 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
273 ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);
274 if (mixer != NULL) {
Jean-Michel Trivi9bd23222012-04-16 13:43:48 -0700275 // calling getTrackName with default channel mask
276 name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700277 ALOG_ASSERT(name >= 0);
278 fastTrackNames[i] = name;
279 mixer->setBufferProvider(name, bufferProvider);
280 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,
281 (void *) mixBuffer);
282 // newly allocated track names default to full scale volume
Glenn Kasten21e8c502012-04-12 09:39:42 -0700283 if (fastTrack->mSampleRate != 0 && fastTrack->mSampleRate != sampleRate) {
284 mixer->setParameter(name, AudioMixer::RESAMPLE,
285 AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate);
286 }
287 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
288 (void *) fastTrack->mChannelMask);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700289 mixer->enable(name);
290 }
291 generations[i] = fastTrack->mGeneration;
292 }
293
294 // finally process modified tracks; these use the same slot
295 // but may have a different buffer provider or volume provider
296 unsigned modifiedTracks = currentTrackMask & previousTrackMask;
297 while (modifiedTracks != 0) {
298 i = __builtin_ctz(modifiedTracks);
299 modifiedTracks &= ~(1 << i);
300 const FastTrack* fastTrack = &current->mFastTracks[i];
301 if (fastTrack->mGeneration != generations[i]) {
302 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
303 ALOG_ASSERT(bufferProvider != NULL);
304 if (mixer != NULL) {
305 name = fastTrackNames[i];
306 ALOG_ASSERT(name >= 0);
307 mixer->setBufferProvider(name, bufferProvider);
308 if (fastTrack->mVolumeProvider == NULL) {
309 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
310 (void *)0x1000);
311 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
312 (void *)0x1000);
313 }
Glenn Kasten21e8c502012-04-12 09:39:42 -0700314 if (fastTrack->mSampleRate != 0 &&
315 fastTrack->mSampleRate != sampleRate) {
316 mixer->setParameter(name, AudioMixer::RESAMPLE,
317 AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate);
318 } else {
319 mixer->setParameter(name, AudioMixer::RESAMPLE,
320 AudioMixer::REMOVE, NULL);
321 }
322 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
323 (void *) fastTrack->mChannelMask);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700324 // already enabled
325 }
326 generations[i] = fastTrack->mGeneration;
327 }
328 }
329
330 fastTracksGen = current->mFastTracksGen;
331
332 dumpState->mNumTracks = popcount(currentTrackMask);
333 }
334
335#if 1 // FIXME shouldn't need this
336 // only process state change once
337 previous = current;
338#endif
339 }
340
341 // do work using current state here
Glenn Kasten288ed212012-04-25 17:52:27 -0700342 if ((command & FastMixerState::MIX) && (mixer != NULL) && isWarm) {
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700343 ALOG_ASSERT(mixBuffer != NULL);
Glenn Kasten288ed212012-04-25 17:52:27 -0700344 // for each track, update volume and check for underrun
345 unsigned currentTrackMask = current->mTrackMask;
346 while (currentTrackMask != 0) {
347 i = __builtin_ctz(currentTrackMask);
348 currentTrackMask &= ~(1 << i);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700349 const FastTrack* fastTrack = &current->mFastTracks[i];
350 int name = fastTrackNames[i];
351 ALOG_ASSERT(name >= 0);
352 if (fastTrack->mVolumeProvider != NULL) {
353 uint32_t vlr = fastTrack->mVolumeProvider->getVolumeLR();
354 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
355 (void *)(vlr & 0xFFFF));
356 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
357 (void *)(vlr >> 16));
358 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700359 // FIXME The current implementation of framesReady() for fast tracks
360 // takes a tryLock, which can block
361 // up to 1 ms. If enough active tracks all blocked in sequence, this would result
362 // in the overall fast mix cycle being delayed. Should use a non-blocking FIFO.
363 size_t framesReady = fastTrack->mBufferProvider->framesReady();
Glenn Kasten99c99d02012-05-14 16:37:13 -0700364#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
365 // I wish we had formatted trace names
366 char traceName[16];
367 strcpy(traceName, "framesReady");
368 traceName[11] = i + (i < 10 ? '0' : 'A' - 10);
369 traceName[12] = '\0';
370 ATRACE_INT(traceName, framesReady);
371#endif
Glenn Kasten288ed212012-04-25 17:52:27 -0700372 FastTrackDump *ftDump = &dumpState->mTracks[i];
Glenn Kasten09474df2012-05-10 14:48:07 -0700373 FastTrackUnderruns underruns = ftDump->mUnderruns;
Glenn Kasten288ed212012-04-25 17:52:27 -0700374 if (framesReady < frameCount) {
Glenn Kasten288ed212012-04-25 17:52:27 -0700375 if (framesReady == 0) {
Glenn Kasten09474df2012-05-10 14:48:07 -0700376 underruns.mBitFields.mEmpty++;
377 underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;
Glenn Kasten288ed212012-04-25 17:52:27 -0700378 mixer->disable(name);
379 } else {
380 // allow mixing partial buffer
Glenn Kasten09474df2012-05-10 14:48:07 -0700381 underruns.mBitFields.mPartial++;
382 underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;
Glenn Kasten288ed212012-04-25 17:52:27 -0700383 mixer->enable(name);
384 }
Glenn Kasten09474df2012-05-10 14:48:07 -0700385 } else {
386 underruns.mBitFields.mFull++;
387 underruns.mBitFields.mMostRecent = UNDERRUN_FULL;
Glenn Kasten288ed212012-04-25 17:52:27 -0700388 mixer->enable(name);
389 }
Glenn Kasten09474df2012-05-10 14:48:07 -0700390 ftDump->mUnderruns = underruns;
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700391 ftDump->mFramesReady = framesReady;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700392 }
393 // process() is CPU-bound
394 mixer->process(AudioBufferProvider::kInvalidPTS);
395 mixBufferState = MIXED;
396 } else if (mixBufferState == MIXED) {
397 mixBufferState = UNDEFINED;
398 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700399 bool attemptedWrite = false;
400 //bool didFullWrite = false; // dumpsys could display a count of partial writes
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700401 if ((command & FastMixerState::WRITE) && (outputSink != NULL) && (mixBuffer != NULL)) {
402 if (mixBufferState == UNDEFINED) {
403 memset(mixBuffer, 0, frameCount * 2 * sizeof(short));
404 mixBufferState = ZEROED;
405 }
Glenn Kastenfbae5da2012-05-21 09:17:20 -0700406 if (teeSink != NULL) {
407 (void) teeSink->write(mixBuffer, frameCount);
408 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700409 // FIXME write() is non-blocking and lock-free for a properly implemented NBAIO sink,
410 // but this code should be modified to handle both non-blocking and blocking sinks
411 dumpState->mWriteSequence++;
Glenn Kasten99c99d02012-05-14 16:37:13 -0700412#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Glenn Kastend8e6fd32012-05-07 11:07:57 -0700413 Tracer::traceBegin(ATRACE_TAG, "write");
Glenn Kasten99c99d02012-05-14 16:37:13 -0700414#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700415 ssize_t framesWritten = outputSink->write(mixBuffer, frameCount);
Glenn Kasten99c99d02012-05-14 16:37:13 -0700416#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Glenn Kastend8e6fd32012-05-07 11:07:57 -0700417 Tracer::traceEnd(ATRACE_TAG);
Glenn Kasten99c99d02012-05-14 16:37:13 -0700418#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700419 dumpState->mWriteSequence++;
420 if (framesWritten >= 0) {
Glenn Kasten288ed212012-04-25 17:52:27 -0700421 ALOG_ASSERT(framesWritten <= frameCount);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700422 dumpState->mFramesWritten += framesWritten;
Glenn Kasten288ed212012-04-25 17:52:27 -0700423 //if ((size_t) framesWritten == frameCount) {
424 // didFullWrite = true;
425 //}
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700426 } else {
427 dumpState->mWriteErrors++;
428 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700429 attemptedWrite = true;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700430 // FIXME count # of writes blocked excessively, CPU usage, etc. for dump
431 }
432
433 // To be exactly periodic, compute the next sleep time based on current time.
434 // This code doesn't have long-term stability when the sink is non-blocking.
435 // FIXME To avoid drift, use the local audio clock or watch the sink's fill status.
436 struct timespec newTs;
437 int rc = clock_gettime(CLOCK_MONOTONIC, &newTs);
438 if (rc == 0) {
439 if (oldTsValid) {
440 time_t sec = newTs.tv_sec - oldTs.tv_sec;
441 long nsec = newTs.tv_nsec - oldTs.tv_nsec;
442 if (nsec < 0) {
443 --sec;
444 nsec += 1000000000;
445 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700446 // To avoid an initial underrun on fast tracks after exiting standby,
447 // do not start pulling data from tracks and mixing until warmup is complete.
448 // Warmup is considered complete after the earlier of:
449 // first successful single write() that blocks for more than warmupNs
450 // MAX_WARMUP_CYCLES write() attempts.
451 // This is overly conservative, but to get better accuracy requires a new HAL API.
452 if (!isWarm && attemptedWrite) {
453 measuredWarmupTs.tv_sec += sec;
454 measuredWarmupTs.tv_nsec += nsec;
455 if (measuredWarmupTs.tv_nsec >= 1000000000) {
456 measuredWarmupTs.tv_sec++;
457 measuredWarmupTs.tv_nsec -= 1000000000;
458 }
459 ++warmupCycles;
460 if ((attemptedWrite && nsec > warmupNs) ||
461 (warmupCycles >= MAX_WARMUP_CYCLES)) {
462 isWarm = true;
463 dumpState->mMeasuredWarmupTs = measuredWarmupTs;
464 dumpState->mWarmupCycles = warmupCycles;
465 }
466 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700467 if (sec > 0 || nsec > underrunNs) {
Glenn Kasten99c99d02012-05-14 16:37:13 -0700468#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Glenn Kastend8e6fd32012-05-07 11:07:57 -0700469 ScopedTrace st(ATRACE_TAG, "underrun");
Glenn Kasten99c99d02012-05-14 16:37:13 -0700470#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700471 // FIXME only log occasionally
472 ALOGV("underrun: time since last cycle %d.%03ld sec",
473 (int) sec, nsec / 1000000L);
474 dumpState->mUnderruns++;
475 sleepNs = -1;
476 ignoreNextOverrun = true;
477 } else if (nsec < overrunNs) {
478 if (ignoreNextOverrun) {
479 ignoreNextOverrun = false;
480 } else {
481 // FIXME only log occasionally
482 ALOGV("overrun: time since last cycle %d.%03ld sec",
483 (int) sec, nsec / 1000000L);
484 dumpState->mOverruns++;
485 }
Eric Laurent9a0d82d2012-06-05 18:12:11 -0700486 // Code for non blocking audio HAL. Sleep time must be tuned to allow
487 // catching up after an underrun
488 // sleepNs = periodNs - overrunNs;
489 sleepNs = -1;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700490 } else {
491 sleepNs = -1;
492 ignoreNextOverrun = false;
493 }
494#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700495 // advance the FIFO queue bounds
496 size_t i = bounds & (FastMixerDumpState::kSamplingN - 1);
Glenn Kastene58ccce2012-05-11 15:19:24 -0700497 bounds = (bounds & 0xFFFF0000) | ((bounds + 1) & 0xFFFF);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700498 if (full) {
499 bounds += 0x10000;
500 } else if (!(bounds & (FastMixerDumpState::kSamplingN - 1))) {
501 full = true;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700502 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700503 // compute the delta value of clock_gettime(CLOCK_MONOTONIC)
504 uint32_t monotonicNs = nsec;
505 if (sec > 0 && sec < 4) {
506 monotonicNs += sec * 1000000000;
507 }
508 // compute the raw CPU load = delta value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
509 uint32_t loadNs = 0;
510 struct timespec newLoad;
511 rc = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &newLoad);
512 if (rc == 0) {
513 if (oldLoadValid) {
514 sec = newLoad.tv_sec - oldLoad.tv_sec;
515 nsec = newLoad.tv_nsec - oldLoad.tv_nsec;
516 if (nsec < 0) {
517 --sec;
518 nsec += 1000000000;
519 }
520 loadNs = nsec;
521 if (sec > 0 && sec < 4) {
522 loadNs += sec * 1000000000;
523 }
524 } else {
525 // first time through the loop
526 oldLoadValid = true;
527 }
528 oldLoad = newLoad;
529 }
530 // get the absolute value of CPU clock frequency in kHz
531 int cpuNum = sched_getcpu();
532 uint32_t kHz = tcu.getCpukHz(cpuNum);
Glenn Kastenc059bd42012-05-14 17:41:09 -0700533 kHz = (kHz << 4) | (cpuNum & 0xF);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700534 // save values in FIFO queues for dumpsys
535 // these stores #1, #2, #3 are not atomic with respect to each other,
536 // or with respect to store #4 below
537 dumpState->mMonotonicNs[i] = monotonicNs;
538 dumpState->mLoadNs[i] = loadNs;
539 dumpState->mCpukHz[i] = kHz;
540 // this store #4 is not atomic with respect to stores #1, #2, #3 above, but
541 // the newest open and oldest closed halves are atomic with respect to each other
542 dumpState->mBounds = bounds;
Glenn Kasten99c99d02012-05-14 16:37:13 -0700543#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
544 ATRACE_INT("cycle_ms", monotonicNs / 1000000);
545 ATRACE_INT("load_us", loadNs / 1000);
546#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700547#endif
548 } else {
549 // first time through the loop
550 oldTsValid = true;
551 sleepNs = periodNs;
552 ignoreNextOverrun = true;
553 }
554 oldTs = newTs;
555 } else {
556 // monotonic clock is broken
557 oldTsValid = false;
558 sleepNs = periodNs;
559 }
560
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700561
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700562 } // for (;;)
563
564 // never return 'true'; Thread::_threadLoop() locks mutex which can result in priority inversion
565}
566
567FastMixerDumpState::FastMixerDumpState() :
568 mCommand(FastMixerState::INITIAL), mWriteSequence(0), mFramesWritten(0),
Glenn Kasten21e8c502012-04-12 09:39:42 -0700569 mNumTracks(0), mWriteErrors(0), mUnderruns(0), mOverruns(0),
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700570 mSampleRate(0), mFrameCount(0), /* mMeasuredWarmupTs({0, 0}), */ mWarmupCycles(0),
571 mTrackMask(0)
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700572#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700573 , mBounds(0)
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700574#endif
575{
Glenn Kasten288ed212012-04-25 17:52:27 -0700576 mMeasuredWarmupTs.tv_sec = 0;
577 mMeasuredWarmupTs.tv_nsec = 0;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700578 // sample arrays aren't accessed atomically with respect to the bounds,
579 // so clearing reduces chance for dumpsys to read random uninitialized samples
580 memset(&mMonotonicNs, 0, sizeof(mMonotonicNs));
581 memset(&mLoadNs, 0, sizeof(mLoadNs));
582 memset(&mCpukHz, 0, sizeof(mCpukHz));
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700583}
584
585FastMixerDumpState::~FastMixerDumpState()
586{
587}
588
589void FastMixerDumpState::dump(int fd)
590{
Glenn Kasten868c0ab2012-06-13 14:59:17 -0700591 if (mCommand == FastMixerState::INITIAL) {
592 fdprintf(fd, "FastMixer not initialized\n");
593 return;
594 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700595#define COMMAND_MAX 32
596 char string[COMMAND_MAX];
597 switch (mCommand) {
598 case FastMixerState::INITIAL:
599 strcpy(string, "INITIAL");
600 break;
601 case FastMixerState::HOT_IDLE:
602 strcpy(string, "HOT_IDLE");
603 break;
604 case FastMixerState::COLD_IDLE:
605 strcpy(string, "COLD_IDLE");
606 break;
607 case FastMixerState::EXIT:
608 strcpy(string, "EXIT");
609 break;
610 case FastMixerState::MIX:
611 strcpy(string, "MIX");
612 break;
613 case FastMixerState::WRITE:
614 strcpy(string, "WRITE");
615 break;
616 case FastMixerState::MIX_WRITE:
617 strcpy(string, "MIX_WRITE");
618 break;
619 default:
620 snprintf(string, COMMAND_MAX, "%d", mCommand);
621 break;
622 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700623 double measuredWarmupMs = (mMeasuredWarmupTs.tv_sec * 1000.0) +
Glenn Kasten288ed212012-04-25 17:52:27 -0700624 (mMeasuredWarmupTs.tv_nsec / 1000000.0);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700625 double mixPeriodSec = (double) mFrameCount / (double) mSampleRate;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700626 fdprintf(fd, "FastMixer command=%s writeSequence=%u framesWritten=%u\n"
Glenn Kasten21e8c502012-04-12 09:39:42 -0700627 " numTracks=%u writeErrors=%u underruns=%u overruns=%u\n"
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700628 " sampleRate=%u frameCount=%u measuredWarmup=%.3g ms, warmupCycles=%u\n"
629 " mixPeriod=%.2f ms\n",
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700630 string, mWriteSequence, mFramesWritten,
Glenn Kasten21e8c502012-04-12 09:39:42 -0700631 mNumTracks, mWriteErrors, mUnderruns, mOverruns,
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700632 mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles,
633 mixPeriodSec * 1e3);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700634#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700635 // find the interval of valid samples
636 uint32_t bounds = mBounds;
637 uint32_t newestOpen = bounds & 0xFFFF;
638 uint32_t oldestClosed = bounds >> 16;
639 uint32_t n = (newestOpen - oldestClosed) & 0xFFFF;
640 if (n > kSamplingN) {
641 ALOGE("too many samples %u", n);
642 n = kSamplingN;
643 }
644 // statistics for monotonic (wall clock) time, thread raw CPU load in time, CPU clock frequency,
645 // and adjusted CPU load in MHz normalized for CPU clock frequency
646 CentralTendencyStatistics wall, loadNs, kHz, loadMHz;
647 // only compute adjusted CPU load in Hz if current CPU number and CPU clock frequency are stable
648 bool valid = false;
649 uint32_t previousCpukHz = 0;
650 // loop over all the samples
651 for (; n > 0; --n) {
652 size_t i = oldestClosed++ & (kSamplingN - 1);
653 uint32_t wallNs = mMonotonicNs[i];
654 wall.sample(wallNs);
655 uint32_t sampleLoadNs = mLoadNs[i];
656 uint32_t sampleCpukHz = mCpukHz[i];
657 loadNs.sample(sampleLoadNs);
Glenn Kastenc059bd42012-05-14 17:41:09 -0700658 // skip bad kHz samples
659 if ((sampleCpukHz & ~0xF) != 0) {
660 kHz.sample(sampleCpukHz >> 4);
661 if (sampleCpukHz == previousCpukHz) {
662 double megacycles = (double) sampleLoadNs * (double) (sampleCpukHz >> 4) * 1e-12;
663 double adjMHz = megacycles / mixPeriodSec; // _not_ wallNs * 1e9
664 loadMHz.sample(adjMHz);
665 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700666 }
667 previousCpukHz = sampleCpukHz;
668 }
669 fdprintf(fd, "Simple moving statistics over last %.1f seconds:\n", wall.n() * mixPeriodSec);
670 fdprintf(fd, " wall clock time in ms per mix cycle:\n"
671 " mean=%.2f min=%.2f max=%.2f stddev=%.2f\n",
672 wall.mean()*1e-6, wall.minimum()*1e-6, wall.maximum()*1e-6, wall.stddev()*1e-6);
673 fdprintf(fd, " raw CPU load in us per mix cycle:\n"
674 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
675 loadNs.mean()*1e-3, loadNs.minimum()*1e-3, loadNs.maximum()*1e-3,
676 loadNs.stddev()*1e-3);
677 fdprintf(fd, " CPU clock frequency in MHz:\n"
678 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
679 kHz.mean()*1e-3, kHz.minimum()*1e-3, kHz.maximum()*1e-3, kHz.stddev()*1e-3);
680 fdprintf(fd, " adjusted CPU load in MHz (i.e. normalized for CPU clock frequency):\n"
681 " mean=%.1f min=%.1f max=%.1f stddev=%.1f\n",
682 loadMHz.mean(), loadMHz.minimum(), loadMHz.maximum(), loadMHz.stddev());
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700683#endif
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700684 // The active track mask and track states are updated non-atomically.
685 // So if we relied on isActive to decide whether to display,
686 // then we might display an obsolete track or omit an active track.
687 // Instead we always display all tracks, with an indication
688 // of whether we think the track is active.
689 uint32_t trackMask = mTrackMask;
690 fdprintf(fd, "Fast tracks: kMaxFastTracks=%u activeMask=%#x\n",
691 FastMixerState::kMaxFastTracks, trackMask);
692 fdprintf(fd, "Index Active Full Partial Empty Recent Ready\n");
693 for (uint32_t i = 0; i < FastMixerState::kMaxFastTracks; ++i, trackMask >>= 1) {
694 bool isActive = trackMask & 1;
695 const FastTrackDump *ftDump = &mTracks[i];
696 const FastTrackUnderruns& underruns = ftDump->mUnderruns;
697 const char *mostRecent;
698 switch (underruns.mBitFields.mMostRecent) {
699 case UNDERRUN_FULL:
700 mostRecent = "full";
701 break;
702 case UNDERRUN_PARTIAL:
703 mostRecent = "partial";
704 break;
705 case UNDERRUN_EMPTY:
706 mostRecent = "empty";
707 break;
708 default:
709 mostRecent = "?";
710 break;
711 }
712 fdprintf(fd, "%5u %6s %4u %7u %5u %7s %5u\n", i, isActive ? "yes" : "no",
713 (underruns.mBitFields.mFull) & UNDERRUN_MASK,
714 (underruns.mBitFields.mPartial) & UNDERRUN_MASK,
715 (underruns.mBitFields.mEmpty) & UNDERRUN_MASK,
716 mostRecent, ftDump->mFramesReady);
717 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700718}
719
720} // namespace android