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/services/oboeservice/AAudioService.cpp b/services/oboeservice/AAudioService.cpp
index aba8e08..cac7453 100644
--- a/services/oboeservice/AAudioService.cpp
+++ b/services/oboeservice/AAudioService.cpp
@@ -144,6 +144,9 @@
         pid_t pid = request.getProcessId();
         AAudioClientTracker::getInstance().registerClientStream(pid, serviceStream);
         configurationOutput.copyFrom(*serviceStream);
+        // Log open in MediaMetrics after we have the handle because we need the handle to
+        // create the metrics ID.
+        serviceStream->logOpen(handle);
         return handle;
     }
 }
diff --git a/services/oboeservice/AAudioService.h b/services/oboeservice/AAudioService.h
index eddb5a0..7167868 100644
--- a/services/oboeservice/AAudioService.h
+++ b/services/oboeservice/AAudioService.h
@@ -115,6 +115,7 @@
     // and share them with this code. Look for "kPriorityFastMixer".
     static constexpr int32_t        kRealTimeAudioPriorityClient = 2;
     static constexpr int32_t        kRealTimeAudioPriorityService = 3;
+
 };
 
 } /* namespace android */
diff --git a/services/oboeservice/AAudioServiceEndpoint.h b/services/oboeservice/AAudioServiceEndpoint.h
index a6bb019..ad30087 100644
--- a/services/oboeservice/AAudioServiceEndpoint.h
+++ b/services/oboeservice/AAudioServiceEndpoint.h
@@ -109,6 +109,8 @@
         return mConnected;
     }
 
+    static audio_attributes_t getAudioAttributesFrom(const AAudioStreamParameters *params);
+
 protected:
 
     /**
@@ -119,8 +121,6 @@
 
     void                     disconnectRegisteredStreams();
 
-    static audio_attributes_t getAudioAttributesFrom(const AAudioStreamParameters *params);
-
     mutable std::mutex       mLockStreams;
     std::vector<android::sp<AAudioServiceStreamBase>> mRegisteredStreams;
 
diff --git a/services/oboeservice/AAudioServiceStreamBase.cpp b/services/oboeservice/AAudioServiceStreamBase.cpp
index 39e90b1..044c361 100644
--- a/services/oboeservice/AAudioServiceStreamBase.cpp
+++ b/services/oboeservice/AAudioServiceStreamBase.cpp
@@ -22,8 +22,12 @@
 #include <iostream>
 #include <mutex>
 
+#include <media/MediaMetricsItem.h>
+#include <media/TypeConverter.h>
+
 #include "binding/IAAudioService.h"
 #include "binding/AAudioServiceMessage.h"
+#include "core/AudioGlobal.h"
 #include "utility/AudioClock.h"
 
 #include "AAudioEndpointManager.h"
@@ -51,6 +55,14 @@
 }
 
 AAudioServiceStreamBase::~AAudioServiceStreamBase() {
+    // May not be set if open failed.
+    if (mMetricsId.size() > 0) {
+        mediametrics::LogItem(mMetricsId)
+                .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_DTOR)
+                .set(AMEDIAMETRICS_PROP_STATE, AudioGlobal_convertStreamStateToText(getState()))
+                .record();
+    }
+
     // If the stream is deleted when OPEN or in use then audio resources will leak.
     // This would indicate an internal error. So we want to find this ASAP.
     LOG_ALWAYS_FATAL_IF(!(getState() == AAUDIO_STREAM_STATE_CLOSED
@@ -81,6 +93,35 @@
     return result.str();
 }
 
+void AAudioServiceStreamBase::logOpen(aaudio_handle_t streamHandle) {
+    // This is the first log sent from the AAudio Service for a stream.
+    mMetricsId = std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_STREAM)
+            + std::to_string(streamHandle);
+
+    audio_attributes_t attributes = AAudioServiceEndpoint::getAudioAttributesFrom(this);
+
+    // Once this item is logged by the server, the client with the same PID, UID
+    // can also log properties.
+    mediametrics::LogItem(mMetricsId)
+        .setPid(getOwnerProcessId())
+        .setUid(getOwnerUserId())
+        .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_OPEN)
+        // the following are immutable
+        .set(AMEDIAMETRICS_PROP_BUFFERCAPACITYFRAMES, (int32_t)getBufferCapacity())
+        .set(AMEDIAMETRICS_PROP_BURSTFRAMES, (int32_t)getFramesPerBurst())
+        .set(AMEDIAMETRICS_PROP_CHANNELCOUNT, (int32_t)getSamplesPerFrame())
+        .set(AMEDIAMETRICS_PROP_CONTENTTYPE, toString(attributes.content_type).c_str())
+        .set(AMEDIAMETRICS_PROP_DIRECTION,
+                AudioGlobal_convertDirectionToText(getDirection()))
+        .set(AMEDIAMETRICS_PROP_ENCODING, toString(getFormat()).c_str())
+        .set(AMEDIAMETRICS_PROP_ROUTEDDEVICEID, (int32_t)getDeviceId())
+        .set(AMEDIAMETRICS_PROP_SAMPLERATE, (int32_t)getSampleRate())
+        .set(AMEDIAMETRICS_PROP_SESSIONID, (int32_t)getSessionId())
+        .set(AMEDIAMETRICS_PROP_SOURCE, toString(attributes.source).c_str())
+        .set(AMEDIAMETRICS_PROP_USAGE, toString(attributes.usage).c_str())
+        .record();
+}
+
 aaudio_result_t AAudioServiceStreamBase::open(const aaudio::AAudioStreamRequest &request) {
     AAudioEndpointManager &mEndpointManager = AAudioEndpointManager::getInstance();
     aaudio_result_t result = AAUDIO_OK;
@@ -154,6 +195,10 @@
     }
 
     setState(AAUDIO_STREAM_STATE_CLOSED);
+
+    mediametrics::LogItem(mMetricsId)
+        .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CLOSE)
+        .record();
     return result;
 }
 
@@ -173,8 +218,17 @@
  * An AAUDIO_SERVICE_EVENT_STARTED will be sent to the client when complete.
  */
 aaudio_result_t AAudioServiceStreamBase::start() {
+    const int64_t beginNs = AudioClock::getNanoseconds();
     aaudio_result_t result = AAUDIO_OK;
 
+    mediametrics::Defer defer([&] {
+        mediametrics::LogItem(mMetricsId)
+            .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_START)
+            .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(AudioClock::getNanoseconds() - beginNs))
+            .set(AMEDIAMETRICS_PROP_STATE, AudioGlobal_convertStreamStateToText(getState()))
+            .set(AMEDIAMETRICS_PROP_STATUS, (int32_t)result)
+            .record(); });
+
     if (isRunning()) {
         return AAUDIO_OK;
     }
@@ -204,11 +258,20 @@
 }
 
 aaudio_result_t AAudioServiceStreamBase::pause() {
+    const int64_t beginNs = AudioClock::getNanoseconds();
     aaudio_result_t result = AAUDIO_OK;
     if (!isRunning()) {
         return result;
     }
 
+    mediametrics::Defer defer([&] {
+        mediametrics::LogItem(mMetricsId)
+            .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_PAUSE)
+            .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(AudioClock::getNanoseconds() - beginNs))
+            .set(AMEDIAMETRICS_PROP_STATE, AudioGlobal_convertStreamStateToText(getState()))
+            .set(AMEDIAMETRICS_PROP_STATUS, (int32_t)result)
+            .record(); });
+
     // Send it now because the timestamp gets rounded up when stopStream() is called below.
     // Also we don't need the timestamps while we are shutting down.
     sendCurrentTimestamp();
@@ -222,7 +285,8 @@
     sp<AAudioServiceEndpoint> endpoint = mServiceEndpointWeak.promote();
     if (endpoint == nullptr) {
         ALOGE("%s() has no endpoint", __func__);
-        return AAUDIO_ERROR_INVALID_STATE;
+        result =  AAUDIO_ERROR_INVALID_STATE; // for MediaMetric tracking
+        return result;
     }
     result = endpoint->stopStream(this, mClientHandle);
     if (result != AAUDIO_OK) {
@@ -236,11 +300,20 @@
 }
 
 aaudio_result_t AAudioServiceStreamBase::stop() {
+    const int64_t beginNs = AudioClock::getNanoseconds();
     aaudio_result_t result = AAUDIO_OK;
     if (!isRunning()) {
         return result;
     }
 
+    mediametrics::Defer defer([&] {
+        mediametrics::LogItem(mMetricsId)
+            .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_STOP)
+            .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(AudioClock::getNanoseconds() - beginNs))
+            .set(AMEDIAMETRICS_PROP_STATE, AudioGlobal_convertStreamStateToText(getState()))
+            .set(AMEDIAMETRICS_PROP_STATUS, (int32_t)result)
+            .record(); });
+
     setState(AAUDIO_STREAM_STATE_STOPPING);
 
     // Send it now because the timestamp gets rounded up when stopStream() is called below.
@@ -255,7 +328,8 @@
     sp<AAudioServiceEndpoint> endpoint = mServiceEndpointWeak.promote();
     if (endpoint == nullptr) {
         ALOGE("%s() has no endpoint", __func__);
-        return AAUDIO_ERROR_INVALID_STATE;
+        result =  AAUDIO_ERROR_INVALID_STATE; // for MediaMetric tracking
+        return result;
     }
     // TODO wait for data to be played out
     result = endpoint->stopStream(this, mClientHandle);
@@ -280,11 +354,20 @@
 }
 
 aaudio_result_t AAudioServiceStreamBase::flush() {
+    const int64_t beginNs = AudioClock::getNanoseconds();
     aaudio_result_t result = AAudio_isFlushAllowed(getState());
     if (result != AAUDIO_OK) {
         return result;
     }
 
+    mediametrics::Defer defer([&] {
+        mediametrics::LogItem(mMetricsId)
+            .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_FLUSH)
+            .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(AudioClock::getNanoseconds() - beginNs))
+            .set(AMEDIAMETRICS_PROP_STATE, AudioGlobal_convertStreamStateToText(getState()))
+            .set(AMEDIAMETRICS_PROP_STATUS, (int32_t)result)
+            .record(); });
+
     // Data will get flushed when the client receives the FLUSHED event.
     sendServiceEvent(AAUDIO_SERVICE_EVENT_FLUSHED);
     setState(AAUDIO_STREAM_STATE_FLUSHED);
@@ -321,6 +404,10 @@
 
 void AAudioServiceStreamBase::disconnect() {
     if (getState() != AAUDIO_STREAM_STATE_DISCONNECTED) {
+        mediametrics::LogItem(mMetricsId)
+            .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_DISCONNECT)
+            .set(AMEDIAMETRICS_PROP_STATE, AudioGlobal_convertStreamStateToText(getState()))
+            .record();
         sendServiceEvent(AAUDIO_SERVICE_EVENT_DISCONNECTED);
         setState(AAUDIO_STREAM_STATE_DISCONNECTED);
     }
diff --git a/services/oboeservice/AAudioServiceStreamBase.h b/services/oboeservice/AAudioServiceStreamBase.h
index aaab567..79dd738 100644
--- a/services/oboeservice/AAudioServiceStreamBase.h
+++ b/services/oboeservice/AAudioServiceStreamBase.h
@@ -68,12 +68,15 @@
     // does not include EOL
     virtual std::string dump() const;
 
-    // -------------------------------------------------------------------
     /**
      * Open the device.
      */
     virtual aaudio_result_t open(const aaudio::AAudioStreamRequest &request) = 0;
 
+    // We log the CLOSE from the close() method. We needed this separate method to log the OPEN
+    // because we had to wait until we generated the handle.
+    void logOpen(aaudio_handle_t streamHandle);
+
     virtual aaudio_result_t close();
 
     /**
@@ -312,6 +315,8 @@
     android::sp<AAudioServiceEndpoint> mServiceEndpoint;
     android::wp<AAudioServiceEndpoint> mServiceEndpointWeak;
 
+    std::string mMetricsId;  // set once during open()
+
 private:
 
     /**
diff --git a/services/oboeservice/Android.bp b/services/oboeservice/Android.bp
index 64d835b..8b1e2c0 100644
--- a/services/oboeservice/Android.bp
+++ b/services/oboeservice/Android.bp
@@ -47,11 +47,13 @@
         "libaudioclient",
         "libaudioflinger",
         "libaudioutils",
+        "libmedia_helper",
+        "libmediametrics",
+        "libmediautils",
         "libbase",
         "libbinder",
         "libcutils",
         "liblog",
-        "libmediautils",
         "libutils",
     ],