MediaMetrics: Add AudioFlinger logging
Test: atest mediametrics_tests
Test: mediametrics dumpsys
Bug: 138583596
Change-Id: I2086c5a780744d409052fde4c5ebc1dc92d95ea8
diff --git a/media/libaudioclient/AudioRecord.cpp b/media/libaudioclient/AudioRecord.cpp
index 981cfee..f9d1798 100644
--- a/media/libaudioclient/AudioRecord.cpp
+++ b/media/libaudioclient/AudioRecord.cpp
@@ -105,6 +105,10 @@
}
}
+static const char *stateToString(bool active) {
+ return active ? "ACTIVE" : "STOPPED";
+}
+
// hand the user a snapshot of the metrics.
status_t AudioRecord::getMetrics(mediametrics::Item * &item)
{
@@ -164,6 +168,11 @@
{
mMediaMetrics.gather(this);
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_DTOR)
+ .set(AMEDIAMETRICS_PROP_STATUS, (int32_t)mStatus)
+ .record();
+
if (mStatus == NO_ERROR) {
// Make sure that callback function exits in the case where
// it is looping on buffer empty condition in obtainBuffer().
@@ -380,11 +389,21 @@
status_t AudioRecord::start(AudioSystem::sync_event_t event, audio_session_t triggerSession)
{
+ const int64_t beginNs = systemTime();
ALOGV("%s(%d): sync event %d trigger session %d", __func__, mPortId, event, triggerSession);
-
AutoMutex lock(mLock);
+
+ status_t status = NO_ERROR;
+ mediametrics::Defer([&] {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_START)
+ .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(systemTime() - beginNs))
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mActive))
+ .set(AMEDIAMETRICS_PROP_STATUS, (int32_t)status)
+ .record(); });
+
if (mActive) {
- return NO_ERROR;
+ return status;
}
// discard data in buffer
@@ -409,7 +428,6 @@
// mActive is checked by restoreRecord_l
mActive = true;
- status_t status = NO_ERROR;
if (!(flags & CBLK_INVALID)) {
status = mAudioRecord->start(event, triggerSession).transactionError();
if (status == DEAD_OBJECT) {
@@ -447,7 +465,15 @@
void AudioRecord::stop()
{
+ const int64_t beginNs = systemTime();
AutoMutex lock(mLock);
+ mediametrics::Defer([&] {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_STOP)
+ .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(systemTime() - beginNs))
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mActive))
+ .record(); });
+
ALOGV("%s(%d): mActive:%d\n", __func__, mPortId, mActive);
if (!mActive) {
return;
@@ -663,6 +689,7 @@
// must be called with mLock held
status_t AudioRecord::createRecord_l(const Modulo<uint32_t> &epoch, const String16& opPackageName)
{
+ const int64_t beginNs = systemTime();
const sp<IAudioFlinger>& audioFlinger = AudioSystem::get_audio_flinger();
IAudioFlinger::CreateRecordInput input;
IAudioFlinger::CreateRecordOutput output;
@@ -849,6 +876,29 @@
mDeathNotifier = new DeathNotifier(this);
IInterface::asBinder(mAudioRecord)->linkToDeath(mDeathNotifier, this);
+ mMetricsId = std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_RECORD) + std::to_string(mPortId);
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATE)
+ .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(systemTime() - beginNs))
+ // the following are immutable (at least until restore)
+ .set(AMEDIAMETRICS_PROP_FLAGS, (int32_t)mFlags)
+ .set(AMEDIAMETRICS_PROP_ORIGINALFLAGS, (int32_t)mOrigFlags)
+ .set(AMEDIAMETRICS_PROP_SESSIONID, (int32_t)mSessionId)
+ .set(AMEDIAMETRICS_PROP_TRACKID, mPortId)
+ .set(AMEDIAMETRICS_PROP_SOURCE, toString(mAttributes.source).c_str())
+ .set(AMEDIAMETRICS_PROP_THREADID, (int32_t)output.inputId)
+ .set(AMEDIAMETRICS_PROP_SELECTEDDEVICEID, (int32_t)mSelectedDeviceId)
+ .set(AMEDIAMETRICS_PROP_ROUTEDDEVICEID, (int32_t)mRoutedDeviceId)
+ .set(AMEDIAMETRICS_PROP_ENCODING, toString(mFormat).c_str())
+ .set(AMEDIAMETRICS_PROP_CHANNELMASK, (int32_t)mChannelMask)
+ .set(AMEDIAMETRICS_PROP_FRAMECOUNT, (int32_t)mFrameCount)
+ .set(AMEDIAMETRICS_PROP_SAMPLERATE, (int32_t)mSampleRate)
+ // the following are NOT immutable
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mActive))
+ .set(AMEDIAMETRICS_PROP_SELECTEDMICDIRECTION, (int32_t)mSelectedMicDirection)
+ .set(AMEDIAMETRICS_PROP_SELECTEDMICFIELDDIRECTION, (double)mSelectedMicFieldDimension)
+ .record();
+
exit:
mStatus = status;
// sp<IAudioTrack> track destructor will cause releaseOutput() to be called by AudioFlinger
@@ -1288,6 +1338,17 @@
status_t AudioRecord::restoreRecord_l(const char *from)
{
+ status_t result = NO_ERROR; // logged: make sure to set this before returning.
+ const int64_t beginNs = systemTime();
+ mediametrics::Defer([&] {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_RESTORE)
+ .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(systemTime() - beginNs))
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mActive))
+ .set(AMEDIAMETRICS_PROP_STATUS, (int32_t)result)
+ .set(AMEDIAMETRICS_PROP_WHERE, from)
+ .record(); });
+
ALOGW("%s(%d): dead IAudioRecord, creating a new one from %s()", __func__, mPortId, from);
++mSequence;
@@ -1306,7 +1367,7 @@
// It will also delete the strong references on previous IAudioRecord and IMemory
Modulo<uint32_t> position(mProxy->getPosition());
mNewPosition = position + mUpdatePeriod;
- status_t result = createRecord_l(position, mOpPackageName);
+ result = createRecord_l(position, mOpPackageName);
if (result == NO_ERROR) {
if (mActive) {
diff --git a/media/libaudioclient/AudioTrack.cpp b/media/libaudioclient/AudioTrack.cpp
index 8cfee50..eda9426 100644
--- a/media/libaudioclient/AudioTrack.cpp
+++ b/media/libaudioclient/AudioTrack.cpp
@@ -296,6 +296,12 @@
// pull together the numbers, before we clean up our structures
mMediaMetrics.gather(this);
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_DTOR)
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mState))
+ .set(AMEDIAMETRICS_PROP_STATUS, (int32_t)mStatus)
+ .record();
+
if (mStatus == NO_ERROR) {
// Make sure that callback function exits in the case where
// it is looping on buffer full condition in obtainBuffer().
@@ -626,11 +632,23 @@
status_t AudioTrack::start()
{
+ const int64_t beginNs = systemTime();
AutoMutex lock(mLock);
+
+ status_t status = NO_ERROR; // logged: make sure to set this before returning.
+ mediametrics::Defer([&] {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_START)
+ .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(systemTime() - beginNs))
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mState))
+ .set(AMEDIAMETRICS_PROP_STATUS, (int32_t)status)
+ .record(); });
+
ALOGV("%s(%d): prior state:%s", __func__, mPortId, stateToString(mState));
if (mState == STATE_ACTIVE) {
- return INVALID_OPERATION;
+ status = INVALID_OPERATION;
+ return status;
}
mInUnderrun = true;
@@ -703,7 +721,6 @@
mNewPosition = mPosition + mUpdatePeriod;
int32_t flags = android_atomic_and(~(CBLK_STREAM_END_DONE | CBLK_DISABLED), &mCblk->mFlags);
- status_t status = NO_ERROR;
if (!(flags & CBLK_INVALID)) {
status = mAudioTrack->start();
if (status == DEAD_OBJECT) {
@@ -749,7 +766,16 @@
void AudioTrack::stop()
{
+ const int64_t beginNs = systemTime();
+
AutoMutex lock(mLock);
+ mediametrics::Defer([&]() {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_STOP)
+ .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(systemTime() - beginNs))
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mState))
+ .record(); });
+
ALOGV("%s(%d): prior state:%s", __func__, mPortId, stateToString(mState));
if (mState != STATE_ACTIVE && mState != STATE_PAUSED) {
@@ -801,7 +827,15 @@
void AudioTrack::flush()
{
+ const int64_t beginNs = systemTime();
AutoMutex lock(mLock);
+ mediametrics::Defer([&]() {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_FLUSH)
+ .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(systemTime() - beginNs))
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mState))
+ .record(); });
+
ALOGV("%s(%d): prior state:%s", __func__, mPortId, stateToString(mState));
if (mSharedBuffer != 0) {
@@ -834,7 +868,15 @@
void AudioTrack::pause()
{
+ const int64_t beginNs = systemTime();
AutoMutex lock(mLock);
+ mediametrics::Defer([&]() {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_PAUSE)
+ .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(systemTime() - beginNs))
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mState))
+ .record(); });
+
ALOGV("%s(%d): prior state:%s", __func__, mPortId, stateToString(mState));
if (mState == STATE_ACTIVE) {
@@ -876,6 +918,12 @@
return BAD_VALUE;
}
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_SETVOLUME)
+ .set(AMEDIAMETRICS_PROP_VOLUME_LEFT, (double)left)
+ .set(AMEDIAMETRICS_PROP_VOLUME_RIGHT, (double)right)
+ .record();
+
AutoMutex lock(mLock);
mVolume[AUDIO_INTERLEAVE_LEFT] = left;
mVolume[AUDIO_INTERLEAVE_RIGHT] = right;
@@ -1027,6 +1075,20 @@
//set effective rates
mProxy->setPlaybackRate(playbackRateTemp);
mProxy->setSampleRate(effectiveRate); // FIXME: not quite "atomic" with setPlaybackRate
+
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_SETPLAYBACKPARAM)
+ .set(AMEDIAMETRICS_PROP_SAMPLERATE, (int32_t)mSampleRate)
+ .set(AMEDIAMETRICS_PROP_PLAYBACK_SPEED, (double)mPlaybackRate.mSpeed)
+ .set(AMEDIAMETRICS_PROP_PLAYBACK_PITCH, (double)mPlaybackRate.mPitch)
+ .set(AMEDIAMETRICS_PROP_PREFIX_EFFECTIVE
+ AMEDIAMETRICS_PROP_SAMPLERATE, (int32_t)effectiveRate)
+ .set(AMEDIAMETRICS_PROP_PREFIX_EFFECTIVE
+ AMEDIAMETRICS_PROP_PLAYBACK_SPEED, (double)playbackRateTemp.mSpeed)
+ .set(AMEDIAMETRICS_PROP_PREFIX_EFFECTIVE
+ AMEDIAMETRICS_PROP_PLAYBACK_PITCH, (double)playbackRateTemp.mPitch)
+ .record();
+
return NO_ERROR;
}
@@ -1618,6 +1680,48 @@
mDeathNotifier = new DeathNotifier(this);
IInterface::asBinder(mAudioTrack)->linkToDeath(mDeathNotifier, this);
+ // This is the first log sent from the AudioTrack client.
+ // The creation of the audio track by AudioFlinger (in the code above)
+ // is the first log of the AudioTrack and must be present before
+ // any AudioTrack client logs will be accepted.
+ mMetricsId = std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_TRACK) + std::to_string(mPortId);
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATE)
+ // the following are immutable
+ .set(AMEDIAMETRICS_PROP_FLAGS, (int32_t)mFlags)
+ .set(AMEDIAMETRICS_PROP_ORIGINALFLAGS, (int32_t)mOrigFlags)
+ .set(AMEDIAMETRICS_PROP_SESSIONID, (int32_t)mSessionId)
+ .set(AMEDIAMETRICS_PROP_TRACKID, mPortId) // dup from key
+ .set(AMEDIAMETRICS_PROP_STREAMTYPE, toString(mStreamType).c_str())
+ .set(AMEDIAMETRICS_PROP_CONTENTTYPE, toString(mAttributes.content_type).c_str())
+ .set(AMEDIAMETRICS_PROP_USAGE, toString(mAttributes.usage).c_str())
+ .set(AMEDIAMETRICS_PROP_THREADID, (int32_t)output.outputId)
+ .set(AMEDIAMETRICS_PROP_SELECTEDDEVICEID, (int32_t)mSelectedDeviceId)
+ .set(AMEDIAMETRICS_PROP_ROUTEDDEVICEID, (int32_t)mRoutedDeviceId)
+ .set(AMEDIAMETRICS_PROP_ENCODING, toString(mFormat).c_str())
+ .set(AMEDIAMETRICS_PROP_CHANNELMASK, (int32_t)mChannelMask)
+ .set(AMEDIAMETRICS_PROP_FRAMECOUNT, (int32_t)mFrameCount)
+ // the following are NOT immutable
+ .set(AMEDIAMETRICS_PROP_VOLUME_LEFT, (double)mVolume[AUDIO_INTERLEAVE_LEFT])
+ .set(AMEDIAMETRICS_PROP_VOLUME_RIGHT, (double)mVolume[AUDIO_INTERLEAVE_RIGHT])
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mState))
+ .set(AMEDIAMETRICS_PROP_AUXEFFECTID, (int32_t)mAuxEffectId)
+ .set(AMEDIAMETRICS_PROP_SAMPLERATE, (int32_t)mSampleRate)
+ .set(AMEDIAMETRICS_PROP_PLAYBACK_SPEED, (double)mPlaybackRate.mSpeed)
+ .set(AMEDIAMETRICS_PROP_PLAYBACK_PITCH, (double)mPlaybackRate.mPitch)
+ .set(AMEDIAMETRICS_PROP_PREFIX_EFFECTIVE
+ AMEDIAMETRICS_PROP_SAMPLERATE, (int32_t)effectiveSampleRate)
+ .set(AMEDIAMETRICS_PROP_PREFIX_EFFECTIVE
+ AMEDIAMETRICS_PROP_PLAYBACK_SPEED, (double)effectiveSpeed)
+ .set(AMEDIAMETRICS_PROP_PREFIX_EFFECTIVE
+ AMEDIAMETRICS_PROP_PLAYBACK_PITCH, (double)effectivePitch)
+ .record();
+
+ // mSendLevel
+ // mReqFrameCount?
+ // mNotificationFramesAct, mNotificationFramesReq, mNotificationsPerBufferReq
+ // mLatency, mAfLatency, mAfFrameCount, mAfSampleRate
+
}
exit:
@@ -2294,6 +2398,17 @@
status_t AudioTrack::restoreTrack_l(const char *from)
{
+ status_t result = NO_ERROR; // logged: make sure to set this before returning.
+ const int64_t beginNs = systemTime();
+ mediametrics::Defer([&] {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_RESTORE)
+ .set(AMEDIAMETRICS_PROP_DURATIONNS, (int64_t)(systemTime() - beginNs))
+ .set(AMEDIAMETRICS_PROP_STATE, stateToString(mState))
+ .set(AMEDIAMETRICS_PROP_STATUS, (int32_t)result)
+ .set(AMEDIAMETRICS_PROP_WHERE, from)
+ .record(); });
+
ALOGW("%s(%d): dead IAudioTrack, %s, creating a new one from %s()",
__func__, mPortId, isOffloadedOrDirect_l() ? "Offloaded or Direct" : "PCM", from);
++mSequence;
@@ -2305,7 +2420,8 @@
if (isOffloadedOrDirect_l() || mDoNotReconnect) {
// FIXME re-creation of offloaded and direct tracks is not yet implemented;
// reconsider enabling for linear PCM encodings when position can be preserved.
- return DEAD_OBJECT;
+ result = DEAD_OBJECT;
+ return result;
}
// Save so we can return count since creation.
@@ -2336,7 +2452,7 @@
// following member variables: mAudioTrack, mCblkMemory and mCblk.
// It will also delete the strong references on previous IAudioTrack and IMemory.
// If a new IAudioTrack cannot be created, the previous (dead) instance will be left intact.
- status_t result = createTrack_l();
+ result = createTrack_l();
if (result == NO_ERROR) {
// take the frames that will be lost by track recreation into account in saved position
diff --git a/media/libaudioclient/include/media/AudioRecord.h b/media/libaudioclient/include/media/AudioRecord.h
index b510378..5c300ed 100644
--- a/media/libaudioclient/include/media/AudioRecord.h
+++ b/media/libaudioclient/include/media/AudioRecord.h
@@ -771,6 +771,7 @@
std::string mLastErrorFunc;
};
MediaMetrics mMediaMetrics;
+ std::string mMetricsId; // GUARDED_BY(mLock), could change in createRecord_l().
};
}; // namespace android
diff --git a/media/libaudioclient/include/media/AudioTrack.h b/media/libaudioclient/include/media/AudioTrack.h
index cfbce03..192d87f 100644
--- a/media/libaudioclient/include/media/AudioTrack.h
+++ b/media/libaudioclient/include/media/AudioTrack.h
@@ -1245,6 +1245,7 @@
std::unique_ptr<mediametrics::Item> mMetricsItem;
};
MediaMetrics mMediaMetrics;
+ std::string mMetricsId; // GUARDED_BY(mLock), could change in createTrack_l().
};
}; // namespace android