FastMixer.cpp revision 4dbb17e333b843a7e446f0fde47eda8564743ef3
1/* 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// <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 23#define LOG_TAG "FastMixer" 24//#define LOG_NDEBUG 0 25 26#define ATRACE_TAG ATRACE_TAG_AUDIO 27 28#include <sys/atomics.h> 29#include <time.h> 30#include <utils/Log.h> 31#include <utils/Trace.h> 32#include <system/audio.h> 33#ifdef FAST_MIXER_STATISTICS 34#include <cpustats/CentralTendencyStatistics.h> 35#ifdef CPU_FREQUENCY_STATISTICS 36#include <cpustats/ThreadCpuUsage.h> 37#endif 38#endif 39#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 44#define MIN_WARMUP_CYCLES 2 // minimum number of loop cycles to wait for warmup 45#define MAX_WARMUP_CYCLES 10 // maximum number of loop cycles to wait for warmup 46 47namespace android { 48 49// Fast mixer thread 50bool FastMixer::threadLoop() 51{ 52 static const FastMixerState initial; 53 const FastMixerState *previous = &initial, *current = &initial; 54 FastMixerState preIdle; // copy of state before we went into idle 55 struct timespec oldTs = {0, 0}; 56 bool oldTsValid = false; 57 long slopNs = 0; // accumulated time we've woken up too early (> 0) or too late (< 0) 58 long sleepNs = -1; // -1: busy wait, 0: sched_yield, > 0: nanosleep 59 int fastTrackNames[FastMixerState::kMaxFastTracks]; // handles used by mixer to identify tracks 60 int generations[FastMixerState::kMaxFastTracks]; // last observed mFastTracks[i].mGeneration 61 unsigned i; 62 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) { 63 fastTrackNames[i] = -1; 64 generations[i] = 0; 65 } 66 NBAIO_Sink *outputSink = NULL; 67 int outputSinkGen = 0; 68 AudioMixer* mixer = NULL; 69 short *mixBuffer = NULL; 70 enum {UNDEFINED, MIXED, ZEROED} mixBufferState = UNDEFINED; 71 NBAIO_Format format = Format_Invalid; 72 unsigned sampleRate = 0; 73 int fastTracksGen = 0; 74 long periodNs = 0; // expected period; the time required to render one mix buffer 75 long underrunNs = 0; // underrun likely when write cycle is greater than this value 76 long overrunNs = 0; // overrun likely when write cycle is less than this value 77 long forceNs = 0; // if overrun detected, force the write cycle to take this much time 78 long warmupNs = 0; // warmup complete when write cycle is greater than to this value 79 FastMixerDumpState dummyDumpState, *dumpState = &dummyDumpState; 80 bool ignoreNextOverrun = true; // used to ignore initial overrun and first after an underrun 81#ifdef FAST_MIXER_STATISTICS 82 struct timespec oldLoad = {0, 0}; // previous value of clock_gettime(CLOCK_THREAD_CPUTIME_ID) 83 bool oldLoadValid = false; // whether oldLoad is valid 84 uint32_t bounds = 0; 85 bool full = false; // whether we have collected at least kSamplingN samples 86#ifdef CPU_FREQUENCY_STATISTICS 87 ThreadCpuUsage tcu; // for reading the current CPU clock frequency in kHz 88#endif 89#endif 90 unsigned coldGen = 0; // last observed mColdGen 91 bool isWarm = false; // true means ready to mix, false means wait for warmup before mixing 92 struct timespec measuredWarmupTs = {0, 0}; // how long did it take for warmup to complete 93 uint32_t warmupCycles = 0; // counter of number of loop cycles required to warmup 94 NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink 95 NBLog::Writer dummyLogWriter, *logWriter = &dummyLogWriter; 96 97 for (;;) { 98 99 // either nanosleep, sched_yield, or busy wait 100 if (sleepNs >= 0) { 101 if (sleepNs > 0) { 102 ALOG_ASSERT(sleepNs < 1000000000); 103 const struct timespec req = {0, sleepNs}; 104 nanosleep(&req, NULL); 105 } else { 106 sched_yield(); 107 } 108 } 109 // default to long sleep for next cycle 110 sleepNs = FAST_DEFAULT_NS; 111 112 // poll for state change 113 const FastMixerState *next = mSQ.poll(); 114 if (next == NULL) { 115 // continue to use the default initial state until a real state is available 116 ALOG_ASSERT(current == &initial && previous == &initial); 117 next = current; 118 } 119 120 FastMixerState::Command command = next->mCommand; 121 if (next != current) { 122 123 logWriter->logTimestamp(); 124 logWriter->log("next != current"); 125 126 // As soon as possible of learning of a new dump area, start using it 127 dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState; 128 teeSink = next->mTeeSink; 129 logWriter = next->mNBLogWriter != NULL ? next->mNBLogWriter : &dummyLogWriter; 130 if (mixer != NULL) { 131 mixer->setLog(logWriter); 132 } 133 134 // We want to always have a valid reference to the previous (non-idle) state. 135 // However, the state queue only guarantees access to current and previous states. 136 // So when there is a transition from a non-idle state into an idle state, we make a 137 // copy of the last known non-idle state so it is still available on return from idle. 138 // The possible transitions are: 139 // non-idle -> non-idle update previous from current in-place 140 // non-idle -> idle update previous from copy of current 141 // idle -> idle don't update previous 142 // idle -> non-idle don't update previous 143 if (!(current->mCommand & FastMixerState::IDLE)) { 144 if (command & FastMixerState::IDLE) { 145 preIdle = *current; 146 current = &preIdle; 147 oldTsValid = false; 148 oldLoadValid = false; 149 ignoreNextOverrun = true; 150 } 151 previous = current; 152 } 153 current = next; 154 } 155#if !LOG_NDEBUG 156 next = NULL; // not referenced again 157#endif 158 159 dumpState->mCommand = command; 160 161 switch (command) { 162 case FastMixerState::INITIAL: 163 case FastMixerState::HOT_IDLE: 164 sleepNs = FAST_HOT_IDLE_NS; 165 continue; 166 case FastMixerState::COLD_IDLE: 167 // only perform a cold idle command once 168 // FIXME consider checking previous state and only perform if previous != COLD_IDLE 169 if (current->mColdGen != coldGen) { 170 int32_t *coldFutexAddr = current->mColdFutexAddr; 171 ALOG_ASSERT(coldFutexAddr != NULL); 172 int32_t old = android_atomic_dec(coldFutexAddr); 173 if (old <= 0) { 174 logWriter->log("wait"); 175 __futex_syscall4(coldFutexAddr, FUTEX_WAIT_PRIVATE, old - 1, NULL); 176 } 177 // This may be overly conservative; there could be times that the normal mixer 178 // requests such a brief cold idle that it doesn't require resetting this flag. 179 isWarm = false; 180 measuredWarmupTs.tv_sec = 0; 181 measuredWarmupTs.tv_nsec = 0; 182 warmupCycles = 0; 183 sleepNs = -1; 184 coldGen = current->mColdGen; 185 bounds = 0; 186 full = false; 187 oldTsValid = !clock_gettime(CLOCK_MONOTONIC, &oldTs); 188 } else { 189 sleepNs = FAST_HOT_IDLE_NS; 190 } 191 continue; 192 case FastMixerState::EXIT: 193 logWriter->log("exit"); 194 delete mixer; 195 delete[] mixBuffer; 196 return false; 197 case FastMixerState::MIX: 198 case FastMixerState::WRITE: 199 case FastMixerState::MIX_WRITE: 200 break; 201 default: 202 LOG_FATAL("bad command %d", command); 203 } 204 205 // there is a non-idle state available to us; did the state change? 206 size_t frameCount = current->mFrameCount; 207 if (current != previous) { 208 209 // handle state change here, but since we want to diff the state, 210 // we're prepared for previous == &initial the first time through 211 unsigned previousTrackMask; 212 213 // check for change in output HAL configuration 214 NBAIO_Format previousFormat = format; 215 if (current->mOutputSinkGen != outputSinkGen) { 216 outputSink = current->mOutputSink; 217 outputSinkGen = current->mOutputSinkGen; 218 if (outputSink == NULL) { 219 format = Format_Invalid; 220 sampleRate = 0; 221 } else { 222 format = outputSink->format(); 223 sampleRate = Format_sampleRate(format); 224 ALOG_ASSERT(Format_channelCount(format) == 2); 225 } 226 dumpState->mSampleRate = sampleRate; 227 } 228 229 if ((format != previousFormat) || (frameCount != previous->mFrameCount)) { 230 // FIXME to avoid priority inversion, don't delete here 231 delete mixer; 232 mixer = NULL; 233 delete[] mixBuffer; 234 mixBuffer = NULL; 235 if (frameCount > 0 && sampleRate > 0) { 236 // FIXME new may block for unbounded time at internal mutex of the heap 237 // implementation; it would be better to have normal mixer allocate for us 238 // to avoid blocking here and to prevent possible priority inversion 239 mixer = new AudioMixer(frameCount, sampleRate, FastMixerState::kMaxFastTracks); 240 mixBuffer = new short[frameCount * 2]; 241 periodNs = (frameCount * 1000000000LL) / sampleRate; // 1.00 242 underrunNs = (frameCount * 1750000000LL) / sampleRate; // 1.75 243 overrunNs = (frameCount * 500000000LL) / sampleRate; // 0.50 244 forceNs = (frameCount * 950000000LL) / sampleRate; // 0.95 245 warmupNs = (frameCount * 500000000LL) / sampleRate; // 0.50 246 } else { 247 periodNs = 0; 248 underrunNs = 0; 249 overrunNs = 0; 250 forceNs = 0; 251 warmupNs = 0; 252 } 253 mixBufferState = UNDEFINED; 254#if !LOG_NDEBUG 255 for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) { 256 fastTrackNames[i] = -1; 257 } 258#endif 259 // we need to reconfigure all active tracks 260 previousTrackMask = 0; 261 fastTracksGen = current->mFastTracksGen - 1; 262 dumpState->mFrameCount = frameCount; 263 } else { 264 previousTrackMask = previous->mTrackMask; 265 } 266 267 // check for change in active track set 268 unsigned currentTrackMask = current->mTrackMask; 269 dumpState->mTrackMask = currentTrackMask; 270 if (current->mFastTracksGen != fastTracksGen) { 271 logWriter->logf("gen %d", current->mFastTracksGen); 272 ALOG_ASSERT(mixBuffer != NULL); 273 int name; 274 275 // process removed tracks first to avoid running out of track names 276 unsigned removedTracks = previousTrackMask & ~currentTrackMask; 277 if (removedTracks) { 278 logWriter->logf("removed %#x", removedTracks); 279 } 280 while (removedTracks != 0) { 281 i = __builtin_ctz(removedTracks); 282 removedTracks &= ~(1 << i); 283 const FastTrack* fastTrack = ¤t->mFastTracks[i]; 284 ALOG_ASSERT(fastTrack->mBufferProvider == NULL); 285 if (mixer != NULL) { 286 name = fastTrackNames[i]; 287 ALOG_ASSERT(name >= 0); 288 mixer->deleteTrackName(name); 289 } 290#if !LOG_NDEBUG 291 fastTrackNames[i] = -1; 292#endif 293 // don't reset track dump state, since other side is ignoring it 294 generations[i] = fastTrack->mGeneration; 295 } 296 297 // now process added tracks 298 unsigned addedTracks = currentTrackMask & ~previousTrackMask; 299 if (addedTracks) { 300 logWriter->logf("added %#x", addedTracks); 301 } 302 while (addedTracks != 0) { 303 i = __builtin_ctz(addedTracks); 304 addedTracks &= ~(1 << i); 305 const FastTrack* fastTrack = ¤t->mFastTracks[i]; 306 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider; 307 logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider); 308 ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1); 309 if (bufferProvider == NULL || 310 bufferProvider->getValid() != AudioBufferProvider::kValid) { 311 logWriter->logTimestamp(); 312 logWriter->logf("added invalid %#x", i); 313 } 314 if (mixer != NULL) { 315 // calling getTrackName with default channel mask and a random invalid 316 // sessionId (no effects here) 317 name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO, -555); 318 ALOG_ASSERT(name >= 0); 319 fastTrackNames[i] = name; 320 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX, 321 (void *) i); 322 mixer->setBufferProvider(name, bufferProvider); 323 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER, 324 (void *) mixBuffer); 325 // newly allocated track names default to full scale volume 326 if (fastTrack->mSampleRate != 0 && fastTrack->mSampleRate != sampleRate) { 327 mixer->setParameter(name, AudioMixer::RESAMPLE, 328 AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate); 329 } 330 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK, 331 (void *) fastTrack->mChannelMask); 332 if (!mixer->enabled(name)) { 333 logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name); 334 } 335 mixer->enable(name); 336 } 337 generations[i] = fastTrack->mGeneration; 338 } 339 340 // finally process (potentially) modified tracks; these use the same slot 341 // but may have a different buffer provider or volume provider 342 unsigned modifiedTracks = currentTrackMask & previousTrackMask; 343 if (modifiedTracks) { 344 logWriter->logf("pot. mod. %#x", modifiedTracks); 345 } 346 unsigned actuallyModifiedTracks = 0; 347 while (modifiedTracks != 0) { 348 i = __builtin_ctz(modifiedTracks); 349 modifiedTracks &= ~(1 << i); 350 const FastTrack* fastTrack = ¤t->mFastTracks[i]; 351 if (fastTrack->mGeneration != generations[i]) { 352 actuallyModifiedTracks |= 1 << i; 353 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider; 354 logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider); 355 ALOG_ASSERT(bufferProvider != NULL); 356 if (bufferProvider == NULL || 357 bufferProvider->getValid() != AudioBufferProvider::kValid) { 358 logWriter->logTimestamp(); 359 logWriter->logf("modified invalid %#x", i); 360 } 361 if (mixer != NULL) { 362 name = fastTrackNames[i]; 363 ALOG_ASSERT(name >= 0); 364 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX, 365 (void *) i); 366 mixer->setBufferProvider(name, bufferProvider); 367 if (fastTrack->mVolumeProvider == NULL) { 368 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0, 369 (void *)0x1000); 370 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1, 371 (void *)0x1000); 372 } 373 if (fastTrack->mSampleRate != 0 && 374 fastTrack->mSampleRate != sampleRate) { 375 mixer->setParameter(name, AudioMixer::RESAMPLE, 376 AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate); 377 } else { 378 mixer->setParameter(name, AudioMixer::RESAMPLE, 379 AudioMixer::REMOVE, NULL); 380 } 381 mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK, 382 (void *) fastTrack->mChannelMask); 383 // already enabled 384 } 385 generations[i] = fastTrack->mGeneration; 386 } 387 } 388 if (actuallyModifiedTracks) { 389 logWriter->logf("act. mod. %#x", actuallyModifiedTracks); 390 } 391 392 fastTracksGen = current->mFastTracksGen; 393 394 dumpState->mNumTracks = popcount(currentTrackMask); 395 } 396 397#if 1 // FIXME shouldn't need this 398 // only process state change once 399 previous = current; 400#endif 401 } 402 403 // do work using current state here 404 if ((command & FastMixerState::MIX) && (mixer != NULL) && isWarm) { 405 ALOG_ASSERT(mixBuffer != NULL); 406 // for each track, update volume and check for underrun 407 unsigned currentTrackMask = current->mTrackMask; 408 logWriter->logf("ctm %#x", currentTrackMask); 409 while (currentTrackMask != 0) { 410 i = __builtin_ctz(currentTrackMask); 411 currentTrackMask &= ~(1 << i); 412 const FastTrack* fastTrack = ¤t->mFastTracks[i]; 413 int name = fastTrackNames[i]; 414 ALOG_ASSERT(name >= 0); 415 if (fastTrack->mVolumeProvider != NULL) { 416 uint32_t vlr = fastTrack->mVolumeProvider->getVolumeLR(); 417 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0, 418 (void *)(vlr & 0xFFFF)); 419 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1, 420 (void *)(vlr >> 16)); 421 } 422 // FIXME The current implementation of framesReady() for fast tracks 423 // takes a tryLock, which can block 424 // up to 1 ms. If enough active tracks all blocked in sequence, this would result 425 // in the overall fast mix cycle being delayed. Should use a non-blocking FIFO. 426 size_t framesReady = fastTrack->mBufferProvider->framesReady(); 427 if (ATRACE_ENABLED()) { 428 // I wish we had formatted trace names 429 char traceName[16]; 430 strcpy(traceName, "framesReady"); 431 traceName[11] = i + (i < 10 ? '0' : 'A' - 10); 432 traceName[12] = '\0'; 433 ATRACE_INT(traceName, framesReady); 434 } 435 FastTrackDump *ftDump = &dumpState->mTracks[i]; 436 FastTrackUnderruns underruns = ftDump->mUnderruns; 437 if (framesReady < frameCount) { 438 if (framesReady == 0) { 439 underruns.mBitFields.mEmpty++; 440 underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY; 441 mixer->disable(name); 442 } else { 443 // allow mixing partial buffer 444 underruns.mBitFields.mPartial++; 445 underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL; 446 if (!mixer->enabled(name)) { 447 logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name); 448 } 449 mixer->enable(name); 450 } 451 } else { 452 underruns.mBitFields.mFull++; 453 underruns.mBitFields.mMostRecent = UNDERRUN_FULL; 454 if (!mixer->enabled(name)) { 455 logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name); 456 } 457 mixer->enable(name); 458 } 459 ftDump->mUnderruns = underruns; 460 ftDump->mFramesReady = framesReady; 461 AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider; 462 if (bufferProvider == NULL || 463 bufferProvider->getValid() != AudioBufferProvider::kValid) { 464 logWriter->logTimestamp(); 465 logWriter->logf("mixing invalid %#x", i); 466 } 467 } 468 469 int64_t pts; 470 if (outputSink == NULL || (OK != outputSink->getNextWriteTimestamp(&pts))) 471 pts = AudioBufferProvider::kInvalidPTS; 472 473 // process() is CPU-bound 474 mixer->process(pts); 475 mixBufferState = MIXED; 476 } else if (mixBufferState == MIXED) { 477 mixBufferState = UNDEFINED; 478 } 479 bool attemptedWrite = false; 480 //bool didFullWrite = false; // dumpsys could display a count of partial writes 481 if ((command & FastMixerState::WRITE) && (outputSink != NULL) && (mixBuffer != NULL)) { 482 if (mixBufferState == UNDEFINED) { 483 memset(mixBuffer, 0, frameCount * 2 * sizeof(short)); 484 mixBufferState = ZEROED; 485 } 486 if (teeSink != NULL) { 487 (void) teeSink->write(mixBuffer, frameCount); 488 } 489 // FIXME write() is non-blocking and lock-free for a properly implemented NBAIO sink, 490 // but this code should be modified to handle both non-blocking and blocking sinks 491 dumpState->mWriteSequence++; 492 ATRACE_BEGIN("write"); 493 ssize_t framesWritten = outputSink->write(mixBuffer, frameCount); 494 ATRACE_END(); 495 dumpState->mWriteSequence++; 496 if (framesWritten >= 0) { 497 ALOG_ASSERT(framesWritten <= frameCount); 498 dumpState->mFramesWritten += framesWritten; 499 //if ((size_t) framesWritten == frameCount) { 500 // didFullWrite = true; 501 //} 502 } else { 503 dumpState->mWriteErrors++; 504 } 505 attemptedWrite = true; 506 // FIXME count # of writes blocked excessively, CPU usage, etc. for dump 507 } 508 509 // To be exactly periodic, compute the next sleep time based on current time. 510 // This code doesn't have long-term stability when the sink is non-blocking. 511 // FIXME To avoid drift, use the local audio clock or watch the sink's fill status. 512 struct timespec newTs; 513 int rc = clock_gettime(CLOCK_MONOTONIC, &newTs); 514 if (rc == 0) { 515 logWriter->logTimestamp(newTs); 516 if (oldTsValid) { 517 time_t sec = newTs.tv_sec - oldTs.tv_sec; 518 long nsec = newTs.tv_nsec - oldTs.tv_nsec; 519 ALOGE_IF(sec < 0 || (sec == 0 && nsec < 0), 520 "clock_gettime(CLOCK_MONOTONIC) failed: was %ld.%09ld but now %ld.%09ld", 521 oldTs.tv_sec, oldTs.tv_nsec, newTs.tv_sec, newTs.tv_nsec); 522 if (nsec < 0) { 523 --sec; 524 nsec += 1000000000; 525 } 526 // To avoid an initial underrun on fast tracks after exiting standby, 527 // do not start pulling data from tracks and mixing until warmup is complete. 528 // Warmup is considered complete after the earlier of: 529 // MIN_WARMUP_CYCLES write() attempts and last one blocks for at least warmupNs 530 // MAX_WARMUP_CYCLES write() attempts. 531 // This is overly conservative, but to get better accuracy requires a new HAL API. 532 if (!isWarm && attemptedWrite) { 533 measuredWarmupTs.tv_sec += sec; 534 measuredWarmupTs.tv_nsec += nsec; 535 if (measuredWarmupTs.tv_nsec >= 1000000000) { 536 measuredWarmupTs.tv_sec++; 537 measuredWarmupTs.tv_nsec -= 1000000000; 538 } 539 ++warmupCycles; 540 if ((nsec > warmupNs && warmupCycles >= MIN_WARMUP_CYCLES) || 541 (warmupCycles >= MAX_WARMUP_CYCLES)) { 542 isWarm = true; 543 dumpState->mMeasuredWarmupTs = measuredWarmupTs; 544 dumpState->mWarmupCycles = warmupCycles; 545 } 546 } 547 sleepNs = -1; 548 if (isWarm) { 549 if (sec > 0 || nsec > underrunNs) { 550 ATRACE_NAME("underrun"); 551 // FIXME only log occasionally 552 ALOGV("underrun: time since last cycle %d.%03ld sec", 553 (int) sec, nsec / 1000000L); 554 dumpState->mUnderruns++; 555 ignoreNextOverrun = true; 556 } else if (nsec < overrunNs) { 557 if (ignoreNextOverrun) { 558 ignoreNextOverrun = false; 559 } else { 560 // FIXME only log occasionally 561 ALOGV("overrun: time since last cycle %d.%03ld sec", 562 (int) sec, nsec / 1000000L); 563 dumpState->mOverruns++; 564 } 565 // This forces a minimum cycle time. It: 566 // - compensates for an audio HAL with jitter due to sample rate conversion 567 // - works with a variable buffer depth audio HAL that never pulls at a rate 568 // < than overrunNs per buffer. 569 // - recovers from overrun immediately after underrun 570 // It doesn't work with a non-blocking audio HAL. 571 sleepNs = forceNs - nsec; 572 } else { 573 ignoreNextOverrun = false; 574 } 575 } 576#ifdef FAST_MIXER_STATISTICS 577 if (isWarm) { 578 // advance the FIFO queue bounds 579 size_t i = bounds & (FastMixerDumpState::kSamplingN - 1); 580 bounds = (bounds & 0xFFFF0000) | ((bounds + 1) & 0xFFFF); 581 if (full) { 582 bounds += 0x10000; 583 } else if (!(bounds & (FastMixerDumpState::kSamplingN - 1))) { 584 full = true; 585 } 586 // compute the delta value of clock_gettime(CLOCK_MONOTONIC) 587 uint32_t monotonicNs = nsec; 588 if (sec > 0 && sec < 4) { 589 monotonicNs += sec * 1000000000; 590 } 591 // compute the raw CPU load = delta value of clock_gettime(CLOCK_THREAD_CPUTIME_ID) 592 uint32_t loadNs = 0; 593 struct timespec newLoad; 594 rc = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &newLoad); 595 if (rc == 0) { 596 if (oldLoadValid) { 597 sec = newLoad.tv_sec - oldLoad.tv_sec; 598 nsec = newLoad.tv_nsec - oldLoad.tv_nsec; 599 if (nsec < 0) { 600 --sec; 601 nsec += 1000000000; 602 } 603 loadNs = nsec; 604 if (sec > 0 && sec < 4) { 605 loadNs += sec * 1000000000; 606 } 607 } else { 608 // first time through the loop 609 oldLoadValid = true; 610 } 611 oldLoad = newLoad; 612 } 613#ifdef CPU_FREQUENCY_STATISTICS 614 // get the absolute value of CPU clock frequency in kHz 615 int cpuNum = sched_getcpu(); 616 uint32_t kHz = tcu.getCpukHz(cpuNum); 617 kHz = (kHz << 4) | (cpuNum & 0xF); 618#endif 619 // save values in FIFO queues for dumpsys 620 // these stores #1, #2, #3 are not atomic with respect to each other, 621 // or with respect to store #4 below 622 dumpState->mMonotonicNs[i] = monotonicNs; 623 dumpState->mLoadNs[i] = loadNs; 624#ifdef CPU_FREQUENCY_STATISTICS 625 dumpState->mCpukHz[i] = kHz; 626#endif 627 // this store #4 is not atomic with respect to stores #1, #2, #3 above, but 628 // the newest open and oldest closed halves are atomic with respect to each other 629 dumpState->mBounds = bounds; 630 ATRACE_INT("cycle_ms", monotonicNs / 1000000); 631 ATRACE_INT("load_us", loadNs / 1000); 632 } 633#endif 634 } else { 635 // first time through the loop 636 oldTsValid = true; 637 sleepNs = periodNs; 638 ignoreNextOverrun = true; 639 } 640 oldTs = newTs; 641 } else { 642 // monotonic clock is broken 643 oldTsValid = false; 644 sleepNs = periodNs; 645 } 646 647 648 } // for (;;) 649 650 // never return 'true'; Thread::_threadLoop() locks mutex which can result in priority inversion 651} 652 653FastMixerDumpState::FastMixerDumpState() : 654 mCommand(FastMixerState::INITIAL), mWriteSequence(0), mFramesWritten(0), 655 mNumTracks(0), mWriteErrors(0), mUnderruns(0), mOverruns(0), 656 mSampleRate(0), mFrameCount(0), /* mMeasuredWarmupTs({0, 0}), */ mWarmupCycles(0), 657 mTrackMask(0) 658#ifdef FAST_MIXER_STATISTICS 659 , mBounds(0) 660#endif 661{ 662 mMeasuredWarmupTs.tv_sec = 0; 663 mMeasuredWarmupTs.tv_nsec = 0; 664 // sample arrays aren't accessed atomically with respect to the bounds, 665 // so clearing reduces chance for dumpsys to read random uninitialized samples 666 memset(&mMonotonicNs, 0, sizeof(mMonotonicNs)); 667 memset(&mLoadNs, 0, sizeof(mLoadNs)); 668#ifdef CPU_FREQUENCY_STATISTICS 669 memset(&mCpukHz, 0, sizeof(mCpukHz)); 670#endif 671} 672 673FastMixerDumpState::~FastMixerDumpState() 674{ 675} 676 677// helper function called by qsort() 678static int compare_uint32_t(const void *pa, const void *pb) 679{ 680 uint32_t a = *(const uint32_t *)pa; 681 uint32_t b = *(const uint32_t *)pb; 682 if (a < b) { 683 return -1; 684 } else if (a > b) { 685 return 1; 686 } else { 687 return 0; 688 } 689} 690 691void FastMixerDumpState::dump(int fd) 692{ 693 if (mCommand == FastMixerState::INITIAL) { 694 fdprintf(fd, "FastMixer not initialized\n"); 695 return; 696 } 697#define COMMAND_MAX 32 698 char string[COMMAND_MAX]; 699 switch (mCommand) { 700 case FastMixerState::INITIAL: 701 strcpy(string, "INITIAL"); 702 break; 703 case FastMixerState::HOT_IDLE: 704 strcpy(string, "HOT_IDLE"); 705 break; 706 case FastMixerState::COLD_IDLE: 707 strcpy(string, "COLD_IDLE"); 708 break; 709 case FastMixerState::EXIT: 710 strcpy(string, "EXIT"); 711 break; 712 case FastMixerState::MIX: 713 strcpy(string, "MIX"); 714 break; 715 case FastMixerState::WRITE: 716 strcpy(string, "WRITE"); 717 break; 718 case FastMixerState::MIX_WRITE: 719 strcpy(string, "MIX_WRITE"); 720 break; 721 default: 722 snprintf(string, COMMAND_MAX, "%d", mCommand); 723 break; 724 } 725 double measuredWarmupMs = (mMeasuredWarmupTs.tv_sec * 1000.0) + 726 (mMeasuredWarmupTs.tv_nsec / 1000000.0); 727 double mixPeriodSec = (double) mFrameCount / (double) mSampleRate; 728 fdprintf(fd, "FastMixer command=%s writeSequence=%u framesWritten=%u\n" 729 " numTracks=%u writeErrors=%u underruns=%u overruns=%u\n" 730 " sampleRate=%u frameCount=%u measuredWarmup=%.3g ms, warmupCycles=%u\n" 731 " mixPeriod=%.2f ms\n", 732 string, mWriteSequence, mFramesWritten, 733 mNumTracks, mWriteErrors, mUnderruns, mOverruns, 734 mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles, 735 mixPeriodSec * 1e3); 736#ifdef FAST_MIXER_STATISTICS 737 // find the interval of valid samples 738 uint32_t bounds = mBounds; 739 uint32_t newestOpen = bounds & 0xFFFF; 740 uint32_t oldestClosed = bounds >> 16; 741 uint32_t n = (newestOpen - oldestClosed) & 0xFFFF; 742 if (n > kSamplingN) { 743 ALOGE("too many samples %u", n); 744 n = kSamplingN; 745 } 746 // statistics for monotonic (wall clock) time, thread raw CPU load in time, CPU clock frequency, 747 // and adjusted CPU load in MHz normalized for CPU clock frequency 748 CentralTendencyStatistics wall, loadNs; 749#ifdef CPU_FREQUENCY_STATISTICS 750 CentralTendencyStatistics kHz, loadMHz; 751 uint32_t previousCpukHz = 0; 752#endif 753 // Assuming a normal distribution for cycle times, three standard deviations on either side of 754 // the mean account for 99.73% of the population. So if we take each tail to be 1/1000 of the 755 // sample set, we get 99.8% combined, or close to three standard deviations. 756 static const uint32_t kTailDenominator = 1000; 757 uint32_t *tail = n >= kTailDenominator ? new uint32_t[n] : NULL; 758 // loop over all the samples 759 for (uint32_t j = 0; j < n; ++j) { 760 size_t i = oldestClosed++ & (kSamplingN - 1); 761 uint32_t wallNs = mMonotonicNs[i]; 762 if (tail != NULL) { 763 tail[j] = wallNs; 764 } 765 wall.sample(wallNs); 766 uint32_t sampleLoadNs = mLoadNs[i]; 767 loadNs.sample(sampleLoadNs); 768#ifdef CPU_FREQUENCY_STATISTICS 769 uint32_t sampleCpukHz = mCpukHz[i]; 770 // skip bad kHz samples 771 if ((sampleCpukHz & ~0xF) != 0) { 772 kHz.sample(sampleCpukHz >> 4); 773 if (sampleCpukHz == previousCpukHz) { 774 double megacycles = (double) sampleLoadNs * (double) (sampleCpukHz >> 4) * 1e-12; 775 double adjMHz = megacycles / mixPeriodSec; // _not_ wallNs * 1e9 776 loadMHz.sample(adjMHz); 777 } 778 } 779 previousCpukHz = sampleCpukHz; 780#endif 781 } 782 fdprintf(fd, "Simple moving statistics over last %.1f seconds:\n", wall.n() * mixPeriodSec); 783 fdprintf(fd, " wall clock time in ms per mix cycle:\n" 784 " mean=%.2f min=%.2f max=%.2f stddev=%.2f\n", 785 wall.mean()*1e-6, wall.minimum()*1e-6, wall.maximum()*1e-6, wall.stddev()*1e-6); 786 fdprintf(fd, " raw CPU load in us per mix cycle:\n" 787 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n", 788 loadNs.mean()*1e-3, loadNs.minimum()*1e-3, loadNs.maximum()*1e-3, 789 loadNs.stddev()*1e-3); 790#ifdef CPU_FREQUENCY_STATISTICS 791 fdprintf(fd, " CPU clock frequency in MHz:\n" 792 " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n", 793 kHz.mean()*1e-3, kHz.minimum()*1e-3, kHz.maximum()*1e-3, kHz.stddev()*1e-3); 794 fdprintf(fd, " adjusted CPU load in MHz (i.e. normalized for CPU clock frequency):\n" 795 " mean=%.1f min=%.1f max=%.1f stddev=%.1f\n", 796 loadMHz.mean(), loadMHz.minimum(), loadMHz.maximum(), loadMHz.stddev()); 797#endif 798 if (tail != NULL) { 799 qsort(tail, n, sizeof(uint32_t), compare_uint32_t); 800 // assume same number of tail samples on each side, left and right 801 uint32_t count = n / kTailDenominator; 802 CentralTendencyStatistics left, right; 803 for (uint32_t i = 0; i < count; ++i) { 804 left.sample(tail[i]); 805 right.sample(tail[n - (i + 1)]); 806 } 807 fdprintf(fd, "Distribution of mix cycle times in ms for the tails (> ~3 stddev outliers):\n" 808 " left tail: mean=%.2f min=%.2f max=%.2f stddev=%.2f\n" 809 " right tail: mean=%.2f min=%.2f max=%.2f stddev=%.2f\n", 810 left.mean()*1e-6, left.minimum()*1e-6, left.maximum()*1e-6, left.stddev()*1e-6, 811 right.mean()*1e-6, right.minimum()*1e-6, right.maximum()*1e-6, 812 right.stddev()*1e-6); 813 delete[] tail; 814 } 815#endif 816 // The active track mask and track states are updated non-atomically. 817 // So if we relied on isActive to decide whether to display, 818 // then we might display an obsolete track or omit an active track. 819 // Instead we always display all tracks, with an indication 820 // of whether we think the track is active. 821 uint32_t trackMask = mTrackMask; 822 fdprintf(fd, "Fast tracks: kMaxFastTracks=%u activeMask=%#x\n", 823 FastMixerState::kMaxFastTracks, trackMask); 824 fdprintf(fd, "Index Active Full Partial Empty Recent Ready\n"); 825 for (uint32_t i = 0; i < FastMixerState::kMaxFastTracks; ++i, trackMask >>= 1) { 826 bool isActive = trackMask & 1; 827 const FastTrackDump *ftDump = &mTracks[i]; 828 const FastTrackUnderruns& underruns = ftDump->mUnderruns; 829 const char *mostRecent; 830 switch (underruns.mBitFields.mMostRecent) { 831 case UNDERRUN_FULL: 832 mostRecent = "full"; 833 break; 834 case UNDERRUN_PARTIAL: 835 mostRecent = "partial"; 836 break; 837 case UNDERRUN_EMPTY: 838 mostRecent = "empty"; 839 break; 840 default: 841 mostRecent = "?"; 842 break; 843 } 844 fdprintf(fd, "%5u %6s %4u %7u %5u %7s %5u\n", i, isActive ? "yes" : "no", 845 (underruns.mBitFields.mFull) & UNDERRUN_MASK, 846 (underruns.mBitFields.mPartial) & UNDERRUN_MASK, 847 (underruns.mBitFields.mEmpty) & UNDERRUN_MASK, 848 mostRecent, ftDump->mFramesReady); 849 } 850} 851 852} // namespace android 853