AudioFlinger, AudioPolicy: Add binder time check statistics
Binder method count and execution time now in dumpsys.
Add method name to TimeCheck abort logs.
Add MethodStatistics utility class to accumulate values.
Test: atest libmediautils_test
Test: atest method_statistics
Test: atest timecheck_tests
Test: adb shell dumpsys media.audio_flinger
Test: adb shell dumpsys media.audio_policy
Test: adb shell dumpsys media.metrics
Bug: 219958414
Change-Id: I7398d706e475596af6ad491463e87e92b09026d8
diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp
index 1dcaf6c..8cafdfd 100644
--- a/services/audioflinger/AudioFlinger.cpp
+++ b/services/audioflinger/AudioFlinger.cpp
@@ -79,6 +79,7 @@
#include <media/nbaio/PipeReader.h>
#include <mediautils/BatteryNotifier.h>
#include <mediautils/MemoryLeakTrackUtil.h>
+#include <mediautils/MethodStatistics.h>
#include <mediautils/ServiceUtilities.h>
#include <mediautils/TimeCheck.h>
#include <private/android_filesystem_config.h>
@@ -158,6 +159,92 @@
return sExternalVibratorService;
}
+// Creates association between Binder code to name for IAudioFlinger.
+#define IAUDIOFLINGER_BINDER_METHOD_MACRO_LIST \
+BINDER_METHOD_ENTRY(createTrack) \
+BINDER_METHOD_ENTRY(createRecord) \
+BINDER_METHOD_ENTRY(sampleRate) \
+BINDER_METHOD_ENTRY(format) \
+BINDER_METHOD_ENTRY(frameCount) \
+BINDER_METHOD_ENTRY(latency) \
+BINDER_METHOD_ENTRY(setMasterVolume) \
+BINDER_METHOD_ENTRY(setMasterMute) \
+BINDER_METHOD_ENTRY(masterVolume) \
+BINDER_METHOD_ENTRY(masterMute) \
+BINDER_METHOD_ENTRY(setStreamVolume) \
+BINDER_METHOD_ENTRY(setStreamMute) \
+BINDER_METHOD_ENTRY(streamVolume) \
+BINDER_METHOD_ENTRY(streamMute) \
+BINDER_METHOD_ENTRY(setMode) \
+BINDER_METHOD_ENTRY(setMicMute) \
+BINDER_METHOD_ENTRY(getMicMute) \
+BINDER_METHOD_ENTRY(setRecordSilenced) \
+BINDER_METHOD_ENTRY(setParameters) \
+BINDER_METHOD_ENTRY(getParameters) \
+BINDER_METHOD_ENTRY(registerClient) \
+BINDER_METHOD_ENTRY(getInputBufferSize) \
+BINDER_METHOD_ENTRY(openOutput) \
+BINDER_METHOD_ENTRY(openDuplicateOutput) \
+BINDER_METHOD_ENTRY(closeOutput) \
+BINDER_METHOD_ENTRY(suspendOutput) \
+BINDER_METHOD_ENTRY(restoreOutput) \
+BINDER_METHOD_ENTRY(openInput) \
+BINDER_METHOD_ENTRY(closeInput) \
+BINDER_METHOD_ENTRY(invalidateStream) \
+BINDER_METHOD_ENTRY(setVoiceVolume) \
+BINDER_METHOD_ENTRY(getRenderPosition) \
+BINDER_METHOD_ENTRY(getInputFramesLost) \
+BINDER_METHOD_ENTRY(newAudioUniqueId) \
+BINDER_METHOD_ENTRY(acquireAudioSessionId) \
+BINDER_METHOD_ENTRY(releaseAudioSessionId) \
+BINDER_METHOD_ENTRY(queryNumberEffects) \
+BINDER_METHOD_ENTRY(queryEffect) \
+BINDER_METHOD_ENTRY(getEffectDescriptor) \
+BINDER_METHOD_ENTRY(createEffect) \
+BINDER_METHOD_ENTRY(moveEffects) \
+BINDER_METHOD_ENTRY(loadHwModule) \
+BINDER_METHOD_ENTRY(getPrimaryOutputSamplingRate) \
+BINDER_METHOD_ENTRY(getPrimaryOutputFrameCount) \
+BINDER_METHOD_ENTRY(setLowRamDevice) \
+BINDER_METHOD_ENTRY(getAudioPort) \
+BINDER_METHOD_ENTRY(createAudioPatch) \
+BINDER_METHOD_ENTRY(releaseAudioPatch) \
+BINDER_METHOD_ENTRY(listAudioPatches) \
+BINDER_METHOD_ENTRY(setAudioPortConfig) \
+BINDER_METHOD_ENTRY(getAudioHwSyncForSession) \
+BINDER_METHOD_ENTRY(systemReady) \
+BINDER_METHOD_ENTRY(audioPolicyReady) \
+BINDER_METHOD_ENTRY(frameCountHAL) \
+BINDER_METHOD_ENTRY(getMicrophones) \
+BINDER_METHOD_ENTRY(setMasterBalance) \
+BINDER_METHOD_ENTRY(getMasterBalance) \
+BINDER_METHOD_ENTRY(setEffectSuspended) \
+BINDER_METHOD_ENTRY(setAudioHalPids) \
+BINDER_METHOD_ENTRY(setVibratorInfos) \
+BINDER_METHOD_ENTRY(updateSecondaryOutputs) \
+BINDER_METHOD_ENTRY(getMmapPolicyInfos) \
+BINDER_METHOD_ENTRY(getAAudioMixerBurstCount) \
+BINDER_METHOD_ENTRY(getAAudioHardwareBurstMinUsec) \
+BINDER_METHOD_ENTRY(setDeviceConnectedState) \
+
+// singleton for Binder Method Statistics for IAudioFlinger
+static auto& getIAudioFlingerStatistics() {
+ using Code = android::AudioFlingerServerAdapter::Delegate::TransactionCode;
+
+#pragma push_macro("BINDER_METHOD_ENTRY")
+#undef BINDER_METHOD_ENTRY
+#define BINDER_METHOD_ENTRY(ENTRY) \
+ {(Code)media::BnAudioFlingerService::TRANSACTION_##ENTRY, #ENTRY},
+
+ static mediautils::MethodStatistics<Code> methodStatistics{
+ IAUDIOFLINGER_BINDER_METHOD_MACRO_LIST
+ METHOD_STATISTICS_BINDER_CODE_NAMES(Code)
+ };
+#pragma pop_macro("BINDER_METHOD_ENTRY")
+
+ return methodStatistics;
+}
+
class DevicesFactoryHalCallbackImpl : public DevicesFactoryHalCallback {
public:
void onNewDevicesAvailable() override {
@@ -828,6 +915,16 @@
std::string s = GetUnreachableMemoryString(true /* contents */, 100 /* limit */);
write(fd, s.c_str(), s.size());
}
+ {
+ std::string timeCheckStats = getIAudioFlingerStatistics().dump();
+ dprintf(fd, "\nIAudioFlinger binder call profile\n");
+ write(fd, timeCheckStats.c_str(), timeCheckStats.size());
+
+ extern mediautils::MethodStatistics<int>& getIEffectStatistics();
+ timeCheckStats = getIEffectStatistics().dump();
+ dprintf(fd, "\nIEffect binder call profile\n");
+ write(fd, timeCheckStats.c_str(), timeCheckStats.size());
+ }
}
return NO_ERROR;
}
@@ -4417,9 +4514,20 @@
break;
}
- std::string tag("IAudioFlinger command " +
- std::to_string(static_cast<std::underlying_type_t<TransactionCode>>(code)));
- mediautils::TimeCheck check(tag.c_str());
+ const std::string methodName = getIAudioFlingerStatistics().getMethodForCode(code);
+ mediautils::TimeCheck check(
+ std::string("IAudioFlinger::").append(methodName),
+ [code, methodName](bool timeout, float elapsedMs) { // don't move methodName.
+ if (timeout) {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_TIMEOUT)
+ .set(AMEDIAMETRICS_PROP_METHODCODE, int64_t(code))
+ .set(AMEDIAMETRICS_PROP_METHODNAME, methodName.c_str())
+ .record();
+ } else {
+ getIAudioFlingerStatistics().event(code, elapsedMs);
+ }
+ });
// Make sure we connect to Audio Policy Service before calling into AudioFlinger:
// - AudioFlinger can call into Audio Policy Service with its global mutex held
diff --git a/services/audioflinger/Effects.cpp b/services/audioflinger/Effects.cpp
index b748f9d..efd2dbd 100644
--- a/services/audioflinger/Effects.cpp
+++ b/services/audioflinger/Effects.cpp
@@ -39,6 +39,7 @@
#include <media/ShmemCompat.h>
#include <media/audiohal/EffectHalInterface.h>
#include <media/audiohal/EffectsFactoryHalInterface.h>
+#include <mediautils/MethodStatistics.h>
#include <mediautils/ServiceUtilities.h>
#include "AudioFlinger.h"
@@ -1751,6 +1752,44 @@
disconnect(false);
}
+// Creates an association between Binder code to name for IEffect.
+#define IEFFECT_BINDER_METHOD_MACRO_LIST \
+BINDER_METHOD_ENTRY(enable) \
+BINDER_METHOD_ENTRY(disable) \
+BINDER_METHOD_ENTRY(command) \
+BINDER_METHOD_ENTRY(disconnect) \
+BINDER_METHOD_ENTRY(getCblk) \
+
+// singleton for Binder Method Statistics for IEffect
+mediautils::MethodStatistics<int>& getIEffectStatistics() {
+ using Code = int;
+
+#pragma push_macro("BINDER_METHOD_ENTRY")
+#undef BINDER_METHOD_ENTRY
+#define BINDER_METHOD_ENTRY(ENTRY) \
+ {(Code)media::BnEffect::TRANSACTION_##ENTRY, #ENTRY},
+
+ static mediautils::MethodStatistics<Code> methodStatistics{
+ IEFFECT_BINDER_METHOD_MACRO_LIST
+ METHOD_STATISTICS_BINDER_CODE_NAMES(Code)
+ };
+#pragma pop_macro("BINDER_METHOD_ENTRY")
+
+ return methodStatistics;
+}
+
+status_t AudioFlinger::EffectHandle::onTransact(
+ uint32_t code, const Parcel& data, Parcel* reply, uint32_t flags) {
+ std::chrono::system_clock::time_point startTime = std::chrono::system_clock::now();
+ mediametrics::Defer defer([startTime, code] {
+ std::chrono::system_clock::time_point endTime = std::chrono::system_clock::now();
+ getIEffectStatistics().event(code,
+ std::chrono::duration_cast<std::chrono::duration<float, std::milli>>(
+ endTime - startTime).count());
+ });
+ return BnEffect::onTransact(code, data, reply, flags);
+}
+
status_t AudioFlinger::EffectHandle::initCheck()
{
return mClient == 0 || mCblkMemory != 0 ? OK : NO_MEMORY;
diff --git a/services/audioflinger/Effects.h b/services/audioflinger/Effects.h
index e2bea67..42614cc 100644
--- a/services/audioflinger/Effects.h
+++ b/services/audioflinger/Effects.h
@@ -356,6 +356,8 @@
const sp<media::IEffectClient>& effectClient,
int32_t priority, bool notifyFramesProcessed);
virtual ~EffectHandle();
+ status_t onTransact(
+ uint32_t code, const Parcel& data, Parcel* reply, uint32_t flags) override;
virtual status_t initCheck();
// IEffect