aaudio: add MediaMetrics for MMAP streams

Log events from service.
Log start, stop, disconnect and other events.
Log underruns and bufferSize.

Bug: 154543374
Test: adb shell dumpsys media.metrics --clear
Test: run an app that uses MMAP, like OboeTester
Test: adb shell dumpsys media.metrics
Test: Expect to see lots of "audio.stream" events.
Change-Id: I690e5226b695d53d038d644f4438c759e08f9fbb
diff --git a/media/libaaudio/src/Android.bp b/media/libaaudio/src/Android.bp
index 901c28f..717f31a 100644
--- a/media/libaaudio/src/Android.bp
+++ b/media/libaaudio/src/Android.bp
@@ -35,6 +35,9 @@
         "libaaudio_internal",
         "libaudioclient",
         "libaudioutils",
+        "libmedia_helper",
+        "libmediametrics",
+        "libmediautils",
         "liblog",
         "libcutils",
         "libutils",
@@ -75,6 +78,9 @@
     shared_libs: [
         "libaudioclient",
         "libaudioutils",
+        "libmedia_helper",
+        "libmediametrics",
+        "libmediautils",
         "liblog",
         "libcutils",
         "libutils",
diff --git a/media/libaaudio/src/client/AudioStreamInternal.cpp b/media/libaaudio/src/client/AudioStreamInternal.cpp
index f89cde7..3db0099 100644
--- a/media/libaaudio/src/client/AudioStreamInternal.cpp
+++ b/media/libaaudio/src/client/AudioStreamInternal.cpp
@@ -14,9 +14,7 @@
  * limitations under the License.
  */
 
-// This file is used in both client and server processes.
-// This is needed to make sense of the logs more easily.
-#define LOG_TAG (mInService ? "AudioStreamInternal_Service" : "AudioStreamInternal_Client")
+#define LOG_TAG "AudioStreamInternal"
 //#define LOG_NDEBUG 0
 #include <utils/Log.h>
 
@@ -28,6 +26,8 @@
 
 #include <aaudio/AAudio.h>
 #include <cutils/properties.h>
+
+#include <media/MediaMetricsItem.h>
 #include <utils/String16.h>
 #include <utils/Trace.h>
 
@@ -36,12 +36,20 @@
 #include "binding/AAudioStreamConfiguration.h"
 #include "binding/IAAudioService.h"
 #include "binding/AAudioServiceMessage.h"
+#include "core/AudioGlobal.h"
 #include "core/AudioStreamBuilder.h"
 #include "fifo/FifoBuffer.h"
 #include "utility/AudioClock.h"
 
 #include "AudioStreamInternal.h"
 
+// We do this after the #includes because if a header uses ALOG.
+// it would fail on the reference to mInService.
+#undef LOG_TAG
+// This file is used in both client and server processes.
+// This is needed to make sense of the logs more easily.
+#define LOG_TAG (mInService ? "AudioStreamInternal_Service" : "AudioStreamInternal_Client")
+
 using android::String16;
 using android::Mutex;
 using android::WrappingBuffer;
@@ -137,6 +145,11 @@
         return mServiceStreamHandle;
     }
 
+    // This must match the key generated in oboeservice/AAudioServiceStreamBase.cpp
+    // so the client can have permission to log.
+    mMetricsId = std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_STREAM)
+            + std::to_string(mServiceStreamHandle);
+
     result = configurationOutput.validate();
     if (result != AAUDIO_OK) {
         goto error;
@@ -274,6 +287,9 @@
         if (isActive() || currentState == AAUDIO_STREAM_STATE_DISCONNECTED) {
             requestStop();
         }
+
+        logBufferState();
+
         setState(AAUDIO_STREAM_STATE_CLOSING);
         aaudio_handle_t serviceStreamHandle = mServiceStreamHandle;
         mServiceStreamHandle = AAUDIO_HANDLE_INVALID;
diff --git a/media/libaaudio/src/core/AudioGlobal.cpp b/media/libaaudio/src/core/AudioGlobal.cpp
index d299761..7f5d8d5 100644
--- a/media/libaaudio/src/core/AudioGlobal.cpp
+++ b/media/libaaudio/src/core/AudioGlobal.cpp
@@ -71,7 +71,42 @@
         AAUDIO_CASE_ENUM(AAUDIO_ERROR_NO_SERVICE);
         AAUDIO_CASE_ENUM(AAUDIO_ERROR_INVALID_RATE);
     }
-    return "Unrecognized AAudio error.";
+    return "Unrecognized";
+}
+
+const char* AudioGlobal_convertFormatToText(aaudio_format_t format) {
+      switch (format) {
+        AAUDIO_CASE_ENUM(AAUDIO_FORMAT_UNSPECIFIED);
+        AAUDIO_CASE_ENUM(AAUDIO_FORMAT_INVALID);
+        AAUDIO_CASE_ENUM(AAUDIO_FORMAT_PCM_I16);
+        AAUDIO_CASE_ENUM(AAUDIO_FORMAT_PCM_FLOAT);
+    }
+    return "Unrecognized";
+}
+
+const char* AudioGlobal_convertDirectionToText(aaudio_direction_t direction) {
+      switch (direction) {
+        AAUDIO_CASE_ENUM(AAUDIO_DIRECTION_INPUT);
+        AAUDIO_CASE_ENUM(AAUDIO_DIRECTION_OUTPUT);
+    }
+    return "Unrecognized";
+}
+
+const char* AudioGlobal_convertPerformanceModeToText(aaudio_performance_mode_t mode) {
+      switch (mode) {
+        AAUDIO_CASE_ENUM(AAUDIO_PERFORMANCE_MODE_POWER_SAVING);
+        AAUDIO_CASE_ENUM(AAUDIO_PERFORMANCE_MODE_NONE);
+        AAUDIO_CASE_ENUM(AAUDIO_PERFORMANCE_MODE_LOW_LATENCY);
+    }
+    return "Unrecognized";
+}
+
+const char* AudioGlobal_convertSharingModeToText(aaudio_sharing_mode_t mode) {
+      switch (mode) {
+        AAUDIO_CASE_ENUM(AAUDIO_SHARING_MODE_SHARED);
+        AAUDIO_CASE_ENUM(AAUDIO_SHARING_MODE_EXCLUSIVE);
+    }
+    return "Unrecognized";
 }
 
 const char* AudioGlobal_convertStreamStateToText(aaudio_stream_state_t state) {
@@ -91,7 +126,7 @@
         AAUDIO_CASE_ENUM(AAUDIO_STREAM_STATE_CLOSED);
         AAUDIO_CASE_ENUM(AAUDIO_STREAM_STATE_DISCONNECTED);
     }
-    return "Unrecognized AAudio state.";
+    return "Unrecognized";
 }
 
 #undef AAUDIO_CASE_ENUM
diff --git a/media/libaaudio/src/core/AudioGlobal.h b/media/libaaudio/src/core/AudioGlobal.h
index 312cef2..1e88d15 100644
--- a/media/libaaudio/src/core/AudioGlobal.h
+++ b/media/libaaudio/src/core/AudioGlobal.h
@@ -25,9 +25,12 @@
 aaudio_policy_t AudioGlobal_getMMapPolicy();
 aaudio_result_t AudioGlobal_setMMapPolicy(aaudio_policy_t policy);
 
+const char* AudioGlobal_convertFormatToText(aaudio_format_t format);
+const char* AudioGlobal_convertDirectionToText(aaudio_direction_t direction);
+const char* AudioGlobal_convertPerformanceModeToText(aaudio_performance_mode_t mode);
 const char* AudioGlobal_convertResultToText(aaudio_result_t returnCode);
+const char* AudioGlobal_convertSharingModeToText(aaudio_sharing_mode_t mode);
 const char* AudioGlobal_convertStreamStateToText(aaudio_stream_state_t state);
-
 }
 
 #endif  // AAUDIO_AUDIOGLOBAL_H
diff --git a/media/libaaudio/src/core/AudioStream.cpp b/media/libaaudio/src/core/AudioStream.cpp
index 4252dfd..17d389e 100644
--- a/media/libaaudio/src/core/AudioStream.cpp
+++ b/media/libaaudio/src/core/AudioStream.cpp
@@ -20,6 +20,9 @@
 
 #include <atomic>
 #include <stdint.h>
+
+#include <media/MediaMetricsItem.h>
+
 #include <aaudio/AAudio.h>
 
 #include "AudioStreamBuilder.h"
@@ -29,7 +32,6 @@
 
 namespace aaudio {
 
-
 // Sequential number assigned to streams solely for debugging purposes.
 static aaudio_stream_id_t AAudio_getNextStreamId() {
     static std::atomic <aaudio_stream_id_t> nextStreamId{1};
@@ -103,6 +105,24 @@
     return AAUDIO_OK;
 }
 
+void AudioStream::logOpen() {
+    LOG_ALWAYS_FATAL_IF(mMetricsId.size() == 0, "mMetricsId is empty!");
+    android::mediametrics::LogItem(mMetricsId)
+            .set(AMEDIAMETRICS_PROP_PERFORMANCEMODE,
+                    AudioGlobal_convertPerformanceModeToText(getPerformanceMode()))
+            .set(AMEDIAMETRICS_PROP_SHARINGMODE,
+                    AudioGlobal_convertSharingModeToText(getSharingMode()))
+            .record();
+}
+
+void AudioStream::logBufferState() {
+    LOG_ALWAYS_FATAL_IF(mMetricsId.size() == 0, "mMetricsId is empty!");
+    android::mediametrics::LogItem(mMetricsId)
+            .set(AMEDIAMETRICS_PROP_BUFFERSIZEFRAMES, (int32_t) getBufferSize())
+            .set(AMEDIAMETRICS_PROP_UNDERRUN, (int32_t) getXRunCount())
+            .record();
+}
+
 aaudio_result_t AudioStream::systemStart() {
     std::lock_guard<std::mutex> lock(mStreamLock);
 
@@ -291,6 +311,13 @@
 
 void AudioStream::setState(aaudio_stream_state_t state) {
     ALOGD("%s(s#%d) from %d to %d", __func__, getId(), mState, state);
+    // Track transition to DISCONNECTED state.
+    if (state == AAUDIO_STREAM_STATE_DISCONNECTED && mState != state) {
+        android::mediametrics::LogItem(mMetricsId)
+                .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_DISCONNECT)
+                .set(AMEDIAMETRICS_PROP_STATE, AudioGlobal_convertStreamStateToText(getState()))
+                .record();
+    }
     // CLOSED is a final state
     if (mState == AAUDIO_STREAM_STATE_CLOSED) {
         ALOGE("%s(%d) tried to set to %d but already CLOSED", __func__, getId(), state);
diff --git a/media/libaaudio/src/core/AudioStream.h b/media/libaaudio/src/core/AudioStream.h
index 9bda41b..613a092 100644
--- a/media/libaaudio/src/core/AudioStream.h
+++ b/media/libaaudio/src/core/AudioStream.h
@@ -95,7 +95,6 @@
                                        int64_t *framePosition,
                                        int64_t *timeNanoseconds) = 0;
 
-
     /**
      * Update state machine.()
      * @return
@@ -114,6 +113,10 @@
      */
     virtual aaudio_result_t open(const AudioStreamBuilder& builder);
 
+    // log to MediaMetrics
+    virtual void logOpen();
+    void logBufferState();
+
     /**
      * Free any hardware or system resources from the open() call.
      * It is safe to call release_l() multiple times.
@@ -573,6 +576,8 @@
         mIsPrivacySensitive = privacySensitive;
     }
 
+    std::string mMetricsId; // set once during open()
+
 private:
 
     aaudio_result_t safeStop();
diff --git a/media/libaaudio/src/core/AudioStreamBuilder.cpp b/media/libaaudio/src/core/AudioStreamBuilder.cpp
index 3a1e1c9..60dad84 100644
--- a/media/libaaudio/src/core/AudioStreamBuilder.cpp
+++ b/media/libaaudio/src/core/AudioStreamBuilder.cpp
@@ -193,10 +193,14 @@
                         *streamPtr = audioStream;
                     } else {
                         delete audioStream;
+                        audioStream = nullptr;
                     }
                 }
             }
         }
+        if (audioStream != nullptr) {
+            audioStream->logOpen();
+        }
     }
 
     return result;
diff --git a/media/libaaudio/src/legacy/AudioStreamLegacy.cpp b/media/libaaudio/src/legacy/AudioStreamLegacy.cpp
index abc3239..c062882 100644
--- a/media/libaaudio/src/legacy/AudioStreamLegacy.cpp
+++ b/media/libaaudio/src/legacy/AudioStreamLegacy.cpp
@@ -26,6 +26,7 @@
 #include <media/AudioTimestamp.h>
 #include <utils/String16.h>
 
+#include "core/AudioGlobal.h"
 #include "core/AudioStream.h"
 #include "legacy/AudioStreamLegacy.h"
 
diff --git a/media/libaaudio/src/legacy/AudioStreamRecord.cpp b/media/libaaudio/src/legacy/AudioStreamRecord.cpp
index 904edd1..eeb45e1 100644
--- a/media/libaaudio/src/legacy/AudioStreamRecord.cpp
+++ b/media/libaaudio/src/legacy/AudioStreamRecord.cpp
@@ -202,6 +202,9 @@
         }
     }
 
+    mMetricsId = std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_RECORD)
+            + std::to_string(mAudioRecord->getPortId());
+
     // Get the actual values from the AudioRecord.
     setSamplesPerFrame(mAudioRecord->channelCount());
 
@@ -286,6 +289,7 @@
     //  Then call it from here
     if (getState() != AAUDIO_STREAM_STATE_CLOSING) {
         mAudioRecord->removeAudioDeviceCallback(mDeviceCallback);
+        logBufferState();
         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 6da63e8..2bdc26b 100644
--- a/media/libaaudio/src/legacy/AudioStreamTrack.cpp
+++ b/media/libaaudio/src/legacy/AudioStreamTrack.cpp
@@ -181,6 +181,9 @@
         return AAudioConvert_androidToAAudioResult(status);
     }
 
+    mMetricsId = std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_TRACK)
+            + std::to_string(mAudioTrack->getPortId());
+
     doSetVolume();
 
     // Get the actual values from the AudioTrack.
@@ -248,6 +251,7 @@
 aaudio_result_t AudioStreamTrack::release_l() {
     if (getState() != AAUDIO_STREAM_STATE_CLOSING) {
         mAudioTrack->removeAudioDeviceCallback(mDeviceCallback);
+        logBufferState();
         // 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 8b357a3..cd1a847 100644
--- a/media/libaudioclient/AudioTrack.cpp
+++ b/media/libaudioclient/AudioTrack.cpp
@@ -777,7 +777,9 @@
             .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_STOP)
             .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(systemTime() - beginNs))
             .set(AMEDIAMETRICS_PROP_STATE, stateToString(mState))
-            .record(); });
+            .record();
+        logBufferSizeUnderruns();
+    });
 
     ALOGV("%s(%d): prior state:%s", __func__, mPortId, stateToString(mState));
 
@@ -1107,6 +1109,7 @@
     if (mOutput == AUDIO_IO_HANDLE_NONE || mProxy.get() == 0) {
         return NO_INIT;
     }
+
     return (ssize_t) mProxy->getBufferSizeInFrames();
 }
 
@@ -1128,6 +1131,16 @@
     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);
@@ -1138,7 +1151,13 @@
     if (!audio_is_linear_pcm(mFormat)) {
         return INVALID_OPERATION;
     }
-    return (ssize_t) mProxy->setBufferSizeInFrames((uint32_t) bufferSizeInFrames);
+
+    ssize_t originalBufferSize = mProxy->getBufferSizeInFrames();
+    ssize_t finalBufferSize  = mProxy->setBufferSizeInFrames((uint32_t) bufferSizeInFrames);
+    if (originalBufferSize != finalBufferSize) {
+        logBufferSizeUnderruns();
+    }
+    return finalBufferSize;
 }
 
 status_t AudioTrack::setLoop(uint32_t loopStart, uint32_t loopEnd, int loopCount)
diff --git a/media/libaudioclient/include/media/AudioTrack.h b/media/libaudioclient/include/media/AudioTrack.h
index afae4d8..30abbb1 100644
--- a/media/libaudioclient/include/media/AudioTrack.h
+++ b/media/libaudioclient/include/media/AudioTrack.h
@@ -1260,6 +1260,8 @@
     MediaMetrics mMediaMetrics;
     std::string mMetricsId;  // GUARDED_BY(mLock), could change in createTrack_l().
 
+    void logBufferSizeUnderruns();
+
 private:
     class AudioTrackCallback : public media::BnAudioTrackCallback {
     public:
diff --git a/media/libmediametrics/include/MediaMetricsConstants.h b/media/libmediametrics/include/MediaMetricsConstants.h
index eb7ac7d..73dd2de 100644
--- a/media/libmediametrics/include/MediaMetricsConstants.h
+++ b/media/libmediametrics/include/MediaMetricsConstants.h
@@ -40,6 +40,9 @@
 // The AudioRecord key appends the "trackId" to the prefix.
 #define AMEDIAMETRICS_KEY_PREFIX_AUDIO_RECORD AMEDIAMETRICS_KEY_PREFIX_AUDIO "record."
 
+// The AudioStream key appends the "streamId" to the prefix.
+#define AMEDIAMETRICS_KEY_PREFIX_AUDIO_STREAM  AMEDIAMETRICS_KEY_PREFIX_AUDIO "stream."
+
 // The AudioThread key appends the "threadId" to the prefix.
 #define AMEDIAMETRICS_KEY_PREFIX_AUDIO_THREAD AMEDIAMETRICS_KEY_PREFIX_AUDIO "thread."
 
@@ -84,9 +87,13 @@
 #define AMEDIAMETRICS_PROP_SUFFIX_CHAR_DUPLICATES_ALLOWED '#'
 
 #define AMEDIAMETRICS_PROP_AUXEFFECTID    "auxEffectId"    // int32 (AudioTrack)
+#define AMEDIAMETRICS_PROP_BUFFERSIZEFRAMES "bufferSizeFrames" // int32
+#define AMEDIAMETRICS_PROP_BUFFERCAPACITYFRAMES "bufferCapacityFrames" // int32
+#define AMEDIAMETRICS_PROP_BURSTFRAMES    "burstFrames"    // int32
 #define AMEDIAMETRICS_PROP_CHANNELCOUNT   "channelCount"   // int32
 #define AMEDIAMETRICS_PROP_CHANNELMASK    "channelMask"    // int32
 #define AMEDIAMETRICS_PROP_CONTENTTYPE    "contentType"    // string attributes (AudioTrack)
+#define AMEDIAMETRICS_PROP_DIRECTION      "direction"      // string AAudio input or output
 #define AMEDIAMETRICS_PROP_DURATIONNS     "durationNs"     // int64 duration time span
 #define AMEDIAMETRICS_PROP_ENCODING       "encoding"       // string value of format
 #define AMEDIAMETRICS_PROP_EVENT          "event#"         // string value (often func name)
@@ -99,6 +106,7 @@
 #define AMEDIAMETRICS_PROP_LATENCYMS      "latencyMs"      // double value
 #define AMEDIAMETRICS_PROP_ORIGINALFLAGS  "originalFlags"  // int32
 #define AMEDIAMETRICS_PROP_OUTPUTDEVICES  "outputDevices"  // string value
+#define AMEDIAMETRICS_PROP_PERFORMANCEMODE "performanceMode"    // string value, "none", lowLatency"
 #define AMEDIAMETRICS_PROP_PLAYBACK_PITCH "playback.pitch" // double value (AudioTrack)
 #define AMEDIAMETRICS_PROP_PLAYBACK_SPEED "playback.speed" // double value (AudioTrack)
 #define AMEDIAMETRICS_PROP_ROUTEDDEVICEID "routedDeviceId" // int32
@@ -107,6 +115,7 @@
 #define AMEDIAMETRICS_PROP_SELECTEDMICDIRECTION "selectedMicDirection" // int32
 #define AMEDIAMETRICS_PROP_SELECTEDMICFIELDDIRECTION "selectedMicFieldDimension" // double
 #define AMEDIAMETRICS_PROP_SESSIONID      "sessionId"      // int32
+#define AMEDIAMETRICS_PROP_SHARINGMODE    "sharingMode"    // string value, "exclusive", shared"
 #define AMEDIAMETRICS_PROP_SOURCE         "source"         // string (AudioAttributes)
 #define AMEDIAMETRICS_PROP_STARTUPMS      "startupMs"      // double value
 // State is "ACTIVE" or "STOPPED" for AudioRecord
@@ -129,12 +138,15 @@
 // Values are strings accepted for a given property.
 
 // An event is a general description, which often is a function name.
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_CLOSE      "close"
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_CREATE     "create"
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_CREATEAUDIOPATCH "createAudioPatch"
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR       "ctor"
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_DISCONNECT "disconnect"
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_DTOR       "dtor"
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_FLUSH      "flush"  // AudioTrack
 #define AMEDIAMETRICS_PROP_EVENT_VALUE_INVALIDATE "invalidate" // server track, record
+#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_RESTORE    "restore"