AudioRecord: Add client side track id for logging
Test: Audio sanity test, check logcat
Bug: 115400221
Change-Id: Ifa9c05c0df66e372e773b5149a0f1ed49a21ef3a
diff --git a/media/libaudioclient/AudioRecord.cpp b/media/libaudioclient/AudioRecord.cpp
index e2de8e7..17f17a3 100644
--- a/media/libaudioclient/AudioRecord.cpp
+++ b/media/libaudioclient/AudioRecord.cpp
@@ -48,8 +48,9 @@
size_t size;
status_t status = AudioSystem::getInputBufferSize(sampleRate, format, channelMask, &size);
if (status != NO_ERROR) {
- ALOGE("AudioSystem could not query the input buffer size for sampleRate %u, format %#x, "
- "channelMask %#x; status %d", sampleRate, format, channelMask, status);
+ ALOGE("%s(): AudioSystem could not query the input buffer size for"
+ " sampleRate %u, format %#x, channelMask %#x; status %d",
+ __func__, sampleRate, format, channelMask, status);
return status;
}
@@ -57,8 +58,8 @@
// Assumes audio_is_linear_pcm(format)
if ((*frameCount = (size * 2) / (audio_channel_count_from_in_mask(channelMask) *
audio_bytes_per_sample(format))) == 0) {
- ALOGE("Unsupported configuration: sampleRate %u, format %#x, channelMask %#x",
- sampleRate, format, channelMask);
+ ALOGE("%s(): Unsupported configuration: sampleRate %u, format %#x, channelMask %#x",
+ __func__, sampleRate, format, channelMask);
return BAD_VALUE;
}
@@ -208,8 +209,8 @@
mCblkMemory.clear();
mBufferMemory.clear();
IPCThreadState::self()->flushCommands();
- ALOGV("~AudioRecord, releasing session id %d",
- mSessionId);
+ ALOGV("%s(%d): releasing session id %d",
+ __func__, mId, mSessionId);
AudioSystem::releaseAudioSessionId(mSessionId, -1 /*pid*/);
}
}
@@ -237,9 +238,11 @@
pid_t callingPid;
pid_t myPid;
- ALOGV("set(): inputSource %d, sampleRate %u, format %#x, channelMask %#x, frameCount %zu, "
+ // Note mId is not valid until the track is created, so omit mId in ALOG for set.
+ ALOGV("%s(): inputSource %d, sampleRate %u, format %#x, channelMask %#x, frameCount %zu, "
"notificationFrames %u, sessionId %d, transferType %d, flags %#x, opPackageName %s "
"uid %d, pid %d",
+ __func__,
inputSource, sampleRate, format, channelMask, frameCount, notificationFrames,
sessionId, transferType, flags, String8(mOpPackageName).string(), uid, pid);
@@ -255,7 +258,7 @@
break;
case TRANSFER_CALLBACK:
if (cbf == NULL) {
- ALOGE("Transfer type TRANSFER_CALLBACK but cbf == NULL");
+ ALOGE("%s(): Transfer type TRANSFER_CALLBACK but cbf == NULL", __func__);
status = BAD_VALUE;
goto exit;
}
@@ -264,7 +267,7 @@
case TRANSFER_SYNC:
break;
default:
- ALOGE("Invalid transfer type %d", transferType);
+ ALOGE("%s(): Invalid transfer type %d", __func__, transferType);
status = BAD_VALUE;
goto exit;
}
@@ -272,7 +275,7 @@
// invariant that mAudioRecord != 0 is true only after set() returns successfully
if (mAudioRecord != 0) {
- ALOGE("Track already in use");
+ ALOGE("%s(): Track already in use", __func__);
status = INVALID_OPERATION;
goto exit;
}
@@ -283,8 +286,8 @@
} else {
// stream type shouldn't be looked at, this track has audio attributes
memcpy(&mAttributes, pAttributes, sizeof(audio_attributes_t));
- ALOGV("Building AudioRecord with attributes: source=%d flags=0x%x tags=[%s]",
- mAttributes.source, mAttributes.flags, mAttributes.tags);
+ ALOGV("%s(): Building AudioRecord with attributes: source=%d flags=0x%x tags=[%s]",
+ __func__, mAttributes.source, mAttributes.flags, mAttributes.tags);
}
mSampleRate = sampleRate;
@@ -297,14 +300,14 @@
// validate parameters
// AudioFlinger capture only supports linear PCM
if (!audio_is_valid_format(format) || !audio_is_linear_pcm(format)) {
- ALOGE("Format %#x is not linear pcm", format);
+ ALOGE("%s(): Format %#x is not linear pcm", __func__, format);
status = BAD_VALUE;
goto exit;
}
mFormat = format;
if (!audio_is_input_channel(channelMask)) {
- ALOGE("Invalid channel mask %#x", channelMask);
+ ALOGE("%s(): Invalid channel mask %#x", __func__, channelMask);
status = BAD_VALUE;
goto exit;
}
@@ -325,7 +328,7 @@
// mNotificationFramesAct is initialized in createRecord_l
mSessionId = sessionId;
- ALOGV("set(): mSessionId %d", mSessionId);
+ ALOGV("%s(): mSessionId %d", __func__, mSessionId);
callingPid = IPCThreadState::self()->getCallingPid();
myPid = getpid();
@@ -352,6 +355,8 @@
// create the IAudioRecord
status = createRecord_l(0 /*epoch*/, mOpPackageName);
+ ALOGV("%s(%d): status %d", __func__, mId, status);
+
if (status != NO_ERROR) {
if (mAudioRecordThread != 0) {
mAudioRecordThread->requestExit(); // see comment in AudioRecord.h
@@ -387,7 +392,7 @@
status_t AudioRecord::start(AudioSystem::sync_event_t event, audio_session_t triggerSession)
{
- ALOGV("start, sync event %d trigger session %d", event, triggerSession);
+ ALOGV("%s(%d): sync event %d trigger session %d", __func__, mId, event, triggerSession);
AutoMutex lock(mLock);
if (mActive) {
@@ -428,7 +433,7 @@
if (status != NO_ERROR) {
mActive = false;
- ALOGE("start() status %d", status);
+ ALOGE("%s(%d): status %d", __func__, mId, status);
} else {
sp<AudioRecordThread> t = mAudioRecordThread;
if (t != 0) {
@@ -452,6 +457,7 @@
void AudioRecord::stop()
{
AutoMutex lock(mLock);
+ ALOGV("%s(%d): mActive:%d\n", __func__, mId, mActive);
if (!mActive) {
return;
}
@@ -630,8 +636,8 @@
String8 result;
result.append(" AudioRecord::dump\n");
- result.appendFormat(" status(%d), active(%d), session Id(%d)\n",
- mStatus, mActive, mSessionId);
+ result.appendFormat(" id(%d) status(%d), active(%d), session Id(%d)\n",
+ mId, mStatus, mActive, mSessionId);
result.appendFormat(" flags(%#x), req. flags(%#x), audio source(%d)\n",
mFlags, mOrigFlags, mAttributes.source);
result.appendFormat(" format(%#x), channel mask(%#x), channel count(%u), sample rate(%u)\n",
@@ -673,7 +679,7 @@
status_t status;
if (audioFlinger == 0) {
- ALOGE("Could not get audioflinger");
+ ALOGE("%s(%d): Could not get audioflinger", __func__, mId);
status = NO_INIT;
goto exit;
}
@@ -700,7 +706,8 @@
// use case 3: obtain/release mode
(mTransfer == TRANSFER_OBTAIN);
if (!useCaseAllowed) {
- ALOGW("AUDIO_INPUT_FLAG_FAST denied, incompatible transfer = %s",
+ ALOGW("%s(%d): AUDIO_INPUT_FLAG_FAST denied, incompatible transfer = %s",
+ __func__, mId,
convertTransferToText(mTransfer));
mFlags = (audio_input_flags_t) (mFlags & ~(AUDIO_INPUT_FLAG_FAST |
AUDIO_INPUT_FLAG_RAW));
@@ -735,7 +742,8 @@
&status);
if (status != NO_ERROR) {
- ALOGE("AudioFlinger could not create record track, status: %d", status);
+ ALOGE("%s(%d): AudioFlinger could not create record track, status: %d",
+ __func__, mId, status);
goto exit;
}
ALOG_ASSERT(record != 0);
@@ -745,7 +753,8 @@
mAwaitBoost = false;
if (output.flags & AUDIO_INPUT_FLAG_FAST) {
- ALOGI("AUDIO_INPUT_FLAG_FAST successful; frameCount %zu -> %zu",
+ ALOGI("%s(%d): AUDIO_INPUT_FLAG_FAST successful; frameCount %zu -> %zu",
+ __func__, mId,
mReqFrameCount, output.frameCount);
mAwaitBoost = true;
}
@@ -755,13 +764,13 @@
mSampleRate = output.sampleRate;
if (output.cblk == 0) {
- ALOGE("Could not get control block");
+ ALOGE("%s(%d): Could not get control block", __func__, mId);
status = NO_INIT;
goto exit;
}
iMemPointer = output.cblk ->pointer();
if (iMemPointer == NULL) {
- ALOGE("Could not get control block pointer");
+ ALOGE("%s(%d): Could not get control block pointer", __func__, mId);
status = NO_INIT;
goto exit;
}
@@ -776,7 +785,7 @@
} else {
buffers = output.buffers->pointer();
if (buffers == NULL) {
- ALOGE("Could not get buffer pointer");
+ ALOGE("%s(%d): Could not get buffer pointer", __func__, mId);
status = NO_INIT;
goto exit;
}
@@ -790,19 +799,22 @@
mAudioRecord = record;
mCblkMemory = output.cblk;
mBufferMemory = output.buffers;
+ mId = output.trackId;
IPCThreadState::self()->flushCommands();
mCblk = cblk;
// note that output.frameCount is the (possibly revised) value of mReqFrameCount
if (output.frameCount < mReqFrameCount || (mReqFrameCount == 0 && output.frameCount == 0)) {
- ALOGW("Requested frameCount %zu but received frameCount %zu",
+ ALOGW("%s(%d): Requested frameCount %zu but received frameCount %zu",
+ __func__, mId,
mReqFrameCount, output.frameCount);
}
// Make sure that application is notified with sufficient margin before overrun.
// The computation is done on server side.
if (mNotificationFramesReq > 0 && output.notificationFrameCount != mNotificationFramesReq) {
- ALOGW("Server adjusted notificationFrames from %u to %zu for frameCount %zu",
+ ALOGW("%s(%d): Server adjusted notificationFrames from %u to %zu for frameCount %zu",
+ __func__, mId,
mNotificationFramesReq, output.notificationFrameCount, output.frameCount);
}
mNotificationFramesAct = (uint32_t)output.notificationFrameCount;
@@ -870,7 +882,7 @@
timeout.tv_nsec = (long) (ms % 1000) * 1000000;
requested = &timeout;
} else {
- ALOGE("%s invalid waitCount %d", __func__, waitCount);
+ ALOGE("%s(%d): invalid waitCount %d", __func__, mId, waitCount);
requested = NULL;
}
return obtainBuffer(audioBuffer, requested, NULL /*elapsed*/, nonContig);
@@ -979,7 +991,8 @@
if (ssize_t(userSize) < 0 || (buffer == NULL && userSize != 0)) {
// sanity-check. user is most-likely passing an error code, and it would
// make the return value ambiguous (actualSize vs error).
- ALOGE("AudioRecord::read(buffer=%p, size=%zu (%zu)", buffer, userSize, userSize);
+ ALOGE("%s(%d) (buffer=%p, size=%zu (%zu)",
+ __func__, mId, buffer, userSize, userSize);
return BAD_VALUE;
}
@@ -1036,7 +1049,7 @@
pollUs <<= 1;
} while (tryCounter-- > 0);
if (tryCounter < 0) {
- ALOGE("did not receive expected priority boost on time");
+ ALOGE("%s(%d): did not receive expected priority boost on time", __func__, mId);
}
// Run again immediately
return 0;
@@ -1159,7 +1172,8 @@
if (ns != NS_WHENEVER) {
timeout.tv_sec = ns / 1000000000LL;
timeout.tv_nsec = ns % 1000000000LL;
- ALOGV("timeout %ld.%03d", timeout.tv_sec, (int) timeout.tv_nsec / 1000000);
+ ALOGV("%s(%d): timeout %ld.%03d",
+ __func__, mId, timeout.tv_sec, (int) timeout.tv_nsec / 1000000);
requested = &timeout;
}
@@ -1171,16 +1185,18 @@
size_t nonContig;
status_t err = obtainBuffer(&audioBuffer, requested, NULL, &nonContig);
LOG_ALWAYS_FATAL_IF((err != NO_ERROR) != (audioBuffer.frameCount == 0),
- "obtainBuffer() err=%d frameCount=%zu", err, audioBuffer.frameCount);
+ "%s(%d): obtainBuffer() err=%d frameCount=%zu",
+ __func__, mId, err, audioBuffer.frameCount);
requested = &ClientProxy::kNonBlocking;
size_t avail = audioBuffer.frameCount + nonContig;
- ALOGV("obtainBuffer(%u) returned %zu = %zu + %zu err %d",
- mRemainingFrames, avail, audioBuffer.frameCount, nonContig, err);
+ ALOGV("%s(%d): obtainBuffer(%u) returned %zu = %zu + %zu err %d",
+ __func__, mId, mRemainingFrames, avail, audioBuffer.frameCount, nonContig, err);
if (err != NO_ERROR) {
if (err == TIMED_OUT || err == WOULD_BLOCK || err == -EINTR) {
break;
}
- ALOGE("Error %d obtaining an audio buffer, giving up.", err);
+ ALOGE("%s(%d): Error %d obtaining an audio buffer, giving up.",
+ __func__, mId, err);
return NS_NEVER;
}
@@ -1202,8 +1218,8 @@
// Sanity check on returned size
if (ssize_t(readSize) < 0 || readSize > reqSize) {
- ALOGE("EVENT_MORE_DATA requested %zu bytes but callback returned %zd bytes",
- reqSize, ssize_t(readSize));
+ ALOGE("%s(%d): EVENT_MORE_DATA requested %zu bytes but callback returned %zd bytes",
+ __func__, mId, reqSize, ssize_t(readSize));
return NS_NEVER;
}
@@ -1263,7 +1279,7 @@
status_t AudioRecord::restoreRecord_l(const char *from)
{
- ALOGW("dead IAudioRecord, creating a new one from %s()", from);
+ ALOGW("%s(%d): dead IAudioRecord, creating a new one from %s()", __func__, mId, from);
++mSequence;
const int INITIAL_RETRIES = 3;
@@ -1284,7 +1300,7 @@
status_t result = createRecord_l(position, mOpPackageName);
if (result != NO_ERROR) {
- ALOGW("%s(): createRecord_l failed, do not retry", __func__);
+ ALOGW("%s(%d): createRecord_l failed, do not retry", __func__, mId);
retries = 0;
} else {
if (mActive) {
@@ -1297,14 +1313,14 @@
}
if (result != NO_ERROR) {
- ALOGW("%s() failed status %d, retries %d", __func__, result, retries);
+ ALOGW("%s(%d): failed status %d, retries %d", __func__, mId, result, retries);
if (--retries > 0) {
goto retry;
}
}
if (result != NO_ERROR) {
- ALOGW("restoreRecord_l() failed status %d", result);
+ ALOGW("%s(%d): failed status %d", __func__, mId, result);
mActive = false;
}
@@ -1314,18 +1330,18 @@
status_t AudioRecord::addAudioDeviceCallback(const sp<AudioSystem::AudioDeviceCallback>& callback)
{
if (callback == 0) {
- ALOGW("%s adding NULL callback!", __FUNCTION__);
+ ALOGW("%s(%d): adding NULL callback!", __func__, mId);
return BAD_VALUE;
}
AutoMutex lock(mLock);
if (mDeviceCallback.unsafe_get() == callback.get()) {
- ALOGW("%s adding same callback!", __FUNCTION__);
+ ALOGW("%s(%d): adding same callback!", __func__, mId);
return INVALID_OPERATION;
}
status_t status = NO_ERROR;
if (mInput != AUDIO_IO_HANDLE_NONE) {
if (mDeviceCallback != 0) {
- ALOGW("%s callback already present!", __FUNCTION__);
+ ALOGW("%s(%d): callback already present!", __func__, mId);
AudioSystem::removeAudioDeviceCallback(this, mInput);
}
status = AudioSystem::addAudioDeviceCallback(this, mInput);
@@ -1338,12 +1354,12 @@
const sp<AudioSystem::AudioDeviceCallback>& callback)
{
if (callback == 0) {
- ALOGW("%s removing NULL callback!", __FUNCTION__);
+ ALOGW("%s(%d): removing NULL callback!", __func__, mId);
return BAD_VALUE;
}
AutoMutex lock(mLock);
if (mDeviceCallback.unsafe_get() != callback.get()) {
- ALOGW("%s removing different callback!", __FUNCTION__);
+ ALOGW("%s(%d): removing different callback!", __func__, mId);
return INVALID_OPERATION;
}
mDeviceCallback.clear();
@@ -1448,7 +1464,7 @@
ns = INT64_MAX;
// fall through
default:
- LOG_ALWAYS_FATAL_IF(ns < 0, "processAudioBuffer() returned %" PRId64, ns);
+ LOG_ALWAYS_FATAL_IF(ns < 0, "%s() returned %lld", __func__, (long long)ns);
pauseInternal(ns);
return true;
}
diff --git a/media/libaudioclient/include/media/AudioRecord.h b/media/libaudioclient/include/media/AudioRecord.h
index 806280a..c226557 100644
--- a/media/libaudioclient/include/media/AudioRecord.h
+++ b/media/libaudioclient/include/media/AudioRecord.h
@@ -654,6 +654,7 @@
audio_input_flags_t mOrigFlags; // as specified in constructor or set(), const
audio_session_t mSessionId;
+ int mId; // Id from AudioFlinger
transfer_type mTransfer;
// Next 5 fields may be changed if IAudioRecord is re-created, but always != 0
diff --git a/media/libaudioclient/include/media/IAudioFlinger.h b/media/libaudioclient/include/media/IAudioFlinger.h
index fb988e5..52cc860 100644
--- a/media/libaudioclient/include/media/IAudioFlinger.h
+++ b/media/libaudioclient/include/media/IAudioFlinger.h
@@ -274,6 +274,7 @@
return BAD_VALUE;
}
}
+ (void)parcel->readInt32(&trackId);
return NO_ERROR;
}
@@ -300,6 +301,7 @@
} else {
(void)parcel->writeInt32(0);
}
+ (void)parcel->writeInt32(trackId);
return NO_ERROR;
}
@@ -316,6 +318,7 @@
audio_io_handle_t inputId;
sp<IMemory> cblk;
sp<IMemory> buffers;
+ int32_t trackId;
};
// invariant on exit for all APIs that return an sp<>:
diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp
index f299d83..7db7d9f 100644
--- a/services/audioflinger/AudioFlinger.cpp
+++ b/services/audioflinger/AudioFlinger.cpp
@@ -1808,6 +1808,7 @@
output.cblk = recordTrack->getCblk();
output.buffers = recordTrack->getBuffers();
+ output.trackId = recordTrack->id();
// return handle to client
recordHandle = new RecordHandle(recordTrack);