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