From 84e84a5dd3b6d9ee4cf032e8d6206c70969b7107 Mon Sep 17 00:00:00 2001 From: Ray Essick Date: Thu, 3 May 2018 18:45:07 -0700 Subject: [PATCH] collect more media metrics around audio new fields in the media metrics 'audiorecord' record for more detail length of time recorded, error conditions add new media metrics type 'audiopolicy' that describes attempts to get microphone access -- success, failure on contention, what type of access was requested, and (important for the contention) which programs are doing the requesting and holding of the microphones. whitelist the 'audiopolicy' metrics type with the media.metrics service. Bug: 78595399 Test: concurrent/serial recordings, dumpsys media.metrics Change-Id: Ia17860940d4c329b0215b4cf97c6dacacb6a8e32 --- media/libaudioclient/AudioRecord.cpp | 35 ++++++++ .../include/media/AudioRecord.h | 17 +++- services/audiopolicy/Android.mk | 3 + services/audiopolicy/AudioPolicyInterface.h | 6 +- .../managerdefault/AudioPolicyManager.cpp | 5 ++ .../service/AudioPolicyInterfaceImpl.cpp | 87 +++++++++++++++++++ .../mediaanalytics/MediaAnalyticsService.cpp | 1 + 7 files changed, 152 insertions(+), 2 deletions(-) diff --git a/media/libaudioclient/AudioRecord.cpp b/media/libaudioclient/AudioRecord.cpp index a8369c22b1..f9df5b10b6 100644 --- a/media/libaudioclient/AudioRecord.cpp +++ b/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 diff --git a/media/libaudioclient/include/media/AudioRecord.h b/media/libaudioclient/include/media/AudioRecord.h index c07c397b5c..cf446a537b 100644 --- a/media/libaudioclient/include/media/AudioRecord.h +++ b/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 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; }; diff --git a/services/audiopolicy/Android.mk b/services/audiopolicy/Android.mk index 65571f9b86..d29cae1dce 100644 --- a/services/audiopolicy/Android.mk +++ b/services/audiopolicy/Android.mk @@ -25,6 +25,7 @@ LOCAL_SHARED_LIBRARIES := \ libserviceutility \ libaudiopolicymanager \ libmedia_helper \ + libmediametrics \ libeffectsconfig LOCAL_STATIC_LIBRARIES := \ @@ -60,6 +61,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 @@ -78,6 +80,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 diff --git a/services/audiopolicy/AudioPolicyInterface.h b/services/audiopolicy/AudioPolicyInterface.h index 7f09e9bc10..923c0914ac 100644 --- a/services/audiopolicy/AudioPolicyInterface.h +++ b/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; diff --git a/services/audiopolicy/managerdefault/AudioPolicyManager.cpp b/services/audiopolicy/managerdefault/AudioPolicyManager.cpp index 264e7097c2..e1467b704f 100644 --- a/services/audiopolicy/managerdefault/AudioPolicyManager.cpp +++ b/services/audiopolicy/managerdefault/AudioPolicyManager.cpp @@ -1878,6 +1878,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; } @@ -1920,17 +1921,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; } } @@ -1955,6 +1959,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 sessions = activeDesc->getPreemptedSessions(); + *concurrency |= API_INPUT_CONCURRENCY_PREEMPT; sessions.add(activeSession); inputDesc->setPreemptedSessions(sessions); stopInput(activeHandle, activeSession); diff --git a/services/audiopolicy/service/AudioPolicyInterfaceImpl.cpp b/services/audiopolicy/service/AudioPolicyInterfaceImpl.cpp index cf24c13ad5..008d655e7a 100644 --- a/services/audiopolicy/service/AudioPolicyInterfaceImpl.cpp +++ b/services/audiopolicy/service/AudioPolicyInterfaceImpl.cpp @@ -18,8 +18,11 @@ //#define LOG_NDEBUG 0 #include +#include + #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 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 client = mAudioRecordClients.valueAt(index); + client->active = false; + // finish the recording app op finishRecording(client->opPackageName, client->uid); AutoCallerClear acc; diff --git a/services/mediaanalytics/MediaAnalyticsService.cpp b/services/mediaanalytics/MediaAnalyticsService.cpp index 6d84a42442..4b05395686 100644 --- a/services/mediaanalytics/MediaAnalyticsService.cpp +++ b/services/mediaanalytics/MediaAnalyticsService.cpp @@ -481,6 +481,7 @@ void MediaAnalyticsService::saveItem(MediaAnalyticsItem * item) static std::string allowedKeys[] = { + "audiopolicy", "audiorecord", "audiotrack", "codec",