More log for issue 2242381.

Added more log in system dump for AudioFlinger and AudioPolicyService to help debug issue 2242381 and other issues where the audio driver hangs.

4 files changed, 120 insertions, 17 deletions

diff --git a/libs/audioflinger/AudioFlinger.cpp b/libs/audioflinger/AudioFlinger.cpp
index 9c0c850860..230e833c9d 100644
--- a/libs/audioflinger/AudioFlinger.cpp
+++ b/libs/audioflinger/AudioFlinger.cpp
@@ -815,6 +815,58 @@ void AudioFlinger::ThreadBase::processConfigEvents()
     mLock.unlock();
 }
 
+status_t AudioFlinger::ThreadBase::dumpBase(int fd, const Vector<String16>& args)
+{
+    const size_t SIZE = 256;
+    char buffer[SIZE];
+    String8 result;
+
+    bool locked = tryLock(mLock);
+    if (!locked) {
+        snprintf(buffer, SIZE, "thread %p maybe dead locked\n", this);
+        write(fd, buffer, strlen(buffer));
+    }
+
+    snprintf(buffer, SIZE, "standby: %d\n", mStandby);
+    result.append(buffer);
+    snprintf(buffer, SIZE, "Sample rate: %d\n", mSampleRate);
+    result.append(buffer);
+    snprintf(buffer, SIZE, "Frame count: %d\n", mFrameCount);
+    result.append(buffer);
+    snprintf(buffer, SIZE, "Channel Count: %d\n", mChannelCount);
+    result.append(buffer);
+    snprintf(buffer, SIZE, "Format: %d\n", mFormat);
+    result.append(buffer);
+    snprintf(buffer, SIZE, "Frame size: %d\n", mFrameSize);
+    result.append(buffer);
+
+    snprintf(buffer, SIZE, "\nPending setParameters commands: \n");
+    result.append(buffer);
+    result.append(" Index Command");
+    for (size_t i = 0; i < mNewParameters.size(); ++i) {
+        snprintf(buffer, SIZE, "\n %02d    ", i);
+        result.append(buffer);
+        result.append(mNewParameters[i]);
+    }
+
+    snprintf(buffer, SIZE, "\n\nPending config events: \n");
+    result.append(buffer);
+    snprintf(buffer, SIZE, " Index event param\n");
+    result.append(buffer);
+    for (size_t i = 0; i < mConfigEvents.size(); i++) {
+        snprintf(buffer, SIZE, " %02d    %02d    %d\n", i, mConfigEvents[i]->mEvent, mConfigEvents[i]->mParam);
+        result.append(buffer);
+    }
+    result.append("\n");
+
+    write(fd, result.string(), result.size());
+
+    if (locked) {
+        mLock.unlock();
+    }
+    return NO_ERROR;
+}
+
 
 // ----------------------------------------------------------------------------
 
@@ -856,7 +908,7 @@ status_t AudioFlinger::PlaybackThread::dumpTracks(int fd, const Vector<String16>
 
     snprintf(buffer, SIZE, "Output thread %p tracks\n", this);
     result.append(buffer);
-    result.append("   Name Clien Typ Fmt Chn Buf S M F SRate LeftV RighV Serv User\n");
+    result.append("   Name Clien Typ Fmt Chn Buf  S M F SRate  LeftV RighV Serv     User\n");
     for (size_t i = 0; i < mTracks.size(); ++i) {
         sp<Track> track = mTracks[i];
         if (track != 0) {
@@ -867,7 +919,7 @@ status_t AudioFlinger::PlaybackThread::dumpTracks(int fd, const Vector<String16>
 
     snprintf(buffer, SIZE, "Output thread %p active tracks\n", this);
     result.append(buffer);
-    result.append("   Name Clien Typ Fmt Chn Buf S M F SRate LeftV RighV Serv User\n");
+    result.append("   Name Clien Typ Fmt Chn Buf  S M F SRate  LeftV RighV Serv     User\n");
     for (size_t i = 0; i < mActiveTracks.size(); ++i) {
         wp<Track> wTrack = mActiveTracks[i];
         if (wTrack != 0) {
@@ -888,7 +940,7 @@ status_t AudioFlinger::PlaybackThread::dumpInternals(int fd, const Vector<String
     char buffer[SIZE];
     String8 result;
 
-    snprintf(buffer, SIZE, "Output thread %p internals\n", this);
+    snprintf(buffer, SIZE, "\nOutput thread %p internals\n", this);
     result.append(buffer);
     snprintf(buffer, SIZE, "last write occurred (msecs): %llu\n", ns2ms(systemTime() - mLastWriteTime));
     result.append(buffer);
@@ -898,9 +950,10 @@ status_t AudioFlinger::PlaybackThread::dumpInternals(int fd, const Vector<String
     result.append(buffer);
     snprintf(buffer, SIZE, "blocked in write: %d\n", mInWrite);
     result.append(buffer);
-    snprintf(buffer, SIZE, "standby: %d\n", mStandby);
-    result.append(buffer);
     write(fd, result.string(), result.size());
+
+    dumpBase(fd, args);
+
     return NO_ERROR;
 }
 
@@ -1493,8 +1546,6 @@ bool AudioFlinger::MixerThread::checkForNewParameters_l()
         AudioParameter param = AudioParameter(keyValuePair);
         int value;
 
-        mNewParameters.removeAt(0);
-
         if (param.getInt(String8(AudioParameter::keySamplingRate), value) == NO_ERROR) {
             reconfig = true;
         }
@@ -1546,6 +1597,9 @@ bool AudioFlinger::MixerThread::checkForNewParameters_l()
                 sendConfigEvent_l(AudioSystem::OUTPUT_CONFIG_CHANGED);
             }
         }
+
+        mNewParameters.removeAt(0);
+
         mParamStatus = status;
         mParamCond.signal();
         mWaitWorkCV.wait(mLock);
@@ -1818,8 +1872,6 @@ bool AudioFlinger::DirectOutputThread::checkForNewParameters_l()
         AudioParameter param = AudioParameter(keyValuePair);
         int value;
 
-        mNewParameters.removeAt(0);
-
         if (param.getInt(String8(AudioParameter::keyFrameCount), value) == NO_ERROR) {
             // do not accept frame count changes if tracks are open as the track buffer
             // size depends on frame count and correct behavior would not be garantied
@@ -1843,6 +1895,9 @@ bool AudioFlinger::DirectOutputThread::checkForNewParameters_l()
                 sendConfigEvent_l(AudioSystem::OUTPUT_CONFIG_CHANGED);
             }
         }
+
+        mNewParameters.removeAt(0);
+
         mParamStatus = status;
         mParamCond.signal();
         mWaitWorkCV.wait(mLock);
@@ -2253,7 +2308,7 @@ void AudioFlinger::PlaybackThread::Track::destroy()
 
 void AudioFlinger::PlaybackThread::Track::dump(char* buffer, size_t size)
 {
-    snprintf(buffer, size, "  %5d %5d %3u %3u %3u %3u %1d %1d %1d %5u %5u %5u %04x %04x\n",
+    snprintf(buffer, size, "  %5d %5d %3u %3u %3u %04u %1d %1d %1d %5u %5u %5u  %08x %08x\n",
             mName - AudioMixer::TRACK0,
             (mClient == NULL) ? getpid() : mClient->pid(),
             mStreamType,
@@ -2509,6 +2564,19 @@ void AudioFlinger::RecordThread::RecordTrack::stop()
     }
 }
 
+void AudioFlinger::RecordThread::RecordTrack::dump(char* buffer, size_t size)
+{
+    snprintf(buffer, size, "   %05d %03u %03u %04u %01d %05u  %08x %08x\n",
+            (mClient == NULL) ? getpid() : mClient->pid(),
+            mFormat,
+            mCblk->channels,
+            mFrameCount,
+            mState,
+            mCblk->sampleRate,
+            mCblk->server,
+            mCblk->user);
+}
+
 
 // ----------------------------------------------------------------------------
 
@@ -3136,13 +3204,34 @@ status_t AudioFlinger::RecordThread::dump(int fd, const Vector<String16>& args)
     String8 result;
     pid_t pid = 0;
 
-    if (mActiveTrack != 0 && mActiveTrack->mClient != 0) {
-        snprintf(buffer, SIZE, "Record client pid: %d\n", mActiveTrack->mClient->pid());
+    snprintf(buffer, SIZE, "\nInput thread %p internals\n", this);
+    result.append(buffer);
+
+    if (mActiveTrack != 0) {
+        result.append("Active Track:\n");
+        result.append("   Clien Fmt Chn Buf  S SRate  Serv     User\n");
+        mActiveTrack->dump(buffer, SIZE);
+        result.append(buffer);
+
+        snprintf(buffer, SIZE, "In index: %d\n", mRsmpInIndex);
+        result.append(buffer);
+        snprintf(buffer, SIZE, "In size: %d\n", mInputBytes);
+        result.append(buffer);
+        snprintf(buffer, SIZE, "Resampling: %d\n", (mResampler != 0));
+        result.append(buffer);
+        snprintf(buffer, SIZE, "Out channel count: %d\n", mReqChannelCount);
+        result.append(buffer);
+        snprintf(buffer, SIZE, "Out sample rate: %d\n", mReqSampleRate);
         result.append(buffer);
+
+
     } else {
         result.append("No record client\n");
     }
     write(fd, result.string(), result.size());
+
+    dumpBase(fd, args);
+
     return NO_ERROR;
 }
 
@@ -3198,8 +3287,6 @@ bool AudioFlinger::RecordThread::checkForNewParameters_l()
         int reqSamplingRate = mReqSampleRate;
         int reqChannelCount = mReqChannelCount;
 
-        mNewParameters.removeAt(0);
-
         if (param.getInt(String8(AudioParameter::keySamplingRate), value) == NO_ERROR) {
             reqSamplingRate = value;
             reconfig = true;
@@ -3241,6 +3328,9 @@ bool AudioFlinger::RecordThread::checkForNewParameters_l()
                 }
             }
         }
+
+        mNewParameters.removeAt(0);
+
         mParamStatus = status;
         mParamCond.signal();
         mWaitWorkCV.wait(mLock);
diff --git a/libs/audioflinger/AudioFlinger.h b/libs/audioflinger/AudioFlinger.h
index 56599f6ea6..22d15c9300 100644
--- a/libs/audioflinger/AudioFlinger.h
+++ b/libs/audioflinger/AudioFlinger.h
@@ -216,6 +216,8 @@ private:
         ThreadBase (const sp<AudioFlinger>& audioFlinger);
         virtual             ~ThreadBase();
 
+        status_t dumpBase(int fd, const Vector<String16>& args);
+
         // base for record and playback
         class TrackBase : public AudioBufferProvider, public RefBase {
 
@@ -678,6 +680,7 @@ private:
                     bool        overflow() { bool tmp = mOverflow; mOverflow = false; return tmp; }
                     bool        setOverflow() { bool tmp = mOverflow; mOverflow = true; return tmp; }
 
+                    void        dump(char* buffer, size_t size);
         private:
             friend class AudioFlinger;
             friend class RecordThread;
diff --git a/libs/audioflinger/AudioPolicyService.cpp b/libs/audioflinger/AudioPolicyService.cpp
index 97236973e6..aa48019929 100644
--- a/libs/audioflinger/AudioPolicyService.cpp
+++ b/libs/audioflinger/AudioPolicyService.cpp
@@ -592,6 +592,8 @@ bool AudioPolicyService::AudioCommandThread::threadLoop()
             if (mAudioCommands[0]->mTime <= curTime) {
                 AudioCommand *command = mAudioCommands[0];
                 mAudioCommands.removeAt(0);
+                mLastCommand = *command;
+
                 switch (command->mCommand) {
                 case START_TONE: {
                     mLock.unlock();
@@ -681,11 +683,15 @@ status_t AudioPolicyService::AudioCommandThread::dump(int fd)
 
     snprintf(buffer, SIZE, "- Commands:\n");
     result = String8(buffer);
-    result.append("   Command Time        Status  Wait pParam\n");
+    result.append("   Command Time        Wait pParam\n");
     for (int i = 0; i < (int)mAudioCommands.size(); i++) {
         mAudioCommands[i]->dump(buffer, SIZE);
         result.append(buffer);
     }
+    result.append("  Last Command\n");
+    mLastCommand.dump(buffer, SIZE);
+    result.append(buffer);
+
     write(fd, result.string(), result.size());
 
     if (locked) mLock.unlock();
@@ -894,11 +900,10 @@ void AudioPolicyService::AudioCommandThread::exit()
 
 void AudioPolicyService::AudioCommandThread::AudioCommand::dump(char* buffer, size_t size)
 {
-    snprintf(buffer, size, "   %02d      %06d.%03d  %03d     %01u    %p\n",
+    snprintf(buffer, size, "   %02d      %06d.%03d  %01u    %p\n",
             mCommand,
             (int)ns2s(mTime),
             (int)ns2ms(mTime)%1000,
-            mStatus,
             mWaitStatus,
             mParam);
 }
diff --git a/libs/audioflinger/AudioPolicyService.h b/libs/audioflinger/AudioPolicyService.h
index 7c1bb85993..b9234ec39c 100644
--- a/libs/audioflinger/AudioPolicyService.h
+++ b/libs/audioflinger/AudioPolicyService.h
@@ -152,7 +152,11 @@ private:
     private:
         // descriptor for requested tone playback event
         class AudioCommand {
+
         public:
+            AudioCommand()
+            : mCommand(-1) {}
+
             void dump(char* buffer, size_t size);
 
             int mCommand;   // START_TONE, STOP_TONE ...
@@ -191,6 +195,7 @@ private:
         Condition mWaitWorkCV;
         Vector <AudioCommand *> mAudioCommands; // list of pending commands
         ToneGenerator *mpToneGenerator;     // the tone generator
+        AudioCommand mLastCommand;
     };
 
     // Internal dump utilities.