audioflinger: fix FIXME in logBufferSizeUnderruns

Some debug code was accidentally merged.
The hang was caused by a recursive lock of mLock.
The code now calls lockfree methods.
Added events for RELEASE and SETBUFFERSIZE.

Bug: 157916126
Test: adb logcat | grep logBufferSize
Test: launch OboeTester
Test: disable MMAP checkbox
Test: Tap OPEN and START
Test: move bufferSize fader
Test: expect to see no spam from logBufferSizeInFrames()
Test: adb shell dumpsys media.metrics
Test: expect to see entries like "(bufferSizeFrames=118, underrun=1)"
Change-Id: I7d782ccea2c2470bc18a3a61cfb8767430a441d8
diff --git a/media/libaaudio/src/client/AudioStreamInternal.cpp b/media/libaaudio/src/client/AudioStreamInternal.cpp
index 79fa5ed..4520823 100644
--- a/media/libaaudio/src/client/AudioStreamInternal.cpp
+++ b/media/libaaudio/src/client/AudioStreamInternal.cpp
@@ -288,7 +288,7 @@
             requestStop();
         }
 
-        logBufferState();
+        logReleaseBufferState();
 
         setState(AAUDIO_STREAM_STATE_CLOSING);
         aaudio_handle_t serviceStreamHandle = mServiceStreamHandle;
@@ -783,6 +783,14 @@
         adjustedFrames = std::min(actualFrames, adjustedFrames);
     }
 
+    if (adjustedFrames != mBufferSizeInFrames) {
+        android::mediametrics::LogItem(mMetricsId)
+                .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_SETBUFFERSIZE)
+                .set(AMEDIAMETRICS_PROP_BUFFERSIZEFRAMES, adjustedFrames)
+                .set(AMEDIAMETRICS_PROP_UNDERRUN, (int32_t) getXRunCount())
+                .record();
+    }
+
     mBufferSizeInFrames = adjustedFrames;
     ALOGV("%s(%d) returns %d", __func__, requestedFrames, adjustedFrames);
     return (aaudio_result_t) adjustedFrames;
diff --git a/media/libaaudio/src/core/AudioStream.cpp b/media/libaaudio/src/core/AudioStream.cpp
index 0644368..bc973bd 100644
--- a/media/libaaudio/src/core/AudioStream.cpp
+++ b/media/libaaudio/src/core/AudioStream.cpp
@@ -116,9 +116,10 @@
     }
 }
 
-void AudioStream::logBufferState() {
+void AudioStream::logReleaseBufferState() {
     if (mMetricsId.size() > 0) {
         android::mediametrics::LogItem(mMetricsId)
+                .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_RELEASE)
                 .set(AMEDIAMETRICS_PROP_BUFFERSIZEFRAMES, (int32_t) getBufferSize())
                 .set(AMEDIAMETRICS_PROP_UNDERRUN, (int32_t) getXRunCount())
                 .record();
diff --git a/media/libaaudio/src/core/AudioStream.h b/media/libaaudio/src/core/AudioStream.h
index 613a092..fb71c36 100644
--- a/media/libaaudio/src/core/AudioStream.h
+++ b/media/libaaudio/src/core/AudioStream.h
@@ -115,7 +115,7 @@
 
     // log to MediaMetrics
     virtual void logOpen();
-    void logBufferState();
+    void logReleaseBufferState();
 
     /**
      * Free any hardware or system resources from the open() call.
diff --git a/media/libaaudio/src/legacy/AudioStreamRecord.cpp b/media/libaaudio/src/legacy/AudioStreamRecord.cpp
index 853c0db..6e5110f 100644
--- a/media/libaaudio/src/legacy/AudioStreamRecord.cpp
+++ b/media/libaaudio/src/legacy/AudioStreamRecord.cpp
@@ -292,7 +292,7 @@
     //  Then call it from here
     if (getState() != AAUDIO_STREAM_STATE_CLOSING) {
         mAudioRecord->removeAudioDeviceCallback(mDeviceCallback);
-        logBufferState();
+        logReleaseBufferState();
         mAudioRecord.clear();
         mFixedBlockWriter.close();
         return AudioStream::release_l();
diff --git a/media/libaaudio/src/legacy/AudioStreamTrack.cpp b/media/libaaudio/src/legacy/AudioStreamTrack.cpp
index 1120f05..ea08361 100644
--- a/media/libaaudio/src/legacy/AudioStreamTrack.cpp
+++ b/media/libaaudio/src/legacy/AudioStreamTrack.cpp
@@ -254,7 +254,7 @@
 aaudio_result_t AudioStreamTrack::release_l() {
     if (getState() != AAUDIO_STREAM_STATE_CLOSING) {
         mAudioTrack->removeAudioDeviceCallback(mDeviceCallback);
-        logBufferState();
+        logReleaseBufferState();
         // TODO Investigate why clear() causes a hang in test_various.cpp
         // if I call close() from a data callback.
         // But the same thing in AudioRecord is OK!
diff --git a/media/libaudioclient/AudioTrack.cpp b/media/libaudioclient/AudioTrack.cpp
index dd84511..88dc14e 100644
--- a/media/libaudioclient/AudioTrack.cpp
+++ b/media/libaudioclient/AudioTrack.cpp
@@ -785,8 +785,9 @@
             .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_STOP)
             .set(AMEDIAMETRICS_PROP_EXECUTIONTIMENS, (int64_t)(systemTime() - beginNs))
             .set(AMEDIAMETRICS_PROP_STATE, stateToString(mState))
+            .set(AMEDIAMETRICS_PROP_BUFFERSIZEFRAMES, (int32_t)mProxy->getBufferSizeInFrames())
+            .set(AMEDIAMETRICS_PROP_UNDERRUN, (int32_t) getUnderrunCount_l())
             .record();
-        logBufferSizeUnderruns();
     });
 
     ALOGV("%s(%d): prior state:%s", __func__, mPortId, stateToString(mState));
@@ -1139,16 +1140,6 @@
     return NO_ERROR;
 }
 
-void AudioTrack::logBufferSizeUnderruns() {
-    LOG_ALWAYS_FATAL_IF(mMetricsId.size() == 0, "mMetricsId is empty!");
-    ALOGD("%s(), mMetricsId = %s", __func__, mMetricsId.c_str());
-    // FIXME THis hangs! Why?
-//    android::mediametrics::LogItem(mMetricsId)
-//            .set(AMEDIAMETRICS_PROP_BUFFERSIZEFRAMES, (int32_t) getBufferSizeInFrames())
-//            .set(AMEDIAMETRICS_PROP_UNDERRUN, (int32_t) getUnderrunCount())
-//            .record();
-}
-
 ssize_t AudioTrack::setBufferSizeInFrames(size_t bufferSizeInFrames)
 {
     AutoMutex lock(mLock);
@@ -1163,7 +1154,11 @@
     ssize_t originalBufferSize = mProxy->getBufferSizeInFrames();
     ssize_t finalBufferSize  = mProxy->setBufferSizeInFrames((uint32_t) bufferSizeInFrames);
     if (originalBufferSize != finalBufferSize) {
-        logBufferSizeUnderruns();
+        android::mediametrics::LogItem(mMetricsId)
+                .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_SETBUFFERSIZE)
+                .set(AMEDIAMETRICS_PROP_BUFFERSIZEFRAMES, (int32_t)mProxy->getBufferSizeInFrames())
+                .set(AMEDIAMETRICS_PROP_UNDERRUN, (int32_t)getUnderrunCount_l())
+                .record();
     }
     return finalBufferSize;
 }
diff --git a/media/libaudioclient/include/media/AudioTrack.h b/media/libaudioclient/include/media/AudioTrack.h
index 17af7d4..0dbd842 100644
--- a/media/libaudioclient/include/media/AudioTrack.h
+++ b/media/libaudioclient/include/media/AudioTrack.h
@@ -1274,8 +1274,6 @@
     std::string mMetricsId;  // GUARDED_BY(mLock), could change in createTrack_l().
     std::string mCallerName; // for example "aaudio"
 
-    void logBufferSizeUnderruns();
-
 private:
     class AudioTrackCallback : public media::BnAudioTrackCallback {
     public:
diff --git a/media/libmediametrics/include/MediaMetricsConstants.h b/media/libmediametrics/include/MediaMetricsConstants.h
index b916a78..0906411 100644
--- a/media/libmediametrics/include/MediaMetricsConstants.h
+++ b/media/libmediametrics/include/MediaMetricsConstants.h
@@ -175,10 +175,12 @@
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_OPEN       "open"
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_PAUSE      "pause"  // AudioTrack
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_READPARAMETERS "readParameters" // Thread
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_RELEASE    "release"
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_RESTORE    "restore"
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_SETMODE    "setMode" // AudioFlinger
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_SETBUFFERSIZE    "setBufferSize" // AudioTrack
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_SETPLAYBACKPARAM "setPlaybackParam" // AudioTrack
-#define AMEDIAMETRICS_PROP_EVENT_VALUE_SETVOICEVOLUME "setVoiceVolume" // AudioFlinger
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_SETVOICEVOLUME   "setVoiceVolume" // AudioFlinger
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_SETVOLUME  "setVolume"  // AudioTrack
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_START      "start"  // AudioTrack, AudioRecord
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_STOP       "stop"   // AudioTrack, AudioRecord