collect more media metrics around audio am: 84e84a5dd3

am: 3b7f469b1e

Change-Id: I03941e3b776ba3cdb84ea39b07f1dcb903cbbf14

media/libaudioclient/AudioRecord.cpp

@@ -99,6 +99,11 @@ void AudioRecord::MediaMetrics::gather(const AudioRecord *record)
     static constexpr char kAudioRecordLatency[] = "android.media.audiorecord.latency";
     static constexpr char kAudioRecordSampleRate[] = "android.media.audiorecord.samplerate";
     static constexpr char kAudioRecordChannelCount[] = "android.media.audiorecord.channels";
+    static constexpr char kAudioRecordCreated[] = "android.media.audiorecord.createdMs";
+    static constexpr char kAudioRecordDuration[] = "android.media.audiorecord.durationMs";
+    static constexpr char kAudioRecordCount[] = "android.media.audiorecord.n";
+    static constexpr char kAudioRecordError[] = "android.media.audiorecord.errcode";
+    static constexpr char kAudioRecordErrorFunction[] = "android.media.audiorecord.errfunc";
 
     // constructor guarantees mAnalyticsItem is valid
 
@@ -109,6 +114,24 @@ void AudioRecord::MediaMetrics::gather(const AudioRecord *record)
                                audioFormatTypeString(record->mFormat).c_str());
     mAnalyticsItem->setCString(kAudioRecordSource,
                                audioSourceString(record->mAttributes.source).c_str());
+
+    // log total duration recording, including anything currently running [and count].
+    nsecs_t active = 0;
+    if (mStartedNs != 0) {
+        active = systemTime() - mStartedNs;
+    }
+    mAnalyticsItem->setInt64(kAudioRecordDuration, (mDurationNs + active) / (1000 * 1000));
+    mAnalyticsItem->setInt32(kAudioRecordCount, mCount);
+
+    // XXX I don't know that this adds a lot of value, long term
+    if (mCreatedNs != 0) {
+        mAnalyticsItem->setInt64(kAudioRecordCreated, mCreatedNs / (1000 * 1000));
+    }
+
+    if (mLastError != NO_ERROR) {
+        mAnalyticsItem->setInt32(kAudioRecordError, mLastError);
+        mAnalyticsItem->setCString(kAudioRecordErrorFunction, mLastErrorFunc.c_str());
+    }
 }
 
 // hand the user a snapshot of the metrics.
@@ -354,6 +377,9 @@ status_t AudioRecord::set(
 
 exit:
     mStatus = status;
+    if (status != NO_ERROR) {
+        mMediaMetrics.markError(status, __FUNCTION__);
+    }
     return status;
 }
 
@@ -412,8 +438,14 @@ status_t AudioRecord::start(AudioSystem::sync_event_t event, audio_session_t tri
             get_sched_policy(0, &mPreviousSchedulingGroup);
             androidSetThreadPriority(0, ANDROID_PRIORITY_AUDIO);
         }
+
+        // we've successfully started, log that time
+        mMediaMetrics.logStart(systemTime());
     }
 
+    if (status != NO_ERROR) {
+        mMediaMetrics.markError(status, __FUNCTION__);
+    }
     return status;
 }
 
@@ -438,6 +470,9 @@ void AudioRecord::stop()
         setpriority(PRIO_PROCESS, 0, mPreviousPriority);
         set_sched_policy(0, mPreviousSchedulingGroup);
     }
+
+    // we've successfully started, log that time
+    mMediaMetrics.logStop(systemTime());
 }
 
 bool AudioRecord::stopped() const

media/libaudioclient/include/media/AudioRecord.h

@@ -704,7 +704,10 @@ private:
 private:
     class MediaMetrics {
       public:
-        MediaMetrics() : mAnalyticsItem(new MediaAnalyticsItem("audiorecord")) {
+        MediaMetrics() : mAnalyticsItem(new MediaAnalyticsItem("audiorecord")),
+                         mCreatedNs(systemTime(SYSTEM_TIME_REALTIME)),
+                         mStartedNs(0), mDurationNs(0), mCount(0),
+                         mLastError(NO_ERROR) {
         }
         ~MediaMetrics() {
             // mAnalyticsItem alloc failure will be flagged in the constructor
@@ -715,8 +718,20 @@ private:
         }
         void gather(const AudioRecord *record);
         MediaAnalyticsItem *dup() { return mAnalyticsItem->dup(); }
+
+        void logStart(nsecs_t when) { mStartedNs = when; mCount++; }
+        void logStop(nsecs_t when) { mDurationNs += (when-mStartedNs); mStartedNs = 0;}
+        void markError(status_t errcode, const char *func)
+                 { mLastError = errcode; mLastErrorFunc = func;}
       private:
         std::unique_ptr<MediaAnalyticsItem> mAnalyticsItem;
+        nsecs_t mCreatedNs;     // XXX: perhaps not worth it in production
+        nsecs_t mStartedNs;
+        nsecs_t mDurationNs;
+        int32_t mCount;
+
+        status_t mLastError;
+        std::string mLastErrorFunc;
     };
     MediaMetrics mMediaMetrics;
 };

services/audiopolicy/Android.mk

@@ -24,6 +24,7 @@ LOCAL_SHARED_LIBRARIES := \
     libserviceutility \
     libaudiopolicymanager \
     libmedia_helper \
+    libmediametrics \
     libeffectsconfig
 
 LOCAL_STATIC_LIBRARIES := \
@@ -59,6 +60,7 @@ LOCAL_REQUIRED_MODULES := \
     audio_policy_criteria.conf \
 
 LOCAL_C_INCLUDES += frameworks/av/services/audiopolicy/engineconfigurable/include
+LOCAL_C_INCLUDES += frameworks/av/include
 
 LOCAL_SHARED_LIBRARIES += libaudiopolicyengineconfigurable
 
@@ -76,6 +78,7 @@ LOCAL_STATIC_LIBRARIES := \
     libaudiopolicycomponents
 
 LOCAL_SHARED_LIBRARIES += libmedia_helper
+LOCAL_SHARED_LIBRARIES += libmediametrics
 
 ifeq ($(USE_XML_AUDIO_POLICY_CONF), 1)
 LOCAL_SHARED_LIBRARIES += libicuuc libxml2

services/audiopolicy/AudioPolicyInterface.h

@@ -69,8 +69,12 @@ public:
         API_INPUT_CONCURRENCY_NONE = 0,
         API_INPUT_CONCURRENCY_CALL = (1 << 0),      // Concurrency with a call
         API_INPUT_CONCURRENCY_CAPTURE = (1 << 1),   // Concurrency with another capture
+        API_INPUT_CONCURRENCY_HOTWORD = (1 << 2),   // Concurrency with a hotword
+        API_INPUT_CONCURRENCY_PREEMPT = (1 << 3),   // pre-empted someone
+                // NB: preempt is marked on a successful return, others are on failing calls
+        API_INPUT_CONCURRENCY_LAST = (1 << 4),
 
-        API_INPUT_CONCURRENCY_ALL = (API_INPUT_CONCURRENCY_CALL | API_INPUT_CONCURRENCY_CAPTURE),
+        API_INPUT_CONCURRENCY_ALL = (API_INPUT_CONCURRENCY_LAST - 1),
     };
 
     typedef uint32_t concurrency_type__mask_t;

services/audiopolicy/managerdefault/AudioPolicyManager.cpp

@@ -1883,6 +1883,7 @@ status_t AudioPolicyManager::startInput(audio_io_handle_t input,
         if (mCallTxPatch != 0 &&
             inputDesc->getModuleHandle() == mCallTxPatch->mPatch.sources[0].ext.device.hw_module) {
             ALOGW("startInput(%d) failed: call in progress", input);
+            *concurrency |= API_INPUT_CONCURRENCY_CALL;
             return INVALID_OPERATION;
         }
 
@@ -1925,17 +1926,20 @@ status_t AudioPolicyManager::startInput(audio_io_handle_t input,
                         ALOGW("startInput(%d) failed for HOTWORD: "
                                 "other input %d already started for HOTWORD",
                               input, activeDesc->mIoHandle);
+                        *concurrency |= API_INPUT_CONCURRENCY_HOTWORD;
                         return INVALID_OPERATION;
                     }
                 } else {
                     ALOGV("startInput(%d) failed for HOTWORD: other input %d already started",
                           input, activeDesc->mIoHandle);
+                    *concurrency |= API_INPUT_CONCURRENCY_CAPTURE;
                     return INVALID_OPERATION;
                 }
             } else {
                 if (activeSource != AUDIO_SOURCE_HOTWORD) {
                     ALOGW("startInput(%d) failed: other input %d already started",
                           input, activeDesc->mIoHandle);
+                    *concurrency |= API_INPUT_CONCURRENCY_CAPTURE;
                     return INVALID_OPERATION;
                 }
             }
@@ -1960,6 +1964,7 @@ status_t AudioPolicyManager::startInput(audio_io_handle_t input,
                 audio_session_t activeSession = activeSessions.keyAt(0);
                 audio_io_handle_t activeHandle = activeDesc->mIoHandle;
                 SortedVector<audio_session_t> sessions = activeDesc->getPreemptedSessions();
+                *concurrency |= API_INPUT_CONCURRENCY_PREEMPT;
                 sessions.add(activeSession);
                 inputDesc->setPreemptedSessions(sessions);
                 stopInput(activeHandle, activeSession);

services/audiopolicy/service/AudioPolicyInterfaceImpl.cpp

@@ -18,8 +18,11 @@
 //#define LOG_NDEBUG 0
 
 #include <utils/Log.h>
+#include <media/MediaAnalyticsItem.h>
+
 #include "AudioPolicyService.h"
 #include "ServiceUtilities.h"
+#include "TypeConverter.h"
 
 namespace android {
 
@@ -409,6 +412,35 @@ status_t AudioPolicyService::getInputForAttr(const audio_attributes_t *attr,
     return NO_ERROR;
 }
 
+// this is replicated from frameworks/av/media/libaudioclient/AudioRecord.cpp
+// XXX -- figure out how to put it into a common, shared location
+
+static std::string audioSourceString(audio_source_t value) {
+    std::string source;
+    if (SourceTypeConverter::toString(value, source)) {
+        return source;
+    }
+    char rawbuffer[16];  // room for "%d"
+    snprintf(rawbuffer, sizeof(rawbuffer), "%d", value);
+    return rawbuffer;
+}
+
+static std::string audioConcurrencyString(AudioPolicyInterface::concurrency_type__mask_t concurrency)
+{
+    char buffer[64]; // oversized
+    if (concurrency & AudioPolicyInterface::API_INPUT_CONCURRENCY_ALL) {
+        snprintf(buffer, sizeof(buffer), "%s%s%s%s",
+            (concurrency & AudioPolicyInterface::API_INPUT_CONCURRENCY_CALL)? ",call":"",
+            (concurrency & AudioPolicyInterface::API_INPUT_CONCURRENCY_CAPTURE)? ",capture":"",
+            (concurrency & AudioPolicyInterface::API_INPUT_CONCURRENCY_HOTWORD)? ",hotword":"",
+            (concurrency & AudioPolicyInterface::API_INPUT_CONCURRENCY_PREEMPT)? ",preempt":"");
+    } else {
+        snprintf(buffer, sizeof(buffer), ",none");
+    }
+
+    return &buffer[1];
+}
+
 status_t AudioPolicyService::startInput(audio_port_handle_t portId, bool *silenced)
 {
     if (mAudioPolicyManager == NULL) {
@@ -444,6 +476,57 @@ status_t AudioPolicyService::startInput(audio_port_handle_t portId, bool *silenc
         AutoCallerClear acc;
         status = mAudioPolicyManager->startInput(
                     client->input, client->session, *silenced, &concurrency);
+
+    }
+
+    // XXX log them all for a while, during some dogfooding.
+    if (1 || status != NO_ERROR) {
+
+        static constexpr char kAudioPolicy[] = "audiopolicy";
+
+        static constexpr char kAudioPolicyReason[] = "android.media.audiopolicy.reason";
+        static constexpr char kAudioPolicyStatus[] = "android.media.audiopolicy.status";
+        static constexpr char kAudioPolicyRqstSrc[] = "android.media.audiopolicy.rqst.src";
+        static constexpr char kAudioPolicyRqstPkg[] = "android.media.audiopolicy.rqst.pkg";
+        static constexpr char kAudioPolicyRqstSession[] = "android.media.audiopolicy.rqst.session";
+        static constexpr char kAudioPolicyActiveSrc[] = "android.media.audiopolicy.active.src";
+        static constexpr char kAudioPolicyActivePkg[] = "android.media.audiopolicy.active.pkg";
+        static constexpr char kAudioPolicyActiveSession[] = "android.media.audiopolicy.active.session";
+
+        MediaAnalyticsItem *item = new MediaAnalyticsItem(kAudioPolicy);
+        if (item != NULL) {
+
+            item->setCString(kAudioPolicyReason, audioConcurrencyString(concurrency).c_str());
+            item->setInt32(kAudioPolicyStatus, status);
+
+            item->setCString(kAudioPolicyRqstSrc, audioSourceString(client->attributes.source).c_str());
+            item->setCString(kAudioPolicyRqstPkg, std::string(String8(client->opPackageName).string()).c_str());
+            item->setInt32(kAudioPolicyRqstSession, client->session);
+
+            // figure out who is active
+            // NB: might the other party have given up the microphone since then? how sure.
+            // perhaps could have given up on it.
+            // we hold mLock, so perhaps we're safe for this looping
+            if (concurrency != AudioPolicyInterface::API_INPUT_CONCURRENCY_NONE) {
+                int count = mAudioRecordClients.size();
+                for (int i = 0; i<count ; i++) {
+                    if (portId == mAudioRecordClients.keyAt(i)) {
+                        continue;
+                    }
+                    sp<AudioRecordClient> other = mAudioRecordClients.valueAt(i);
+                    if (other->active) {
+                        // keeps the last of the clients marked active
+                        item->setCString(kAudioPolicyActiveSrc,
+                                         audioSourceString(other->attributes.source).c_str());
+                        item->setCString(kAudioPolicyActivePkg, std::string(String8(other->opPackageName).string()).c_str());
+                        item->setInt32(kAudioPolicyActiveSession, other->session);
+                    }
+                }
+            }
+            item->selfrecord();
+            delete item;
+            item = NULL;
+        }
     }
 
     if (status == NO_ERROR) {
@@ -457,6 +540,8 @@ status_t AudioPolicyService::startInput(audio_port_handle_t portId, bool *silenc
         if (concurrency & AudioPolicyInterface::API_INPUT_CONCURRENCY_CAPTURE) {
             //TODO: check concurrent capture permission
         }
+
+        client->active = true;
     } else {
         finishRecording(client->opPackageName, client->uid);
     }
@@ -477,6 +562,8 @@ status_t AudioPolicyService::stopInput(audio_port_handle_t portId)
     }
     sp<AudioRecordClient> client = mAudioRecordClients.valueAt(index);
 
+    client->active = false;
+
     // finish the recording app op
     finishRecording(client->opPackageName, client->uid);
     AutoCallerClear acc;

services/mediaanalytics/MediaAnalyticsService.cpp

@@ -481,6 +481,7 @@ void MediaAnalyticsService::saveItem(MediaAnalyticsItem * item)
 
 static std::string allowedKeys[] =
 {
+    "audiopolicy",
     "audiorecord",
     "audiotrack",
     "codec",