blob: 13003d970787a77f2171febdf61630d6dd08fee2 [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 Kasten0a14c4c2012-06-13 14:58:49 -070027#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070028#include <cpustats/ThreadCpuUsage.h>
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070029#endif
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070030#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070031#include "AudioMixer.h"
32#include "FastMixer.h"
33
34#define FAST_HOT_IDLE_NS 1000000L // 1 ms: time to sleep while hot idling
35#define FAST_DEFAULT_NS 999999999L // ~1 sec: default time to sleep
Glenn Kasteneb157162012-06-13 14:59:07 -070036#define MIN_WARMUP_CYCLES 2 // minimum number of loop cycles to wait for warmup
Glenn Kasten288ed212012-04-25 17:52:27 -070037#define MAX_WARMUP_CYCLES 10 // maximum number of loop cycles to wait for warmup
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070038
39namespace android {
40
41// Fast mixer thread
42bool FastMixer::threadLoop()
43{
44 static const FastMixerState initial;
45 const FastMixerState *previous = &initial, *current = &initial;
46 FastMixerState preIdle; // copy of state before we went into idle
47 struct timespec oldTs = {0, 0};
48 bool oldTsValid = false;
49 long slopNs = 0; // accumulated time we've woken up too early (> 0) or too late (< 0)
50 long sleepNs = -1; // -1: busy wait, 0: sched_yield, > 0: nanosleep
51 int fastTrackNames[FastMixerState::kMaxFastTracks]; // handles used by mixer to identify tracks
52 int generations[FastMixerState::kMaxFastTracks]; // last observed mFastTracks[i].mGeneration
53 unsigned i;
54 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
55 fastTrackNames[i] = -1;
56 generations[i] = 0;
57 }
58 NBAIO_Sink *outputSink = NULL;
59 int outputSinkGen = 0;
60 AudioMixer* mixer = NULL;
61 short *mixBuffer = NULL;
62 enum {UNDEFINED, MIXED, ZEROED} mixBufferState = UNDEFINED;
63 NBAIO_Format format = Format_Invalid;
64 unsigned sampleRate = 0;
65 int fastTracksGen = 0;
66 long periodNs = 0; // expected period; the time required to render one mix buffer
Glenn Kasten288ed212012-04-25 17:52:27 -070067 long underrunNs = 0; // underrun likely when write cycle is greater than this value
68 long overrunNs = 0; // overrun likely when write cycle is less than this value
Glenn Kasten972af222012-06-13 17:14:03 -070069 long forceNs = 0; // if overrun detected, force the write cycle to take this much time
Glenn Kasten288ed212012-04-25 17:52:27 -070070 long warmupNs = 0; // warmup complete when write cycle is greater than to this value
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070071 FastMixerDumpState dummyDumpState, *dumpState = &dummyDumpState;
72 bool ignoreNextOverrun = true; // used to ignore initial overrun and first after an underrun
73#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070074 struct timespec oldLoad = {0, 0}; // previous value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
75 bool oldLoadValid = false; // whether oldLoad is valid
76 uint32_t bounds = 0;
77 bool full = false; // whether we have collected at least kSamplingN samples
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070078#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070079 ThreadCpuUsage tcu; // for reading the current CPU clock frequency in kHz
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070080#endif
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070081#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070082 unsigned coldGen = 0; // last observed mColdGen
Glenn Kasten288ed212012-04-25 17:52:27 -070083 bool isWarm = false; // true means ready to mix, false means wait for warmup before mixing
84 struct timespec measuredWarmupTs = {0, 0}; // how long did it take for warmup to complete
85 uint32_t warmupCycles = 0; // counter of number of loop cycles required to warmup
Glenn Kastenfbae5da2012-05-21 09:17:20 -070086 NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070087
88 for (;;) {
89
90 // either nanosleep, sched_yield, or busy wait
91 if (sleepNs >= 0) {
92 if (sleepNs > 0) {
93 ALOG_ASSERT(sleepNs < 1000000000);
94 const struct timespec req = {0, sleepNs};
95 nanosleep(&req, NULL);
96 } else {
97 sched_yield();
98 }
99 }
100 // default to long sleep for next cycle
101 sleepNs = FAST_DEFAULT_NS;
102
103 // poll for state change
104 const FastMixerState *next = mSQ.poll();
105 if (next == NULL) {
106 // continue to use the default initial state until a real state is available
107 ALOG_ASSERT(current == &initial && previous == &initial);
108 next = current;
109 }
110
111 FastMixerState::Command command = next->mCommand;
112 if (next != current) {
113
114 // As soon as possible of learning of a new dump area, start using it
115 dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
Glenn Kastenfbae5da2012-05-21 09:17:20 -0700116 teeSink = next->mTeeSink;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700117
118 // We want to always have a valid reference to the previous (non-idle) state.
119 // However, the state queue only guarantees access to current and previous states.
120 // So when there is a transition from a non-idle state into an idle state, we make a
121 // copy of the last known non-idle state so it is still available on return from idle.
122 // The possible transitions are:
123 // non-idle -> non-idle update previous from current in-place
124 // non-idle -> idle update previous from copy of current
125 // idle -> idle don't update previous
126 // idle -> non-idle don't update previous
127 if (!(current->mCommand & FastMixerState::IDLE)) {
128 if (command & FastMixerState::IDLE) {
129 preIdle = *current;
130 current = &preIdle;
131 oldTsValid = false;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700132 oldLoadValid = false;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700133 ignoreNextOverrun = true;
134 }
135 previous = current;
136 }
137 current = next;
138 }
139#if !LOG_NDEBUG
140 next = NULL; // not referenced again
141#endif
142
143 dumpState->mCommand = command;
144
145 switch (command) {
146 case FastMixerState::INITIAL:
147 case FastMixerState::HOT_IDLE:
148 sleepNs = FAST_HOT_IDLE_NS;
149 continue;
150 case FastMixerState::COLD_IDLE:
151 // only perform a cold idle command once
Glenn Kasten21e8c502012-04-12 09:39:42 -0700152 // FIXME consider checking previous state and only perform if previous != COLD_IDLE
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700153 if (current->mColdGen != coldGen) {
154 int32_t *coldFutexAddr = current->mColdFutexAddr;
155 ALOG_ASSERT(coldFutexAddr != NULL);
156 int32_t old = android_atomic_dec(coldFutexAddr);
157 if (old <= 0) {
158 __futex_syscall4(coldFutexAddr, FUTEX_WAIT_PRIVATE, old - 1, NULL);
159 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700160 // This may be overly conservative; there could be times that the normal mixer
161 // requests such a brief cold idle that it doesn't require resetting this flag.
162 isWarm = false;
163 measuredWarmupTs.tv_sec = 0;
164 measuredWarmupTs.tv_nsec = 0;
165 warmupCycles = 0;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700166 sleepNs = -1;
167 coldGen = current->mColdGen;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700168 bounds = 0;
169 full = false;
Glenn Kasten04a4ca42012-06-01 10:49:51 -0700170 oldTsValid = !clock_gettime(CLOCK_MONOTONIC, &oldTs);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700171 } else {
172 sleepNs = FAST_HOT_IDLE_NS;
173 }
174 continue;
175 case FastMixerState::EXIT:
176 delete mixer;
177 delete[] mixBuffer;
178 return false;
179 case FastMixerState::MIX:
180 case FastMixerState::WRITE:
181 case FastMixerState::MIX_WRITE:
182 break;
183 default:
184 LOG_FATAL("bad command %d", command);
185 }
186
187 // there is a non-idle state available to us; did the state change?
188 size_t frameCount = current->mFrameCount;
189 if (current != previous) {
190
191 // handle state change here, but since we want to diff the state,
192 // we're prepared for previous == &initial the first time through
193 unsigned previousTrackMask;
194
195 // check for change in output HAL configuration
196 NBAIO_Format previousFormat = format;
197 if (current->mOutputSinkGen != outputSinkGen) {
198 outputSink = current->mOutputSink;
199 outputSinkGen = current->mOutputSinkGen;
200 if (outputSink == NULL) {
201 format = Format_Invalid;
202 sampleRate = 0;
203 } else {
204 format = outputSink->format();
205 sampleRate = Format_sampleRate(format);
206 ALOG_ASSERT(Format_channelCount(format) == 2);
207 }
Glenn Kasten21e8c502012-04-12 09:39:42 -0700208 dumpState->mSampleRate = sampleRate;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700209 }
210
211 if ((format != previousFormat) || (frameCount != previous->mFrameCount)) {
212 // FIXME to avoid priority inversion, don't delete here
213 delete mixer;
214 mixer = NULL;
215 delete[] mixBuffer;
216 mixBuffer = NULL;
217 if (frameCount > 0 && sampleRate > 0) {
218 // FIXME new may block for unbounded time at internal mutex of the heap
219 // implementation; it would be better to have normal mixer allocate for us
220 // to avoid blocking here and to prevent possible priority inversion
221 mixer = new AudioMixer(frameCount, sampleRate, FastMixerState::kMaxFastTracks);
222 mixBuffer = new short[frameCount * 2];
223 periodNs = (frameCount * 1000000000LL) / sampleRate; // 1.00
224 underrunNs = (frameCount * 1750000000LL) / sampleRate; // 1.75
Glenn Kasten0d27c652012-08-07 10:38:59 -0700225 overrunNs = (frameCount * 500000000LL) / sampleRate; // 0.50
226 forceNs = (frameCount * 950000000LL) / sampleRate; // 0.95
Glenn Kasten288ed212012-04-25 17:52:27 -0700227 warmupNs = (frameCount * 500000000LL) / sampleRate; // 0.50
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700228 } else {
229 periodNs = 0;
230 underrunNs = 0;
231 overrunNs = 0;
Glenn Kasten972af222012-06-13 17:14:03 -0700232 forceNs = 0;
233 warmupNs = 0;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700234 }
235 mixBufferState = UNDEFINED;
236#if !LOG_NDEBUG
237 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
238 fastTrackNames[i] = -1;
239 }
240#endif
241 // we need to reconfigure all active tracks
242 previousTrackMask = 0;
243 fastTracksGen = current->mFastTracksGen - 1;
Glenn Kasten21e8c502012-04-12 09:39:42 -0700244 dumpState->mFrameCount = frameCount;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700245 } else {
246 previousTrackMask = previous->mTrackMask;
247 }
248
249 // check for change in active track set
250 unsigned currentTrackMask = current->mTrackMask;
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700251 dumpState->mTrackMask = currentTrackMask;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700252 if (current->mFastTracksGen != fastTracksGen) {
253 ALOG_ASSERT(mixBuffer != NULL);
254 int name;
255
256 // process removed tracks first to avoid running out of track names
257 unsigned removedTracks = previousTrackMask & ~currentTrackMask;
258 while (removedTracks != 0) {
259 i = __builtin_ctz(removedTracks);
260 removedTracks &= ~(1 << i);
261 const FastTrack* fastTrack = &current->mFastTracks[i];
Glenn Kasten288ed212012-04-25 17:52:27 -0700262 ALOG_ASSERT(fastTrack->mBufferProvider == NULL);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700263 if (mixer != NULL) {
264 name = fastTrackNames[i];
265 ALOG_ASSERT(name >= 0);
266 mixer->deleteTrackName(name);
267 }
268#if !LOG_NDEBUG
269 fastTrackNames[i] = -1;
270#endif
Glenn Kasten288ed212012-04-25 17:52:27 -0700271 // don't reset track dump state, since other side is ignoring it
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700272 generations[i] = fastTrack->mGeneration;
273 }
274
275 // now process added tracks
276 unsigned addedTracks = currentTrackMask & ~previousTrackMask;
277 while (addedTracks != 0) {
278 i = __builtin_ctz(addedTracks);
279 addedTracks &= ~(1 << i);
280 const FastTrack* fastTrack = &current->mFastTracks[i];
281 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
282 ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);
283 if (mixer != NULL) {
Jean-Michel Trivife3156e2012-09-10 18:58:27 -0700284 // calling getTrackName with default channel mask and a random invalid
285 // sessionId (no effects here)
286 name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO, -555);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700287 ALOG_ASSERT(name >= 0);
288 fastTrackNames[i] = name;
289 mixer->setBufferProvider(name, bufferProvider);
290 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,
291 (void *) mixBuffer);
292 // newly allocated track names default to full scale volume
Glenn Kasten21e8c502012-04-12 09:39:42 -0700293 if (fastTrack->mSampleRate != 0 && fastTrack->mSampleRate != sampleRate) {
294 mixer->setParameter(name, AudioMixer::RESAMPLE,
295 AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate);
296 }
297 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
298 (void *) fastTrack->mChannelMask);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700299 mixer->enable(name);
300 }
301 generations[i] = fastTrack->mGeneration;
302 }
303
304 // finally process modified tracks; these use the same slot
305 // but may have a different buffer provider or volume provider
306 unsigned modifiedTracks = currentTrackMask & previousTrackMask;
307 while (modifiedTracks != 0) {
308 i = __builtin_ctz(modifiedTracks);
309 modifiedTracks &= ~(1 << i);
310 const FastTrack* fastTrack = &current->mFastTracks[i];
311 if (fastTrack->mGeneration != generations[i]) {
312 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
313 ALOG_ASSERT(bufferProvider != NULL);
314 if (mixer != NULL) {
315 name = fastTrackNames[i];
316 ALOG_ASSERT(name >= 0);
317 mixer->setBufferProvider(name, bufferProvider);
318 if (fastTrack->mVolumeProvider == NULL) {
319 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
320 (void *)0x1000);
321 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
322 (void *)0x1000);
323 }
Glenn Kasten21e8c502012-04-12 09:39:42 -0700324 if (fastTrack->mSampleRate != 0 &&
325 fastTrack->mSampleRate != sampleRate) {
326 mixer->setParameter(name, AudioMixer::RESAMPLE,
327 AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate);
328 } else {
329 mixer->setParameter(name, AudioMixer::RESAMPLE,
330 AudioMixer::REMOVE, NULL);
331 }
332 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
333 (void *) fastTrack->mChannelMask);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700334 // already enabled
335 }
336 generations[i] = fastTrack->mGeneration;
337 }
338 }
339
340 fastTracksGen = current->mFastTracksGen;
341
342 dumpState->mNumTracks = popcount(currentTrackMask);
343 }
344
345#if 1 // FIXME shouldn't need this
346 // only process state change once
347 previous = current;
348#endif
349 }
350
351 // do work using current state here
Glenn Kasten288ed212012-04-25 17:52:27 -0700352 if ((command & FastMixerState::MIX) && (mixer != NULL) && isWarm) {
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700353 ALOG_ASSERT(mixBuffer != NULL);
Glenn Kasten288ed212012-04-25 17:52:27 -0700354 // for each track, update volume and check for underrun
355 unsigned currentTrackMask = current->mTrackMask;
356 while (currentTrackMask != 0) {
357 i = __builtin_ctz(currentTrackMask);
358 currentTrackMask &= ~(1 << i);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700359 const FastTrack* fastTrack = &current->mFastTracks[i];
360 int name = fastTrackNames[i];
361 ALOG_ASSERT(name >= 0);
362 if (fastTrack->mVolumeProvider != NULL) {
363 uint32_t vlr = fastTrack->mVolumeProvider->getVolumeLR();
364 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
365 (void *)(vlr & 0xFFFF));
366 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
367 (void *)(vlr >> 16));
368 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700369 // FIXME The current implementation of framesReady() for fast tracks
370 // takes a tryLock, which can block
371 // up to 1 ms. If enough active tracks all blocked in sequence, this would result
372 // in the overall fast mix cycle being delayed. Should use a non-blocking FIFO.
373 size_t framesReady = fastTrack->mBufferProvider->framesReady();
Glenn Kasten99c99d02012-05-14 16:37:13 -0700374#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
375 // I wish we had formatted trace names
376 char traceName[16];
377 strcpy(traceName, "framesReady");
378 traceName[11] = i + (i < 10 ? '0' : 'A' - 10);
379 traceName[12] = '\0';
380 ATRACE_INT(traceName, framesReady);
381#endif
Glenn Kasten288ed212012-04-25 17:52:27 -0700382 FastTrackDump *ftDump = &dumpState->mTracks[i];
Glenn Kasten09474df2012-05-10 14:48:07 -0700383 FastTrackUnderruns underruns = ftDump->mUnderruns;
Glenn Kasten288ed212012-04-25 17:52:27 -0700384 if (framesReady < frameCount) {
Glenn Kasten288ed212012-04-25 17:52:27 -0700385 if (framesReady == 0) {
Glenn Kasten09474df2012-05-10 14:48:07 -0700386 underruns.mBitFields.mEmpty++;
387 underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;
Glenn Kasten288ed212012-04-25 17:52:27 -0700388 mixer->disable(name);
389 } else {
390 // allow mixing partial buffer
Glenn Kasten09474df2012-05-10 14:48:07 -0700391 underruns.mBitFields.mPartial++;
392 underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;
Glenn Kasten288ed212012-04-25 17:52:27 -0700393 mixer->enable(name);
394 }
Glenn Kasten09474df2012-05-10 14:48:07 -0700395 } else {
396 underruns.mBitFields.mFull++;
397 underruns.mBitFields.mMostRecent = UNDERRUN_FULL;
Glenn Kasten288ed212012-04-25 17:52:27 -0700398 mixer->enable(name);
399 }
Glenn Kasten09474df2012-05-10 14:48:07 -0700400 ftDump->mUnderruns = underruns;
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700401 ftDump->mFramesReady = framesReady;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700402 }
John Grossman2c3b2da2012-08-02 17:08:54 -0700403
404 int64_t pts;
405 if (outputSink == NULL || (OK != outputSink->getNextWriteTimestamp(&pts)))
406 pts = AudioBufferProvider::kInvalidPTS;
407
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700408 // process() is CPU-bound
John Grossman2c3b2da2012-08-02 17:08:54 -0700409 mixer->process(pts);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700410 mixBufferState = MIXED;
411 } else if (mixBufferState == MIXED) {
412 mixBufferState = UNDEFINED;
413 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700414 bool attemptedWrite = false;
415 //bool didFullWrite = false; // dumpsys could display a count of partial writes
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700416 if ((command & FastMixerState::WRITE) && (outputSink != NULL) && (mixBuffer != NULL)) {
417 if (mixBufferState == UNDEFINED) {
418 memset(mixBuffer, 0, frameCount * 2 * sizeof(short));
419 mixBufferState = ZEROED;
420 }
Glenn Kastenfbae5da2012-05-21 09:17:20 -0700421 if (teeSink != NULL) {
422 (void) teeSink->write(mixBuffer, frameCount);
423 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700424 // FIXME write() is non-blocking and lock-free for a properly implemented NBAIO sink,
425 // but this code should be modified to handle both non-blocking and blocking sinks
426 dumpState->mWriteSequence++;
Glenn Kasten99c99d02012-05-14 16:37:13 -0700427#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Glenn Kastend8e6fd32012-05-07 11:07:57 -0700428 Tracer::traceBegin(ATRACE_TAG, "write");
Glenn Kasten99c99d02012-05-14 16:37:13 -0700429#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700430 ssize_t framesWritten = outputSink->write(mixBuffer, frameCount);
Glenn Kasten99c99d02012-05-14 16:37:13 -0700431#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Glenn Kastend8e6fd32012-05-07 11:07:57 -0700432 Tracer::traceEnd(ATRACE_TAG);
Glenn Kasten99c99d02012-05-14 16:37:13 -0700433#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700434 dumpState->mWriteSequence++;
435 if (framesWritten >= 0) {
Glenn Kasten288ed212012-04-25 17:52:27 -0700436 ALOG_ASSERT(framesWritten <= frameCount);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700437 dumpState->mFramesWritten += framesWritten;
Glenn Kasten288ed212012-04-25 17:52:27 -0700438 //if ((size_t) framesWritten == frameCount) {
439 // didFullWrite = true;
440 //}
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700441 } else {
442 dumpState->mWriteErrors++;
443 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700444 attemptedWrite = true;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700445 // FIXME count # of writes blocked excessively, CPU usage, etc. for dump
446 }
447
448 // To be exactly periodic, compute the next sleep time based on current time.
449 // This code doesn't have long-term stability when the sink is non-blocking.
450 // FIXME To avoid drift, use the local audio clock or watch the sink's fill status.
451 struct timespec newTs;
452 int rc = clock_gettime(CLOCK_MONOTONIC, &newTs);
453 if (rc == 0) {
454 if (oldTsValid) {
455 time_t sec = newTs.tv_sec - oldTs.tv_sec;
456 long nsec = newTs.tv_nsec - oldTs.tv_nsec;
457 if (nsec < 0) {
458 --sec;
459 nsec += 1000000000;
460 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700461 // To avoid an initial underrun on fast tracks after exiting standby,
462 // do not start pulling data from tracks and mixing until warmup is complete.
463 // Warmup is considered complete after the earlier of:
Glenn Kasteneb157162012-06-13 14:59:07 -0700464 // MIN_WARMUP_CYCLES write() attempts and last one blocks for at least warmupNs
Glenn Kasten288ed212012-04-25 17:52:27 -0700465 // MAX_WARMUP_CYCLES write() attempts.
466 // This is overly conservative, but to get better accuracy requires a new HAL API.
467 if (!isWarm && attemptedWrite) {
468 measuredWarmupTs.tv_sec += sec;
469 measuredWarmupTs.tv_nsec += nsec;
470 if (measuredWarmupTs.tv_nsec >= 1000000000) {
471 measuredWarmupTs.tv_sec++;
472 measuredWarmupTs.tv_nsec -= 1000000000;
473 }
474 ++warmupCycles;
Glenn Kasteneb157162012-06-13 14:59:07 -0700475 if ((nsec > warmupNs && warmupCycles >= MIN_WARMUP_CYCLES) ||
Glenn Kasten288ed212012-04-25 17:52:27 -0700476 (warmupCycles >= MAX_WARMUP_CYCLES)) {
477 isWarm = true;
478 dumpState->mMeasuredWarmupTs = measuredWarmupTs;
479 dumpState->mWarmupCycles = warmupCycles;
480 }
481 }
Glenn Kasten972af222012-06-13 17:14:03 -0700482 sleepNs = -1;
483 if (isWarm) {
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700484 if (sec > 0 || nsec > underrunNs) {
Glenn Kasten99c99d02012-05-14 16:37:13 -0700485#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Glenn Kastend8e6fd32012-05-07 11:07:57 -0700486 ScopedTrace st(ATRACE_TAG, "underrun");
Glenn Kasten99c99d02012-05-14 16:37:13 -0700487#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700488 // FIXME only log occasionally
489 ALOGV("underrun: time since last cycle %d.%03ld sec",
490 (int) sec, nsec / 1000000L);
491 dumpState->mUnderruns++;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700492 ignoreNextOverrun = true;
493 } else if (nsec < overrunNs) {
494 if (ignoreNextOverrun) {
495 ignoreNextOverrun = false;
496 } else {
497 // FIXME only log occasionally
498 ALOGV("overrun: time since last cycle %d.%03ld sec",
499 (int) sec, nsec / 1000000L);
500 dumpState->mOverruns++;
501 }
Glenn Kasten972af222012-06-13 17:14:03 -0700502 // This forces a minimum cycle time. It:
503 // - compensates for an audio HAL with jitter due to sample rate conversion
504 // - works with a variable buffer depth audio HAL that never pulls at a rate
505 // < than overrunNs per buffer.
506 // - recovers from overrun immediately after underrun
507 // It doesn't work with a non-blocking audio HAL.
508 sleepNs = forceNs - nsec;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700509 } else {
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700510 ignoreNextOverrun = false;
511 }
Glenn Kasten972af222012-06-13 17:14:03 -0700512 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700513#ifdef FAST_MIXER_STATISTICS
Glenn Kasteneb157162012-06-13 14:59:07 -0700514 if (isWarm) {
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700515 // advance the FIFO queue bounds
516 size_t i = bounds & (FastMixerDumpState::kSamplingN - 1);
Glenn Kastene58ccce2012-05-11 15:19:24 -0700517 bounds = (bounds & 0xFFFF0000) | ((bounds + 1) & 0xFFFF);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700518 if (full) {
519 bounds += 0x10000;
520 } else if (!(bounds & (FastMixerDumpState::kSamplingN - 1))) {
521 full = true;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700522 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700523 // compute the delta value of clock_gettime(CLOCK_MONOTONIC)
524 uint32_t monotonicNs = nsec;
525 if (sec > 0 && sec < 4) {
526 monotonicNs += sec * 1000000000;
527 }
528 // compute the raw CPU load = delta value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
529 uint32_t loadNs = 0;
530 struct timespec newLoad;
531 rc = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &newLoad);
532 if (rc == 0) {
533 if (oldLoadValid) {
534 sec = newLoad.tv_sec - oldLoad.tv_sec;
535 nsec = newLoad.tv_nsec - oldLoad.tv_nsec;
536 if (nsec < 0) {
537 --sec;
538 nsec += 1000000000;
539 }
540 loadNs = nsec;
541 if (sec > 0 && sec < 4) {
542 loadNs += sec * 1000000000;
543 }
544 } else {
545 // first time through the loop
546 oldLoadValid = true;
547 }
548 oldLoad = newLoad;
549 }
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700550#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700551 // get the absolute value of CPU clock frequency in kHz
552 int cpuNum = sched_getcpu();
553 uint32_t kHz = tcu.getCpukHz(cpuNum);
Glenn Kastenc059bd42012-05-14 17:41:09 -0700554 kHz = (kHz << 4) | (cpuNum & 0xF);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700555#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700556 // save values in FIFO queues for dumpsys
557 // these stores #1, #2, #3 are not atomic with respect to each other,
558 // or with respect to store #4 below
559 dumpState->mMonotonicNs[i] = monotonicNs;
560 dumpState->mLoadNs[i] = loadNs;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700561#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700562 dumpState->mCpukHz[i] = kHz;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700563#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700564 // this store #4 is not atomic with respect to stores #1, #2, #3 above, but
565 // the newest open and oldest closed halves are atomic with respect to each other
566 dumpState->mBounds = bounds;
Glenn Kasten99c99d02012-05-14 16:37:13 -0700567#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
568 ATRACE_INT("cycle_ms", monotonicNs / 1000000);
569 ATRACE_INT("load_us", loadNs / 1000);
570#endif
Glenn Kasteneb157162012-06-13 14:59:07 -0700571 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700572#endif
573 } else {
574 // first time through the loop
575 oldTsValid = true;
576 sleepNs = periodNs;
577 ignoreNextOverrun = true;
578 }
579 oldTs = newTs;
580 } else {
581 // monotonic clock is broken
582 oldTsValid = false;
583 sleepNs = periodNs;
584 }
585
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700586
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700587 } // for (;;)
588
589 // never return 'true'; Thread::_threadLoop() locks mutex which can result in priority inversion
590}
591
592FastMixerDumpState::FastMixerDumpState() :
593 mCommand(FastMixerState::INITIAL), mWriteSequence(0), mFramesWritten(0),
Glenn Kasten21e8c502012-04-12 09:39:42 -0700594 mNumTracks(0), mWriteErrors(0), mUnderruns(0), mOverruns(0),
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700595 mSampleRate(0), mFrameCount(0), /* mMeasuredWarmupTs({0, 0}), */ mWarmupCycles(0),
596 mTrackMask(0)
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700597#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700598 , mBounds(0)
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700599#endif
600{
Glenn Kasten288ed212012-04-25 17:52:27 -0700601 mMeasuredWarmupTs.tv_sec = 0;
602 mMeasuredWarmupTs.tv_nsec = 0;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700603 // sample arrays aren't accessed atomically with respect to the bounds,
604 // so clearing reduces chance for dumpsys to read random uninitialized samples
605 memset(&mMonotonicNs, 0, sizeof(mMonotonicNs));
606 memset(&mLoadNs, 0, sizeof(mLoadNs));
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700607#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700608 memset(&mCpukHz, 0, sizeof(mCpukHz));
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700609#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700610}
611
612FastMixerDumpState::~FastMixerDumpState()
613{
614}
615
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700616// helper function called by qsort()
617static int compare_uint32_t(const void *pa, const void *pb)
618{
619 uint32_t a = *(const uint32_t *)pa;
620 uint32_t b = *(const uint32_t *)pb;
621 if (a < b) {
622 return -1;
623 } else if (a > b) {
624 return 1;
625 } else {
626 return 0;
627 }
628}
629
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700630void FastMixerDumpState::dump(int fd)
631{
Glenn Kasten868c0ab2012-06-13 14:59:17 -0700632 if (mCommand == FastMixerState::INITIAL) {
633 fdprintf(fd, "FastMixer not initialized\n");
634 return;
635 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700636#define COMMAND_MAX 32
637 char string[COMMAND_MAX];
638 switch (mCommand) {
639 case FastMixerState::INITIAL:
640 strcpy(string, "INITIAL");
641 break;
642 case FastMixerState::HOT_IDLE:
643 strcpy(string, "HOT_IDLE");
644 break;
645 case FastMixerState::COLD_IDLE:
646 strcpy(string, "COLD_IDLE");
647 break;
648 case FastMixerState::EXIT:
649 strcpy(string, "EXIT");
650 break;
651 case FastMixerState::MIX:
652 strcpy(string, "MIX");
653 break;
654 case FastMixerState::WRITE:
655 strcpy(string, "WRITE");
656 break;
657 case FastMixerState::MIX_WRITE:
658 strcpy(string, "MIX_WRITE");
659 break;
660 default:
661 snprintf(string, COMMAND_MAX, "%d", mCommand);
662 break;
663 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700664 double measuredWarmupMs = (mMeasuredWarmupTs.tv_sec * 1000.0) +
Glenn Kasten288ed212012-04-25 17:52:27 -0700665 (mMeasuredWarmupTs.tv_nsec / 1000000.0);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700666 double mixPeriodSec = (double) mFrameCount / (double) mSampleRate;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700667 fdprintf(fd, "FastMixer command=%s writeSequence=%u framesWritten=%u\n"
Glenn Kasten21e8c502012-04-12 09:39:42 -0700668 " numTracks=%u writeErrors=%u underruns=%u overruns=%u\n"
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700669 " sampleRate=%u frameCount=%u measuredWarmup=%.3g ms, warmupCycles=%u\n"
670 " mixPeriod=%.2f ms\n",
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700671 string, mWriteSequence, mFramesWritten,
Glenn Kasten21e8c502012-04-12 09:39:42 -0700672 mNumTracks, mWriteErrors, mUnderruns, mOverruns,
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700673 mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles,
674 mixPeriodSec * 1e3);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700675#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700676 // find the interval of valid samples
677 uint32_t bounds = mBounds;
678 uint32_t newestOpen = bounds & 0xFFFF;
679 uint32_t oldestClosed = bounds >> 16;
680 uint32_t n = (newestOpen - oldestClosed) & 0xFFFF;
681 if (n > kSamplingN) {
682 ALOGE("too many samples %u", n);
683 n = kSamplingN;
684 }
685 // statistics for monotonic (wall clock) time, thread raw CPU load in time, CPU clock frequency,
686 // and adjusted CPU load in MHz normalized for CPU clock frequency
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700687 CentralTendencyStatistics wall, loadNs;
688#ifdef CPU_FREQUENCY_STATISTICS
689 CentralTendencyStatistics kHz, loadMHz;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700690 uint32_t previousCpukHz = 0;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700691#endif
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700692 // Assuming a normal distribution for cycle times, three standard deviations on either side of
693 // the mean account for 99.73% of the population. So if we take each tail to be 1/1000 of the
694 // sample set, we get 99.8% combined, or close to three standard deviations.
695 static const uint32_t kTailDenominator = 1000;
696 uint32_t *tail = n >= kTailDenominator ? new uint32_t[n] : NULL;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700697 // loop over all the samples
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700698 for (uint32_t j = 0; j < n; ++j) {
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700699 size_t i = oldestClosed++ & (kSamplingN - 1);
700 uint32_t wallNs = mMonotonicNs[i];
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700701 if (tail != NULL) {
702 tail[j] = wallNs;
703 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700704 wall.sample(wallNs);
705 uint32_t sampleLoadNs = mLoadNs[i];
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700706 loadNs.sample(sampleLoadNs);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700707#ifdef CPU_FREQUENCY_STATISTICS
708 uint32_t sampleCpukHz = mCpukHz[i];
Glenn Kastenc059bd42012-05-14 17:41:09 -0700709 // skip bad kHz samples
710 if ((sampleCpukHz & ~0xF) != 0) {
711 kHz.sample(sampleCpukHz >> 4);
712 if (sampleCpukHz == previousCpukHz) {
713 double megacycles = (double) sampleLoadNs * (double) (sampleCpukHz >> 4) * 1e-12;
714 double adjMHz = megacycles / mixPeriodSec; // _not_ wallNs * 1e9
715 loadMHz.sample(adjMHz);
716 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700717 }
718 previousCpukHz = sampleCpukHz;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700719#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700720 }
721 fdprintf(fd, "Simple moving statistics over last %.1f seconds:\n", wall.n() * mixPeriodSec);
722 fdprintf(fd, " wall clock time in ms per mix cycle:\n"
723 " mean=%.2f min=%.2f max=%.2f stddev=%.2f\n",
724 wall.mean()*1e-6, wall.minimum()*1e-6, wall.maximum()*1e-6, wall.stddev()*1e-6);
725 fdprintf(fd, " raw CPU load in us per mix cycle:\n"
726 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
727 loadNs.mean()*1e-3, loadNs.minimum()*1e-3, loadNs.maximum()*1e-3,
728 loadNs.stddev()*1e-3);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700729#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700730 fdprintf(fd, " CPU clock frequency in MHz:\n"
731 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
732 kHz.mean()*1e-3, kHz.minimum()*1e-3, kHz.maximum()*1e-3, kHz.stddev()*1e-3);
733 fdprintf(fd, " adjusted CPU load in MHz (i.e. normalized for CPU clock frequency):\n"
734 " mean=%.1f min=%.1f max=%.1f stddev=%.1f\n",
735 loadMHz.mean(), loadMHz.minimum(), loadMHz.maximum(), loadMHz.stddev());
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700736#endif
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700737 if (tail != NULL) {
738 qsort(tail, n, sizeof(uint32_t), compare_uint32_t);
739 // assume same number of tail samples on each side, left and right
740 uint32_t count = n / kTailDenominator;
741 CentralTendencyStatistics left, right;
742 for (uint32_t i = 0; i < count; ++i) {
743 left.sample(tail[i]);
744 right.sample(tail[n - (i + 1)]);
745 }
746 fdprintf(fd, "Distribution of mix cycle times in ms for the tails (> ~3 stddev outliers):\n"
747 " left tail: mean=%.2f min=%.2f max=%.2f stddev=%.2f\n"
748 " right tail: mean=%.2f min=%.2f max=%.2f stddev=%.2f\n",
749 left.mean()*1e-6, left.minimum()*1e-6, left.maximum()*1e-6, left.stddev()*1e-6,
750 right.mean()*1e-6, right.minimum()*1e-6, right.maximum()*1e-6,
751 right.stddev()*1e-6);
752 delete[] tail;
753 }
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700754#endif
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700755 // The active track mask and track states are updated non-atomically.
756 // So if we relied on isActive to decide whether to display,
757 // then we might display an obsolete track or omit an active track.
758 // Instead we always display all tracks, with an indication
759 // of whether we think the track is active.
760 uint32_t trackMask = mTrackMask;
761 fdprintf(fd, "Fast tracks: kMaxFastTracks=%u activeMask=%#x\n",
762 FastMixerState::kMaxFastTracks, trackMask);
763 fdprintf(fd, "Index Active Full Partial Empty Recent Ready\n");
764 for (uint32_t i = 0; i < FastMixerState::kMaxFastTracks; ++i, trackMask >>= 1) {
765 bool isActive = trackMask & 1;
766 const FastTrackDump *ftDump = &mTracks[i];
767 const FastTrackUnderruns& underruns = ftDump->mUnderruns;
768 const char *mostRecent;
769 switch (underruns.mBitFields.mMostRecent) {
770 case UNDERRUN_FULL:
771 mostRecent = "full";
772 break;
773 case UNDERRUN_PARTIAL:
774 mostRecent = "partial";
775 break;
776 case UNDERRUN_EMPTY:
777 mostRecent = "empty";
778 break;
779 default:
780 mostRecent = "?";
781 break;
782 }
783 fdprintf(fd, "%5u %6s %4u %7u %5u %7s %5u\n", i, isActive ? "yes" : "no",
784 (underruns.mBitFields.mFull) & UNDERRUN_MASK,
785 (underruns.mBitFields.mPartial) & UNDERRUN_MASK,
786 (underruns.mBitFields.mEmpty) & UNDERRUN_MASK,
787 mostRecent, ftDump->mFramesReady);
788 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700789}
790
791} // namespace android