blob: 6d878386ee68dcc2bb8b9d4203b1a720cb83ec37 [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
Glenn Kastena3d26282012-11-30 07:57:43 -080017// <IMPORTANT_WARNING>
18// Design rules for threadLoop() are given in the comments at section "Fast mixer thread" of
19// StateQueue.h. In particular, avoid library and system calls except at well-known points.
20// The design rules are only for threadLoop(), and don't apply to FastMixerDumpState methods.
21// </IMPORTANT_WARNING>
22
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070023#define LOG_TAG "FastMixer"
Glenn Kasten7f5d3352013-02-15 23:55:04 +000024//#define LOG_NDEBUG 0
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070025
Alex Rayb3a83642012-11-30 19:42:28 -080026#define ATRACE_TAG ATRACE_TAG_AUDIO
Alex Ray371eb972012-11-30 11:11:54 -080027
Glenn Kasten153b9fe2013-07-15 11:23:36 -070028#include "Configuration.h"
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070029#include <time.h>
30#include <utils/Log.h>
Glenn Kastend8e6fd32012-05-07 11:07:57 -070031#include <utils/Trace.h>
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070032#include <system/audio.h>
33#ifdef FAST_MIXER_STATISTICS
34#include <cpustats/CentralTendencyStatistics.h>
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070035#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070036#include <cpustats/ThreadCpuUsage.h>
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070037#endif
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070038#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070039#include "AudioMixer.h"
40#include "FastMixer.h"
41
42#define FAST_HOT_IDLE_NS 1000000L // 1 ms: time to sleep while hot idling
43#define FAST_DEFAULT_NS 999999999L // ~1 sec: default time to sleep
Glenn Kasteneb157162012-06-13 14:59:07 -070044#define MIN_WARMUP_CYCLES 2 // minimum number of loop cycles to wait for warmup
Glenn Kasten288ed212012-04-25 17:52:27 -070045#define MAX_WARMUP_CYCLES 10 // maximum number of loop cycles to wait for warmup
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070046
Glenn Kasten7fc97ba2013-07-16 17:18:58 -070047#define FCC_2 2 // fixed channel count assumption
48
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070049namespace android {
50
51// Fast mixer thread
52bool FastMixer::threadLoop()
53{
54 static const FastMixerState initial;
55 const FastMixerState *previous = &initial, *current = &initial;
56 FastMixerState preIdle; // copy of state before we went into idle
57 struct timespec oldTs = {0, 0};
58 bool oldTsValid = false;
59 long slopNs = 0; // accumulated time we've woken up too early (> 0) or too late (< 0)
60 long sleepNs = -1; // -1: busy wait, 0: sched_yield, > 0: nanosleep
61 int fastTrackNames[FastMixerState::kMaxFastTracks]; // handles used by mixer to identify tracks
62 int generations[FastMixerState::kMaxFastTracks]; // last observed mFastTracks[i].mGeneration
63 unsigned i;
64 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
65 fastTrackNames[i] = -1;
66 generations[i] = 0;
67 }
68 NBAIO_Sink *outputSink = NULL;
69 int outputSinkGen = 0;
70 AudioMixer* mixer = NULL;
71 short *mixBuffer = NULL;
72 enum {UNDEFINED, MIXED, ZEROED} mixBufferState = UNDEFINED;
73 NBAIO_Format format = Format_Invalid;
74 unsigned sampleRate = 0;
75 int fastTracksGen = 0;
76 long periodNs = 0; // expected period; the time required to render one mix buffer
Glenn Kasten288ed212012-04-25 17:52:27 -070077 long underrunNs = 0; // underrun likely when write cycle is greater than this value
78 long overrunNs = 0; // overrun likely when write cycle is less than this value
Glenn Kasten972af222012-06-13 17:14:03 -070079 long forceNs = 0; // if overrun detected, force the write cycle to take this much time
Glenn Kasten288ed212012-04-25 17:52:27 -070080 long warmupNs = 0; // warmup complete when write cycle is greater than to this value
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070081 FastMixerDumpState dummyDumpState, *dumpState = &dummyDumpState;
82 bool ignoreNextOverrun = true; // used to ignore initial overrun and first after an underrun
83#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070084 struct timespec oldLoad = {0, 0}; // previous value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
85 bool oldLoadValid = false; // whether oldLoad is valid
86 uint32_t bounds = 0;
Glenn Kasten4182c4e2013-07-15 14:45:07 -070087 bool full = false; // whether we have collected at least mSamplingN samples
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070088#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -070089 ThreadCpuUsage tcu; // for reading the current CPU clock frequency in kHz
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070090#endif
Glenn Kasten0a14c4c2012-06-13 14:58:49 -070091#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -070092 unsigned coldGen = 0; // last observed mColdGen
Glenn Kasten288ed212012-04-25 17:52:27 -070093 bool isWarm = false; // true means ready to mix, false means wait for warmup before mixing
94 struct timespec measuredWarmupTs = {0, 0}; // how long did it take for warmup to complete
95 uint32_t warmupCycles = 0; // counter of number of loop cycles required to warmup
Glenn Kastenfbae5da2012-05-21 09:17:20 -070096 NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink
Glenn Kasten9e58b552013-01-18 15:09:48 -080097 NBLog::Writer dummyLogWriter, *logWriter = &dummyLogWriter;
Glenn Kasten732845c2013-08-23 09:26:31 -070098 uint32_t totalNativeFramesWritten = 0; // copied to dumpState->mFramesWritten
99
100 // next 2 fields are valid only when timestampStatus == NO_ERROR
101 AudioTimestamp timestamp;
102 uint32_t nativeFramesWrittenButNotPresented = 0; // the = 0 is to silence the compiler
103 status_t timestampStatus = INVALID_OPERATION;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700104
105 for (;;) {
106
107 // either nanosleep, sched_yield, or busy wait
108 if (sleepNs >= 0) {
109 if (sleepNs > 0) {
110 ALOG_ASSERT(sleepNs < 1000000000);
111 const struct timespec req = {0, sleepNs};
112 nanosleep(&req, NULL);
113 } else {
114 sched_yield();
115 }
116 }
117 // default to long sleep for next cycle
118 sleepNs = FAST_DEFAULT_NS;
119
120 // poll for state change
121 const FastMixerState *next = mSQ.poll();
122 if (next == NULL) {
123 // continue to use the default initial state until a real state is available
124 ALOG_ASSERT(current == &initial && previous == &initial);
125 next = current;
126 }
127
128 FastMixerState::Command command = next->mCommand;
129 if (next != current) {
130
131 // As soon as possible of learning of a new dump area, start using it
132 dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
Glenn Kastenfbae5da2012-05-21 09:17:20 -0700133 teeSink = next->mTeeSink;
Glenn Kasten9e58b552013-01-18 15:09:48 -0800134 logWriter = next->mNBLogWriter != NULL ? next->mNBLogWriter : &dummyLogWriter;
Glenn Kastenab7d72f2013-02-27 09:05:28 -0800135 if (mixer != NULL) {
136 mixer->setLog(logWriter);
137 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700138
139 // We want to always have a valid reference to the previous (non-idle) state.
140 // However, the state queue only guarantees access to current and previous states.
141 // So when there is a transition from a non-idle state into an idle state, we make a
142 // copy of the last known non-idle state so it is still available on return from idle.
143 // The possible transitions are:
144 // non-idle -> non-idle update previous from current in-place
145 // non-idle -> idle update previous from copy of current
146 // idle -> idle don't update previous
147 // idle -> non-idle don't update previous
148 if (!(current->mCommand & FastMixerState::IDLE)) {
149 if (command & FastMixerState::IDLE) {
150 preIdle = *current;
151 current = &preIdle;
152 oldTsValid = false;
Glenn Kasten153b9fe2013-07-15 11:23:36 -0700153#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700154 oldLoadValid = false;
Glenn Kasten153b9fe2013-07-15 11:23:36 -0700155#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700156 ignoreNextOverrun = true;
157 }
158 previous = current;
159 }
160 current = next;
161 }
162#if !LOG_NDEBUG
163 next = NULL; // not referenced again
164#endif
165
166 dumpState->mCommand = command;
167
168 switch (command) {
169 case FastMixerState::INITIAL:
170 case FastMixerState::HOT_IDLE:
171 sleepNs = FAST_HOT_IDLE_NS;
172 continue;
173 case FastMixerState::COLD_IDLE:
174 // only perform a cold idle command once
Glenn Kasten21e8c502012-04-12 09:39:42 -0700175 // FIXME consider checking previous state and only perform if previous != COLD_IDLE
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700176 if (current->mColdGen != coldGen) {
177 int32_t *coldFutexAddr = current->mColdFutexAddr;
178 ALOG_ASSERT(coldFutexAddr != NULL);
179 int32_t old = android_atomic_dec(coldFutexAddr);
180 if (old <= 0) {
Elliott Hughes22f22ff2014-05-21 18:44:27 -0700181 (void) syscall(__NR_futex, coldFutexAddr, FUTEX_WAIT_PRIVATE, old - 1, NULL);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700182 }
Glenn Kastena07f17c2013-04-23 12:39:37 -0700183 int policy = sched_getscheduler(0);
184 if (!(policy == SCHED_FIFO || policy == SCHED_RR)) {
185 ALOGE("did not receive expected priority boost");
186 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700187 // This may be overly conservative; there could be times that the normal mixer
188 // requests such a brief cold idle that it doesn't require resetting this flag.
189 isWarm = false;
190 measuredWarmupTs.tv_sec = 0;
191 measuredWarmupTs.tv_nsec = 0;
192 warmupCycles = 0;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700193 sleepNs = -1;
194 coldGen = current->mColdGen;
Glenn Kasten153b9fe2013-07-15 11:23:36 -0700195#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700196 bounds = 0;
197 full = false;
Glenn Kasten153b9fe2013-07-15 11:23:36 -0700198#endif
Glenn Kasten04a4ca42012-06-01 10:49:51 -0700199 oldTsValid = !clock_gettime(CLOCK_MONOTONIC, &oldTs);
Glenn Kasten732845c2013-08-23 09:26:31 -0700200 timestampStatus = INVALID_OPERATION;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700201 } else {
202 sleepNs = FAST_HOT_IDLE_NS;
203 }
204 continue;
205 case FastMixerState::EXIT:
206 delete mixer;
207 delete[] mixBuffer;
208 return false;
209 case FastMixerState::MIX:
210 case FastMixerState::WRITE:
211 case FastMixerState::MIX_WRITE:
212 break;
213 default:
214 LOG_FATAL("bad command %d", command);
215 }
216
217 // there is a non-idle state available to us; did the state change?
218 size_t frameCount = current->mFrameCount;
219 if (current != previous) {
220
221 // handle state change here, but since we want to diff the state,
222 // we're prepared for previous == &initial the first time through
223 unsigned previousTrackMask;
224
225 // check for change in output HAL configuration
226 NBAIO_Format previousFormat = format;
227 if (current->mOutputSinkGen != outputSinkGen) {
228 outputSink = current->mOutputSink;
229 outputSinkGen = current->mOutputSinkGen;
230 if (outputSink == NULL) {
231 format = Format_Invalid;
232 sampleRate = 0;
233 } else {
234 format = outputSink->format();
235 sampleRate = Format_sampleRate(format);
Glenn Kasten7fc97ba2013-07-16 17:18:58 -0700236 ALOG_ASSERT(Format_channelCount(format) == FCC_2);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700237 }
238 }
239
240 if ((format != previousFormat) || (frameCount != previous->mFrameCount)) {
241 // FIXME to avoid priority inversion, don't delete here
242 delete mixer;
243 mixer = NULL;
244 delete[] mixBuffer;
245 mixBuffer = NULL;
246 if (frameCount > 0 && sampleRate > 0) {
247 // FIXME new may block for unbounded time at internal mutex of the heap
248 // implementation; it would be better to have normal mixer allocate for us
249 // to avoid blocking here and to prevent possible priority inversion
250 mixer = new AudioMixer(frameCount, sampleRate, FastMixerState::kMaxFastTracks);
Glenn Kasten7fc97ba2013-07-16 17:18:58 -0700251 mixBuffer = new short[frameCount * FCC_2];
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700252 periodNs = (frameCount * 1000000000LL) / sampleRate; // 1.00
253 underrunNs = (frameCount * 1750000000LL) / sampleRate; // 1.75
Glenn Kasten0d27c652012-08-07 10:38:59 -0700254 overrunNs = (frameCount * 500000000LL) / sampleRate; // 0.50
255 forceNs = (frameCount * 950000000LL) / sampleRate; // 0.95
Glenn Kasten288ed212012-04-25 17:52:27 -0700256 warmupNs = (frameCount * 500000000LL) / sampleRate; // 0.50
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700257 } else {
258 periodNs = 0;
259 underrunNs = 0;
260 overrunNs = 0;
Glenn Kasten972af222012-06-13 17:14:03 -0700261 forceNs = 0;
262 warmupNs = 0;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700263 }
264 mixBufferState = UNDEFINED;
265#if !LOG_NDEBUG
266 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
267 fastTrackNames[i] = -1;
268 }
269#endif
270 // we need to reconfigure all active tracks
271 previousTrackMask = 0;
272 fastTracksGen = current->mFastTracksGen - 1;
Glenn Kasten21e8c502012-04-12 09:39:42 -0700273 dumpState->mFrameCount = frameCount;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700274 } else {
275 previousTrackMask = previous->mTrackMask;
276 }
277
278 // check for change in active track set
279 unsigned currentTrackMask = current->mTrackMask;
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700280 dumpState->mTrackMask = currentTrackMask;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700281 if (current->mFastTracksGen != fastTracksGen) {
282 ALOG_ASSERT(mixBuffer != NULL);
283 int name;
284
285 // process removed tracks first to avoid running out of track names
286 unsigned removedTracks = previousTrackMask & ~currentTrackMask;
287 while (removedTracks != 0) {
288 i = __builtin_ctz(removedTracks);
289 removedTracks &= ~(1 << i);
290 const FastTrack* fastTrack = &current->mFastTracks[i];
Glenn Kasten288ed212012-04-25 17:52:27 -0700291 ALOG_ASSERT(fastTrack->mBufferProvider == NULL);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700292 if (mixer != NULL) {
293 name = fastTrackNames[i];
294 ALOG_ASSERT(name >= 0);
295 mixer->deleteTrackName(name);
296 }
297#if !LOG_NDEBUG
298 fastTrackNames[i] = -1;
299#endif
Glenn Kasten288ed212012-04-25 17:52:27 -0700300 // don't reset track dump state, since other side is ignoring it
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700301 generations[i] = fastTrack->mGeneration;
302 }
303
304 // now process added tracks
305 unsigned addedTracks = currentTrackMask & ~previousTrackMask;
306 while (addedTracks != 0) {
307 i = __builtin_ctz(addedTracks);
308 addedTracks &= ~(1 << i);
309 const FastTrack* fastTrack = &current->mFastTracks[i];
310 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
311 ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);
312 if (mixer != NULL) {
Jean-Michel Trivife3156e2012-09-10 18:58:27 -0700313 // calling getTrackName with default channel mask and a random invalid
314 // sessionId (no effects here)
315 name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO, -555);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700316 ALOG_ASSERT(name >= 0);
317 fastTrackNames[i] = name;
318 mixer->setBufferProvider(name, bufferProvider);
319 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,
320 (void *) mixBuffer);
321 // newly allocated track names default to full scale volume
Glenn Kasten21e8c502012-04-12 09:39:42 -0700322 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
Kévin PETIT377b2ec2014-02-03 12:35:36 +0000323 (void *)(uintptr_t)fastTrack->mChannelMask);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700324 mixer->enable(name);
325 }
326 generations[i] = fastTrack->mGeneration;
327 }
328
Glenn Kastenab7d72f2013-02-27 09:05:28 -0800329 // finally process (potentially) modified tracks; these use the same slot
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700330 // but may have a different buffer provider or volume provider
331 unsigned modifiedTracks = currentTrackMask & previousTrackMask;
332 while (modifiedTracks != 0) {
333 i = __builtin_ctz(modifiedTracks);
334 modifiedTracks &= ~(1 << i);
335 const FastTrack* fastTrack = &current->mFastTracks[i];
336 if (fastTrack->mGeneration != generations[i]) {
Glenn Kastenab7d72f2013-02-27 09:05:28 -0800337 // this track was actually modified
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700338 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
339 ALOG_ASSERT(bufferProvider != NULL);
340 if (mixer != NULL) {
341 name = fastTrackNames[i];
342 ALOG_ASSERT(name >= 0);
343 mixer->setBufferProvider(name, bufferProvider);
344 if (fastTrack->mVolumeProvider == NULL) {
345 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
346 (void *)0x1000);
347 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
348 (void *)0x1000);
349 }
Martin Storsjo3ce28aa2014-02-05 19:49:05 +0200350 mixer->setParameter(name, AudioMixer::RESAMPLE,
351 AudioMixer::REMOVE, NULL);
Glenn Kasten21e8c502012-04-12 09:39:42 -0700352 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
Kévin PETIT377b2ec2014-02-03 12:35:36 +0000353 (void *)(uintptr_t) fastTrack->mChannelMask);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700354 // already enabled
355 }
356 generations[i] = fastTrack->mGeneration;
357 }
358 }
359
360 fastTracksGen = current->mFastTracksGen;
361
362 dumpState->mNumTracks = popcount(currentTrackMask);
363 }
364
365#if 1 // FIXME shouldn't need this
366 // only process state change once
367 previous = current;
368#endif
369 }
370
371 // do work using current state here
Glenn Kasten288ed212012-04-25 17:52:27 -0700372 if ((command & FastMixerState::MIX) && (mixer != NULL) && isWarm) {
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700373 ALOG_ASSERT(mixBuffer != NULL);
Glenn Kasten288ed212012-04-25 17:52:27 -0700374 // for each track, update volume and check for underrun
375 unsigned currentTrackMask = current->mTrackMask;
376 while (currentTrackMask != 0) {
377 i = __builtin_ctz(currentTrackMask);
378 currentTrackMask &= ~(1 << i);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700379 const FastTrack* fastTrack = &current->mFastTracks[i];
Glenn Kasten732845c2013-08-23 09:26:31 -0700380
381 // Refresh the per-track timestamp
382 if (timestampStatus == NO_ERROR) {
Martin Storsjo3ce28aa2014-02-05 19:49:05 +0200383 uint32_t trackFramesWrittenButNotPresented =
384 nativeFramesWrittenButNotPresented;
Glenn Kasten732845c2013-08-23 09:26:31 -0700385 uint32_t trackFramesWritten = fastTrack->mBufferProvider->framesReleased();
386 // Can't provide an AudioTimestamp before first frame presented,
387 // or during the brief 32-bit wraparound window
388 if (trackFramesWritten >= trackFramesWrittenButNotPresented) {
389 AudioTimestamp perTrackTimestamp;
390 perTrackTimestamp.mPosition =
391 trackFramesWritten - trackFramesWrittenButNotPresented;
392 perTrackTimestamp.mTime = timestamp.mTime;
393 fastTrack->mBufferProvider->onTimestamp(perTrackTimestamp);
394 }
395 }
396
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700397 int name = fastTrackNames[i];
398 ALOG_ASSERT(name >= 0);
399 if (fastTrack->mVolumeProvider != NULL) {
400 uint32_t vlr = fastTrack->mVolumeProvider->getVolumeLR();
401 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
Kévin PETIT377b2ec2014-02-03 12:35:36 +0000402 (void *)(uintptr_t)(vlr & 0xFFFF));
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700403 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
Kévin PETIT377b2ec2014-02-03 12:35:36 +0000404 (void *)(uintptr_t)(vlr >> 16));
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700405 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700406 // FIXME The current implementation of framesReady() for fast tracks
407 // takes a tryLock, which can block
408 // up to 1 ms. If enough active tracks all blocked in sequence, this would result
409 // in the overall fast mix cycle being delayed. Should use a non-blocking FIFO.
410 size_t framesReady = fastTrack->mBufferProvider->framesReady();
Alex Rayb3a83642012-11-30 19:42:28 -0800411 if (ATRACE_ENABLED()) {
412 // I wish we had formatted trace names
413 char traceName[16];
Glenn Kastenc9b2e202013-02-26 11:32:32 -0800414 strcpy(traceName, "fRdy");
415 traceName[4] = i + (i < 10 ? '0' : 'A' - 10);
416 traceName[5] = '\0';
Alex Rayb3a83642012-11-30 19:42:28 -0800417 ATRACE_INT(traceName, framesReady);
418 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700419 FastTrackDump *ftDump = &dumpState->mTracks[i];
Glenn Kasten09474df2012-05-10 14:48:07 -0700420 FastTrackUnderruns underruns = ftDump->mUnderruns;
Glenn Kasten288ed212012-04-25 17:52:27 -0700421 if (framesReady < frameCount) {
Glenn Kasten288ed212012-04-25 17:52:27 -0700422 if (framesReady == 0) {
Glenn Kasten09474df2012-05-10 14:48:07 -0700423 underruns.mBitFields.mEmpty++;
424 underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;
Glenn Kasten288ed212012-04-25 17:52:27 -0700425 mixer->disable(name);
426 } else {
427 // allow mixing partial buffer
Glenn Kasten09474df2012-05-10 14:48:07 -0700428 underruns.mBitFields.mPartial++;
429 underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;
Glenn Kasten288ed212012-04-25 17:52:27 -0700430 mixer->enable(name);
431 }
Glenn Kasten09474df2012-05-10 14:48:07 -0700432 } else {
433 underruns.mBitFields.mFull++;
434 underruns.mBitFields.mMostRecent = UNDERRUN_FULL;
Glenn Kasten288ed212012-04-25 17:52:27 -0700435 mixer->enable(name);
436 }
Glenn Kasten09474df2012-05-10 14:48:07 -0700437 ftDump->mUnderruns = underruns;
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700438 ftDump->mFramesReady = framesReady;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700439 }
John Grossman2c3b2da2012-08-02 17:08:54 -0700440
441 int64_t pts;
442 if (outputSink == NULL || (OK != outputSink->getNextWriteTimestamp(&pts)))
443 pts = AudioBufferProvider::kInvalidPTS;
444
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700445 // process() is CPU-bound
John Grossman2c3b2da2012-08-02 17:08:54 -0700446 mixer->process(pts);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700447 mixBufferState = MIXED;
448 } else if (mixBufferState == MIXED) {
449 mixBufferState = UNDEFINED;
450 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700451 bool attemptedWrite = false;
452 //bool didFullWrite = false; // dumpsys could display a count of partial writes
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700453 if ((command & FastMixerState::WRITE) && (outputSink != NULL) && (mixBuffer != NULL)) {
454 if (mixBufferState == UNDEFINED) {
Glenn Kasten7fc97ba2013-07-16 17:18:58 -0700455 memset(mixBuffer, 0, frameCount * FCC_2 * sizeof(short));
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700456 mixBufferState = ZEROED;
457 }
Glenn Kastenfbae5da2012-05-21 09:17:20 -0700458 if (teeSink != NULL) {
459 (void) teeSink->write(mixBuffer, frameCount);
460 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700461 // FIXME write() is non-blocking and lock-free for a properly implemented NBAIO sink,
462 // but this code should be modified to handle both non-blocking and blocking sinks
463 dumpState->mWriteSequence++;
Simon Wilson2d590962012-11-29 15:18:50 -0800464 ATRACE_BEGIN("write");
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700465 ssize_t framesWritten = outputSink->write(mixBuffer, frameCount);
Simon Wilson2d590962012-11-29 15:18:50 -0800466 ATRACE_END();
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700467 dumpState->mWriteSequence++;
468 if (framesWritten >= 0) {
Glenn Kastenab7d72f2013-02-27 09:05:28 -0800469 ALOG_ASSERT((size_t) framesWritten <= frameCount);
Glenn Kasten732845c2013-08-23 09:26:31 -0700470 totalNativeFramesWritten += framesWritten;
471 dumpState->mFramesWritten = totalNativeFramesWritten;
Glenn Kasten288ed212012-04-25 17:52:27 -0700472 //if ((size_t) framesWritten == frameCount) {
473 // didFullWrite = true;
474 //}
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700475 } else {
476 dumpState->mWriteErrors++;
477 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700478 attemptedWrite = true;
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700479 // FIXME count # of writes blocked excessively, CPU usage, etc. for dump
Glenn Kasten732845c2013-08-23 09:26:31 -0700480
481 timestampStatus = outputSink->getTimestamp(timestamp);
482 if (timestampStatus == NO_ERROR) {
483 uint32_t totalNativeFramesPresented = timestamp.mPosition;
484 if (totalNativeFramesPresented <= totalNativeFramesWritten) {
485 nativeFramesWrittenButNotPresented =
486 totalNativeFramesWritten - totalNativeFramesPresented;
487 } else {
488 // HAL reported that more frames were presented than were written
489 timestampStatus = INVALID_OPERATION;
490 }
491 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700492 }
493
494 // To be exactly periodic, compute the next sleep time based on current time.
495 // This code doesn't have long-term stability when the sink is non-blocking.
496 // FIXME To avoid drift, use the local audio clock or watch the sink's fill status.
497 struct timespec newTs;
498 int rc = clock_gettime(CLOCK_MONOTONIC, &newTs);
499 if (rc == 0) {
Glenn Kastenab7d72f2013-02-27 09:05:28 -0800500 //logWriter->logTimestamp(newTs);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700501 if (oldTsValid) {
502 time_t sec = newTs.tv_sec - oldTs.tv_sec;
503 long nsec = newTs.tv_nsec - oldTs.tv_nsec;
Glenn Kasten80b32732012-09-24 11:29:00 -0700504 ALOGE_IF(sec < 0 || (sec == 0 && nsec < 0),
505 "clock_gettime(CLOCK_MONOTONIC) failed: was %ld.%09ld but now %ld.%09ld",
506 oldTs.tv_sec, oldTs.tv_nsec, newTs.tv_sec, newTs.tv_nsec);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700507 if (nsec < 0) {
508 --sec;
509 nsec += 1000000000;
510 }
Glenn Kasten288ed212012-04-25 17:52:27 -0700511 // To avoid an initial underrun on fast tracks after exiting standby,
512 // do not start pulling data from tracks and mixing until warmup is complete.
513 // Warmup is considered complete after the earlier of:
Glenn Kasteneb157162012-06-13 14:59:07 -0700514 // MIN_WARMUP_CYCLES write() attempts and last one blocks for at least warmupNs
Glenn Kasten288ed212012-04-25 17:52:27 -0700515 // MAX_WARMUP_CYCLES write() attempts.
516 // This is overly conservative, but to get better accuracy requires a new HAL API.
517 if (!isWarm && attemptedWrite) {
518 measuredWarmupTs.tv_sec += sec;
519 measuredWarmupTs.tv_nsec += nsec;
520 if (measuredWarmupTs.tv_nsec >= 1000000000) {
521 measuredWarmupTs.tv_sec++;
522 measuredWarmupTs.tv_nsec -= 1000000000;
523 }
524 ++warmupCycles;
Glenn Kasteneb157162012-06-13 14:59:07 -0700525 if ((nsec > warmupNs && warmupCycles >= MIN_WARMUP_CYCLES) ||
Glenn Kasten288ed212012-04-25 17:52:27 -0700526 (warmupCycles >= MAX_WARMUP_CYCLES)) {
527 isWarm = true;
528 dumpState->mMeasuredWarmupTs = measuredWarmupTs;
529 dumpState->mWarmupCycles = warmupCycles;
530 }
531 }
Glenn Kasten972af222012-06-13 17:14:03 -0700532 sleepNs = -1;
Glenn Kasten3d198252013-07-10 17:20:54 -0700533 if (isWarm) {
534 if (sec > 0 || nsec > underrunNs) {
535 ATRACE_NAME("underrun");
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700536 // FIXME only log occasionally
Glenn Kasten3d198252013-07-10 17:20:54 -0700537 ALOGV("underrun: time since last cycle %d.%03ld sec",
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700538 (int) sec, nsec / 1000000L);
Glenn Kasten3d198252013-07-10 17:20:54 -0700539 dumpState->mUnderruns++;
540 ignoreNextOverrun = true;
541 } else if (nsec < overrunNs) {
542 if (ignoreNextOverrun) {
543 ignoreNextOverrun = false;
544 } else {
545 // FIXME only log occasionally
546 ALOGV("overrun: time since last cycle %d.%03ld sec",
547 (int) sec, nsec / 1000000L);
548 dumpState->mOverruns++;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700549 }
Glenn Kasten3d198252013-07-10 17:20:54 -0700550 // This forces a minimum cycle time. It:
551 // - compensates for an audio HAL with jitter due to sample rate conversion
552 // - works with a variable buffer depth audio HAL that never pulls at a
553 // rate < than overrunNs per buffer.
554 // - recovers from overrun immediately after underrun
555 // It doesn't work with a non-blocking audio HAL.
556 sleepNs = forceNs - nsec;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700557 } else {
Glenn Kasten3d198252013-07-10 17:20:54 -0700558 ignoreNextOverrun = false;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700559 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700560 }
Glenn Kasten3d198252013-07-10 17:20:54 -0700561#ifdef FAST_MIXER_STATISTICS
562 if (isWarm) {
563 // advance the FIFO queue bounds
Glenn Kasten4182c4e2013-07-15 14:45:07 -0700564 size_t i = bounds & (dumpState->mSamplingN - 1);
Glenn Kasten3d198252013-07-10 17:20:54 -0700565 bounds = (bounds & 0xFFFF0000) | ((bounds + 1) & 0xFFFF);
566 if (full) {
567 bounds += 0x10000;
Glenn Kasten4182c4e2013-07-15 14:45:07 -0700568 } else if (!(bounds & (dumpState->mSamplingN - 1))) {
Glenn Kasten3d198252013-07-10 17:20:54 -0700569 full = true;
570 }
571 // compute the delta value of clock_gettime(CLOCK_MONOTONIC)
572 uint32_t monotonicNs = nsec;
573 if (sec > 0 && sec < 4) {
574 monotonicNs += sec * 1000000000;
575 }
576 // compute raw CPU load = delta value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
577 uint32_t loadNs = 0;
578 struct timespec newLoad;
579 rc = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &newLoad);
580 if (rc == 0) {
581 if (oldLoadValid) {
582 sec = newLoad.tv_sec - oldLoad.tv_sec;
583 nsec = newLoad.tv_nsec - oldLoad.tv_nsec;
584 if (nsec < 0) {
585 --sec;
586 nsec += 1000000000;
587 }
588 loadNs = nsec;
589 if (sec > 0 && sec < 4) {
590 loadNs += sec * 1000000000;
591 }
592 } else {
593 // first time through the loop
594 oldLoadValid = true;
595 }
596 oldLoad = newLoad;
597 }
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700598#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten3d198252013-07-10 17:20:54 -0700599 // get the absolute value of CPU clock frequency in kHz
600 int cpuNum = sched_getcpu();
601 uint32_t kHz = tcu.getCpukHz(cpuNum);
602 kHz = (kHz << 4) | (cpuNum & 0xF);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700603#endif
Glenn Kasten3d198252013-07-10 17:20:54 -0700604 // save values in FIFO queues for dumpsys
605 // these stores #1, #2, #3 are not atomic with respect to each other,
606 // or with respect to store #4 below
607 dumpState->mMonotonicNs[i] = monotonicNs;
608 dumpState->mLoadNs[i] = loadNs;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700609#ifdef CPU_FREQUENCY_STATISTICS
Glenn Kasten3d198252013-07-10 17:20:54 -0700610 dumpState->mCpukHz[i] = kHz;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700611#endif
Glenn Kasten3d198252013-07-10 17:20:54 -0700612 // this store #4 is not atomic with respect to stores #1, #2, #3 above, but
613 // the newest open & oldest closed halves are atomic with respect to each other
614 dumpState->mBounds = bounds;
615 ATRACE_INT("cycle_ms", monotonicNs / 1000000);
616 ATRACE_INT("load_us", loadNs / 1000);
617 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700618#endif
619 } else {
620 // first time through the loop
621 oldTsValid = true;
622 sleepNs = periodNs;
623 ignoreNextOverrun = true;
624 }
625 oldTs = newTs;
626 } else {
627 // monotonic clock is broken
628 oldTsValid = false;
629 sleepNs = periodNs;
630 }
631
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700632
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700633 } // for (;;)
634
635 // never return 'true'; Thread::_threadLoop() locks mutex which can result in priority inversion
636}
637
Glenn Kasten4182c4e2013-07-15 14:45:07 -0700638FastMixerDumpState::FastMixerDumpState(
639#ifdef FAST_MIXER_STATISTICS
640 uint32_t samplingN
641#endif
642 ) :
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700643 mCommand(FastMixerState::INITIAL), mWriteSequence(0), mFramesWritten(0),
Glenn Kasten21e8c502012-04-12 09:39:42 -0700644 mNumTracks(0), mWriteErrors(0), mUnderruns(0), mOverruns(0),
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700645 mSampleRate(0), mFrameCount(0), /* mMeasuredWarmupTs({0, 0}), */ mWarmupCycles(0),
646 mTrackMask(0)
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700647#ifdef FAST_MIXER_STATISTICS
Glenn Kasten4182c4e2013-07-15 14:45:07 -0700648 , mSamplingN(0), mBounds(0)
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700649#endif
650{
Glenn Kasten288ed212012-04-25 17:52:27 -0700651 mMeasuredWarmupTs.tv_sec = 0;
652 mMeasuredWarmupTs.tv_nsec = 0;
Glenn Kasten153b9fe2013-07-15 11:23:36 -0700653#ifdef FAST_MIXER_STATISTICS
Glenn Kasten4182c4e2013-07-15 14:45:07 -0700654 increaseSamplingN(samplingN);
Glenn Kasten153b9fe2013-07-15 11:23:36 -0700655#endif
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700656}
657
Glenn Kasten4182c4e2013-07-15 14:45:07 -0700658#ifdef FAST_MIXER_STATISTICS
659void FastMixerDumpState::increaseSamplingN(uint32_t samplingN)
660{
661 if (samplingN <= mSamplingN || samplingN > kSamplingN || roundup(samplingN) != samplingN) {
662 return;
663 }
664 uint32_t additional = samplingN - mSamplingN;
665 // sample arrays aren't accessed atomically with respect to the bounds,
666 // so clearing reduces chance for dumpsys to read random uninitialized samples
667 memset(&mMonotonicNs[mSamplingN], 0, sizeof(mMonotonicNs[0]) * additional);
668 memset(&mLoadNs[mSamplingN], 0, sizeof(mLoadNs[0]) * additional);
669#ifdef CPU_FREQUENCY_STATISTICS
670 memset(&mCpukHz[mSamplingN], 0, sizeof(mCpukHz[0]) * additional);
671#endif
672 mSamplingN = samplingN;
673}
674#endif
675
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700676FastMixerDumpState::~FastMixerDumpState()
677{
678}
679
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700680// helper function called by qsort()
681static int compare_uint32_t(const void *pa, const void *pb)
682{
683 uint32_t a = *(const uint32_t *)pa;
684 uint32_t b = *(const uint32_t *)pb;
685 if (a < b) {
686 return -1;
687 } else if (a > b) {
688 return 1;
689 } else {
690 return 0;
691 }
692}
693
Glenn Kasten4182c4e2013-07-15 14:45:07 -0700694void FastMixerDumpState::dump(int fd) const
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700695{
Glenn Kasten868c0ab2012-06-13 14:59:17 -0700696 if (mCommand == FastMixerState::INITIAL) {
Elliott Hughes8b5f6422014-05-22 01:22:06 -0700697 dprintf(fd, "FastMixer not initialized\n");
Glenn Kasten868c0ab2012-06-13 14:59:17 -0700698 return;
699 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700700#define COMMAND_MAX 32
701 char string[COMMAND_MAX];
702 switch (mCommand) {
703 case FastMixerState::INITIAL:
704 strcpy(string, "INITIAL");
705 break;
706 case FastMixerState::HOT_IDLE:
707 strcpy(string, "HOT_IDLE");
708 break;
709 case FastMixerState::COLD_IDLE:
710 strcpy(string, "COLD_IDLE");
711 break;
712 case FastMixerState::EXIT:
713 strcpy(string, "EXIT");
714 break;
715 case FastMixerState::MIX:
716 strcpy(string, "MIX");
717 break;
718 case FastMixerState::WRITE:
719 strcpy(string, "WRITE");
720 break;
721 case FastMixerState::MIX_WRITE:
722 strcpy(string, "MIX_WRITE");
723 break;
724 default:
725 snprintf(string, COMMAND_MAX, "%d", mCommand);
726 break;
727 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700728 double measuredWarmupMs = (mMeasuredWarmupTs.tv_sec * 1000.0) +
Glenn Kasten288ed212012-04-25 17:52:27 -0700729 (mMeasuredWarmupTs.tv_nsec / 1000000.0);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700730 double mixPeriodSec = (double) mFrameCount / (double) mSampleRate;
Elliott Hughes8b5f6422014-05-22 01:22:06 -0700731 dprintf(fd, "FastMixer command=%s writeSequence=%u framesWritten=%u\n"
Glenn Kasten21e8c502012-04-12 09:39:42 -0700732 " numTracks=%u writeErrors=%u underruns=%u overruns=%u\n"
Kévin PETIT377b2ec2014-02-03 12:35:36 +0000733 " sampleRate=%u frameCount=%zu measuredWarmup=%.3g ms, warmupCycles=%u\n"
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700734 " mixPeriod=%.2f ms\n",
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700735 string, mWriteSequence, mFramesWritten,
Glenn Kasten21e8c502012-04-12 09:39:42 -0700736 mNumTracks, mWriteErrors, mUnderruns, mOverruns,
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700737 mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles,
738 mixPeriodSec * 1e3);
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700739#ifdef FAST_MIXER_STATISTICS
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700740 // find the interval of valid samples
741 uint32_t bounds = mBounds;
742 uint32_t newestOpen = bounds & 0xFFFF;
743 uint32_t oldestClosed = bounds >> 16;
744 uint32_t n = (newestOpen - oldestClosed) & 0xFFFF;
Glenn Kasten4182c4e2013-07-15 14:45:07 -0700745 if (n > mSamplingN) {
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700746 ALOGE("too many samples %u", n);
Glenn Kasten4182c4e2013-07-15 14:45:07 -0700747 n = mSamplingN;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700748 }
749 // statistics for monotonic (wall clock) time, thread raw CPU load in time, CPU clock frequency,
750 // and adjusted CPU load in MHz normalized for CPU clock frequency
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700751 CentralTendencyStatistics wall, loadNs;
752#ifdef CPU_FREQUENCY_STATISTICS
753 CentralTendencyStatistics kHz, loadMHz;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700754 uint32_t previousCpukHz = 0;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700755#endif
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700756 // Assuming a normal distribution for cycle times, three standard deviations on either side of
757 // the mean account for 99.73% of the population. So if we take each tail to be 1/1000 of the
758 // sample set, we get 99.8% combined, or close to three standard deviations.
759 static const uint32_t kTailDenominator = 1000;
760 uint32_t *tail = n >= kTailDenominator ? new uint32_t[n] : NULL;
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700761 // loop over all the samples
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700762 for (uint32_t j = 0; j < n; ++j) {
Glenn Kasten4182c4e2013-07-15 14:45:07 -0700763 size_t i = oldestClosed++ & (mSamplingN - 1);
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700764 uint32_t wallNs = mMonotonicNs[i];
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700765 if (tail != NULL) {
766 tail[j] = wallNs;
767 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700768 wall.sample(wallNs);
769 uint32_t sampleLoadNs = mLoadNs[i];
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700770 loadNs.sample(sampleLoadNs);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700771#ifdef CPU_FREQUENCY_STATISTICS
772 uint32_t sampleCpukHz = mCpukHz[i];
Glenn Kastenc059bd42012-05-14 17:41:09 -0700773 // skip bad kHz samples
774 if ((sampleCpukHz & ~0xF) != 0) {
775 kHz.sample(sampleCpukHz >> 4);
776 if (sampleCpukHz == previousCpukHz) {
777 double megacycles = (double) sampleLoadNs * (double) (sampleCpukHz >> 4) * 1e-12;
778 double adjMHz = megacycles / mixPeriodSec; // _not_ wallNs * 1e9
779 loadMHz.sample(adjMHz);
780 }
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700781 }
782 previousCpukHz = sampleCpukHz;
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700783#endif
Glenn Kasten42d45cf2012-05-02 10:34:47 -0700784 }
Elliott Hughes8b5f6422014-05-22 01:22:06 -0700785 dprintf(fd, "Simple moving statistics over last %.1f seconds:\n", wall.n() * mixPeriodSec);
786 dprintf(fd, " wall clock time in ms per mix cycle:\n"
787 " mean=%.2f min=%.2f max=%.2f stddev=%.2f\n",
788 wall.mean()*1e-6, wall.minimum()*1e-6, wall.maximum()*1e-6, wall.stddev()*1e-6);
789 dprintf(fd, " raw CPU load in us per mix cycle:\n"
790 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
791 loadNs.mean()*1e-3, loadNs.minimum()*1e-3, loadNs.maximum()*1e-3,
792 loadNs.stddev()*1e-3);
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700793#ifdef CPU_FREQUENCY_STATISTICS
Elliott Hughes8b5f6422014-05-22 01:22:06 -0700794 dprintf(fd, " CPU clock frequency in MHz:\n"
795 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
796 kHz.mean()*1e-3, kHz.minimum()*1e-3, kHz.maximum()*1e-3, kHz.stddev()*1e-3);
797 dprintf(fd, " adjusted CPU load in MHz (i.e. normalized for CPU clock frequency):\n"
798 " mean=%.1f min=%.1f max=%.1f stddev=%.1f\n",
799 loadMHz.mean(), loadMHz.minimum(), loadMHz.maximum(), loadMHz.stddev());
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700800#endif
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700801 if (tail != NULL) {
802 qsort(tail, n, sizeof(uint32_t), compare_uint32_t);
803 // assume same number of tail samples on each side, left and right
804 uint32_t count = n / kTailDenominator;
805 CentralTendencyStatistics left, right;
806 for (uint32_t i = 0; i < count; ++i) {
807 left.sample(tail[i]);
808 right.sample(tail[n - (i + 1)]);
809 }
Elliott Hughes8b5f6422014-05-22 01:22:06 -0700810 dprintf(fd, "Distribution of mix cycle times in ms for the tails (> ~3 stddev outliers):\n"
811 " left tail: mean=%.2f min=%.2f max=%.2f stddev=%.2f\n"
812 " right tail: mean=%.2f min=%.2f max=%.2f stddev=%.2f\n",
813 left.mean()*1e-6, left.minimum()*1e-6, left.maximum()*1e-6, left.stddev()*1e-6,
814 right.mean()*1e-6, right.minimum()*1e-6, right.maximum()*1e-6,
815 right.stddev()*1e-6);
Glenn Kasten1ab212cf2012-09-07 12:58:38 -0700816 delete[] tail;
817 }
Glenn Kasten0a14c4c2012-06-13 14:58:49 -0700818#endif
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700819 // The active track mask and track states are updated non-atomically.
820 // So if we relied on isActive to decide whether to display,
821 // then we might display an obsolete track or omit an active track.
822 // Instead we always display all tracks, with an indication
823 // of whether we think the track is active.
824 uint32_t trackMask = mTrackMask;
Elliott Hughes8b5f6422014-05-22 01:22:06 -0700825 dprintf(fd, "Fast tracks: kMaxFastTracks=%u activeMask=%#x\n",
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700826 FastMixerState::kMaxFastTracks, trackMask);
Elliott Hughes8b5f6422014-05-22 01:22:06 -0700827 dprintf(fd, "Index Active Full Partial Empty Recent Ready\n");
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700828 for (uint32_t i = 0; i < FastMixerState::kMaxFastTracks; ++i, trackMask >>= 1) {
829 bool isActive = trackMask & 1;
830 const FastTrackDump *ftDump = &mTracks[i];
831 const FastTrackUnderruns& underruns = ftDump->mUnderruns;
832 const char *mostRecent;
833 switch (underruns.mBitFields.mMostRecent) {
834 case UNDERRUN_FULL:
835 mostRecent = "full";
836 break;
837 case UNDERRUN_PARTIAL:
838 mostRecent = "partial";
839 break;
840 case UNDERRUN_EMPTY:
841 mostRecent = "empty";
842 break;
843 default:
844 mostRecent = "?";
845 break;
846 }
Elliott Hughes8b5f6422014-05-22 01:22:06 -0700847 dprintf(fd, "%5u %6s %4u %7u %5u %7s %5zu\n", i, isActive ? "yes" : "no",
Glenn Kasten1295bb4d2012-05-31 07:43:43 -0700848 (underruns.mBitFields.mFull) & UNDERRUN_MASK,
849 (underruns.mBitFields.mPartial) & UNDERRUN_MASK,
850 (underruns.mBitFields.mEmpty) & UNDERRUN_MASK,
851 mostRecent, ftDump->mFramesReady);
852 }
Glenn Kasten97b5d0d2012-03-23 18:54:19 -0700853}
854
855} // namespace android