blob: 2c5d751241e1aeaa95684cb31b78a654d9324acc [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
Glenn Kasten972af222012-06-13 17:14:03 -070068 long forceNs = 0; // if overrun detected, force the write cycle to take this much time
Glenn Kasten288ed212012-04-25 17:52:27 -070069 long warmupNs = 0; // warmup complete when write cycle is greater than to this value
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070070 FastMixerDumpState dummyDumpState, *dumpState = &dummyDumpState;
71 bool ignoreNextOverrun = true; // used to ignore initial overrun and first after an underrun
72#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070073 struct timespec oldLoad = {0, 0}; // previous value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
74 bool oldLoadValid = false; // whether oldLoad is valid
75 uint32_t bounds = 0;
76 bool full = false; // whether we have collected at least kSamplingN samples
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070077#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070078 ThreadCpuUsage tcu; // for reading the current CPU clock frequency in kHz
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070079#endif
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070080#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070081 unsigned coldGen = 0; // last observed mColdGen
Glenn Kasten288ed212012-04-25 17:52:27 -070082 bool isWarm = false; // true means ready to mix, false means wait for warmup before mixing
83 struct timespec measuredWarmupTs = {0, 0}; // how long did it take for warmup to complete
84 uint32_t warmupCycles = 0; // counter of number of loop cycles required to warmup
Glenn Kastenfbae5da2012-05-21 09:17:20 -070085 NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070086
87 for (;;) {
88
89 // either nanosleep, sched_yield, or busy wait
90 if (sleepNs >= 0) {
91 if (sleepNs > 0) {
92 ALOG_ASSERT(sleepNs < 1000000000);
93 const struct timespec req = {0, sleepNs};
94 nanosleep(&req, NULL);
95 } else {
96 sched_yield();
97 }
98 }
99 // default to long sleep for next cycle
100 sleepNs = FAST_DEFAULT_NS;
101
102 // poll for state change
103 const FastMixerState *next = mSQ.poll();
104 if (next == NULL) {
105 // continue to use the default initial state until a real state is available
106 ALOG_ASSERT(current == &initial && previous == &initial);
107 next = current;
108 }
109
110 FastMixerState::Command command = next->mCommand;
111 if (next != current) {
112
113 // As soon as possible of learning of a new dump area, start using it
114 dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
Glenn Kastenfbae5da2012-05-21 09:17:20 -0700115 teeSink = next->mTeeSink;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700116
117 // We want to always have a valid reference to the previous (non-idle) state.
118 // However, the state queue only guarantees access to current and previous states.
119 // So when there is a transition from a non-idle state into an idle state, we make a
120 // copy of the last known non-idle state so it is still available on return from idle.
121 // The possible transitions are:
122 // non-idle -> non-idle update previous from current in-place
123 // non-idle -> idle update previous from copy of current
124 // idle -> idle don't update previous
125 // idle -> non-idle don't update previous
126 if (!(current->mCommand & FastMixerState::IDLE)) {
127 if (command & FastMixerState::IDLE) {
128 preIdle = *current;
129 current = &preIdle;
130 oldTsValid = false;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700131 oldLoadValid = false;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700132 ignoreNextOverrun = true;
133 }
134 previous = current;
135 }
136 current = next;
137 }
138#if !LOG_NDEBUG
139 next = NULL; // not referenced again
140#endif
141
142 dumpState->mCommand = command;
143
144 switch (command) {
145 case FastMixerState::INITIAL:
146 case FastMixerState::HOT_IDLE:
147 sleepNs = FAST_HOT_IDLE_NS;
148 continue;
149 case FastMixerState::COLD_IDLE:
150 // only perform a cold idle command once
Glenn Kasten21e8c502012-04-12 09:39:42 -0700151 // FIXME consider checking previous state and only perform if previous != COLD_IDLE
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700152 if (current->mColdGen != coldGen) {
153 int32_t *coldFutexAddr = current->mColdFutexAddr;
154 ALOG_ASSERT(coldFutexAddr != NULL);
155 int32_t old = android_atomic_dec(coldFutexAddr);
156 if (old <= 0) {
157 __futex_syscall4(coldFutexAddr, FUTEX_WAIT_PRIVATE, old - 1, NULL);
158 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700159 // This may be overly conservative; there could be times that the normal mixer
160 // requests such a brief cold idle that it doesn't require resetting this flag.
161 isWarm = false;
162 measuredWarmupTs.tv_sec = 0;
163 measuredWarmupTs.tv_nsec = 0;
164 warmupCycles = 0;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700165 sleepNs = -1;
166 coldGen = current->mColdGen;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700167 bounds = 0;
168 full = false;
Glenn Kasten04a4ca42012-06-01 10:49:51 -0700169 oldTsValid = !clock_gettime(CLOCK_MONOTONIC, &oldTs);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700170 } else {
171 sleepNs = FAST_HOT_IDLE_NS;
172 }
173 continue;
174 case FastMixerState::EXIT:
175 delete mixer;
176 delete[] mixBuffer;
177 return false;
178 case FastMixerState::MIX:
179 case FastMixerState::WRITE:
180 case FastMixerState::MIX_WRITE:
181 break;
182 default:
183 LOG_FATAL("bad command %d", command);
184 }
185
186 // there is a non-idle state available to us; did the state change?
187 size_t frameCount = current->mFrameCount;
188 if (current != previous) {
189
190 // handle state change here, but since we want to diff the state,
191 // we're prepared for previous == &initial the first time through
192 unsigned previousTrackMask;
193
194 // check for change in output HAL configuration
195 NBAIO_Format previousFormat = format;
196 if (current->mOutputSinkGen != outputSinkGen) {
197 outputSink = current->mOutputSink;
198 outputSinkGen = current->mOutputSinkGen;
199 if (outputSink == NULL) {
200 format = Format_Invalid;
201 sampleRate = 0;
202 } else {
203 format = outputSink->format();
204 sampleRate = Format_sampleRate(format);
205 ALOG_ASSERT(Format_channelCount(format) == 2);
206 }
Glenn Kasten21e8c502012-04-12 09:39:42 -0700207 dumpState->mSampleRate = sampleRate;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700208 }
209
210 if ((format != previousFormat) || (frameCount != previous->mFrameCount)) {
211 // FIXME to avoid priority inversion, don't delete here
212 delete mixer;
213 mixer = NULL;
214 delete[] mixBuffer;
215 mixBuffer = NULL;
216 if (frameCount > 0 && sampleRate > 0) {
217 // FIXME new may block for unbounded time at internal mutex of the heap
218 // implementation; it would be better to have normal mixer allocate for us
219 // to avoid blocking here and to prevent possible priority inversion
220 mixer = new AudioMixer(frameCount, sampleRate, FastMixerState::kMaxFastTracks);
221 mixBuffer = new short[frameCount * 2];
222 periodNs = (frameCount * 1000000000LL) / sampleRate; // 1.00
223 underrunNs = (frameCount * 1750000000LL) / sampleRate; // 1.75
224 overrunNs = (frameCount * 250000000LL) / sampleRate; // 0.25
Glenn Kasten972af222012-06-13 17:14:03 -0700225 forceNs = (frameCount * 750000000LL) / sampleRate; // 0.75
Glenn Kasten288ed212012-04-25 17:52:27 -0700226 warmupNs = (frameCount * 500000000LL) / sampleRate; // 0.50
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700227 } else {
228 periodNs = 0;
229 underrunNs = 0;
230 overrunNs = 0;
Glenn Kasten972af222012-06-13 17:14:03 -0700231 forceNs = 0;
232 warmupNs = 0;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700233 }
234 mixBufferState = UNDEFINED;
235#if !LOG_NDEBUG
236 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
237 fastTrackNames[i] = -1;
238 }
239#endif
240 // we need to reconfigure all active tracks
241 previousTrackMask = 0;
242 fastTracksGen = current->mFastTracksGen - 1;
Glenn Kasten21e8c502012-04-12 09:39:42 -0700243 dumpState->mFrameCount = frameCount;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700244 } else {
245 previousTrackMask = previous->mTrackMask;
246 }
247
248 // check for change in active track set
249 unsigned currentTrackMask = current->mTrackMask;
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700250 dumpState->mTrackMask = currentTrackMask;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700251 if (current->mFastTracksGen != fastTracksGen) {
252 ALOG_ASSERT(mixBuffer != NULL);
253 int name;
254
255 // process removed tracks first to avoid running out of track names
256 unsigned removedTracks = previousTrackMask & ~currentTrackMask;
257 while (removedTracks != 0) {
258 i = __builtin_ctz(removedTracks);
259 removedTracks &= ~(1 << i);
260 const FastTrack* fastTrack = &current->mFastTracks[i];
Glenn Kasten288ed212012-04-25 17:52:27 -0700261 ALOG_ASSERT(fastTrack->mBufferProvider == NULL);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700262 if (mixer != NULL) {
263 name = fastTrackNames[i];
264 ALOG_ASSERT(name >= 0);
265 mixer->deleteTrackName(name);
266 }
267#if !LOG_NDEBUG
268 fastTrackNames[i] = -1;
269#endif
Glenn Kasten288ed212012-04-25 17:52:27 -0700270 // don't reset track dump state, since other side is ignoring it
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700271 generations[i] = fastTrack->mGeneration;
272 }
273
274 // now process added tracks
275 unsigned addedTracks = currentTrackMask & ~previousTrackMask;
276 while (addedTracks != 0) {
277 i = __builtin_ctz(addedTracks);
278 addedTracks &= ~(1 << i);
279 const FastTrack* fastTrack = &current->mFastTracks[i];
280 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
281 ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);
282 if (mixer != NULL) {
Jean-Michel Trivi9bd23222012-04-16 13:43:48 -0700283 // calling getTrackName with default channel mask
284 name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700285 ALOG_ASSERT(name >= 0);
286 fastTrackNames[i] = name;
287 mixer->setBufferProvider(name, bufferProvider);
288 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,
289 (void *) mixBuffer);
290 // newly allocated track names default to full scale volume
Glenn Kasten21e8c502012-04-12 09:39:42 -0700291 if (fastTrack->mSampleRate != 0 && fastTrack->mSampleRate != sampleRate) {
292 mixer->setParameter(name, AudioMixer::RESAMPLE,
293 AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate);
294 }
295 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
296 (void *) fastTrack->mChannelMask);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700297 mixer->enable(name);
298 }
299 generations[i] = fastTrack->mGeneration;
300 }
301
302 // finally process modified tracks; these use the same slot
303 // but may have a different buffer provider or volume provider
304 unsigned modifiedTracks = currentTrackMask & previousTrackMask;
305 while (modifiedTracks != 0) {
306 i = __builtin_ctz(modifiedTracks);
307 modifiedTracks &= ~(1 << i);
308 const FastTrack* fastTrack = &current->mFastTracks[i];
309 if (fastTrack->mGeneration != generations[i]) {
310 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
311 ALOG_ASSERT(bufferProvider != NULL);
312 if (mixer != NULL) {
313 name = fastTrackNames[i];
314 ALOG_ASSERT(name >= 0);
315 mixer->setBufferProvider(name, bufferProvider);
316 if (fastTrack->mVolumeProvider == NULL) {
317 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
318 (void *)0x1000);
319 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
320 (void *)0x1000);
321 }
Glenn Kasten21e8c502012-04-12 09:39:42 -0700322 if (fastTrack->mSampleRate != 0 &&
323 fastTrack->mSampleRate != sampleRate) {
324 mixer->setParameter(name, AudioMixer::RESAMPLE,
325 AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate);
326 } else {
327 mixer->setParameter(name, AudioMixer::RESAMPLE,
328 AudioMixer::REMOVE, NULL);
329 }
330 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
331 (void *) fastTrack->mChannelMask);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700332 // already enabled
333 }
334 generations[i] = fastTrack->mGeneration;
335 }
336 }
337
338 fastTracksGen = current->mFastTracksGen;
339
340 dumpState->mNumTracks = popcount(currentTrackMask);
341 }
342
343#if 1 // FIXME shouldn't need this
344 // only process state change once
345 previous = current;
346#endif
347 }
348
349 // do work using current state here
Glenn Kasten288ed212012-04-25 17:52:27 -0700350 if ((command & FastMixerState::MIX) && (mixer != NULL) && isWarm) {
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700351 ALOG_ASSERT(mixBuffer != NULL);
Glenn Kasten288ed212012-04-25 17:52:27 -0700352 // for each track, update volume and check for underrun
353 unsigned currentTrackMask = current->mTrackMask;
354 while (currentTrackMask != 0) {
355 i = __builtin_ctz(currentTrackMask);
356 currentTrackMask &= ~(1 << i);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700357 const FastTrack* fastTrack = &current->mFastTracks[i];
358 int name = fastTrackNames[i];
359 ALOG_ASSERT(name >= 0);
360 if (fastTrack->mVolumeProvider != NULL) {
361 uint32_t vlr = fastTrack->mVolumeProvider->getVolumeLR();
362 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
363 (void *)(vlr & 0xFFFF));
364 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
365 (void *)(vlr >> 16));
366 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700367 // FIXME The current implementation of framesReady() for fast tracks
368 // takes a tryLock, which can block
369 // up to 1 ms. If enough active tracks all blocked in sequence, this would result
370 // in the overall fast mix cycle being delayed. Should use a non-blocking FIFO.
371 size_t framesReady = fastTrack->mBufferProvider->framesReady();
Glenn Kasten99c99d02012-05-14 16:37:13 -0700372#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
373 // I wish we had formatted trace names
374 char traceName[16];
375 strcpy(traceName, "framesReady");
376 traceName[11] = i + (i < 10 ? '0' : 'A' - 10);
377 traceName[12] = '\0';
378 ATRACE_INT(traceName, framesReady);
379#endif
Glenn Kasten288ed212012-04-25 17:52:27 -0700380 FastTrackDump *ftDump = &dumpState->mTracks[i];
Glenn Kasten09474df2012-05-10 14:48:07 -0700381 FastTrackUnderruns underruns = ftDump->mUnderruns;
Glenn Kasten288ed212012-04-25 17:52:27 -0700382 if (framesReady < frameCount) {
Glenn Kasten288ed212012-04-25 17:52:27 -0700383 if (framesReady == 0) {
Glenn Kasten09474df2012-05-10 14:48:07 -0700384 underruns.mBitFields.mEmpty++;
385 underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;
Glenn Kasten288ed212012-04-25 17:52:27 -0700386 mixer->disable(name);
387 } else {
388 // allow mixing partial buffer
Glenn Kasten09474df2012-05-10 14:48:07 -0700389 underruns.mBitFields.mPartial++;
390 underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;
Glenn Kasten288ed212012-04-25 17:52:27 -0700391 mixer->enable(name);
392 }
Glenn Kasten09474df2012-05-10 14:48:07 -0700393 } else {
394 underruns.mBitFields.mFull++;
395 underruns.mBitFields.mMostRecent = UNDERRUN_FULL;
Glenn Kasten288ed212012-04-25 17:52:27 -0700396 mixer->enable(name);
397 }
Glenn Kasten09474df2012-05-10 14:48:07 -0700398 ftDump->mUnderruns = underruns;
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700399 ftDump->mFramesReady = framesReady;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700400 }
401 // process() is CPU-bound
402 mixer->process(AudioBufferProvider::kInvalidPTS);
403 mixBufferState = MIXED;
404 } else if (mixBufferState == MIXED) {
405 mixBufferState = UNDEFINED;
406 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700407 bool attemptedWrite = false;
408 //bool didFullWrite = false; // dumpsys could display a count of partial writes
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700409 if ((command & FastMixerState::WRITE) && (outputSink != NULL) && (mixBuffer != NULL)) {
410 if (mixBufferState == UNDEFINED) {
411 memset(mixBuffer, 0, frameCount * 2 * sizeof(short));
412 mixBufferState = ZEROED;
413 }
Glenn Kastenfbae5da2012-05-21 09:17:20 -0700414 if (teeSink != NULL) {
415 (void) teeSink->write(mixBuffer, frameCount);
416 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700417 // FIXME write() is non-blocking and lock-free for a properly implemented NBAIO sink,
418 // but this code should be modified to handle both non-blocking and blocking sinks
419 dumpState->mWriteSequence++;
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::traceBegin(ATRACE_TAG, "write");
Glenn Kasten99c99d02012-05-14 16:37:13 -0700422#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700423 ssize_t framesWritten = outputSink->write(mixBuffer, frameCount);
Glenn Kasten99c99d02012-05-14 16:37:13 -0700424#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Glenn Kastend8e6fd32012-05-07 11:07:57 -0700425 Tracer::traceEnd(ATRACE_TAG);
Glenn Kasten99c99d02012-05-14 16:37:13 -0700426#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700427 dumpState->mWriteSequence++;
428 if (framesWritten >= 0) {
Glenn Kasten288ed212012-04-25 17:52:27 -0700429 ALOG_ASSERT(framesWritten <= frameCount);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700430 dumpState->mFramesWritten += framesWritten;
Glenn Kasten288ed212012-04-25 17:52:27 -0700431 //if ((size_t) framesWritten == frameCount) {
432 // didFullWrite = true;
433 //}
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700434 } else {
435 dumpState->mWriteErrors++;
436 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700437 attemptedWrite = true;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700438 // FIXME count # of writes blocked excessively, CPU usage, etc. for dump
439 }
440
441 // To be exactly periodic, compute the next sleep time based on current time.
442 // This code doesn't have long-term stability when the sink is non-blocking.
443 // FIXME To avoid drift, use the local audio clock or watch the sink's fill status.
444 struct timespec newTs;
445 int rc = clock_gettime(CLOCK_MONOTONIC, &newTs);
446 if (rc == 0) {
447 if (oldTsValid) {
448 time_t sec = newTs.tv_sec - oldTs.tv_sec;
449 long nsec = newTs.tv_nsec - oldTs.tv_nsec;
450 if (nsec < 0) {
451 --sec;
452 nsec += 1000000000;
453 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700454 // To avoid an initial underrun on fast tracks after exiting standby,
455 // do not start pulling data from tracks and mixing until warmup is complete.
456 // Warmup is considered complete after the earlier of:
457 // first successful single write() that blocks for more than warmupNs
458 // MAX_WARMUP_CYCLES write() attempts.
459 // This is overly conservative, but to get better accuracy requires a new HAL API.
460 if (!isWarm && attemptedWrite) {
461 measuredWarmupTs.tv_sec += sec;
462 measuredWarmupTs.tv_nsec += nsec;
463 if (measuredWarmupTs.tv_nsec >= 1000000000) {
464 measuredWarmupTs.tv_sec++;
465 measuredWarmupTs.tv_nsec -= 1000000000;
466 }
467 ++warmupCycles;
468 if ((attemptedWrite && nsec > warmupNs) ||
469 (warmupCycles >= MAX_WARMUP_CYCLES)) {
470 isWarm = true;
471 dumpState->mMeasuredWarmupTs = measuredWarmupTs;
472 dumpState->mWarmupCycles = warmupCycles;
473 }
474 }
Glenn Kasten972af222012-06-13 17:14:03 -0700475 sleepNs = -1;
476 if (isWarm) {
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700477 if (sec > 0 || nsec > underrunNs) {
Glenn Kasten99c99d02012-05-14 16:37:13 -0700478#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Glenn Kastend8e6fd32012-05-07 11:07:57 -0700479 ScopedTrace st(ATRACE_TAG, "underrun");
Glenn Kasten99c99d02012-05-14 16:37:13 -0700480#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700481 // FIXME only log occasionally
482 ALOGV("underrun: time since last cycle %d.%03ld sec",
483 (int) sec, nsec / 1000000L);
484 dumpState->mUnderruns++;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700485 ignoreNextOverrun = true;
486 } else if (nsec < overrunNs) {
487 if (ignoreNextOverrun) {
488 ignoreNextOverrun = false;
489 } else {
490 // FIXME only log occasionally
491 ALOGV("overrun: time since last cycle %d.%03ld sec",
492 (int) sec, nsec / 1000000L);
493 dumpState->mOverruns++;
494 }
Glenn Kasten972af222012-06-13 17:14:03 -0700495 // This forces a minimum cycle time. It:
496 // - compensates for an audio HAL with jitter due to sample rate conversion
497 // - works with a variable buffer depth audio HAL that never pulls at a rate
498 // < than overrunNs per buffer.
499 // - recovers from overrun immediately after underrun
500 // It doesn't work with a non-blocking audio HAL.
501 sleepNs = forceNs - nsec;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700502 } else {
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700503 ignoreNextOverrun = false;
504 }
Glenn Kasten972af222012-06-13 17:14:03 -0700505 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700506#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700507 // advance the FIFO queue bounds
508 size_t i = bounds & (FastMixerDumpState::kSamplingN - 1);
Glenn Kastene58ccce2012-05-11 15:19:24 -0700509 bounds = (bounds & 0xFFFF0000) | ((bounds + 1) & 0xFFFF);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700510 if (full) {
511 bounds += 0x10000;
512 } else if (!(bounds & (FastMixerDumpState::kSamplingN - 1))) {
513 full = true;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700514 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700515 // compute the delta value of clock_gettime(CLOCK_MONOTONIC)
516 uint32_t monotonicNs = nsec;
517 if (sec > 0 && sec < 4) {
518 monotonicNs += sec * 1000000000;
519 }
520 // compute the raw CPU load = delta value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
521 uint32_t loadNs = 0;
522 struct timespec newLoad;
523 rc = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &newLoad);
524 if (rc == 0) {
525 if (oldLoadValid) {
526 sec = newLoad.tv_sec - oldLoad.tv_sec;
527 nsec = newLoad.tv_nsec - oldLoad.tv_nsec;
528 if (nsec < 0) {
529 --sec;
530 nsec += 1000000000;
531 }
532 loadNs = nsec;
533 if (sec > 0 && sec < 4) {
534 loadNs += sec * 1000000000;
535 }
536 } else {
537 // first time through the loop
538 oldLoadValid = true;
539 }
540 oldLoad = newLoad;
541 }
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700542#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700543 // get the absolute value of CPU clock frequency in kHz
544 int cpuNum = sched_getcpu();
545 uint32_t kHz = tcu.getCpukHz(cpuNum);
Glenn Kastenc059bd42012-05-14 17:41:09 -0700546 kHz = (kHz << 4) | (cpuNum & 0xF);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700547#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700548 // save values in FIFO queues for dumpsys
549 // these stores #1, #2, #3 are not atomic with respect to each other,
550 // or with respect to store #4 below
551 dumpState->mMonotonicNs[i] = monotonicNs;
552 dumpState->mLoadNs[i] = loadNs;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700553#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700554 dumpState->mCpukHz[i] = kHz;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700555#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700556 // this store #4 is not atomic with respect to stores #1, #2, #3 above, but
557 // the newest open and oldest closed halves are atomic with respect to each other
558 dumpState->mBounds = bounds;
Glenn Kasten99c99d02012-05-14 16:37:13 -0700559#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
560 ATRACE_INT("cycle_ms", monotonicNs / 1000000);
561 ATRACE_INT("load_us", loadNs / 1000);
562#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700563#endif
564 } else {
565 // first time through the loop
566 oldTsValid = true;
567 sleepNs = periodNs;
568 ignoreNextOverrun = true;
569 }
570 oldTs = newTs;
571 } else {
572 // monotonic clock is broken
573 oldTsValid = false;
574 sleepNs = periodNs;
575 }
576
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700577
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700578 } // for (;;)
579
580 // never return 'true'; Thread::_threadLoop() locks mutex which can result in priority inversion
581}
582
583FastMixerDumpState::FastMixerDumpState() :
584 mCommand(FastMixerState::INITIAL), mWriteSequence(0), mFramesWritten(0),
Glenn Kasten21e8c502012-04-12 09:39:42 -0700585 mNumTracks(0), mWriteErrors(0), mUnderruns(0), mOverruns(0),
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700586 mSampleRate(0), mFrameCount(0), /* mMeasuredWarmupTs({0, 0}), */ mWarmupCycles(0),
587 mTrackMask(0)
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700588#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700589 , mBounds(0)
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700590#endif
591{
Glenn Kasten288ed212012-04-25 17:52:27 -0700592 mMeasuredWarmupTs.tv_sec = 0;
593 mMeasuredWarmupTs.tv_nsec = 0;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700594 // sample arrays aren't accessed atomically with respect to the bounds,
595 // so clearing reduces chance for dumpsys to read random uninitialized samples
596 memset(&mMonotonicNs, 0, sizeof(mMonotonicNs));
597 memset(&mLoadNs, 0, sizeof(mLoadNs));
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700598#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700599 memset(&mCpukHz, 0, sizeof(mCpukHz));
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700600#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700601}
602
603FastMixerDumpState::~FastMixerDumpState()
604{
605}
606
607void FastMixerDumpState::dump(int fd)
608{
Glenn Kasten868c0ab2012-06-13 14:59:17 -0700609 if (mCommand == FastMixerState::INITIAL) {
610 fdprintf(fd, "FastMixer not initialized\n");
611 return;
612 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700613#define COMMAND_MAX 32
614 char string[COMMAND_MAX];
615 switch (mCommand) {
616 case FastMixerState::INITIAL:
617 strcpy(string, "INITIAL");
618 break;
619 case FastMixerState::HOT_IDLE:
620 strcpy(string, "HOT_IDLE");
621 break;
622 case FastMixerState::COLD_IDLE:
623 strcpy(string, "COLD_IDLE");
624 break;
625 case FastMixerState::EXIT:
626 strcpy(string, "EXIT");
627 break;
628 case FastMixerState::MIX:
629 strcpy(string, "MIX");
630 break;
631 case FastMixerState::WRITE:
632 strcpy(string, "WRITE");
633 break;
634 case FastMixerState::MIX_WRITE:
635 strcpy(string, "MIX_WRITE");
636 break;
637 default:
638 snprintf(string, COMMAND_MAX, "%d", mCommand);
639 break;
640 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700641 double measuredWarmupMs = (mMeasuredWarmupTs.tv_sec * 1000.0) +
Glenn Kasten288ed212012-04-25 17:52:27 -0700642 (mMeasuredWarmupTs.tv_nsec / 1000000.0);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700643 double mixPeriodSec = (double) mFrameCount / (double) mSampleRate;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700644 fdprintf(fd, "FastMixer command=%s writeSequence=%u framesWritten=%u\n"
Glenn Kasten21e8c502012-04-12 09:39:42 -0700645 " numTracks=%u writeErrors=%u underruns=%u overruns=%u\n"
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700646 " sampleRate=%u frameCount=%u measuredWarmup=%.3g ms, warmupCycles=%u\n"
647 " mixPeriod=%.2f ms\n",
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700648 string, mWriteSequence, mFramesWritten,
Glenn Kasten21e8c502012-04-12 09:39:42 -0700649 mNumTracks, mWriteErrors, mUnderruns, mOverruns,
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700650 mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles,
651 mixPeriodSec * 1e3);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700652#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700653 // find the interval of valid samples
654 uint32_t bounds = mBounds;
655 uint32_t newestOpen = bounds & 0xFFFF;
656 uint32_t oldestClosed = bounds >> 16;
657 uint32_t n = (newestOpen - oldestClosed) & 0xFFFF;
658 if (n > kSamplingN) {
659 ALOGE("too many samples %u", n);
660 n = kSamplingN;
661 }
662 // statistics for monotonic (wall clock) time, thread raw CPU load in time, CPU clock frequency,
663 // and adjusted CPU load in MHz normalized for CPU clock frequency
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700664 CentralTendencyStatistics wall, loadNs;
665#ifdef CPU_FREQUENCY_STATISTICS
666 CentralTendencyStatistics kHz, loadMHz;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700667 uint32_t previousCpukHz = 0;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700668#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700669 // loop over all the samples
670 for (; n > 0; --n) {
671 size_t i = oldestClosed++ & (kSamplingN - 1);
672 uint32_t wallNs = mMonotonicNs[i];
673 wall.sample(wallNs);
674 uint32_t sampleLoadNs = mLoadNs[i];
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700675 loadNs.sample(sampleLoadNs);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700676#ifdef CPU_FREQUENCY_STATISTICS
677 uint32_t sampleCpukHz = mCpukHz[i];
Glenn Kastenc059bd42012-05-14 17:41:09 -0700678 // skip bad kHz samples
679 if ((sampleCpukHz & ~0xF) != 0) {
680 kHz.sample(sampleCpukHz >> 4);
681 if (sampleCpukHz == previousCpukHz) {
682 double megacycles = (double) sampleLoadNs * (double) (sampleCpukHz >> 4) * 1e-12;
683 double adjMHz = megacycles / mixPeriodSec; // _not_ wallNs * 1e9
684 loadMHz.sample(adjMHz);
685 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700686 }
687 previousCpukHz = sampleCpukHz;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700688#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700689 }
690 fdprintf(fd, "Simple moving statistics over last %.1f seconds:\n", wall.n() * mixPeriodSec);
691 fdprintf(fd, " wall clock time in ms per mix cycle:\n"
692 " mean=%.2f min=%.2f max=%.2f stddev=%.2f\n",
693 wall.mean()*1e-6, wall.minimum()*1e-6, wall.maximum()*1e-6, wall.stddev()*1e-6);
694 fdprintf(fd, " raw CPU load in us per mix cycle:\n"
695 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
696 loadNs.mean()*1e-3, loadNs.minimum()*1e-3, loadNs.maximum()*1e-3,
697 loadNs.stddev()*1e-3);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700698#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700699 fdprintf(fd, " CPU clock frequency in MHz:\n"
700 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
701 kHz.mean()*1e-3, kHz.minimum()*1e-3, kHz.maximum()*1e-3, kHz.stddev()*1e-3);
702 fdprintf(fd, " adjusted CPU load in MHz (i.e. normalized for CPU clock frequency):\n"
703 " mean=%.1f min=%.1f max=%.1f stddev=%.1f\n",
704 loadMHz.mean(), loadMHz.minimum(), loadMHz.maximum(), loadMHz.stddev());
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700705#endif
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700706#endif
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700707 // The active track mask and track states are updated non-atomically.
708 // So if we relied on isActive to decide whether to display,
709 // then we might display an obsolete track or omit an active track.
710 // Instead we always display all tracks, with an indication
711 // of whether we think the track is active.
712 uint32_t trackMask = mTrackMask;
713 fdprintf(fd, "Fast tracks: kMaxFastTracks=%u activeMask=%#x\n",
714 FastMixerState::kMaxFastTracks, trackMask);
715 fdprintf(fd, "Index Active Full Partial Empty Recent Ready\n");
716 for (uint32_t i = 0; i < FastMixerState::kMaxFastTracks; ++i, trackMask >>= 1) {
717 bool isActive = trackMask & 1;
718 const FastTrackDump *ftDump = &mTracks[i];
719 const FastTrackUnderruns& underruns = ftDump->mUnderruns;
720 const char *mostRecent;
721 switch (underruns.mBitFields.mMostRecent) {
722 case UNDERRUN_FULL:
723 mostRecent = "full";
724 break;
725 case UNDERRUN_PARTIAL:
726 mostRecent = "partial";
727 break;
728 case UNDERRUN_EMPTY:
729 mostRecent = "empty";
730 break;
731 default:
732 mostRecent = "?";
733 break;
734 }
735 fdprintf(fd, "%5u %6s %4u %7u %5u %7s %5u\n", i, isActive ? "yes" : "no",
736 (underruns.mBitFields.mFull) & UNDERRUN_MASK,
737 (underruns.mBitFields.mPartial) & UNDERRUN_MASK,
738 (underruns.mBitFields.mEmpty) & UNDERRUN_MASK,
739 mostRecent, ftDump->mFramesReady);
740 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700741}
742
743} // namespace android