Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 4dbb17e3 authored by Glenn Kasten's avatar Glenn Kasten Committed by The Android Automerger
Browse files

Temporary additional logging to investigate bug 

The bug appears related to continuing to use an invalid buffer provider
in fast mixer after track destruction, so focus the added logs in that area.

Also includes a bug fix: was calling log in an unsafe place
near Threads.cpp AudioFlinger::PlaybackThread::createTrack_l line 1250.

Details:
 - include caller pid or client pid where appropriate
 - increase log buffer size
 - log mFastIndex when AudioMixer sees an invalid bufferProvider.
 - log both potentially modified and actually modified tracks in FastMixer.
 - fix benign bug where sq->end() was called more than once.
 - log StateQueue push() call and return.
 - increase StateQueue size from 4 to 8 entries
 - log mixer->enable(), bufferProvider, and currentTrackMask
 - log buffer provider addresses
 - increase fast mixer log buffer again
 - check logf format vs. argument list compatibility
 - add logging to AudioMixer
 - add checking of magic field in AudioMixer to detect overwrites
 - add bool AudioMixer::enabled()

Bug: 6490974
Change-Id: I1f3f18aa62d9fbd35bc32285b669f5ba40efe28e
parent 15381e33

include/media/nbaio/NBLog.h

+2 −2
Original line number Diff line number Diff line
@@ -115,7 +115,7 @@ public: 
    virtual ~Writer() { }



    virtual void    log(const char *string);

    virtual void    logf(const char *fmt, ...);

    virtual void    logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));

    virtual void    logvf(const char *fmt, va_list ap);

    virtual void    logTimestamp();

    virtual void    logTimestamp(const struct timespec& ts);
@@ -149,7 +149,7 @@ public: 
    LockedWriter(size_t size, void *shared);



    virtual void    log(const char *string);

    virtual void    logf(const char *fmt, ...);

    virtual void    logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));

    virtual void    logvf(const char *fmt, va_list ap);

    virtual void    logTimestamp();

    virtual void    logTimestamp(const struct timespec& ts);

services/audioflinger/AudioFlinger.h

+1 −1
Original line number Diff line number Diff line
@@ -227,7 +227,7 @@ public: 
    sp<NBLog::Writer>   newWriter_l(size_t size, const char *name);

    void                unregisterWriter(const sp<NBLog::Writer>& writer);

private:

    static const size_t kLogMemorySize = 10 * 1024;

    static const size_t kLogMemorySize = 30 * 1024;

    sp<MemoryDealer>    mLogMemoryDealer;   // == 0 when NBLog is disabled

public:

services/audioflinger/AudioMixer.cpp

+43 −3
Original line number Diff line number Diff line
@@ -98,7 +98,7 @@ effect_descriptor_t AudioMixer::dwnmFxDesc; 


AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTracks)

    :   mTrackNames(0), mConfiguredNames((maxNumTracks >= 32 ? 0 : 1 << maxNumTracks) - 1),

        mSampleRate(sampleRate)

        mSampleRate(sampleRate), mLog(&mDummyLog)

{

    // AudioMixer is not yet capable of multi-channel beyond stereo

    COMPILE_TIME_ASSERT_FUNCTION_SCOPE(2 == MAX_NUM_CHANNELS);
@@ -122,6 +122,7 @@ AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTr 
    mState.hook         = process__nop;

    mState.outputTemp   = NULL;

    mState.resampleTemp = NULL;

    mState.mLog         = &mDummyLog;

    // mState.reserved



    // FIXME Most of the following initialization is probably redundant since
@@ -131,6 +132,7 @@ AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTr 
    for (unsigned i=0 ; i < MAX_NUM_TRACKS ; i++) {

        t->resampler = NULL;

        t->downmixerBufferProvider = NULL;

        t->magic = track_t::kMagic;

        t++;

    }
@@ -169,6 +171,12 @@ AudioMixer::~AudioMixer() 
    delete [] mState.resampleTemp;

}



void AudioMixer::setLog(NBLog::Writer *log)

{

    mLog = log;

    mState.mLog = log;

}



int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId)

{

    uint32_t names = (~mTrackNames) & mConfiguredNames;
@@ -209,9 +217,12 @@ int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId) 
        t->mainBuffer = NULL;

        t->auxBuffer = NULL;

        t->downmixerBufferProvider = NULL;

        t->fastIndex = -1;

        // t->magic unchanged



        status_t status = initTrackDownmix(&mState.tracks[n], n, channelMask);

        if (status == OK) {

            mLog->logf("getTrackName %d", n);

            return TRACK0 + n;

        }

        ALOGE("AudioMixer::getTrackName(0x%x) failed, error preparing track for downmix",
@@ -366,9 +377,11 @@ void AudioMixer::deleteTrackName(int name) 
{

    ALOGV("AudioMixer::deleteTrackName(%d)", name);

    name -= TRACK0;

    mLog->logf("deleteTrackName %d", name);

    ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);

    ALOGV("deleteTrackName(%d)", name);

    track_t& track(mState.tracks[ name ]);

    track.checkMagic();

    if (track.enabled) {

        track.enabled = false;

        invalidateState(1<<name);
@@ -387,8 +400,10 @@ void AudioMixer::enable(int name) 
    name -= TRACK0;

    ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);

    track_t& track = mState.tracks[name];

    track.checkMagic();



    if (!track.enabled) {

        mLog->logf("enable %d", name);

        track.enabled = true;

        ALOGV("enable(%d)", name);

        invalidateState(1 << name);
@@ -400,19 +415,32 @@ void AudioMixer::disable(int name) 
    name -= TRACK0;

    ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);

    track_t& track = mState.tracks[name];

    track.checkMagic();



    if (track.enabled) {

        mLog->logf("disable %d", name);

        track.enabled = false;

        ALOGV("disable(%d)", name);

        invalidateState(1 << name);

    }

}



bool AudioMixer::enabled(int name)

{

    name -= TRACK0;

    ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);

    track_t& track = mState.tracks[name];

    track.checkMagic();



    return track.enabled;

}



void AudioMixer::setParameter(int name, int target, int param, void *value)

{

    name -= TRACK0;

    ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);

    track_t& track = mState.tracks[name];

    track.checkMagic();



    int valueInt = (int)value;

    int32_t *valueBuf = (int32_t *)value;
@@ -455,6 +483,9 @@ void AudioMixer::setParameter(int name, int target, int param, void *value) 
        //         for a specific track? or per mixer?

        /* case DOWNMIX_TYPE:

            break          */

        case FAST_INDEX:

            track.fastIndex = valueInt;

            break;

        default:

            LOG_FATAL("bad param");

        }
@@ -540,6 +571,7 @@ void AudioMixer::setParameter(int name, int target, int param, void *value) 


bool AudioMixer::track_t::setResampler(uint32_t value, uint32_t devSampleRate)

{

    checkMagic();

    if (value != devSampleRate || resampler != NULL) {

        if (sampleRate != value) {

            sampleRate = value;
@@ -572,6 +604,7 @@ bool AudioMixer::track_t::setResampler(uint32_t value, uint32_t devSampleRate) 
inline

void AudioMixer::track_t::adjustVolumeRamp(bool aux)

{

    checkMagic();

    for (uint32_t i=0 ; i<MAX_NUM_CHANNELS ; i++) {

        if (((volumeInc[i]>0) && (((prevVolume[i]+volumeInc[i])>>16) >= volume[i])) ||

            ((volumeInc[i]<0) && (((prevVolume[i]+volumeInc[i])>>16) <= volume[i]))) {
@@ -600,8 +633,10 @@ size_t AudioMixer::getUnreleasedFrames(int name) const 
void AudioMixer::setBufferProvider(int name, AudioBufferProvider* bufferProvider)

{

    name -= TRACK0;

    mLog->logf("bp %d-%p", name, bufferProvider);

    ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);



    mState.tracks[name].checkMagic();

    if (mState.tracks[name].downmixerBufferProvider != NULL) {

        // update required?

        if (mState.tracks[name].downmixerBufferProvider->mTrackBufferProvider != bufferProvider) {
@@ -623,6 +658,9 @@ void AudioMixer::setBufferProvider(int name, AudioBufferProvider* bufferProvider 


void AudioMixer::process(int64_t pts)

{

    if (mState.needsChanged) {

        mLog->logf("process needs=%#x", mState.needsChanged);

    }

    mState.hook(&mState, pts);

}
@@ -647,6 +685,7 @@ void AudioMixer::process__validate(state_t* state, int64_t pts) 
    }

    state->enabledTracks &= ~disabled;

    state->enabledTracks |=  enabled;

    state->mLog->logf("process_validate ena=%#x", state->enabledTracks);



    // compute everything we need...

    int countActiveTracks = 0;
@@ -1103,6 +1142,7 @@ void AudioMixer::process__genericNoResampling(state_t* state, int64_t pts) 


    // acquire each track's buffer

    uint32_t enabledTracks = state->enabledTracks;

    state->mLog->logf("process_gNR ena=%#x", enabledTracks);

    uint32_t e0 = enabledTracks;

    while (e0) {

        const int i = 31 - __builtin_clz(e0);
@@ -1111,8 +1151,8 @@ void AudioMixer::process__genericNoResampling(state_t* state, int64_t pts) 
        t.buffer.frameCount = state->frameCount;

        int valid = t.bufferProvider->getValid();

        if (valid != AudioBufferProvider::kValid) {

            ALOGE("invalid bufferProvider=%p name=%d frameCount=%d valid=%#x enabledTracks=%#x",

                    t.bufferProvider, i, t.buffer.frameCount, valid, enabledTracks);

            ALOGE("invalid bufferProvider=%p name=%d fastIndex=%d frameCount=%d valid=%#x enabledTracks=%#x",

                    t.bufferProvider, i, t.fastIndex, t.buffer.frameCount, valid, enabledTracks);

            // expect to crash

        }

        t.bufferProvider->getNextBuffer(&t.buffer, pts);

services/audioflinger/AudioMixer.h

+20 −2
Original line number Diff line number Diff line
@@ -28,6 +28,7 @@ 


#include <audio_effects/effect_downmix.h>

#include <system/audio.h>

#include <media/nbaio/NBLog.h>



namespace android {
@@ -76,6 +77,7 @@ public: 
        MAIN_BUFFER     = 0x4002,

        AUX_BUFFER      = 0x4003,

        DOWNMIX_TYPE    = 0X4004,

        FAST_INDEX      = 0x4005, // for debugging only

        // for target RESAMPLE

        SAMPLE_RATE     = 0x4100, // Configure sample rate conversion on this track name;

                                  // parameter 'value' is the new sample rate in Hz.
@@ -106,6 +108,7 @@ public: 
    // Enable or disable an allocated track by name

    void        enable(int name);

    void        disable(int name);

    bool        enabled(int name);



    void        setParameter(int name, int target, int param, void *value);
@@ -200,7 +203,10 @@ private: 


        int32_t     sessionId;



        int32_t     padding[2];

        int32_t     fastIndex;

        int32_t     magic;

        static const int kMagic = 0x54637281;

        //int32_t     padding[1];



        // 16-byte boundary
@@ -210,6 +216,12 @@ private: 
        void        adjustVolumeRamp(bool aux);

        size_t      getUnreleasedFrames() const { return resampler != NULL ?

                                                    resampler->getUnreleasedFrames() : 0; };

        void        checkMagic() {

            if (magic != kMagic) {

                ALOGE("magic=%#x fastIndex=%d", magic, fastIndex);

            }

        }



    };



    // pad to 32-bytes to fill cache line
@@ -220,7 +232,8 @@ private: 
        void            (*hook)(state_t* state, int64_t pts);   // one of process__*, never NULL

        int32_t         *outputTemp;

        int32_t         *resampleTemp;

        int32_t         reserved[2];

        NBLog::Writer*  mLog;

        int32_t         reserved[1];

        // FIXME allocate dynamically to save some memory when maxNumTracks < MAX_NUM_TRACKS

        track_t         tracks[MAX_NUM_TRACKS]; __attribute__((aligned(32)));

    };
@@ -247,6 +260,11 @@ private: 


    const uint32_t  mSampleRate;



    NBLog::Writer*  mLog;

    NBLog::Writer   mDummyLog;

public:

    void            setLog(NBLog::Writer* log);

private:

    state_t         mState __attribute__((aligned(32)));



    // effect descriptor for the downmixer used by the mixer

services/audioflinger/FastMixer.cpp

+43 −2
Original line number Diff line number Diff line
@@ -120,12 +120,16 @@ bool FastMixer::threadLoop() 
        FastMixerState::Command command = next->mCommand;

        if (next != current) {



            logWriter->logTimestamp();

            logWriter->log("next != current");



            // As soon as possible of learning of a new dump area, start using it

            dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;

            teeSink = next->mTeeSink;

            logWriter = next->mNBLogWriter != NULL ? next->mNBLogWriter : &dummyLogWriter;

            if (mixer != NULL) {

                mixer->setLog(logWriter);

            }



            // We want to always have a valid reference to the previous (non-idle) state.

            // However, the state queue only guarantees access to current and previous states.
@@ -300,13 +304,21 @@ bool FastMixer::threadLoop() 
                    addedTracks &= ~(1 << i);

                    const FastTrack* fastTrack = &current->mFastTracks[i];

                    AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;

                    logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);

                    ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);

                    if (bufferProvider == NULL ||

                            bufferProvider->getValid() != AudioBufferProvider::kValid) {

                        logWriter->logTimestamp();

                        logWriter->logf("added invalid %#x", i);

                    }

                    if (mixer != NULL) {

                        // calling getTrackName with default channel mask and a random invalid

                        //   sessionId (no effects here)

                        name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO, -555);

                        ALOG_ASSERT(name >= 0);

                        fastTrackNames[i] = name;

                        mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX,

                                (void *) i);

                        mixer->setBufferProvider(name, bufferProvider);

                        mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,

                                (void *) mixBuffer);
@@ -317,27 +329,40 @@ bool FastMixer::threadLoop() 
                        }

                        mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,

                                (void *) fastTrack->mChannelMask);

                        if (!mixer->enabled(name)) {

                            logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);

                        }

                        mixer->enable(name);

                    }

                    generations[i] = fastTrack->mGeneration;

                }



                // finally process modified tracks; these use the same slot

                // finally process (potentially) modified tracks; these use the same slot

                // but may have a different buffer provider or volume provider

                unsigned modifiedTracks = currentTrackMask & previousTrackMask;

                if (modifiedTracks) {

                    logWriter->logf("modified %#x", modifiedTracks);

                    logWriter->logf("pot. mod. %#x", modifiedTracks);

                }

                unsigned actuallyModifiedTracks = 0;

                while (modifiedTracks != 0) {

                    i = __builtin_ctz(modifiedTracks);

                    modifiedTracks &= ~(1 << i);

                    const FastTrack* fastTrack = &current->mFastTracks[i];

                    if (fastTrack->mGeneration != generations[i]) {

                        actuallyModifiedTracks |= 1 << i;

                        AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;

                        logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);

                        ALOG_ASSERT(bufferProvider != NULL);

                        if (bufferProvider == NULL ||

                                bufferProvider->getValid() != AudioBufferProvider::kValid) {

                            logWriter->logTimestamp();

                            logWriter->logf("modified invalid %#x", i);

                        }

                        if (mixer != NULL) {

                            name = fastTrackNames[i];

                            ALOG_ASSERT(name >= 0);

                            mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX,

                                    (void *) i);

                            mixer->setBufferProvider(name, bufferProvider);

                            if (fastTrack->mVolumeProvider == NULL) {

                                mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
@@ -360,6 +385,9 @@ bool FastMixer::threadLoop() 
                        generations[i] = fastTrack->mGeneration;

                    }

                }

                if (actuallyModifiedTracks) {

                    logWriter->logf("act. mod. %#x", actuallyModifiedTracks);

                }



                fastTracksGen = current->mFastTracksGen;
@@ -377,6 +405,7 @@ bool FastMixer::threadLoop() 
            ALOG_ASSERT(mixBuffer != NULL);

            // for each track, update volume and check for underrun

            unsigned currentTrackMask = current->mTrackMask;

            logWriter->logf("ctm %#x", currentTrackMask);

            while (currentTrackMask != 0) {

                i = __builtin_ctz(currentTrackMask);

                currentTrackMask &= ~(1 << i);
@@ -414,15 +443,27 @@ bool FastMixer::threadLoop() 
                        // allow mixing partial buffer

                        underruns.mBitFields.mPartial++;

                        underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;

                        if (!mixer->enabled(name)) {

                            logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);

                        }

                        mixer->enable(name);

                    }

                } else {

                    underruns.mBitFields.mFull++;

                    underruns.mBitFields.mMostRecent = UNDERRUN_FULL;

                    if (!mixer->enabled(name)) {

                        logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);

                    }

                    mixer->enable(name);

                }

                ftDump->mUnderruns = underruns;

                ftDump->mFramesReady = framesReady;

                AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;

                if (bufferProvider == NULL ||

                        bufferProvider->getValid() != AudioBufferProvider::kValid) {

                    logWriter->logTimestamp();

                    logWriter->logf("mixing invalid %#x", i);

                }

            }



            int64_t pts;