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
diff --git a/media/libmediametrics/include/MediaMetricsConstants.h b/media/libmediametrics/include/MediaMetricsConstants.h
new file mode 100644
index 0000000..e49917f
--- /dev/null
+++ b/media/libmediametrics/include/MediaMetricsConstants.h
@@ -0,0 +1,135 @@
+/*
+ * Copyright (C) 2020 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef ANDROID_MEDIA_MEDIAMETRICSCONSTANTS_H
+#define ANDROID_MEDIA_MEDIAMETRICSCONSTANTS_H
+
+/*
+ * MediaMetrics Keys and Properties.
+ *
+ * C/C++ friendly constants that ensure
+ * 1) Compilation error on misspelling
+ * 2) Consistent behavior and documentation.
+ */
+
+/*
+ * Taxonomy of audio keys
+ *
+ * To build longer keys, we use compiler string concatenation of
+ * adjacent string literals. This is done in the translation phase
+ * of compilation to make a single string token.
+ */
+
+// Key Prefixes are used for MediaMetrics Item Keys and ends with a ".".
+// They must be appended with another value to make a key.
+#define AMEDIAMETRICS_KEY_PREFIX_AUDIO "audio."
+
+// The AudioRecord key appends the "trackId" to the prefix.
+#define AMEDIAMETRICS_KEY_PREFIX_AUDIO_RECORD AMEDIAMETRICS_KEY_PREFIX_AUDIO "record."
+
+// The AudioThread key appends the "threadId" to the prefix.
+#define AMEDIAMETRICS_KEY_PREFIX_AUDIO_THREAD AMEDIAMETRICS_KEY_PREFIX_AUDIO "thread."
+
+// The AudioTrack key appends the "trackId" to the prefix.
+#define AMEDIAMETRICS_KEY_PREFIX_AUDIO_TRACK AMEDIAMETRICS_KEY_PREFIX_AUDIO "track."
+
+// Keys are strings used for MediaMetrics Item Keys
+#define AMEDIAMETRICS_KEY_AUDIO_FLINGER AMEDIAMETRICS_KEY_PREFIX_AUDIO "flinger"
+#define AMEDIAMETRICS_KEY_AUDIO_POLICY AMEDIAMETRICS_KEY_PREFIX_AUDIO "policy"
+
+/*
+ * MediaMetrics Properties are unified space for consistency and readability.
+ */
+
+// Property prefixes may be applied before a property name to indicate a specific
+// category to which it is associated.
+#define AMEDIAMETRICS_PROP_PREFIX_EFFECTIVE "effective."
+#define AMEDIAMETRICS_PROP_PREFIX_HAL "hal."
+#define AMEDIAMETRICS_PROP_PREFIX_HAPTIC "haptic."
+#define AMEDIAMETRICS_PROP_PREFIX_SERVER "server."
+
+// Properties within mediametrics are string constants denoted by
+// a macro name beginning with AMEDIAMETRICS_PROP_*
+//
+// For a property name like "auxEffectId" we write this as a single upper case word
+// at the end of the macro name, such as AMEDIAMETRICS_PROP_AUXEFFECTID.
+//
+// Underscores after the AMEDIAMETRICS_PROP_* prefix indicate
+// a "dot" in the property name. For example AMEDIAMETRICS_PROP_VOLUME_LEFT
+// corresponds to "volume.left".
+
+#define AMEDIAMETRICS_PROP_AUXEFFECTID "auxEffectId" // int32 (AudioTrack)
+#define AMEDIAMETRICS_PROP_CHANNELCOUNT "channelCount" // int32
+#define AMEDIAMETRICS_PROP_CHANNELMASK "channelMask" // int32
+#define AMEDIAMETRICS_PROP_CONTENTTYPE "contentType" // string attributes (AudioTrack)
+#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)
+
+// TODO: fix inconsistency in flags: AudioRecord / AudioTrack int32, AudioThread string
+#define AMEDIAMETRICS_PROP_FLAGS "flags"
+
+#define AMEDIAMETRICS_PROP_FRAMECOUNT "frameCount" // int32
+#define AMEDIAMETRICS_PROP_INPUTDEVICES "inputDevices" // string value
+#define AMEDIAMETRICS_PROP_LATENCYMS "latencyMs" // double value
+#define AMEDIAMETRICS_PROP_ORIGINALFLAGS "originalFlags" // int32
+#define AMEDIAMETRICS_PROP_OUTPUTDEVICES "outputDevices" // string value
+#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
+#define AMEDIAMETRICS_PROP_SAMPLERATE "sampleRate" // int32
+#define AMEDIAMETRICS_PROP_SELECTEDDEVICEID "selectedDeviceId" // int32
+#define AMEDIAMETRICS_PROP_SELECTEDMICDIRECTION "selectedMicDirection" // int32
+#define AMEDIAMETRICS_PROP_SELECTEDMICFIELDDIRECTION "selectedMicFieldDimension" // double
+#define AMEDIAMETRICS_PROP_SESSIONID "sessionId" // int32
+#define AMEDIAMETRICS_PROP_SOURCE "source" // string (AudioAttributes)
+#define AMEDIAMETRICS_PROP_STARTUPMS "startupMs" // double value
+// State is "ACTIVE" or "STOPPED" for AudioRecord
+#define AMEDIAMETRICS_PROP_STATE "state" // string
+#define AMEDIAMETRICS_PROP_STATUS "status" // int32 status_t
+#define AMEDIAMETRICS_PROP_STREAMTYPE "streamType" // string (AudioTrack)
+#define AMEDIAMETRICS_PROP_THREADID "threadId" // int32 value io handle
+#define AMEDIAMETRICS_PROP_THROTTLEMS "throttleMs" // double
+#define AMEDIAMETRICS_PROP_TRACKID "trackId" // int32 port id of track/record
+#define AMEDIAMETRICS_PROP_TYPE "type" // string (thread type)
+#define AMEDIAMETRICS_PROP_UNDERRUN "underrun" // int32
+#define AMEDIAMETRICS_PROP_USAGE "usage" // string attributes (ATrack)
+#define AMEDIAMETRICS_PROP_VOLUME_LEFT "volume.left" // double (AudioTrack)
+#define AMEDIAMETRICS_PROP_VOLUME_RIGHT "volume.right" // double (AudioTrack)
+#define AMEDIAMETRICS_PROP_WHERE "where" // string value
+
+// Timing values: millisecond values are suffixed with MS and the type is double
+// nanosecond values are suffixed with NS and the type is int64.
+
+// 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_CREATE "create"
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_CREATEAUDIOPATCH "createAudioPatch"
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR "ctor"
+#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_PAUSE "pause" // AudioTrack
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_READPARAMETERS "readParameters" // Thread
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_RESTORE "restore"
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_SETPLAYBACKPARAM "setPlaybackParam" // AudioTrack
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_SETVOLUME "setVolume" // AudioTrack
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_START "start" // AudioTrack, AudioRecord
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_STOP "stop" // AudioTrack, AudioRecord
+#define AMEDIAMETRICS_PROP_EVENT_VALUE_UNDERRUN "underrun" // from Thread
+
+#endif // ANDROID_MEDIA_MEDIAMETRICSCONSTANTS_H
diff --git a/media/libmediametrics/include/media/MediaMetricsItem.h b/media/libmediametrics/include/media/MediaMetricsItem.h
index b40eb4c..08720f1 100644
--- a/media/libmediametrics/include/media/MediaMetricsItem.h
+++ b/media/libmediametrics/include/media/MediaMetricsItem.h
@@ -18,6 +18,7 @@
#define ANDROID_MEDIA_MEDIAMETRICSITEM_H
#include "MediaMetrics.h"
+#include "MediaMetricsConstants.h"
#include <algorithm>
#include <map>
@@ -35,49 +36,6 @@
namespace android {
-/*
- * MediaMetrics Keys and Properties for Audio.
- *
- * C/C++ friendly constants that ensure
- * 1) Compilation error on misspelling
- * 2) Consistent behavior and documentation.
- *
- * TODO: Move to separate header file.
- */
-
-// Taxonomy of audio keys
-
-// Key Prefixes are used for MediaMetrics Item Keys and ends with a ".".
-// They must be appended with another value to make a key.
-#define AMEDIAMETRICS_KEY_PREFIX_AUDIO "audio."
-
-// The AudioRecord key appends the "trackId" to the prefix.
-#define AMEDIAMETRICS_KEY_PREFIX_AUDIO_RECORD AMEDIAMETRICS_KEY_PREFIX_AUDIO "record."
-
-// The AudioThread key appends the "threadId" to the prefix.
-#define AMEDIAMETRICS_KEY_PREFIX_AUDIO_THREAD AMEDIAMETRICS_KEY_PREFIX_AUDIO "thread."
-
-// The AudioTrack key appends the "trackId" to the prefix.
-#define AMEDIAMETRICS_KEY_PREFIX_AUDIO_TRACK AMEDIAMETRICS_KEY_PREFIX_AUDIO "track."
-
-// Keys are strings used for MediaMetrics Item Keys
-#define AMEDIAMETRICS_KEY_AUDIO_FLINGER AMEDIAMETRICS_KEY_PREFIX_AUDIO "flinger"
-#define AMEDIAMETRICS_KEY_AUDIO_POLICY AMEDIAMETRICS_KEY_PREFIX_AUDIO "policy"
-
-// Props are properties allowed for Mediametrics Items.
-#define AMEDIAMETRICS_PROP_EVENT "event" // string value (often func name)
-#define AMEDIAMETRICS_PROP_LATENCYMS "latencyMs" // double value
-#define AMEDIAMETRICS_PROP_OUTPUTDEVICES "outputDevices" // string value
-#define AMEDIAMETRICS_PROP_STARTUPMS "startupMs" // double value
-#define AMEDIAMETRICS_PROP_THREADID "threadId" // int32 value io handle
-
-// 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_CTOR "ctor"
-#define AMEDIAMETRICS_PROP_EVENT_VALUE_DTOR "dtor"
-#define AMEDIAMETRICS_PROP_EVENT_VALUE_UNDERRUN "underrun" // from Thread
-
class IMediaMetricsService;
class Parcel;
@@ -684,7 +642,11 @@
void init(const char *key) {
mBptr = mBegin;
- const size_t keylen = strlen(key) + 1;
+ const size_t keylen = key == nullptr ? 0 : strlen(key) + 1;
+ if (keylen <= 1) {
+ mStatus = BAD_VALUE; // prevent null pointer or empty keys.
+ return;
+ }
mHeaderLen = 4 + 4 + 2 + 2 + keylen + 4 + 4 + 8;
reallocFor(mHeaderLen);
if (mStatus != NO_ERROR) return;
diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp
index d6f0824..5c5c5bb 100644
--- a/services/audioflinger/AudioFlinger.cpp
+++ b/services/audioflinger/AudioFlinger.cpp
@@ -40,6 +40,7 @@
#include <media/audiohal/DevicesFactoryHalInterface.h>
#include <media/audiohal/EffectsFactoryHalInterface.h>
#include <media/AudioParameter.h>
+#include <media/MediaMetricsItem.h>
#include <media/TypeConverter.h>
#include <memunreachable/memunreachable.h>
#include <utils/String16.h>
@@ -198,6 +199,11 @@
std::vector<pid_t> halPids;
mDevicesFactoryHal->getHalPids(&halPids);
TimeCheck::setAudioHalPids(halPids);
+
+ // Notify that we have started (also called when audioserver service restarts)
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
+ .record();
}
void AudioFlinger::onFirstRef()
diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index d4e0ae2..a16fa94 100644
--- a/services/audioflinger/AudioFlinger.h
+++ b/services/audioflinger/AudioFlinger.h
@@ -952,6 +952,8 @@
SimpleLog mRejectedSetParameterLog;
SimpleLog mAppSetParameterLog;
SimpleLog mSystemSetParameterLog;
+
+ static inline constexpr const char *mMetricsId = AMEDIAMETRICS_KEY_AUDIO_FLINGER;
};
#undef INCLUDING_FROM_AUDIOFLINGER_H
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 87b72fb..7b14050 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -24,6 +24,7 @@
#include <math.h>
#include <fcntl.h>
#include <memory>
+#include <sstream>
#include <string>
#include <linux/futex.h>
#include <sys/stat.h>
@@ -212,6 +213,28 @@
// ----------------------------------------------------------------------------
+// TODO: move all toString helpers to audio.h
+// under #ifdef __cplusplus #endif
+static std::string patchSinksToString(const struct audio_patch *patch)
+{
+ std::stringstream ss;
+ for (size_t i = 0; i < patch->num_sinks; ++i) {
+ ss << "(" << toString(patch->sinks[i].ext.device.type)
+ << ", " << patch->sinks[i].ext.device.address << ")";
+ }
+ return ss.str();
+}
+
+static std::string patchSourcesToString(const struct audio_patch *patch)
+{
+ std::stringstream ss;
+ for (size_t i = 0; i < patch->num_sources; ++i) {
+ ss << "(" << toString(patch->sources[i].ext.device.type)
+ << ", " << patch->sources[i].ext.device.address << ")";
+ }
+ return ss.str();
+}
+
static pthread_once_t sFastTrackMultiplierOnce = PTHREAD_ONCE_INIT;
static void sFastTrackMultiplierInit()
@@ -466,6 +489,7 @@
: Thread(false /*canCallJava*/),
mType(type),
mAudioFlinger(audioFlinger),
+ mMetricsId(std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_THREAD) + std::to_string(id)),
// mSampleRate, mFrameCount, mChannelMask, mChannelCount, mFrameSize, mFormat, mBufferSize
// are set by PlaybackThread::readOutputParameters_l() or
// RecordThread::readInputParameters_l()
@@ -477,6 +501,13 @@
mSystemReady(systemReady),
mSignalPending(false)
{
+ mediametrics::LogItem(mMetricsId)
+ .setPid(getpid())
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
+ .set(AMEDIAMETRICS_PROP_TYPE, threadTypeToString(type))
+ .set(AMEDIAMETRICS_PROP_THREADID, id)
+ .record();
+
memset(&mPatch, 0, sizeof(struct audio_patch));
}
@@ -493,6 +524,10 @@
}
sendStatistics(true /* force */);
+
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_DTOR)
+ .record();
}
status_t AudioFlinger::ThreadBase::readyToRun()
@@ -2794,6 +2829,30 @@
mAudioFlinger->moveEffectChain_l(effectChains[i]->sessionId(),
this/* srcThread */, this/* dstThread */);
}
+
+ audio_output_flags_t flags = mOutput != nullptr ? mOutput->flags : AUDIO_OUTPUT_FLAG_NONE;
+ mediametrics::LogItem item(mMetricsId);
+ item.set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_READPARAMETERS)
+ .set(AMEDIAMETRICS_PROP_ENCODING, formatToString(mFormat).c_str())
+ .set(AMEDIAMETRICS_PROP_SAMPLERATE, (int32_t)mSampleRate)
+ .set(AMEDIAMETRICS_PROP_CHANNELMASK, (int32_t)mChannelMask)
+ .set(AMEDIAMETRICS_PROP_CHANNELCOUNT, (int32_t)mChannelCount)
+ .set(AMEDIAMETRICS_PROP_FRAMECOUNT, (int32_t)mNormalFrameCount)
+ .set(AMEDIAMETRICS_PROP_FLAGS, toString(flags).c_str())
+ .set(AMEDIAMETRICS_PROP_PREFIX_HAPTIC AMEDIAMETRICS_PROP_CHANNELMASK,
+ (int32_t)mHapticChannelMask)
+ .set(AMEDIAMETRICS_PROP_PREFIX_HAPTIC AMEDIAMETRICS_PROP_CHANNELCOUNT,
+ (int32_t)mHapticChannelCount)
+ .set(AMEDIAMETRICS_PROP_PREFIX_HAL AMEDIAMETRICS_PROP_ENCODING,
+ formatToString(mHALFormat).c_str())
+ .set(AMEDIAMETRICS_PROP_PREFIX_HAL AMEDIAMETRICS_PROP_FRAMECOUNT,
+ (int32_t)mFrameCount) // sic - added HAL
+ ;
+ uint32_t latencyMs;
+ if (mOutput->stream->getLatency(&latencyMs) == NO_ERROR) {
+ item.set(AMEDIAMETRICS_PROP_PREFIX_HAL AMEDIAMETRICS_PROP_LATENCYMS, (double)latencyMs);
+ }
+ item.record();
}
void AudioFlinger::PlaybackThread::updateMetadata_l()
@@ -3870,6 +3929,11 @@
const int32_t throttleMs = (int32_t)mHalfBufferMs - deltaMs;
if ((signed)mHalfBufferMs >= throttleMs && throttleMs > 0) {
+ mediametrics::LogItem(mMetricsId)
+ // ms units always double
+ .set(AMEDIAMETRICS_PROP_THROTTLEMS, (double)throttleMs)
+ .record();
+
usleep(throttleMs * 1000);
// notify of throttle start on verbose log
ALOGV_IF(mThreadThrottleEndMs == mThreadThrottleTimeMs,
@@ -4142,6 +4206,11 @@
status = mOutput->stream->setParameters(param.toString());
*handle = AUDIO_PATCH_HANDLE_NONE;
}
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATEAUDIOPATCH)
+ .set(AMEDIAMETRICS_PROP_OUTPUTDEVICES, patchSinksToString(patch).c_str())
+ .record();
+
if (configChanged) {
sendIoConfigEvent_l(AUDIO_OUTPUT_CONFIG_CHANGED);
}
@@ -4683,19 +4752,29 @@
// DeferredOperations handles statistics after setting mixerStatus.
class DeferredOperations {
public:
- DeferredOperations(mixer_state *mixerStatus)
- : mMixerStatus(mixerStatus) { }
+ DeferredOperations(mixer_state *mixerStatus, const std::string &metricsId)
+ : mMixerStatus(mixerStatus)
+ , mMetricsId(metricsId) {}
// when leaving scope, tally frames properly.
~DeferredOperations() {
// Tally underrun frames only if we are actually mixing (MIXER_TRACKS_READY)
// because that is when the underrun occurs.
// We do not distinguish between FastTracks and NormalTracks here.
- if (*mMixerStatus == MIXER_TRACKS_READY) {
+ if (*mMixerStatus == MIXER_TRACKS_READY && mUnderrunFrames.size() > 0) {
+ mediametrics::LogItem item(mMetricsId);
+
+ item.set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_UNDERRUN);
for (const auto &underrun : mUnderrunFrames) {
underrun.first->mAudioTrackServerProxy->tallyUnderrunFrames(
underrun.second);
+
+ item.set(std::string("[" AMEDIAMETRICS_KEY_PREFIX_AUDIO_TRACK)
+ + std::to_string(underrun.first->portId())
+ + "]" AMEDIAMETRICS_PROP_UNDERRUN,
+ (int32_t)underrun.second);
}
+ item.record();
}
}
@@ -4708,8 +4787,10 @@
private:
const mixer_state * const mMixerStatus;
+ const std::string& mMetricsId;
std::vector<std::pair<sp<Track>, size_t>> mUnderrunFrames;
- } deferredOperations(&mixerStatus); // implicit nested scope for variable capture
+ } deferredOperations(&mixerStatus, mMetricsId);
+ // implicit nested scope for variable capture
bool noFastHapticTrack = true;
for (size_t i=0 ; i<count ; i++) {
@@ -5187,11 +5268,20 @@
mixerStatus != MIXER_TRACKS_ENABLED) {
mixerStatus = MIXER_TRACKS_READY;
}
+
+ // Enable the next few lines to instrument a test for underrun log handling.
+ // TODO: Remove when we have a better way of testing the underrun log.
+#if 0
+ static int i;
+ if ((++i & 0xf) == 0) {
+ deferredOperations.tallyUnderrunFrames(track, 10 /* underrunFrames */);
+ }
+#endif
} else {
size_t underrunFrames = 0;
if (framesReady < desiredFrames && !track->isStopped() && !track->isPaused()) {
- ALOGV("track(%d) underrun, framesReady(%zu) < framesDesired(%zd)",
- trackId, framesReady, desiredFrames);
+ ALOGV("track(%d) underrun, track state %s framesReady(%zu) < framesDesired(%zd)",
+ trackId, track->getTrackStateAsString(), framesReady, desiredFrames);
underrunFrames = desiredFrames;
}
deferredOperations.tallyUnderrunFrames(track, underrunFrames);
@@ -8404,6 +8494,12 @@
mPatch = *patch;
}
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATEAUDIOPATCH)
+ .set(AMEDIAMETRICS_PROP_INPUTDEVICES, patchSourcesToString(patch).c_str())
+ .set(AMEDIAMETRICS_PROP_SOURCE, toString(mAudioSource).c_str())
+ .record();
+
return status;
}
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index f1adc23..b0eb75d 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -523,6 +523,7 @@
Condition mWaitWorkCV;
const sp<AudioFlinger> mAudioFlinger;
+ const std::string mMetricsId;
// updated by PlaybackThread::readOutputParameters_l() or
// RecordThread::readInputParameters_l()
diff --git a/services/audioflinger/TrackBase.h b/services/audioflinger/TrackBase.h
index 91dbfa4..e39b944 100644
--- a/services/audioflinger/TrackBase.h
+++ b/services/audioflinger/TrackBase.h
@@ -69,7 +69,8 @@
bool isOut,
alloc_type alloc = ALLOC_CBLK,
track_type type = TYPE_DEFAULT,
- audio_port_handle_t portId = AUDIO_PORT_HANDLE_NONE);
+ audio_port_handle_t portId = AUDIO_PORT_HANDLE_NONE,
+ std::string metricsId = {});
virtual ~TrackBase();
virtual status_t initCheck() const;
@@ -94,7 +95,14 @@
bool isPatchTrack() const { return (mType == TYPE_PATCH); }
bool isExternalTrack() const { return !isOutputTrack() && !isPatchTrack(); }
- virtual void invalidate() { mIsInvalid = true; }
+ virtual void invalidate() {
+ if (mIsInvalid) return;
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT,
+ AMEDIAMETRICS_PROP_EVENT_VALUE_INVALIDATE)
+ .record();
+ mIsInvalid = true;
+ }
bool isInvalid() const { return mIsInvalid; }
void terminate() { mTerminated = true; }
@@ -353,6 +361,14 @@
audio_port_handle_t mPortId; // unique ID for this track used by audio policy
bool mIsInvalid; // non-resettable latch, set by invalidate()
+ // It typically takes 5 threadloop mix iterations for latency to stabilize.
+ static inline constexpr int32_t LOG_START_COUNTDOWN = 8;
+ int32_t mLogStartCountdown = 0;
+ int64_t mLogStartTimeNs = 0;
+ int64_t mLogStartFrames = 0;
+
+ const std::string mMetricsId;
+
bool mServerLatencySupported = false;
std::atomic<bool> mServerLatencyFromTrack{}; // latency from track or server timestamp.
std::atomic<double> mServerLatencyMs{}; // last latency pushed from server thread.
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index 2437202..23d8329 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -80,7 +80,8 @@
bool isOut,
alloc_type alloc,
track_type type,
- audio_port_handle_t portId)
+ audio_port_handle_t portId,
+ std::string metricsId)
: RefBase(),
mThread(thread),
mClient(client),
@@ -105,6 +106,7 @@
mThreadIoHandle(thread ? thread->id() : AUDIO_IO_HANDLE_NONE),
mPortId(portId),
mIsInvalid(false),
+ mMetricsId(std::move(metricsId)),
mCreatorPid(creatorPid)
{
const uid_t callingUid = IPCThreadState::self()->getCallingUid();
@@ -519,7 +521,9 @@
(sharedBuffer != 0) ? sharedBuffer->size() : bufferSize,
sessionId, creatorPid, uid, true /*isOut*/,
(type == TYPE_PATCH) ? ( buffer == NULL ? ALLOC_LOCAL : ALLOC_NONE) : ALLOC_CBLK,
- type, portId),
+ type,
+ portId,
+ std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_TRACK) + std::to_string(portId)),
mFillingUpStatus(FS_INVALID),
// mRetryCount initialized later when needed
mSharedBuffer(sharedBuffer),
@@ -596,6 +600,14 @@
mExternalVibration = new os::ExternalVibration(
mUid, "" /* pkg */, mAttr, mAudioVibrationController);
}
+
+ // Once this item is logged by the server, the client can add properties.
+ mediametrics::LogItem(mMetricsId)
+ .setPid(creatorPid)
+ .setUid(uid)
+ .set(AMEDIAMETRICS_PROP_EVENT,
+ AMEDIAMETRICS_PROP_PREFIX_SERVER AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
+ .record();
}
AudioFlinger::PlaybackThread::Track::~Track()
@@ -966,6 +978,14 @@
}
}
+ // Audio timing metrics are computed a few mix cycles after starting.
+ {
+ mLogStartCountdown = LOG_START_COUNTDOWN;
+ mLogStartTimeNs = systemTime();
+ mLogStartFrames = mAudioTrackServerProxy->getTimestamp()
+ .mPosition[ExtendedTimestamp::LOCATION_SERVER];
+ }
+
if (status == NO_ERROR || status == ALREADY_EXISTS) {
// for streaming tracks, remove the buffer read stop limit.
mAudioTrackServerProxy->start();
@@ -1497,6 +1517,28 @@
mServerLatencyFromTrack.store(useTrackTimestamp);
mServerLatencyMs.store(latencyMs);
+
+ if (mLogStartCountdown > 0) {
+ if (--mLogStartCountdown == 0) {
+ // startup is the difference in times for the current timestamp and our start
+ double startUpMs =
+ (local.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] - mLogStartTimeNs) * 1e-6;
+ // adjust for frames played.
+ startUpMs -= (local.mPosition[ExtendedTimestamp::LOCATION_SERVER] - mLogStartFrames)
+ * 1e3 / mSampleRate;
+ ALOGV("%s: logging localTime:%lld, startTime:%lld"
+ " localPosition:%lld, startPosition:%lld",
+ __func__,
+ (long long)local.mTimeNs[ExtendedTimestamp::LOCATION_SERVER],
+ (long long)mLogStartTimeNs,
+ (long long)local.mPosition[ExtendedTimestamp::LOCATION_SERVER],
+ (long long)mLogStartFrames);
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_LATENCYMS, latencyMs)
+ .set(AMEDIAMETRICS_PROP_STARTUPMS, startUpMs)
+ .record();
+ }
+ }
}
binder::Status AudioFlinger::PlaybackThread::Track::AudioVibrationController::mute(
@@ -2071,7 +2113,8 @@
(type == TYPE_DEFAULT) ?
((flags & AUDIO_INPUT_FLAG_FAST) ? ALLOC_PIPE : ALLOC_CBLK) :
((buffer == NULL) ? ALLOC_LOCAL : ALLOC_NONE),
- type, portId),
+ type, portId,
+ std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_RECORD) + std::to_string(portId)),
mOverflow(false),
mFramesToDrop(0),
mResamplerBufferProvider(NULL), // initialize in case of early constructor exit
@@ -2117,6 +2160,13 @@
+ "_" + std::to_string(mId)
+ "_R");
#endif
+
+ // Once this item is logged by the server, the client can add properties.
+ mediametrics::LogItem(mMetricsId)
+ .setPid(creatorPid)
+ .setUid(uid)
+ .set(AMEDIAMETRICS_PROP_EVENT, "server." AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
+ .record();
}
AudioFlinger::RecordThread::RecordTrack::~RecordTrack()