blob: 19ee9b34046fc1f6362e2b091bf97f653cc121e9 [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 Kasten288ed212012-04-25 17:52:27 -070036#define MAX_WARMUP_CYCLES 10 // maximum number of loop cycles to wait for warmup
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070037
38namespace android {
39
40// Fast mixer thread
41bool FastMixer::threadLoop()
42{
43 static const FastMixerState initial;
44 const FastMixerState *previous = &initial, *current = &initial;
45 FastMixerState preIdle; // copy of state before we went into idle
46 struct timespec oldTs = {0, 0};
47 bool oldTsValid = false;
48 long slopNs = 0; // accumulated time we've woken up too early (> 0) or too late (< 0)
49 long sleepNs = -1; // -1: busy wait, 0: sched_yield, > 0: nanosleep
50 int fastTrackNames[FastMixerState::kMaxFastTracks]; // handles used by mixer to identify tracks
51 int generations[FastMixerState::kMaxFastTracks]; // last observed mFastTracks[i].mGeneration
52 unsigned i;
53 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
54 fastTrackNames[i] = -1;
55 generations[i] = 0;
56 }
57 NBAIO_Sink *outputSink = NULL;
58 int outputSinkGen = 0;
59 AudioMixer* mixer = NULL;
60 short *mixBuffer = NULL;
61 enum {UNDEFINED, MIXED, ZEROED} mixBufferState = UNDEFINED;
62 NBAIO_Format format = Format_Invalid;
63 unsigned sampleRate = 0;
64 int fastTracksGen = 0;
65 long periodNs = 0; // expected period; the time required to render one mix buffer
Glenn Kasten288ed212012-04-25 17:52:27 -070066 long underrunNs = 0; // underrun likely when write cycle is greater than this value
67 long overrunNs = 0; // overrun likely when write cycle is less than this value
68 long warmupNs = 0; // warmup complete when write cycle is greater than to this value
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070069 FastMixerDumpState dummyDumpState, *dumpState = &dummyDumpState;
70 bool ignoreNextOverrun = true; // used to ignore initial overrun and first after an underrun
71#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070072 struct timespec oldLoad = {0, 0}; // previous value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
73 bool oldLoadValid = false; // whether oldLoad is valid
74 uint32_t bounds = 0;
75 bool full = false; // whether we have collected at least kSamplingN samples
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070076#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070077 ThreadCpuUsage tcu; // for reading the current CPU clock frequency in kHz
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070078#endif
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070079#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070080 unsigned coldGen = 0; // last observed mColdGen
Glenn Kasten288ed212012-04-25 17:52:27 -070081 bool isWarm = false; // true means ready to mix, false means wait for warmup before mixing
82 struct timespec measuredWarmupTs = {0, 0}; // how long did it take for warmup to complete
83 uint32_t warmupCycles = 0; // counter of number of loop cycles required to warmup
Glenn Kastenfbae5da2012-05-21 09:17:20 -070084 NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070085
86 for (;;) {
87
88 // either nanosleep, sched_yield, or busy wait
89 if (sleepNs >= 0) {
90 if (sleepNs > 0) {
91 ALOG_ASSERT(sleepNs < 1000000000);
92 const struct timespec req = {0, sleepNs};
93 nanosleep(&req, NULL);
94 } else {
95 sched_yield();
96 }
97 }
98 // default to long sleep for next cycle
99 sleepNs = FAST_DEFAULT_NS;
100
101 // poll for state change
102 const FastMixerState *next = mSQ.poll();
103 if (next == NULL) {
104 // continue to use the default initial state until a real state is available
105 ALOG_ASSERT(current == &initial && previous == &initial);
106 next = current;
107 }
108
109 FastMixerState::Command command = next->mCommand;
110 if (next != current) {
111
112 // As soon as possible of learning of a new dump area, start using it
113 dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
Glenn Kastenfbae5da2012-05-21 09:17:20 -0700114 teeSink = next->mTeeSink;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700115
116 // We want to always have a valid reference to the previous (non-idle) state.
117 // However, the state queue only guarantees access to current and previous states.
118 // So when there is a transition from a non-idle state into an idle state, we make a
119 // copy of the last known non-idle state so it is still available on return from idle.
120 // The possible transitions are:
121 // non-idle -> non-idle update previous from current in-place
122 // non-idle -> idle update previous from copy of current
123 // idle -> idle don't update previous
124 // idle -> non-idle don't update previous
125 if (!(current->mCommand & FastMixerState::IDLE)) {
126 if (command & FastMixerState::IDLE) {
127 preIdle = *current;
128 current = &preIdle;
129 oldTsValid = false;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700130 oldLoadValid = false;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700131 ignoreNextOverrun = true;
132 }
133 previous = current;
134 }
135 current = next;
136 }
137#if !LOG_NDEBUG
138 next = NULL; // not referenced again
139#endif
140
141 dumpState->mCommand = command;
142
143 switch (command) {
144 case FastMixerState::INITIAL:
145 case FastMixerState::HOT_IDLE:
146 sleepNs = FAST_HOT_IDLE_NS;
147 continue;
148 case FastMixerState::COLD_IDLE:
149 // only perform a cold idle command once
Glenn Kasten21e8c502012-04-12 09:39:42 -0700150 // FIXME consider checking previous state and only perform if previous != COLD_IDLE
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700151 if (current->mColdGen != coldGen) {
152 int32_t *coldFutexAddr = current->mColdFutexAddr;
153 ALOG_ASSERT(coldFutexAddr != NULL);
154 int32_t old = android_atomic_dec(coldFutexAddr);
155 if (old <= 0) {
156 __futex_syscall4(coldFutexAddr, FUTEX_WAIT_PRIVATE, old - 1, NULL);
157 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700158 // This may be overly conservative; there could be times that the normal mixer
159 // requests such a brief cold idle that it doesn't require resetting this flag.
160 isWarm = false;
161 measuredWarmupTs.tv_sec = 0;
162 measuredWarmupTs.tv_nsec = 0;
163 warmupCycles = 0;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700164 sleepNs = -1;
165 coldGen = current->mColdGen;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700166 bounds = 0;
167 full = false;
Glenn Kasten04a4ca42012-06-01 10:49:51 -0700168 oldTsValid = !clock_gettime(CLOCK_MONOTONIC, &oldTs);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700169 } else {
170 sleepNs = FAST_HOT_IDLE_NS;
171 }
172 continue;
173 case FastMixerState::EXIT:
174 delete mixer;
175 delete[] mixBuffer;
176 return false;
177 case FastMixerState::MIX:
178 case FastMixerState::WRITE:
179 case FastMixerState::MIX_WRITE:
180 break;
181 default:
182 LOG_FATAL("bad command %d", command);
183 }
184
185 // there is a non-idle state available to us; did the state change?
186 size_t frameCount = current->mFrameCount;
187 if (current != previous) {
188
189 // handle state change here, but since we want to diff the state,
190 // we're prepared for previous == &initial the first time through
191 unsigned previousTrackMask;
192
193 // check for change in output HAL configuration
194 NBAIO_Format previousFormat = format;
195 if (current->mOutputSinkGen != outputSinkGen) {
196 outputSink = current->mOutputSink;
197 outputSinkGen = current->mOutputSinkGen;
198 if (outputSink == NULL) {
199 format = Format_Invalid;
200 sampleRate = 0;
201 } else {
202 format = outputSink->format();
203 sampleRate = Format_sampleRate(format);
204 ALOG_ASSERT(Format_channelCount(format) == 2);
205 }
Glenn Kasten21e8c502012-04-12 09:39:42 -0700206 dumpState->mSampleRate = sampleRate;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700207 }
208
209 if ((format != previousFormat) || (frameCount != previous->mFrameCount)) {
210 // FIXME to avoid priority inversion, don't delete here
211 delete mixer;
212 mixer = NULL;
213 delete[] mixBuffer;
214 mixBuffer = NULL;
215 if (frameCount > 0 && sampleRate > 0) {
216 // FIXME new may block for unbounded time at internal mutex of the heap
217 // implementation; it would be better to have normal mixer allocate for us
218 // to avoid blocking here and to prevent possible priority inversion
219 mixer = new AudioMixer(frameCount, sampleRate, FastMixerState::kMaxFastTracks);
220 mixBuffer = new short[frameCount * 2];
221 periodNs = (frameCount * 1000000000LL) / sampleRate; // 1.00
222 underrunNs = (frameCount * 1750000000LL) / sampleRate; // 1.75
223 overrunNs = (frameCount * 250000000LL) / sampleRate; // 0.25
Glenn Kasten288ed212012-04-25 17:52:27 -0700224 warmupNs = (frameCount * 500000000LL) / sampleRate; // 0.50
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700225 } else {
226 periodNs = 0;
227 underrunNs = 0;
228 overrunNs = 0;
229 }
230 mixBufferState = UNDEFINED;
231#if !LOG_NDEBUG
232 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
233 fastTrackNames[i] = -1;
234 }
235#endif
236 // we need to reconfigure all active tracks
237 previousTrackMask = 0;
238 fastTracksGen = current->mFastTracksGen - 1;
Glenn Kasten21e8c502012-04-12 09:39:42 -0700239 dumpState->mFrameCount = frameCount;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700240 } else {
241 previousTrackMask = previous->mTrackMask;
242 }
243
244 // check for change in active track set
245 unsigned currentTrackMask = current->mTrackMask;
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700246 dumpState->mTrackMask = currentTrackMask;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700247 if (current->mFastTracksGen != fastTracksGen) {
248 ALOG_ASSERT(mixBuffer != NULL);
249 int name;
250
251 // process removed tracks first to avoid running out of track names
252 unsigned removedTracks = previousTrackMask & ~currentTrackMask;
253 while (removedTracks != 0) {
254 i = __builtin_ctz(removedTracks);
255 removedTracks &= ~(1 << i);
256 const FastTrack* fastTrack = &current->mFastTracks[i];
Glenn Kasten288ed212012-04-25 17:52:27 -0700257 ALOG_ASSERT(fastTrack->mBufferProvider == NULL);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700258 if (mixer != NULL) {
259 name = fastTrackNames[i];
260 ALOG_ASSERT(name >= 0);
261 mixer->deleteTrackName(name);
262 }
263#if !LOG_NDEBUG
264 fastTrackNames[i] = -1;
265#endif
Glenn Kasten288ed212012-04-25 17:52:27 -0700266 // don't reset track dump state, since other side is ignoring it
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700267 generations[i] = fastTrack->mGeneration;
268 }
269
270 // now process added tracks
271 unsigned addedTracks = currentTrackMask & ~previousTrackMask;
272 while (addedTracks != 0) {
273 i = __builtin_ctz(addedTracks);
274 addedTracks &= ~(1 << i);
275 const FastTrack* fastTrack = &current->mFastTracks[i];
276 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
277 ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);
278 if (mixer != NULL) {
Jean-Michel Trivi9bd23222012-04-16 13:43:48 -0700279 // calling getTrackName with default channel mask
280 name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700281 ALOG_ASSERT(name >= 0);
282 fastTrackNames[i] = name;
283 mixer->setBufferProvider(name, bufferProvider);
284 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,
285 (void *) mixBuffer);
286 // newly allocated track names default to full scale volume
Glenn Kasten21e8c502012-04-12 09:39:42 -0700287 if (fastTrack->mSampleRate != 0 && fastTrack->mSampleRate != sampleRate) {
288 mixer->setParameter(name, AudioMixer::RESAMPLE,
289 AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate);
290 }
291 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
292 (void *) fastTrack->mChannelMask);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700293 mixer->enable(name);
294 }
295 generations[i] = fastTrack->mGeneration;
296 }
297
298 // finally process modified tracks; these use the same slot
299 // but may have a different buffer provider or volume provider
300 unsigned modifiedTracks = currentTrackMask & previousTrackMask;
301 while (modifiedTracks != 0) {
302 i = __builtin_ctz(modifiedTracks);
303 modifiedTracks &= ~(1 << i);
304 const FastTrack* fastTrack = &current->mFastTracks[i];
305 if (fastTrack->mGeneration != generations[i]) {
306 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
307 ALOG_ASSERT(bufferProvider != NULL);
308 if (mixer != NULL) {
309 name = fastTrackNames[i];
310 ALOG_ASSERT(name >= 0);
311 mixer->setBufferProvider(name, bufferProvider);
312 if (fastTrack->mVolumeProvider == NULL) {
313 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
314 (void *)0x1000);
315 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
316 (void *)0x1000);
317 }
Glenn Kasten21e8c502012-04-12 09:39:42 -0700318 if (fastTrack->mSampleRate != 0 &&
319 fastTrack->mSampleRate != sampleRate) {
320 mixer->setParameter(name, AudioMixer::RESAMPLE,
321 AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate);
322 } else {
323 mixer->setParameter(name, AudioMixer::RESAMPLE,
324 AudioMixer::REMOVE, NULL);
325 }
326 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
327 (void *) fastTrack->mChannelMask);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700328 // already enabled
329 }
330 generations[i] = fastTrack->mGeneration;
331 }
332 }
333
334 fastTracksGen = current->mFastTracksGen;
335
336 dumpState->mNumTracks = popcount(currentTrackMask);
337 }
338
339#if 1 // FIXME shouldn't need this
340 // only process state change once
341 previous = current;
342#endif
343 }
344
345 // do work using current state here
Glenn Kasten288ed212012-04-25 17:52:27 -0700346 if ((command & FastMixerState::MIX) && (mixer != NULL) && isWarm) {
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700347 ALOG_ASSERT(mixBuffer != NULL);
Glenn Kasten288ed212012-04-25 17:52:27 -0700348 // for each track, update volume and check for underrun
349 unsigned currentTrackMask = current->mTrackMask;
350 while (currentTrackMask != 0) {
351 i = __builtin_ctz(currentTrackMask);
352 currentTrackMask &= ~(1 << i);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700353 const FastTrack* fastTrack = &current->mFastTracks[i];
354 int name = fastTrackNames[i];
355 ALOG_ASSERT(name >= 0);
356 if (fastTrack->mVolumeProvider != NULL) {
357 uint32_t vlr = fastTrack->mVolumeProvider->getVolumeLR();
358 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
359 (void *)(vlr & 0xFFFF));
360 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
361 (void *)(vlr >> 16));
362 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700363 // FIXME The current implementation of framesReady() for fast tracks
364 // takes a tryLock, which can block
365 // up to 1 ms. If enough active tracks all blocked in sequence, this would result
366 // in the overall fast mix cycle being delayed. Should use a non-blocking FIFO.
367 size_t framesReady = fastTrack->mBufferProvider->framesReady();
Glenn Kasten99c99d02012-05-14 16:37:13 -0700368#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
369 // I wish we had formatted trace names
370 char traceName[16];
371 strcpy(traceName, "framesReady");
372 traceName[11] = i + (i < 10 ? '0' : 'A' - 10);
373 traceName[12] = '\0';
374 ATRACE_INT(traceName, framesReady);
375#endif
Glenn Kasten288ed212012-04-25 17:52:27 -0700376 FastTrackDump *ftDump = &dumpState->mTracks[i];
Glenn Kasten09474df2012-05-10 14:48:07 -0700377 FastTrackUnderruns underruns = ftDump->mUnderruns;
Glenn Kasten288ed212012-04-25 17:52:27 -0700378 if (framesReady < frameCount) {
Glenn Kasten288ed212012-04-25 17:52:27 -0700379 if (framesReady == 0) {
Glenn Kasten09474df2012-05-10 14:48:07 -0700380 underruns.mBitFields.mEmpty++;
381 underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;
Glenn Kasten288ed212012-04-25 17:52:27 -0700382 mixer->disable(name);
383 } else {
384 // allow mixing partial buffer
Glenn Kasten09474df2012-05-10 14:48:07 -0700385 underruns.mBitFields.mPartial++;
386 underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;
Glenn Kasten288ed212012-04-25 17:52:27 -0700387 mixer->enable(name);
388 }
Glenn Kasten09474df2012-05-10 14:48:07 -0700389 } else {
390 underruns.mBitFields.mFull++;
391 underruns.mBitFields.mMostRecent = UNDERRUN_FULL;
Glenn Kasten288ed212012-04-25 17:52:27 -0700392 mixer->enable(name);
393 }
Glenn Kasten09474df2012-05-10 14:48:07 -0700394 ftDump->mUnderruns = underruns;
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700395 ftDump->mFramesReady = framesReady;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700396 }
397 // process() is CPU-bound
398 mixer->process(AudioBufferProvider::kInvalidPTS);
399 mixBufferState = MIXED;
400 } else if (mixBufferState == MIXED) {
401 mixBufferState = UNDEFINED;
402 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700403 bool attemptedWrite = false;
404 //bool didFullWrite = false; // dumpsys could display a count of partial writes
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700405 if ((command & FastMixerState::WRITE) && (outputSink != NULL) && (mixBuffer != NULL)) {
406 if (mixBufferState == UNDEFINED) {
407 memset(mixBuffer, 0, frameCount * 2 * sizeof(short));
408 mixBufferState = ZEROED;
409 }
Glenn Kastenfbae5da2012-05-21 09:17:20 -0700410 if (teeSink != NULL) {
411 (void) teeSink->write(mixBuffer, frameCount);
412 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700413 // FIXME write() is non-blocking and lock-free for a properly implemented NBAIO sink,
414 // but this code should be modified to handle both non-blocking and blocking sinks
415 dumpState->mWriteSequence++;
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::traceBegin(ATRACE_TAG, "write");
Glenn Kasten99c99d02012-05-14 16:37:13 -0700418#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700419 ssize_t framesWritten = outputSink->write(mixBuffer, frameCount);
Glenn Kasten99c99d02012-05-14 16:37:13 -0700420#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Glenn Kastend8e6fd32012-05-07 11:07:57 -0700421 Tracer::traceEnd(ATRACE_TAG);
Glenn Kasten99c99d02012-05-14 16:37:13 -0700422#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700423 dumpState->mWriteSequence++;
424 if (framesWritten >= 0) {
Glenn Kasten288ed212012-04-25 17:52:27 -0700425 ALOG_ASSERT(framesWritten <= frameCount);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700426 dumpState->mFramesWritten += framesWritten;
Glenn Kasten288ed212012-04-25 17:52:27 -0700427 //if ((size_t) framesWritten == frameCount) {
428 // didFullWrite = true;
429 //}
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700430 } else {
431 dumpState->mWriteErrors++;
432 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700433 attemptedWrite = true;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700434 // FIXME count # of writes blocked excessively, CPU usage, etc. for dump
435 }
436
437 // To be exactly periodic, compute the next sleep time based on current time.
438 // This code doesn't have long-term stability when the sink is non-blocking.
439 // FIXME To avoid drift, use the local audio clock or watch the sink's fill status.
440 struct timespec newTs;
441 int rc = clock_gettime(CLOCK_MONOTONIC, &newTs);
442 if (rc == 0) {
443 if (oldTsValid) {
444 time_t sec = newTs.tv_sec - oldTs.tv_sec;
445 long nsec = newTs.tv_nsec - oldTs.tv_nsec;
446 if (nsec < 0) {
447 --sec;
448 nsec += 1000000000;
449 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700450 // To avoid an initial underrun on fast tracks after exiting standby,
451 // do not start pulling data from tracks and mixing until warmup is complete.
452 // Warmup is considered complete after the earlier of:
453 // first successful single write() that blocks for more than warmupNs
454 // MAX_WARMUP_CYCLES write() attempts.
455 // This is overly conservative, but to get better accuracy requires a new HAL API.
456 if (!isWarm && attemptedWrite) {
457 measuredWarmupTs.tv_sec += sec;
458 measuredWarmupTs.tv_nsec += nsec;
459 if (measuredWarmupTs.tv_nsec >= 1000000000) {
460 measuredWarmupTs.tv_sec++;
461 measuredWarmupTs.tv_nsec -= 1000000000;
462 }
463 ++warmupCycles;
464 if ((attemptedWrite && nsec > warmupNs) ||
465 (warmupCycles >= MAX_WARMUP_CYCLES)) {
466 isWarm = true;
467 dumpState->mMeasuredWarmupTs = measuredWarmupTs;
468 dumpState->mWarmupCycles = warmupCycles;
469 }
470 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700471 if (sec > 0 || nsec > underrunNs) {
Glenn Kasten99c99d02012-05-14 16:37:13 -0700472#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Glenn Kastend8e6fd32012-05-07 11:07:57 -0700473 ScopedTrace st(ATRACE_TAG, "underrun");
Glenn Kasten99c99d02012-05-14 16:37:13 -0700474#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700475 // FIXME only log occasionally
476 ALOGV("underrun: time since last cycle %d.%03ld sec",
477 (int) sec, nsec / 1000000L);
478 dumpState->mUnderruns++;
479 sleepNs = -1;
480 ignoreNextOverrun = true;
481 } else if (nsec < overrunNs) {
482 if (ignoreNextOverrun) {
483 ignoreNextOverrun = false;
484 } else {
485 // FIXME only log occasionally
486 ALOGV("overrun: time since last cycle %d.%03ld sec",
487 (int) sec, nsec / 1000000L);
488 dumpState->mOverruns++;
489 }
Eric Laurent9a0d82d2012-06-05 18:12:11 -0700490 // Code for non blocking audio HAL. Sleep time must be tuned to allow
491 // catching up after an underrun
492 // sleepNs = periodNs - overrunNs;
493 sleepNs = -1;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700494 } else {
495 sleepNs = -1;
496 ignoreNextOverrun = false;
497 }
498#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700499 // advance the FIFO queue bounds
500 size_t i = bounds & (FastMixerDumpState::kSamplingN - 1);
Glenn Kastene58ccce2012-05-11 15:19:24 -0700501 bounds = (bounds & 0xFFFF0000) | ((bounds + 1) & 0xFFFF);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700502 if (full) {
503 bounds += 0x10000;
504 } else if (!(bounds & (FastMixerDumpState::kSamplingN - 1))) {
505 full = true;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700506 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700507 // compute the delta value of clock_gettime(CLOCK_MONOTONIC)
508 uint32_t monotonicNs = nsec;
509 if (sec > 0 && sec < 4) {
510 monotonicNs += sec * 1000000000;
511 }
512 // compute the raw CPU load = delta value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
513 uint32_t loadNs = 0;
514 struct timespec newLoad;
515 rc = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &newLoad);
516 if (rc == 0) {
517 if (oldLoadValid) {
518 sec = newLoad.tv_sec - oldLoad.tv_sec;
519 nsec = newLoad.tv_nsec - oldLoad.tv_nsec;
520 if (nsec < 0) {
521 --sec;
522 nsec += 1000000000;
523 }
524 loadNs = nsec;
525 if (sec > 0 && sec < 4) {
526 loadNs += sec * 1000000000;
527 }
528 } else {
529 // first time through the loop
530 oldLoadValid = true;
531 }
532 oldLoad = newLoad;
533 }
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700534#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700535 // get the absolute value of CPU clock frequency in kHz
536 int cpuNum = sched_getcpu();
537 uint32_t kHz = tcu.getCpukHz(cpuNum);
Glenn Kastenc059bd42012-05-14 17:41:09 -0700538 kHz = (kHz << 4) | (cpuNum & 0xF);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700539#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700540 // save values in FIFO queues for dumpsys
541 // these stores #1, #2, #3 are not atomic with respect to each other,
542 // or with respect to store #4 below
543 dumpState->mMonotonicNs[i] = monotonicNs;
544 dumpState->mLoadNs[i] = loadNs;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700545#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700546 dumpState->mCpukHz[i] = kHz;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700547#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700548 // this store #4 is not atomic with respect to stores #1, #2, #3 above, but
549 // the newest open and oldest closed halves are atomic with respect to each other
550 dumpState->mBounds = bounds;
Glenn Kasten99c99d02012-05-14 16:37:13 -0700551#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
552 ATRACE_INT("cycle_ms", monotonicNs / 1000000);
553 ATRACE_INT("load_us", loadNs / 1000);
554#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700555#endif
556 } else {
557 // first time through the loop
558 oldTsValid = true;
559 sleepNs = periodNs;
560 ignoreNextOverrun = true;
561 }
562 oldTs = newTs;
563 } else {
564 // monotonic clock is broken
565 oldTsValid = false;
566 sleepNs = periodNs;
567 }
568
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700569
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700570 } // for (;;)
571
572 // never return 'true'; Thread::_threadLoop() locks mutex which can result in priority inversion
573}
574
575FastMixerDumpState::FastMixerDumpState() :
576 mCommand(FastMixerState::INITIAL), mWriteSequence(0), mFramesWritten(0),
Glenn Kasten21e8c502012-04-12 09:39:42 -0700577 mNumTracks(0), mWriteErrors(0), mUnderruns(0), mOverruns(0),
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700578 mSampleRate(0), mFrameCount(0), /* mMeasuredWarmupTs({0, 0}), */ mWarmupCycles(0),
579 mTrackMask(0)
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700580#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700581 , mBounds(0)
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700582#endif
583{
Glenn Kasten288ed212012-04-25 17:52:27 -0700584 mMeasuredWarmupTs.tv_sec = 0;
585 mMeasuredWarmupTs.tv_nsec = 0;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700586 // sample arrays aren't accessed atomically with respect to the bounds,
587 // so clearing reduces chance for dumpsys to read random uninitialized samples
588 memset(&mMonotonicNs, 0, sizeof(mMonotonicNs));
589 memset(&mLoadNs, 0, sizeof(mLoadNs));
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700590#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700591 memset(&mCpukHz, 0, sizeof(mCpukHz));
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700592#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700593}
594
595FastMixerDumpState::~FastMixerDumpState()
596{
597}
598
599void FastMixerDumpState::dump(int fd)
600{
Glenn Kasten868c0ab2012-06-13 14:59:17 -0700601 if (mCommand == FastMixerState::INITIAL) {
602 fdprintf(fd, "FastMixer not initialized\n");
603 return;
604 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700605#define COMMAND_MAX 32
606 char string[COMMAND_MAX];
607 switch (mCommand) {
608 case FastMixerState::INITIAL:
609 strcpy(string, "INITIAL");
610 break;
611 case FastMixerState::HOT_IDLE:
612 strcpy(string, "HOT_IDLE");
613 break;
614 case FastMixerState::COLD_IDLE:
615 strcpy(string, "COLD_IDLE");
616 break;
617 case FastMixerState::EXIT:
618 strcpy(string, "EXIT");
619 break;
620 case FastMixerState::MIX:
621 strcpy(string, "MIX");
622 break;
623 case FastMixerState::WRITE:
624 strcpy(string, "WRITE");
625 break;
626 case FastMixerState::MIX_WRITE:
627 strcpy(string, "MIX_WRITE");
628 break;
629 default:
630 snprintf(string, COMMAND_MAX, "%d", mCommand);
631 break;
632 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700633 double measuredWarmupMs = (mMeasuredWarmupTs.tv_sec * 1000.0) +
Glenn Kasten288ed212012-04-25 17:52:27 -0700634 (mMeasuredWarmupTs.tv_nsec / 1000000.0);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700635 double mixPeriodSec = (double) mFrameCount / (double) mSampleRate;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700636 fdprintf(fd, "FastMixer command=%s writeSequence=%u framesWritten=%u\n"
Glenn Kasten21e8c502012-04-12 09:39:42 -0700637 " numTracks=%u writeErrors=%u underruns=%u overruns=%u\n"
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700638 " sampleRate=%u frameCount=%u measuredWarmup=%.3g ms, warmupCycles=%u\n"
639 " mixPeriod=%.2f ms\n",
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700640 string, mWriteSequence, mFramesWritten,
Glenn Kasten21e8c502012-04-12 09:39:42 -0700641 mNumTracks, mWriteErrors, mUnderruns, mOverruns,
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700642 mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles,
643 mixPeriodSec * 1e3);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700644#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700645 // find the interval of valid samples
646 uint32_t bounds = mBounds;
647 uint32_t newestOpen = bounds & 0xFFFF;
648 uint32_t oldestClosed = bounds >> 16;
649 uint32_t n = (newestOpen - oldestClosed) & 0xFFFF;
650 if (n > kSamplingN) {
651 ALOGE("too many samples %u", n);
652 n = kSamplingN;
653 }
654 // statistics for monotonic (wall clock) time, thread raw CPU load in time, CPU clock frequency,
655 // and adjusted CPU load in MHz normalized for CPU clock frequency
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700656 CentralTendencyStatistics wall, loadNs;
657#ifdef CPU_FREQUENCY_STATISTICS
658 CentralTendencyStatistics kHz, loadMHz;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700659 uint32_t previousCpukHz = 0;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700660#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700661 // loop over all the samples
662 for (; n > 0; --n) {
663 size_t i = oldestClosed++ & (kSamplingN - 1);
664 uint32_t wallNs = mMonotonicNs[i];
665 wall.sample(wallNs);
666 uint32_t sampleLoadNs = mLoadNs[i];
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700667 loadNs.sample(sampleLoadNs);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700668#ifdef CPU_FREQUENCY_STATISTICS
669 uint32_t sampleCpukHz = mCpukHz[i];
Glenn Kastenc059bd42012-05-14 17:41:09 -0700670 // skip bad kHz samples
671 if ((sampleCpukHz & ~0xF) != 0) {
672 kHz.sample(sampleCpukHz >> 4);
673 if (sampleCpukHz == previousCpukHz) {
674 double megacycles = (double) sampleLoadNs * (double) (sampleCpukHz >> 4) * 1e-12;
675 double adjMHz = megacycles / mixPeriodSec; // _not_ wallNs * 1e9
676 loadMHz.sample(adjMHz);
677 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700678 }
679 previousCpukHz = sampleCpukHz;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700680#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700681 }
682 fdprintf(fd, "Simple moving statistics over last %.1f seconds:\n", wall.n() * mixPeriodSec);
683 fdprintf(fd, " wall clock time in ms per mix cycle:\n"
684 " mean=%.2f min=%.2f max=%.2f stddev=%.2f\n",
685 wall.mean()*1e-6, wall.minimum()*1e-6, wall.maximum()*1e-6, wall.stddev()*1e-6);
686 fdprintf(fd, " raw CPU load in us per mix cycle:\n"
687 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
688 loadNs.mean()*1e-3, loadNs.minimum()*1e-3, loadNs.maximum()*1e-3,
689 loadNs.stddev()*1e-3);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700690#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700691 fdprintf(fd, " CPU clock frequency in MHz:\n"
692 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
693 kHz.mean()*1e-3, kHz.minimum()*1e-3, kHz.maximum()*1e-3, kHz.stddev()*1e-3);
694 fdprintf(fd, " adjusted CPU load in MHz (i.e. normalized for CPU clock frequency):\n"
695 " mean=%.1f min=%.1f max=%.1f stddev=%.1f\n",
696 loadMHz.mean(), loadMHz.minimum(), loadMHz.maximum(), loadMHz.stddev());
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700697#endif
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700698#endif
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700699 // The active track mask and track states are updated non-atomically.
700 // So if we relied on isActive to decide whether to display,
701 // then we might display an obsolete track or omit an active track.
702 // Instead we always display all tracks, with an indication
703 // of whether we think the track is active.
704 uint32_t trackMask = mTrackMask;
705 fdprintf(fd, "Fast tracks: kMaxFastTracks=%u activeMask=%#x\n",
706 FastMixerState::kMaxFastTracks, trackMask);
707 fdprintf(fd, "Index Active Full Partial Empty Recent Ready\n");
708 for (uint32_t i = 0; i < FastMixerState::kMaxFastTracks; ++i, trackMask >>= 1) {
709 bool isActive = trackMask & 1;
710 const FastTrackDump *ftDump = &mTracks[i];
711 const FastTrackUnderruns& underruns = ftDump->mUnderruns;
712 const char *mostRecent;
713 switch (underruns.mBitFields.mMostRecent) {
714 case UNDERRUN_FULL:
715 mostRecent = "full";
716 break;
717 case UNDERRUN_PARTIAL:
718 mostRecent = "partial";
719 break;
720 case UNDERRUN_EMPTY:
721 mostRecent = "empty";
722 break;
723 default:
724 mostRecent = "?";
725 break;
726 }
727 fdprintf(fd, "%5u %6s %4u %7u %5u %7s %5u\n", i, isActive ? "yes" : "no",
728 (underruns.mBitFields.mFull) & UNDERRUN_MASK,
729 (underruns.mBitFields.mPartial) & UNDERRUN_MASK,
730 (underruns.mBitFields.mEmpty) & UNDERRUN_MASK,
731 mostRecent, ftDump->mFramesReady);
732 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700733}
734
735} // namespace android