FastMixer.cpp revision 42d45cfd0c3d62357a6549c62f535e4d4fe08d91
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#define LOG_TAG "FastMixer"
18//#define LOG_NDEBUG 0
19
20#include <sys/atomics.h>
21#include <time.h>
22#include <utils/Log.h>
23#include <system/audio.h>
24#ifdef FAST_MIXER_STATISTICS
25#include <cpustats/CentralTendencyStatistics.h>
26#include <cpustats/ThreadCpuUsage.h>
27#endif
28#include "AudioMixer.h"
29#include "FastMixer.h"
30
31#define FAST_HOT_IDLE_NS     1000000L   // 1 ms: time to sleep while hot idling
32#define FAST_DEFAULT_NS    999999999L   // ~1 sec: default time to sleep
33#define MAX_WARMUP_CYCLES         10    // maximum number of loop cycles to wait for warmup
34
35namespace android {
36
37// Fast mixer thread
38bool FastMixer::threadLoop()
39{
40    static const FastMixerState initial;
41    const FastMixerState *previous = &initial, *current = &initial;
42    FastMixerState preIdle; // copy of state before we went into idle
43    struct timespec oldTs = {0, 0};
44    bool oldTsValid = false;
45    long slopNs = 0;    // accumulated time we've woken up too early (> 0) or too late (< 0)
46    long sleepNs = -1;  // -1: busy wait, 0: sched_yield, > 0: nanosleep
47    int fastTrackNames[FastMixerState::kMaxFastTracks]; // handles used by mixer to identify tracks
48    int generations[FastMixerState::kMaxFastTracks];    // last observed mFastTracks[i].mGeneration
49    unsigned i;
50    for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
51        fastTrackNames[i] = -1;
52        generations[i] = 0;
53    }
54    NBAIO_Sink *outputSink = NULL;
55    int outputSinkGen = 0;
56    AudioMixer* mixer = NULL;
57    short *mixBuffer = NULL;
58    enum {UNDEFINED, MIXED, ZEROED} mixBufferState = UNDEFINED;
59    NBAIO_Format format = Format_Invalid;
60    unsigned sampleRate = 0;
61    int fastTracksGen = 0;
62    long periodNs = 0;      // expected period; the time required to render one mix buffer
63    long underrunNs = 0;    // underrun likely when write cycle is greater than this value
64    long overrunNs = 0;     // overrun likely when write cycle is less than this value
65    long warmupNs = 0;      // warmup complete when write cycle is greater than to this value
66    FastMixerDumpState dummyDumpState, *dumpState = &dummyDumpState;
67    bool ignoreNextOverrun = true;  // used to ignore initial overrun and first after an underrun
68#ifdef FAST_MIXER_STATISTICS
69    struct timespec oldLoad = {0, 0};    // previous value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
70    bool oldLoadValid = false;  // whether oldLoad is valid
71    uint32_t bounds = 0;
72    bool full = false;      // whether we have collected at least kSamplingN samples
73    ThreadCpuUsage tcu;     // for reading the current CPU clock frequency in kHz
74#endif
75    unsigned coldGen = 0;   // last observed mColdGen
76    bool isWarm = false;    // true means ready to mix, false means wait for warmup before mixing
77    struct timespec measuredWarmupTs = {0, 0};  // how long did it take for warmup to complete
78    uint32_t warmupCycles = 0;  // counter of number of loop cycles required to warmup
79
80    for (;;) {
81
82        // either nanosleep, sched_yield, or busy wait
83        if (sleepNs >= 0) {
84            if (sleepNs > 0) {
85                ALOG_ASSERT(sleepNs < 1000000000);
86                const struct timespec req = {0, sleepNs};
87                nanosleep(&req, NULL);
88            } else {
89                sched_yield();
90            }
91        }
92        // default to long sleep for next cycle
93        sleepNs = FAST_DEFAULT_NS;
94
95        // poll for state change
96        const FastMixerState *next = mSQ.poll();
97        if (next == NULL) {
98            // continue to use the default initial state until a real state is available
99            ALOG_ASSERT(current == &initial && previous == &initial);
100            next = current;
101        }
102
103        FastMixerState::Command command = next->mCommand;
104        if (next != current) {
105
106            // As soon as possible of learning of a new dump area, start using it
107            dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
108
109            // We want to always have a valid reference to the previous (non-idle) state.
110            // However, the state queue only guarantees access to current and previous states.
111            // So when there is a transition from a non-idle state into an idle state, we make a
112            // copy of the last known non-idle state so it is still available on return from idle.
113            // The possible transitions are:
114            //  non-idle -> non-idle    update previous from current in-place
115            //  non-idle -> idle        update previous from copy of current
116            //  idle     -> idle        don't update previous
117            //  idle     -> non-idle    don't update previous
118            if (!(current->mCommand & FastMixerState::IDLE)) {
119                if (command & FastMixerState::IDLE) {
120                    preIdle = *current;
121                    current = &preIdle;
122                    oldTsValid = false;
123                    oldLoadValid = false;
124                    ignoreNextOverrun = true;
125                }
126                previous = current;
127            }
128            current = next;
129        }
130#if !LOG_NDEBUG
131        next = NULL;    // not referenced again
132#endif
133
134        dumpState->mCommand = command;
135
136        switch (command) {
137        case FastMixerState::INITIAL:
138        case FastMixerState::HOT_IDLE:
139            sleepNs = FAST_HOT_IDLE_NS;
140            continue;
141        case FastMixerState::COLD_IDLE:
142            // only perform a cold idle command once
143            // FIXME consider checking previous state and only perform if previous != COLD_IDLE
144            if (current->mColdGen != coldGen) {
145                int32_t *coldFutexAddr = current->mColdFutexAddr;
146                ALOG_ASSERT(coldFutexAddr != NULL);
147                int32_t old = android_atomic_dec(coldFutexAddr);
148                if (old <= 0) {
149                    __futex_syscall4(coldFutexAddr, FUTEX_WAIT_PRIVATE, old - 1, NULL);
150                }
151                // This may be overly conservative; there could be times that the normal mixer
152                // requests such a brief cold idle that it doesn't require resetting this flag.
153                isWarm = false;
154                measuredWarmupTs.tv_sec = 0;
155                measuredWarmupTs.tv_nsec = 0;
156                warmupCycles = 0;
157                sleepNs = -1;
158                coldGen = current->mColdGen;
159                bounds = 0;
160                full = false;
161            } else {
162                sleepNs = FAST_HOT_IDLE_NS;
163            }
164            continue;
165        case FastMixerState::EXIT:
166            delete mixer;
167            delete[] mixBuffer;
168            return false;
169        case FastMixerState::MIX:
170        case FastMixerState::WRITE:
171        case FastMixerState::MIX_WRITE:
172            break;
173        default:
174            LOG_FATAL("bad command %d", command);
175        }
176
177        // there is a non-idle state available to us; did the state change?
178        size_t frameCount = current->mFrameCount;
179        if (current != previous) {
180
181            // handle state change here, but since we want to diff the state,
182            // we're prepared for previous == &initial the first time through
183            unsigned previousTrackMask;
184
185            // check for change in output HAL configuration
186            NBAIO_Format previousFormat = format;
187            if (current->mOutputSinkGen != outputSinkGen) {
188                outputSink = current->mOutputSink;
189                outputSinkGen = current->mOutputSinkGen;
190                if (outputSink == NULL) {
191                    format = Format_Invalid;
192                    sampleRate = 0;
193                } else {
194                    format = outputSink->format();
195                    sampleRate = Format_sampleRate(format);
196                    ALOG_ASSERT(Format_channelCount(format) == 2);
197                }
198                dumpState->mSampleRate = sampleRate;
199            }
200
201            if ((format != previousFormat) || (frameCount != previous->mFrameCount)) {
202                // FIXME to avoid priority inversion, don't delete here
203                delete mixer;
204                mixer = NULL;
205                delete[] mixBuffer;
206                mixBuffer = NULL;
207                if (frameCount > 0 && sampleRate > 0) {
208                    // FIXME new may block for unbounded time at internal mutex of the heap
209                    //       implementation; it would be better to have normal mixer allocate for us
210                    //       to avoid blocking here and to prevent possible priority inversion
211                    mixer = new AudioMixer(frameCount, sampleRate, FastMixerState::kMaxFastTracks);
212                    mixBuffer = new short[frameCount * 2];
213                    periodNs = (frameCount * 1000000000LL) / sampleRate;    // 1.00
214                    underrunNs = (frameCount * 1750000000LL) / sampleRate;  // 1.75
215                    overrunNs = (frameCount * 250000000LL) / sampleRate;    // 0.25
216                    warmupNs = (frameCount * 500000000LL) / sampleRate;     // 0.50
217                } else {
218                    periodNs = 0;
219                    underrunNs = 0;
220                    overrunNs = 0;
221                }
222                mixBufferState = UNDEFINED;
223#if !LOG_NDEBUG
224                for (i = 0; i < FastMixerState::kMaxFastTracks; ++i) {
225                    fastTrackNames[i] = -1;
226                }
227#endif
228                // we need to reconfigure all active tracks
229                previousTrackMask = 0;
230                fastTracksGen = current->mFastTracksGen - 1;
231                dumpState->mFrameCount = frameCount;
232            } else {
233                previousTrackMask = previous->mTrackMask;
234            }
235
236            // check for change in active track set
237            unsigned currentTrackMask = current->mTrackMask;
238            if (current->mFastTracksGen != fastTracksGen) {
239                ALOG_ASSERT(mixBuffer != NULL);
240                int name;
241
242                // process removed tracks first to avoid running out of track names
243                unsigned removedTracks = previousTrackMask & ~currentTrackMask;
244                while (removedTracks != 0) {
245                    i = __builtin_ctz(removedTracks);
246                    removedTracks &= ~(1 << i);
247                    const FastTrack* fastTrack = &current->mFastTracks[i];
248                    ALOG_ASSERT(fastTrack->mBufferProvider == NULL);
249                    if (mixer != NULL) {
250                        name = fastTrackNames[i];
251                        ALOG_ASSERT(name >= 0);
252                        mixer->deleteTrackName(name);
253                    }
254#if !LOG_NDEBUG
255                    fastTrackNames[i] = -1;
256#endif
257                    // don't reset track dump state, since other side is ignoring it
258                    generations[i] = fastTrack->mGeneration;
259                }
260
261                // now process added tracks
262                unsigned addedTracks = currentTrackMask & ~previousTrackMask;
263                while (addedTracks != 0) {
264                    i = __builtin_ctz(addedTracks);
265                    addedTracks &= ~(1 << i);
266                    const FastTrack* fastTrack = &current->mFastTracks[i];
267                    AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
268                    ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);
269                    if (mixer != NULL) {
270                        // calling getTrackName with default channel mask
271                        name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO);
272                        ALOG_ASSERT(name >= 0);
273                        fastTrackNames[i] = name;
274                        mixer->setBufferProvider(name, bufferProvider);
275                        mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,
276                                (void *) mixBuffer);
277                        // newly allocated track names default to full scale volume
278                        if (fastTrack->mSampleRate != 0 && fastTrack->mSampleRate != sampleRate) {
279                            mixer->setParameter(name, AudioMixer::RESAMPLE,
280                                    AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate);
281                        }
282                        mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
283                                (void *) fastTrack->mChannelMask);
284                        mixer->enable(name);
285                    }
286                    generations[i] = fastTrack->mGeneration;
287                }
288
289                // finally process modified tracks; these use the same slot
290                // but may have a different buffer provider or volume provider
291                unsigned modifiedTracks = currentTrackMask & previousTrackMask;
292                while (modifiedTracks != 0) {
293                    i = __builtin_ctz(modifiedTracks);
294                    modifiedTracks &= ~(1 << i);
295                    const FastTrack* fastTrack = &current->mFastTracks[i];
296                    if (fastTrack->mGeneration != generations[i]) {
297                        AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
298                        ALOG_ASSERT(bufferProvider != NULL);
299                        if (mixer != NULL) {
300                            name = fastTrackNames[i];
301                            ALOG_ASSERT(name >= 0);
302                            mixer->setBufferProvider(name, bufferProvider);
303                            if (fastTrack->mVolumeProvider == NULL) {
304                                mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
305                                        (void *)0x1000);
306                                mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
307                                        (void *)0x1000);
308                            }
309                            if (fastTrack->mSampleRate != 0 &&
310                                    fastTrack->mSampleRate != sampleRate) {
311                                mixer->setParameter(name, AudioMixer::RESAMPLE,
312                                        AudioMixer::SAMPLE_RATE, (void*) fastTrack->mSampleRate);
313                            } else {
314                                mixer->setParameter(name, AudioMixer::RESAMPLE,
315                                        AudioMixer::REMOVE, NULL);
316                            }
317                            mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
318                                    (void *) fastTrack->mChannelMask);
319                            // already enabled
320                        }
321                        generations[i] = fastTrack->mGeneration;
322                    }
323                }
324
325                fastTracksGen = current->mFastTracksGen;
326
327                dumpState->mNumTracks = popcount(currentTrackMask);
328            }
329
330#if 1   // FIXME shouldn't need this
331            // only process state change once
332            previous = current;
333#endif
334        }
335
336        // do work using current state here
337        if ((command & FastMixerState::MIX) && (mixer != NULL) && isWarm) {
338            ALOG_ASSERT(mixBuffer != NULL);
339            // for each track, update volume and check for underrun
340            unsigned currentTrackMask = current->mTrackMask;
341            while (currentTrackMask != 0) {
342                i = __builtin_ctz(currentTrackMask);
343                currentTrackMask &= ~(1 << i);
344                const FastTrack* fastTrack = &current->mFastTracks[i];
345                int name = fastTrackNames[i];
346                ALOG_ASSERT(name >= 0);
347                if (fastTrack->mVolumeProvider != NULL) {
348                    uint32_t vlr = fastTrack->mVolumeProvider->getVolumeLR();
349                    mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
350                            (void *)(vlr & 0xFFFF));
351                    mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME1,
352                            (void *)(vlr >> 16));
353                }
354                // FIXME The current implementation of framesReady() for fast tracks
355                // takes a tryLock, which can block
356                // up to 1 ms.  If enough active tracks all blocked in sequence, this would result
357                // in the overall fast mix cycle being delayed.  Should use a non-blocking FIFO.
358                size_t framesReady = fastTrack->mBufferProvider->framesReady();
359                FastTrackDump *ftDump = &dumpState->mTracks[i];
360                uint32_t underruns = ftDump->mUnderruns;
361                if (framesReady < frameCount) {
362                    ftDump->mUnderruns = (underruns + 2) | 1;
363                    if (framesReady == 0) {
364                        mixer->disable(name);
365                    } else {
366                        // allow mixing partial buffer
367                        mixer->enable(name);
368                    }
369                } else if (underruns & 1) {
370                    ftDump->mUnderruns = underruns & ~1;
371                    mixer->enable(name);
372                }
373            }
374            // process() is CPU-bound
375            mixer->process(AudioBufferProvider::kInvalidPTS);
376            mixBufferState = MIXED;
377        } else if (mixBufferState == MIXED) {
378            mixBufferState = UNDEFINED;
379        }
380        bool attemptedWrite = false;
381        //bool didFullWrite = false;    // dumpsys could display a count of partial writes
382        if ((command & FastMixerState::WRITE) && (outputSink != NULL) && (mixBuffer != NULL)) {
383            if (mixBufferState == UNDEFINED) {
384                memset(mixBuffer, 0, frameCount * 2 * sizeof(short));
385                mixBufferState = ZEROED;
386            }
387            // FIXME write() is non-blocking and lock-free for a properly implemented NBAIO sink,
388            //       but this code should be modified to handle both non-blocking and blocking sinks
389            dumpState->mWriteSequence++;
390            ssize_t framesWritten = outputSink->write(mixBuffer, frameCount);
391            dumpState->mWriteSequence++;
392            if (framesWritten >= 0) {
393                ALOG_ASSERT(framesWritten <= frameCount);
394                dumpState->mFramesWritten += framesWritten;
395                //if ((size_t) framesWritten == frameCount) {
396                //    didFullWrite = true;
397                //}
398            } else {
399                dumpState->mWriteErrors++;
400            }
401            attemptedWrite = true;
402            // FIXME count # of writes blocked excessively, CPU usage, etc. for dump
403        }
404
405        // To be exactly periodic, compute the next sleep time based on current time.
406        // This code doesn't have long-term stability when the sink is non-blocking.
407        // FIXME To avoid drift, use the local audio clock or watch the sink's fill status.
408        struct timespec newTs;
409        int rc = clock_gettime(CLOCK_MONOTONIC, &newTs);
410        if (rc == 0) {
411            if (oldTsValid) {
412                time_t sec = newTs.tv_sec - oldTs.tv_sec;
413                long nsec = newTs.tv_nsec - oldTs.tv_nsec;
414                if (nsec < 0) {
415                    --sec;
416                    nsec += 1000000000;
417                }
418                // To avoid an initial underrun on fast tracks after exiting standby,
419                // do not start pulling data from tracks and mixing until warmup is complete.
420                // Warmup is considered complete after the earlier of:
421                //      first successful single write() that blocks for more than warmupNs
422                //      MAX_WARMUP_CYCLES write() attempts.
423                // This is overly conservative, but to get better accuracy requires a new HAL API.
424                if (!isWarm && attemptedWrite) {
425                    measuredWarmupTs.tv_sec += sec;
426                    measuredWarmupTs.tv_nsec += nsec;
427                    if (measuredWarmupTs.tv_nsec >= 1000000000) {
428                        measuredWarmupTs.tv_sec++;
429                        measuredWarmupTs.tv_nsec -= 1000000000;
430                    }
431                    ++warmupCycles;
432                    if ((attemptedWrite && nsec > warmupNs) ||
433                            (warmupCycles >= MAX_WARMUP_CYCLES)) {
434                        isWarm = true;
435                        dumpState->mMeasuredWarmupTs = measuredWarmupTs;
436                        dumpState->mWarmupCycles = warmupCycles;
437                    }
438                }
439                if (sec > 0 || nsec > underrunNs) {
440                    // FIXME only log occasionally
441                    ALOGV("underrun: time since last cycle %d.%03ld sec",
442                            (int) sec, nsec / 1000000L);
443                    dumpState->mUnderruns++;
444                    sleepNs = -1;
445                    ignoreNextOverrun = true;
446                } else if (nsec < overrunNs) {
447                    if (ignoreNextOverrun) {
448                        ignoreNextOverrun = false;
449                    } else {
450                        // FIXME only log occasionally
451                        ALOGV("overrun: time since last cycle %d.%03ld sec",
452                                (int) sec, nsec / 1000000L);
453                        dumpState->mOverruns++;
454                    }
455                    sleepNs = periodNs - overrunNs;
456                } else {
457                    sleepNs = -1;
458                    ignoreNextOverrun = false;
459                }
460#ifdef FAST_MIXER_STATISTICS
461                // advance the FIFO queue bounds
462                size_t i = bounds & (FastMixerDumpState::kSamplingN - 1);
463                bounds = (bounds + 1) & 0xFFFF;
464                if (full) {
465                    bounds += 0x10000;
466                } else if (!(bounds & (FastMixerDumpState::kSamplingN - 1))) {
467                    full = true;
468                }
469                // compute the delta value of clock_gettime(CLOCK_MONOTONIC)
470                uint32_t monotonicNs = nsec;
471                if (sec > 0 && sec < 4) {
472                    monotonicNs += sec * 1000000000;
473                }
474                // compute the raw CPU load = delta value of clock_gettime(CLOCK_THREAD_CPUTIME_ID)
475                uint32_t loadNs = 0;
476                struct timespec newLoad;
477                rc = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &newLoad);
478                if (rc == 0) {
479                    if (oldLoadValid) {
480                        sec = newLoad.tv_sec - oldLoad.tv_sec;
481                        nsec = newLoad.tv_nsec - oldLoad.tv_nsec;
482                        if (nsec < 0) {
483                            --sec;
484                            nsec += 1000000000;
485                        }
486                        loadNs = nsec;
487                        if (sec > 0 && sec < 4) {
488                            loadNs += sec * 1000000000;
489                        }
490                    } else {
491                        // first time through the loop
492                        oldLoadValid = true;
493                    }
494                    oldLoad = newLoad;
495                }
496                // get the absolute value of CPU clock frequency in kHz
497                int cpuNum = sched_getcpu();
498                uint32_t kHz = tcu.getCpukHz(cpuNum);
499                kHz = (kHz & ~0xF) | (cpuNum & 0xF);
500                // save values in FIFO queues for dumpsys
501                // these stores #1, #2, #3 are not atomic with respect to each other,
502                // or with respect to store #4 below
503                dumpState->mMonotonicNs[i] = monotonicNs;
504                dumpState->mLoadNs[i] = loadNs;
505                dumpState->mCpukHz[i] = kHz;
506                // this store #4 is not atomic with respect to stores #1, #2, #3 above, but
507                // the newest open and oldest closed halves are atomic with respect to each other
508                dumpState->mBounds = bounds;
509#endif
510            } else {
511                // first time through the loop
512                oldTsValid = true;
513                sleepNs = periodNs;
514                ignoreNextOverrun = true;
515            }
516            oldTs = newTs;
517        } else {
518            // monotonic clock is broken
519            oldTsValid = false;
520            sleepNs = periodNs;
521        }
522
523
524    }   // for (;;)
525
526    // never return 'true'; Thread::_threadLoop() locks mutex which can result in priority inversion
527}
528
529FastMixerDumpState::FastMixerDumpState() :
530    mCommand(FastMixerState::INITIAL), mWriteSequence(0), mFramesWritten(0),
531    mNumTracks(0), mWriteErrors(0), mUnderruns(0), mOverruns(0),
532    mSampleRate(0), mFrameCount(0), /* mMeasuredWarmupTs({0, 0}), */ mWarmupCycles(0)
533#ifdef FAST_MIXER_STATISTICS
534    , mBounds(0)
535#endif
536{
537    mMeasuredWarmupTs.tv_sec = 0;
538    mMeasuredWarmupTs.tv_nsec = 0;
539    // sample arrays aren't accessed atomically with respect to the bounds,
540    // so clearing reduces chance for dumpsys to read random uninitialized samples
541    memset(&mMonotonicNs, 0, sizeof(mMonotonicNs));
542    memset(&mLoadNs, 0, sizeof(mLoadNs));
543    memset(&mCpukHz, 0, sizeof(mCpukHz));
544}
545
546FastMixerDumpState::~FastMixerDumpState()
547{
548}
549
550void FastMixerDumpState::dump(int fd)
551{
552#define COMMAND_MAX 32
553    char string[COMMAND_MAX];
554    switch (mCommand) {
555    case FastMixerState::INITIAL:
556        strcpy(string, "INITIAL");
557        break;
558    case FastMixerState::HOT_IDLE:
559        strcpy(string, "HOT_IDLE");
560        break;
561    case FastMixerState::COLD_IDLE:
562        strcpy(string, "COLD_IDLE");
563        break;
564    case FastMixerState::EXIT:
565        strcpy(string, "EXIT");
566        break;
567    case FastMixerState::MIX:
568        strcpy(string, "MIX");
569        break;
570    case FastMixerState::WRITE:
571        strcpy(string, "WRITE");
572        break;
573    case FastMixerState::MIX_WRITE:
574        strcpy(string, "MIX_WRITE");
575        break;
576    default:
577        snprintf(string, COMMAND_MAX, "%d", mCommand);
578        break;
579    }
580    double measuredWarmupMs = (mMeasuredWarmupTs.tv_sec * 1000.0) +
581            (mMeasuredWarmupTs.tv_nsec / 1000000.0);
582    double mixPeriodSec = (double) mFrameCount / (double) mSampleRate;
583    fdprintf(fd, "FastMixer command=%s writeSequence=%u framesWritten=%u\n"
584                 "          numTracks=%u writeErrors=%u underruns=%u overruns=%u\n"
585                 "          sampleRate=%u frameCount=%u measuredWarmup=%.3g ms, warmupCycles=%u\n"
586                 "          mixPeriod=%.2f ms\n",
587                 string, mWriteSequence, mFramesWritten,
588                 mNumTracks, mWriteErrors, mUnderruns, mOverruns,
589                 mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles,
590                 mixPeriodSec * 1e3);
591#ifdef FAST_MIXER_STATISTICS
592    // find the interval of valid samples
593    uint32_t bounds = mBounds;
594    uint32_t newestOpen = bounds & 0xFFFF;
595    uint32_t oldestClosed = bounds >> 16;
596    uint32_t n = (newestOpen - oldestClosed) & 0xFFFF;
597    if (n > kSamplingN) {
598        ALOGE("too many samples %u", n);
599        n = kSamplingN;
600    }
601    // statistics for monotonic (wall clock) time, thread raw CPU load in time, CPU clock frequency,
602    // and adjusted CPU load in MHz normalized for CPU clock frequency
603    CentralTendencyStatistics wall, loadNs, kHz, loadMHz;
604    // only compute adjusted CPU load in Hz if current CPU number and CPU clock frequency are stable
605    bool valid = false;
606    uint32_t previousCpukHz = 0;
607    // loop over all the samples
608    for (; n > 0; --n) {
609        size_t i = oldestClosed++ & (kSamplingN - 1);
610        uint32_t wallNs = mMonotonicNs[i];
611        wall.sample(wallNs);
612        uint32_t sampleLoadNs = mLoadNs[i];
613        uint32_t sampleCpukHz = mCpukHz[i];
614        loadNs.sample(sampleLoadNs);
615        kHz.sample(sampleCpukHz & ~0xF);
616        if (sampleCpukHz == previousCpukHz) {
617            double megacycles = (double) sampleLoadNs * (double) sampleCpukHz;
618            double adjMHz = megacycles / mixPeriodSec;  // _not_ wallNs * 1e9
619            loadMHz.sample(adjMHz);
620        }
621        previousCpukHz = sampleCpukHz;
622    }
623    fdprintf(fd, "Simple moving statistics over last %.1f seconds:\n", wall.n() * mixPeriodSec);
624    fdprintf(fd, "  wall clock time in ms per mix cycle:\n"
625                 "    mean=%.2f min=%.2f max=%.2f stddev=%.2f\n",
626                 wall.mean()*1e-6, wall.minimum()*1e-6, wall.maximum()*1e-6, wall.stddev()*1e-6);
627    fdprintf(fd, "  raw CPU load in us per mix cycle:\n"
628                 "    mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
629                 loadNs.mean()*1e-3, loadNs.minimum()*1e-3, loadNs.maximum()*1e-3,
630                 loadNs.stddev()*1e-3);
631    fdprintf(fd, "  CPU clock frequency in MHz:\n"
632                 "    mean=%.0f min=%.0f max=%.0f stddev=%.0f\n",
633                 kHz.mean()*1e-3, kHz.minimum()*1e-3, kHz.maximum()*1e-3, kHz.stddev()*1e-3);
634    fdprintf(fd, "  adjusted CPU load in MHz (i.e. normalized for CPU clock frequency):\n"
635                 "    mean=%.1f min=%.1f max=%.1f stddev=%.1f\n",
636                 loadMHz.mean(), loadMHz.minimum(), loadMHz.maximum(), loadMHz.stddev());
637#endif
638}
639
640}   // namespace android
641