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