AudioFlinger: Improve Thread logging.
Test: dumpsys media.audio_flinger
Bug: 30572472
Change-Id: I43f72354a6ece045f5f9f664946a406166974258
diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index fca840b..75b4e4c 100644
--- a/services/audioflinger/AudioFlinger.h
+++ b/services/audioflinger/AudioFlinger.h
@@ -58,6 +58,8 @@
#include <media/LinearMap.h>
#include <media/VolumeShaper.h>
+#include <audio_utils/SimpleLog.h>
+
#include "FastCapture.h"
#include "FastMixer.h"
#include <media/nbaio/NBAIO.h>
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 54e07c0..3b1edec 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -699,17 +699,29 @@
SetParameterConfigEventData *data = (SetParameterConfigEventData *)event->mData.get();
if (checkForNewParameter_l(data->mKeyValuePairs, event->mStatus)) {
configChanged = true;
+ mLocalLog.log("CFG_EVENT_SET_PARAMETER: (%s) configuration changed",
+ data->mKeyValuePairs.string());
}
} break;
case CFG_EVENT_CREATE_AUDIO_PATCH: {
+ const audio_devices_t oldDevice = getDevice();
CreateAudioPatchConfigEventData *data =
(CreateAudioPatchConfigEventData *)event->mData.get();
event->mStatus = createAudioPatch_l(&data->mPatch, &data->mHandle);
+ const audio_devices_t newDevice = getDevice();
+ mLocalLog.log("CFG_EVENT_CREATE_AUDIO_PATCH: old device %#x (%s) new device %#x (%s)",
+ (unsigned)oldDevice, devicesToString(oldDevice).c_str(),
+ (unsigned)newDevice, devicesToString(newDevice).c_str());
} break;
case CFG_EVENT_RELEASE_AUDIO_PATCH: {
+ const audio_devices_t oldDevice = getDevice();
ReleaseAudioPatchConfigEventData *data =
(ReleaseAudioPatchConfigEventData *)event->mData.get();
event->mStatus = releaseAudioPatch_l(data->mHandle);
+ const audio_devices_t newDevice = getDevice();
+ mLocalLog.log("CFG_EVENT_RELEASE_AUDIO_PATCH: old device %#x (%s) new device %#x (%s)",
+ (unsigned)oldDevice, devicesToString(oldDevice).c_str(),
+ (unsigned)newDevice, devicesToString(newDevice).c_str());
} break;
default:
ALOG_ASSERT(false, "processConfigEvents_l() unknown event type %d", event->mType);
@@ -826,6 +838,7 @@
} else {
dprintf(fd, " none\n");
}
+ // Note: output device may be used by capture threads for effects such as AEC.
dprintf(fd, " Output device: %#x (%s)\n", mOutDevice, devicesToString(mOutDevice).c_str());
dprintf(fd, " Input device: %#x (%s)\n", mInDevice, devicesToString(mInDevice).c_str());
dprintf(fd, " Audio source: %d (%s)\n", mAudioSource, sourceToString(mAudioSource));
@@ -1694,7 +1707,8 @@
dumpInternals(fd, args);
dumpTracks(fd, args);
dumpEffectChains(fd, args);
- mLocalLog.dump(fd, args, " " /* prefix */);
+ dprintf(fd, " Local log:\n");
+ mLocalLog.dump(fd, " " /* prefix */, 40 /* lines */);
}
void AudioFlinger::PlaybackThread::dumpTracks(int fd, const Vector<String16>& args __unused)
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index 422eeb5..8270e74 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -288,6 +288,9 @@
bool standby() const { return mStandby; }
audio_devices_t outDevice() const { return mOutDevice; }
audio_devices_t inDevice() const { return mInDevice; }
+ audio_devices_t getDevice() const { return isOutput() ? mOutDevice : mInDevice; }
+
+ virtual bool isOutput() const = 0;
virtual sp<StreamHalInterface> stream() const = 0;
@@ -575,6 +578,8 @@
int mLastActiveTracksGeneration;
wp<T> mLatestActiveTrack; // latest track added to ActiveTracks
};
+
+ SimpleLog mLocalLog;
};
class VolumeInterface {
@@ -760,6 +765,8 @@
// Return the asynchronous signal wait time.
virtual int64_t computeWaitTimeNs_l() const { return INT64_MAX; }
+ virtual bool isOutput() const override { return true; }
+
protected:
// updated by readOutputParameters_l()
size_t mNormalFrameCount; // normal mixer and effects
@@ -971,80 +978,6 @@
static const size_t kFastMixerLogSize = 4 * 1024;
sp<NBLog::Writer> mFastMixerNBLogWriter;
- // Do not call from a sched_fifo thread as it uses a system time call
- // and obtains a local mutex.
- class LocalLog {
- public:
- void log(const char *fmt, ...) {
- va_list val;
- va_start(val, fmt);
-
- // format to buffer
- char buffer[512];
- int length = vsnprintf(buffer, sizeof(buffer), fmt, val);
- if (length >= (signed)sizeof(buffer)) {
- length = sizeof(buffer) - 1;
- }
-
- // strip out trailing newline
- while (length > 0 && buffer[length - 1] == '\n') {
- buffer[--length] = 0;
- }
-
- // store in circular array
- AutoMutex _l(mLock);
- mLog.emplace_back(
- std::make_pair(systemTime(SYSTEM_TIME_REALTIME), std::string(buffer)));
- if (mLog.size() > kLogSize) {
- mLog.pop_front();
- }
-
- va_end(val);
- }
-
- void dump(int fd, const Vector<String16>& args, const char *prefix = "") {
- if (!AudioFlinger::dumpTryLock(mLock)) return; // a local lock, shouldn't happen
- if (mLog.size() > 0) {
- bool dumpAll = false;
- for (const auto &arg : args) {
- if (arg == String16("--locallog")) {
- dumpAll = true;
- }
- }
-
- dprintf(fd, "Local Log:\n");
- auto it = mLog.begin();
- if (!dumpAll) {
- const size_t lines =
- (size_t)property_get_int32("audio.locallog.lines", kLogPrint);
- if (mLog.size() > lines) {
- it += (mLog.size() - lines);
- }
- }
- for (; it != mLog.end(); ++it) {
- const int64_t ns = it->first;
- const int ns_per_sec = 1000000000;
- const time_t sec = ns / ns_per_sec;
- struct tm tm;
- localtime_r(&sec, &tm);
-
- dprintf(fd, "%s%02d-%02d %02d:%02d:%02d.%03d %s\n",
- prefix,
- tm.tm_mon + 1, // localtime_r uses months in 0 - 11 range
- tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec,
- (int)(ns % ns_per_sec / 1000000),
- it->second.c_str());
- }
- }
- mLock.unlock();
- }
-
- private:
- Mutex mLock;
- static const size_t kLogSize = 256; // full history
- static const size_t kLogPrint = 32; // default print history
- std::deque<std::pair<int64_t, std::string>> mLog;
- } mLocalLog;
public:
virtual bool hasFastMixer() const = 0;
@@ -1446,6 +1379,7 @@
ThreadBase::acquireWakeLock_l();
mActiveTracks.updatePowerState(this, true /* force */);
}
+ virtual bool isOutput() const override { return false; }
private:
// Enter standby if not already in standby, and set mStandby flag
@@ -1587,8 +1521,6 @@
virtual void dumpInternals(int fd, const Vector<String16>& args);
void dumpTracks(int fd, const Vector<String16>& args);
- virtual bool isOutput() const = 0;
-
protected:
audio_attributes_t mAttr;
@@ -1636,7 +1568,7 @@
virtual void dumpInternals(int fd, const Vector<String16>& args);
- virtual bool isOutput() const { return true; }
+ virtual bool isOutput() const override { return true; }
protected:
@@ -1660,7 +1592,7 @@
AudioStreamIn* clearInput();
- virtual bool isOutput() const { return false; }
+ virtual bool isOutput() const override { return false; }
protected: