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