AudioTrack: Add client side track id for logging
Test: Audio sanity test, check logcat
Bug: 115400221
Change-Id: I7c74af8962f7d3b72a7b843df906c54f79f6f009
diff --git a/media/libaudioclient/AudioTrack.cpp b/media/libaudioclient/AudioTrack.cpp
index 76c9bfb..4e39585 100644
--- a/media/libaudioclient/AudioTrack.cpp
+++ b/media/libaudioclient/AudioTrack.cpp
@@ -119,22 +119,22 @@
status_t status;
status = AudioSystem::getOutputSamplingRate(&afSampleRate, streamType);
if (status != NO_ERROR) {
- ALOGE("Unable to query output sample rate for stream type %d; status %d",
- streamType, status);
+ ALOGE("%s(): Unable to query output sample rate for stream type %d; status %d",
+ __func__, streamType, status);
return status;
}
size_t afFrameCount;
status = AudioSystem::getOutputFrameCount(&afFrameCount, streamType);
if (status != NO_ERROR) {
- ALOGE("Unable to query output frame count for stream type %d; status %d",
- streamType, status);
+ ALOGE("%s(): Unable to query output frame count for stream type %d; status %d",
+ __func__, streamType, status);
return status;
}
uint32_t afLatency;
status = AudioSystem::getOutputLatency(&afLatency, streamType);
if (status != NO_ERROR) {
- ALOGE("Unable to query output latency for stream type %d; status %d",
- streamType, status);
+ ALOGE("%s(): Unable to query output latency for stream type %d; status %d",
+ __func__, streamType, status);
return status;
}
@@ -147,12 +147,12 @@
// AudioTrack.SAMPLE_RATE_HZ_MIN <= sampleRate <= AudioTrack.SAMPLE_RATE_HZ_MAX.
// Return error in the unlikely event that it does not, as that's part of the API contract.
if (*frameCount == 0) {
- ALOGE("AudioTrack::getMinFrameCount failed for streamType %d, sampleRate %u",
- streamType, sampleRate);
+ ALOGE("%s(): failed for streamType %d, sampleRate %u",
+ __func__, streamType, sampleRate);
return BAD_VALUE;
}
- ALOGV("getMinFrameCount=%zu: afFrameCount=%zu, afSampleRate=%u, afLatency=%u",
- *frameCount, afFrameCount, afSampleRate, afLatency);
+ ALOGV("%s(): getMinFrameCount=%zu: afFrameCount=%zu, afSampleRate=%u, afLatency=%u",
+ __func__, *frameCount, afFrameCount, afSampleRate, afLatency);
return NO_ERROR;
}
@@ -200,7 +200,7 @@
// XXX: shall we gather alternative info if failing?
const status_t lstatus = track->initCheck();
if (lstatus != NO_ERROR) {
- ALOGD("no metrics gathered, track status=%d", (int) lstatus);
+ ALOGD("%s(): no metrics gathered, track status=%d", __func__, (int) lstatus);
return;
}
@@ -342,7 +342,8 @@
mCblkMemory.clear();
mSharedBuffer.clear();
IPCThreadState::self()->flushCommands();
- ALOGV("~AudioTrack, releasing session id %d from %d on behalf of %d",
+ ALOGV("%s(%d), releasing session id %d from %d on behalf of %d",
+ __func__, mId,
mSessionId, IPCThreadState::self()->getCallingPid(), mClientPid);
AudioSystem::releaseAudioSessionId(mSessionId, mClientPid);
}
@@ -375,8 +376,10 @@
pid_t callingPid;
pid_t myPid;
- ALOGV("set(): streamType %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(): streamType %d, sampleRate %u, format %#x, channelMask %#x, frameCount %zu, "
"flags #%x, notificationFrames %d, sessionId %d, transferType %d, uid %d, pid %d",
+ __func__,
streamType, sampleRate, format, channelMask, frameCount, flags, notificationFrames,
sessionId, transferType, uid, pid);
@@ -396,7 +399,8 @@
break;
case TRANSFER_CALLBACK:
if (cbf == NULL || sharedBuffer != 0) {
- ALOGE("Transfer type TRANSFER_CALLBACK but cbf == NULL || sharedBuffer != 0");
+ ALOGE("%s(): Transfer type TRANSFER_CALLBACK but cbf == NULL || sharedBuffer != 0",
+ __func__);
status = BAD_VALUE;
goto exit;
}
@@ -404,20 +408,21 @@
case TRANSFER_OBTAIN:
case TRANSFER_SYNC:
if (sharedBuffer != 0) {
- ALOGE("Transfer type TRANSFER_OBTAIN but sharedBuffer != 0");
+ ALOGE("%s(): Transfer type TRANSFER_OBTAIN but sharedBuffer != 0", __func__);
status = BAD_VALUE;
goto exit;
}
break;
case TRANSFER_SHARED:
if (sharedBuffer == 0) {
- ALOGE("Transfer type TRANSFER_SHARED but sharedBuffer == 0");
+ ALOGE("%s(): Transfer type TRANSFER_SHARED but sharedBuffer == 0", __func__);
status = BAD_VALUE;
goto exit;
}
break;
default:
- ALOGE("Invalid transfer type %d", transferType);
+ ALOGE("%s(): Invalid transfer type %d",
+ __func__, transferType);
status = BAD_VALUE;
goto exit;
}
@@ -425,14 +430,15 @@
mTransfer = transferType;
mDoNotReconnect = doNotReconnect;
- ALOGV_IF(sharedBuffer != 0, "sharedBuffer: %p, size: %zu", sharedBuffer->pointer(),
- sharedBuffer->size());
+ ALOGV_IF(sharedBuffer != 0, "%s(): sharedBuffer: %p, size: %zu",
+ __func__, sharedBuffer->pointer(), sharedBuffer->size());
- ALOGV("set() streamType %d frameCount %zu flags %04x", streamType, frameCount, flags);
+ ALOGV("%s(): streamType %d frameCount %zu flags %04x",
+ __func__, streamType, frameCount, flags);
// invariant that mAudioTrack != 0 is true only after set() returns successfully
if (mAudioTrack != 0) {
- ALOGE("Track already in use");
+ ALOGE("%s(): Track already in use", __func__);
status = INVALID_OPERATION;
goto exit;
}
@@ -443,7 +449,7 @@
}
if (pAttributes == NULL) {
if (uint32_t(streamType) >= AUDIO_STREAM_PUBLIC_CNT) {
- ALOGE("Invalid stream type %d", streamType);
+ ALOGE("%s(): Invalid stream type %d", __func__, streamType);
status = BAD_VALUE;
goto exit;
}
@@ -452,8 +458,10 @@
} else {
// stream type shouldn't be looked at, this track has audio attributes
memcpy(&mAttributes, pAttributes, sizeof(audio_attributes_t));
- ALOGV("Building AudioTrack with attributes: usage=%d content=%d flags=0x%x tags=[%s]",
- mAttributes.usage, mAttributes.content_type, mAttributes.flags, mAttributes.tags);
+ ALOGV("%s(): Building AudioTrack with attributes:"
+ " usage=%d content=%d flags=0x%x tags=[%s]",
+ __func__,
+ mAttributes.usage, mAttributes.content_type, mAttributes.flags, mAttributes.tags);
mStreamType = AUDIO_STREAM_DEFAULT;
if ((mAttributes.flags & AUDIO_FLAG_HW_AV_SYNC) != 0) {
flags = (audio_output_flags_t)(flags | AUDIO_OUTPUT_FLAG_HW_AV_SYNC);
@@ -476,14 +484,14 @@
// validate parameters
if (!audio_is_valid_format(format)) {
- ALOGE("Invalid format %#x", format);
+ ALOGE("%s(): Invalid format %#x", __func__, format);
status = BAD_VALUE;
goto exit;
}
mFormat = format;
if (!audio_is_output_channel(channelMask)) {
- ALOGE("Invalid channel mask %#x", channelMask);
+ ALOGE("%s(): Invalid channel mask %#x", __func__, channelMask);
status = BAD_VALUE;
goto exit;
}
@@ -496,8 +504,9 @@
if ((flags & AUDIO_OUTPUT_FLAG_COMPRESS_OFFLOAD)
|| !audio_is_linear_pcm(format)) {
ALOGV( (flags & AUDIO_OUTPUT_FLAG_COMPRESS_OFFLOAD)
- ? "Offload request, forcing to Direct Output"
- : "Not linear PCM, forcing to Direct Output");
+ ? "%s(): Offload request, forcing to Direct Output"
+ : "%s(): Not linear PCM, forcing to Direct Output",
+ __func__);
flags = (audio_output_flags_t)
// FIXME why can't we allow direct AND fast?
((flags | AUDIO_OUTPUT_FLAG_DIRECT) & ~AUDIO_OUTPUT_FLAG_FAST);
@@ -553,14 +562,14 @@
mNotificationsPerBufferReq = 0;
} else {
if (!(flags & AUDIO_OUTPUT_FLAG_FAST)) {
- ALOGE("notificationFrames=%d not permitted for non-fast track",
- notificationFrames);
+ ALOGE("%s(): notificationFrames=%d not permitted for non-fast track",
+ __func__, notificationFrames);
status = BAD_VALUE;
goto exit;
}
if (frameCount > 0) {
- ALOGE("notificationFrames=%d not permitted with non-zero frameCount=%zu",
- notificationFrames, frameCount);
+ ALOGE("%s(): notificationFrames=%d not permitted with non-zero frameCount=%zu",
+ __func__, notificationFrames, frameCount);
status = BAD_VALUE;
goto exit;
}
@@ -570,7 +579,8 @@
mNotificationsPerBufferReq = min(maxNotificationsPerBuffer,
max((uint32_t) -notificationFrames, minNotificationsPerBuffer));
ALOGW_IF(mNotificationsPerBufferReq != (uint32_t) -notificationFrames,
- "notificationFrames=%d clamped to the range -%u to -%u",
+ "%s(): notificationFrames=%d clamped to the range -%u to -%u",
+ __func__,
notificationFrames, minNotificationsPerBuffer, maxNotificationsPerBuffer);
}
mNotificationFramesAct = 0;
@@ -646,6 +656,7 @@
status_t AudioTrack::start()
{
AutoMutex lock(mLock);
+ ALOGV("%s(%d): prior state:%s", __func__, mId, stateToString(mState));
if (mState == STATE_ACTIVE) {
return INVALID_OPERATION;
@@ -685,7 +696,8 @@
// Server side has consumed something, but is it finished consuming?
// It is possible since flush and stop are asynchronous that the server
// is still active at this point.
- ALOGV("start: server read:%lld cumulative flushed:%lld client written:%lld",
+ ALOGV("%s(%d): server read:%lld cumulative flushed:%lld client written:%lld",
+ __func__, mId,
(long long)(mFramesWrittenServerOffset
+ mStartEts.mPosition[ExtendedTimestamp::LOCATION_SERVER]),
(long long)mStartEts.mFlushed,
@@ -746,7 +758,7 @@
// Start our local VolumeHandler for restoration purposes.
mVolumeHandler->setStarted();
} else {
- ALOGE("start() status %d", status);
+ ALOGE("%s(%d): status %d", __func__, mId, status);
mState = previousState;
if (t != 0) {
if (previousState != STATE_STOPPING) {
@@ -764,6 +776,8 @@
void AudioTrack::stop()
{
AutoMutex lock(mLock);
+ ALOGV("%s(%d): prior state:%s", __func__, mId, stateToString(mState));
+
if (mState != STATE_ACTIVE && mState != STATE_PAUSED) {
return;
}
@@ -773,7 +787,7 @@
} else {
mState = STATE_STOPPED;
ALOGD_IF(mSharedBuffer == nullptr,
- "stop() called with %u frames delivered", mReleased.value());
+ "%s(%d): called with %u frames delivered", __func__, mId, mReleased.value());
mReleased = 0;
}
@@ -809,10 +823,12 @@
void AudioTrack::flush()
{
+ AutoMutex lock(mLock);
+ ALOGV("%s(%d): prior state:%s", __func__, mId, stateToString(mState));
+
if (mSharedBuffer != 0) {
return;
}
- AutoMutex lock(mLock);
if (mState == STATE_ACTIVE) {
return;
}
@@ -841,6 +857,8 @@
void AudioTrack::pause()
{
AutoMutex lock(mLock);
+ ALOGV("%s(%d): prior state:%s", __func__, mId, stateToString(mState));
+
if (mState == STATE_ACTIVE) {
mState = STATE_PAUSED;
} else if (mState == STATE_STOPPING) {
@@ -866,7 +884,8 @@
uint32_t halFrames;
AudioSystem::getRenderPosition(mOutput, &halFrames, &mPausedPosition);
- ALOGV("AudioTrack::pause for offload, cache current position %u", mPausedPosition);
+ ALOGV("%s(%d): for offload, cache current position %u",
+ __func__, mId, mPausedPosition);
}
}
}
@@ -920,6 +939,8 @@
status_t AudioTrack::setSampleRate(uint32_t rate)
{
AutoMutex lock(mLock);
+ ALOGV("%s(%d): prior state:%s rate:%u", __func__, mId, stateToString(mState), rate);
+
if (rate == mSampleRate) {
return NO_ERROR;
}
@@ -985,8 +1006,8 @@
return INVALID_OPERATION;
}
- ALOGV("setPlaybackRate (input): mSampleRate:%u mSpeed:%f mPitch:%f",
- mSampleRate, playbackRate.mSpeed, playbackRate.mPitch);
+ ALOGV("%s(%d): mSampleRate:%u mSpeed:%f mPitch:%f",
+ __func__, mId, mSampleRate, playbackRate.mSpeed, playbackRate.mPitch);
// pitch is emulated by adjusting speed and sampleRate
const uint32_t effectiveRate = adjustSampleRate(mSampleRate, playbackRate.mPitch);
const float effectiveSpeed = adjustSpeed(playbackRate.mSpeed, playbackRate.mPitch);
@@ -995,32 +1016,32 @@
playbackRateTemp.mSpeed = effectiveSpeed;
playbackRateTemp.mPitch = effectivePitch;
- ALOGV("setPlaybackRate (effective): mSampleRate:%u mSpeed:%f mPitch:%f",
- effectiveRate, effectiveSpeed, effectivePitch);
+ ALOGV("%s(%d) (effective) mSampleRate:%u mSpeed:%f mPitch:%f",
+ __func__, mId, effectiveRate, effectiveSpeed, effectivePitch);
if (!isAudioPlaybackRateValid(playbackRateTemp)) {
- ALOGW("setPlaybackRate(%f, %f) failed (effective rate out of bounds)",
- playbackRate.mSpeed, playbackRate.mPitch);
+ ALOGW("%s(%d) (%f, %f) failed (effective rate out of bounds)",
+ __func__, mId, playbackRate.mSpeed, playbackRate.mPitch);
return BAD_VALUE;
}
// Check if the buffer size is compatible.
if (!isSampleRateSpeedAllowed_l(effectiveRate, effectiveSpeed)) {
- ALOGW("setPlaybackRate(%f, %f) failed (buffer size)",
- playbackRate.mSpeed, playbackRate.mPitch);
+ ALOGW("%s(%d) (%f, %f) failed (buffer size)",
+ __func__, mId, playbackRate.mSpeed, playbackRate.mPitch);
return BAD_VALUE;
}
// Check resampler ratios are within bounds
if ((uint64_t)effectiveRate > (uint64_t)mSampleRate *
(uint64_t)AUDIO_RESAMPLER_DOWN_RATIO_MAX) {
- ALOGW("setPlaybackRate(%f, %f) failed. Resample rate exceeds max accepted value",
- playbackRate.mSpeed, playbackRate.mPitch);
+ ALOGW("%s(%d) (%f, %f) failed. Resample rate exceeds max accepted value",
+ __func__, mId, playbackRate.mSpeed, playbackRate.mPitch);
return BAD_VALUE;
}
if ((uint64_t)effectiveRate * (uint64_t)AUDIO_RESAMPLER_UP_RATIO_MAX < (uint64_t)mSampleRate) {
- ALOGW("setPlaybackRate(%f, %f) failed. Resample rate below min accepted value",
- playbackRate.mSpeed, playbackRate.mPitch);
+ ALOGW("%s(%d) (%f, %f) failed. Resample rate below min accepted value",
+ __func__, mId, playbackRate.mSpeed, playbackRate.mPitch);
return BAD_VALUE;
}
mPlaybackRate = playbackRate;
@@ -1221,7 +1242,8 @@
uint32_t dspFrames = 0;
if (isOffloaded_l() && ((mState == STATE_PAUSED) || (mState == STATE_PAUSED_STOPPING))) {
- ALOGV("getPosition called in paused state, return cached position %u", mPausedPosition);
+ ALOGV("%s(%d): called in paused state, return cached position %u",
+ __func__, mId, mPausedPosition);
*position = mPausedPosition;
return NO_ERROR;
}
@@ -1367,7 +1389,7 @@
{
status_t status = AudioSystem::getLatency(mOutput, &mAfLatency);
if (status != NO_ERROR) {
- ALOGW("getLatency(%d) failed status %d", mOutput, status);
+ ALOGW("%s(%d): getLatency(%d) failed status %d", __func__, mId, mOutput, status);
} else {
// FIXME don't believe this lie
mLatency = mAfLatency + (1000LL * mFrameCount) / mSampleRate;
@@ -1395,7 +1417,8 @@
const sp<IAudioFlinger>& audioFlinger = AudioSystem::get_audio_flinger();
if (audioFlinger == 0) {
- ALOGE("Could not get audioflinger");
+ ALOGE("%s(%d): Could not get audioflinger",
+ __func__, mId);
status = NO_INIT;
goto exit;
}
@@ -1418,7 +1441,9 @@
bool fastAllowed = sharedBuffer || transferAllowed;
if (!fastAllowed) {
- ALOGW("AUDIO_OUTPUT_FLAG_FAST denied by client, not shared buffer and transfer = %s",
+ ALOGW("%s(%d): AUDIO_OUTPUT_FLAG_FAST denied by client,"
+ " not shared buffer and transfer = %s",
+ __func__, mId,
convertTransferToText(mTransfer));
mFlags = (audio_output_flags_t) (mFlags & ~AUDIO_OUTPUT_FLAG_FAST);
}
@@ -1467,7 +1492,8 @@
&status);
if (status != NO_ERROR || output.outputId == AUDIO_IO_HANDLE_NONE) {
- ALOGE("AudioFlinger could not create track, status: %d output %d", status, output.outputId);
+ ALOGE("%s(%d): AudioFlinger could not create track, status: %d output %d",
+ __func__, mId, status, output.outputId);
if (status == NO_ERROR) {
status = NO_INIT;
}
@@ -1488,6 +1514,7 @@
mAfFrameCount = output.afFrameCount;
mAfSampleRate = output.afSampleRate;
mAfLatency = output.afLatencyMs;
+ mId = output.trackId;
mLatency = mAfLatency + (1000LL * mFrameCount) / mSampleRate;
@@ -1497,13 +1524,13 @@
// FIXME compare to AudioRecord
sp<IMemory> iMem = track->getCblk();
if (iMem == 0) {
- ALOGE("Could not get control block");
+ ALOGE("%s(%d): Could not get control block", __func__, mId);
status = NO_INIT;
goto exit;
}
void *iMemPointer = iMem->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;
}
@@ -1522,14 +1549,14 @@
mAwaitBoost = false;
if (mFlags & AUDIO_OUTPUT_FLAG_FAST) {
if (output.flags & AUDIO_OUTPUT_FLAG_FAST) {
- ALOGI("AUDIO_OUTPUT_FLAG_FAST successful; frameCount %zu -> %zu",
- mReqFrameCount, mFrameCount);
+ ALOGI("%s(%d): AUDIO_OUTPUT_FLAG_FAST successful; frameCount %zu -> %zu",
+ __func__, mId, mReqFrameCount, mFrameCount);
if (!mThreadCanCallJava) {
mAwaitBoost = true;
}
} else {
- ALOGW("AUDIO_OUTPUT_FLAG_FAST denied by server; frameCount %zu -> %zu", mReqFrameCount,
- mFrameCount);
+ ALOGW("%s(%d): AUDIO_OUTPUT_FLAG_FAST denied by server; frameCount %zu -> %zu",
+ __func__, mId, mReqFrameCount, mFrameCount);
}
}
mFlags = output.flags;
@@ -1557,7 +1584,7 @@
} else {
buffers = mSharedBuffer->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;
}
@@ -1646,7 +1673,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);
@@ -1756,7 +1783,8 @@
{
int32_t flags = android_atomic_and(~CBLK_DISABLED, &mCblk->mFlags);
if ((mState == STATE_ACTIVE) && (flags & CBLK_DISABLED)) {
- ALOGW("releaseBuffer() track %p disabled due to previous underrun, restarting", this);
+ ALOGW("%s(%d): releaseBuffer() track %p disabled due to previous underrun, restarting",
+ __func__, mId, this);
// FIXME ignoring status
mAudioTrack->start();
}
@@ -1783,7 +1811,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("AudioTrack::write(buffer=%p, size=%zu (%zd)", buffer, userSize, userSize);
+ ALOGE("%s(%d): AudioTrack::write(buffer=%p, size=%zu (%zd)",
+ __func__, mId, buffer, userSize, userSize);
return BAD_VALUE;
}
@@ -1845,7 +1874,8 @@
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;
@@ -2086,7 +2116,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;
}
@@ -2098,18 +2129,20 @@
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 ||
(isOffloaded() && (err == DEAD_OBJECT))) {
// FIXME bug 25195759
return 1000000;
}
- 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;
}
@@ -2134,8 +2167,8 @@
// Sanity check on returned size
if (ssize_t(writtenSize) < 0 || writtenSize > reqSize) {
- ALOGE("EVENT_MORE_DATA requested %zu bytes but callback returned %zd bytes",
- reqSize, ssize_t(writtenSize));
+ ALOGE("%s(%d): EVENT_MORE_DATA requested %zu bytes but callback returned %zd bytes",
+ __func__, mId, reqSize, ssize_t(writtenSize));
return NS_NEVER;
}
@@ -2230,8 +2263,8 @@
status_t AudioTrack::restoreTrack_l(const char *from)
{
- ALOGW("dead IAudioTrack, %s, creating a new one from %s()",
- isOffloadedOrDirect_l() ? "Offloaded or Direct" : "PCM", from);
+ ALOGW("%s(%d): dead IAudioTrack, %s, creating a new one from %s()",
+ __func__, mId, isOffloadedOrDirect_l() ? "Offloaded or Direct" : "PCM", from);
++mSequence;
// refresh the audio configuration cache in this process to make sure we get new
@@ -2275,7 +2308,7 @@
status_t result = createTrack_l();
if (result != NO_ERROR) {
- ALOGW("%s(): createTrack_l failed, do not retry", __func__);
+ ALOGW("%s(%d): createTrack_l failed, do not retry", __func__, mId);
retries = 0;
} else {
// take the frames that will be lost by track recreation into account in saved position
@@ -2292,7 +2325,7 @@
} else {
mStaticProxy->setBufferPosition(bufferPosition);
if (bufferPosition == mFrameCount) {
- ALOGD("restoring track at end of static buffer");
+ ALOGD("%s(%d): restoring track at end of static buffer", __func__, mId);
}
}
}
@@ -2322,7 +2355,7 @@
mFramesWrittenAtRestore = mFramesWrittenServerOffset;
}
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;
}
@@ -2347,8 +2380,8 @@
// unless the server has more than 2^31 frames in its buffer,
// in which case the use of uint32_t for these counters has bigger issues.
ALOGE_IF(delta < 0,
- "detected illegal retrograde motion by the server: mServer advanced by %d",
- delta);
+ "%s(%d): detected illegal retrograde motion by the server: mServer advanced by %d",
+ __func__, mId, delta);
mServer = newServer;
if (delta > 0) { // avoid retrograde
mPosition += delta;
@@ -2368,9 +2401,10 @@
sampleRate, speed /*, 0 mNotificationsPerBufferReq*/);
const bool allowed = mFrameCount >= minFrameCount;
ALOGD_IF(!allowed,
- "isSampleRateSpeedAllowed_l denied "
+ "%s(%d): denied "
"mAfLatency:%u mAfFrameCount:%zu mAfSampleRate:%u sampleRate:%u speed:%f "
"mFrameCount:%zu < minFrameCount:%zu",
+ __func__, mId,
mAfLatency, mAfFrameCount, mAfSampleRate, sampleRate, speed,
mFrameCount, minFrameCount);
return allowed;
@@ -2388,7 +2422,8 @@
AudioParameter param = AudioParameter();
param.addInt(String8(AudioParameter::keyPresentationId), presentationId);
param.addInt(String8(AudioParameter::keyProgramId), programId);
- ALOGV("PresentationId/ProgramId[%s]",param.toString().string());
+ ALOGV("%s(%d): PresentationId/ProgramId[%s]",
+ __func__, mId, param.toString().string());
return mAudioTrack->setParameters(param.toString());
}
@@ -2415,7 +2450,7 @@
} else {
// warn only if not an expected restore failure.
ALOGW_IF(!((isOffloadedOrDirect_l() || mDoNotReconnect) && status == DEAD_OBJECT),
- "applyVolumeShaper failed: %d", status);
+ "%s(%d): applyVolumeShaper failed: %d", __func__, mId, status);
}
return status;
}
@@ -2456,7 +2491,8 @@
return INVALID_OPERATION; // not supported
}
status_t status = mProxy->getTimestamp(timestamp);
- LOG_ALWAYS_FATAL_IF(status != OK, "status %d not allowed from proxy getTimestamp", status);
+ LOG_ALWAYS_FATAL_IF(status != OK, "%s(%d): status %d not allowed from proxy getTimestamp",
+ __func__, mId, status);
bool found = false;
timestamp->mPosition[ExtendedTimestamp::LOCATION_CLIENT] = mFramesWritten;
timestamp->mTimeNs[ExtendedTimestamp::LOCATION_CLIENT] = 0;
@@ -2499,7 +2535,8 @@
}
break; // offloaded tracks handled below
default:
- LOG_ALWAYS_FATAL("Invalid mState in getTimestamp(): %d", mState);
+ LOG_ALWAYS_FATAL("%s(%d): Invalid mState in getTimestamp(): %d",
+ __func__, mId, mState);
break;
}
@@ -2533,7 +2570,8 @@
// In this case we adjust the position from the previous computed latency.
if (location == ExtendedTimestamp::LOCATION_SERVER) {
ALOGW_IF(mPreviousLocation == ExtendedTimestamp::LOCATION_KERNEL,
- "getTimestamp() location moved from kernel to server");
+ "%s(%d): location moved from kernel to server",
+ __func__, mId);
// check that the last kernel OK time info exists and the positions
// are valid (if they predate the current track, the positions may
// be zero or negative).
@@ -2548,8 +2586,8 @@
:
(ets.mPosition[ExtendedTimestamp::LOCATION_SERVER_LASTKERNELOK]
- ets.mPosition[ExtendedTimestamp::LOCATION_KERNEL_LASTKERNELOK]);
- ALOGV("frame adjustment:%lld timestamp:%s",
- (long long)frames, ets.toString().c_str());
+ ALOGV("%s(%d): frame adjustment:%lld timestamp:%s",
+ __func__, mId, (long long)frames, ets.toString().c_str());
if (frames >= ets.mPosition[location]) {
timestamp.mPosition = 0;
} else {
@@ -2557,7 +2595,8 @@
}
} else if (location == ExtendedTimestamp::LOCATION_KERNEL) {
ALOGV_IF(mPreviousLocation == ExtendedTimestamp::LOCATION_SERVER,
- "getTimestamp() location moved from server to kernel");
+ "%s(%d): location moved from server to kernel",
+ __func__, mId);
}
// We update the timestamp time even when paused.
@@ -2581,7 +2620,7 @@
mPreviousLocation = location;
} else {
// right after AudioTrack is started, one may not find a timestamp
- ALOGV("getBestTimestamp did not find timestamp");
+ ALOGV("%s(%d): getBestTimestamp did not find timestamp", __func__, mId);
}
}
if (status == INVALID_OPERATION) {
@@ -2591,7 +2630,8 @@
// to be zero we convert this to WOULD_BLOCK (with the implicit meaning of
// "zero" for NuPlayer). We don't convert for track restoration as position
// does not reset.
- ALOGV("timestamp server offset:%lld restore frames:%lld",
+ ALOGV("%s(%d): timestamp server offset:%lld restore frames:%lld",
+ __func__, mId,
(long long)mFramesWrittenServerOffset, (long long)mFramesWrittenAtRestore);
if (mFramesWrittenServerOffset != mFramesWrittenAtRestore) {
status = WOULD_BLOCK;
@@ -2599,7 +2639,7 @@
}
}
if (status != NO_ERROR) {
- ALOGV_IF(status != WOULD_BLOCK, "getTimestamp error:%#x", status);
+ ALOGV_IF(status != WOULD_BLOCK, "%s(%d): getTimestamp error:%#x", __func__, mId, status);
return status;
}
if (isOffloadedOrDirect_l()) {
@@ -2638,8 +2678,9 @@
// since the start time. If greater, then that means we may have failed
// to completely flush or stop the previous playing track.
ALOGW_IF(!mTimestampStartupGlitchReported,
- "getTimestamp startup glitch detected"
+ "%s(%d): startup glitch detected"
" deltaTimeUs(%lld) deltaPositionUs(%lld) tsmPosition(%u)",
+ __func__, mId,
(long long)deltaTimeUs, (long long)deltaPositionByUs,
timestamp.mPosition);
mTimestampStartupGlitchReported = true;
@@ -2707,8 +2748,9 @@
const int64_t lagNs = int64_t(mAfLatency * 1000000LL);
const int64_t limitNs = mStartNs - lagNs;
if (currentTimeNanos < limitNs) {
- ALOGD("correcting timestamp time for pause, "
+ ALOGD("%s(%d): correcting timestamp time for pause, "
"currentTimeNanos: %lld < limitNs: %lld < mStartNs: %lld",
+ __func__, mId,
(long long)currentTimeNanos, (long long)limitNs, (long long)mStartNs);
timestamp.mTime = convertNsToTimespec(limitNs);
currentTimeNanos = limitNs;
@@ -2716,7 +2758,8 @@
// retrograde check
if (currentTimeNanos < previousTimeNanos) {
- ALOGW("retrograde timestamp time corrected, %lld < %lld",
+ ALOGW("%s(%d): retrograde timestamp time corrected, %lld < %lld",
+ __func__, mId,
(long long)currentTimeNanos, (long long)previousTimeNanos);
timestamp.mTime = mPreviousTimestamp.mTime;
// currentTimeNanos not used below.
@@ -2729,7 +2772,8 @@
if (deltaPosition < 0) {
// Only report once per position instead of spamming the log.
if (!mRetrogradeMotionReported) {
- ALOGW("retrograde timestamp position corrected, %d = %u - %u",
+ ALOGW("%s(%d): retrograde timestamp position corrected, %d = %u - %u",
+ __func__, mId,
deltaPosition,
timestamp.mPosition,
mPreviousTimestamp.mPosition);
@@ -2749,7 +2793,8 @@
if (deltaTime != 0) {
const int64_t computedSampleRate =
deltaPosition * (long long)NANOS_PER_SECOND / deltaTime;
- ALOGD("computedSampleRate:%u sampleRate:%u",
+ ALOGD("%s(%d): computedSampleRate:%u sampleRate:%u",
+ __func__, mId,
(unsigned)computedSampleRate, mSampleRate);
}
#endif
@@ -2795,8 +2840,8 @@
String8 result;
result.append(" AudioTrack::dump\n");
- result.appendFormat(" status(%d), state(%d), session Id(%d), flags(%#x)\n",
- mStatus, mState, mSessionId, mFlags);
+ result.appendFormat(" id(%d) status(%d), state(%d), session Id(%d), flags(%#x)\n",
+ mId, mStatus, mState, mSessionId, mFlags);
result.appendFormat(" stream type(%d), left - right volume(%f, %f)\n",
(mStreamType == AUDIO_STREAM_DEFAULT) ?
audio_attributes_to_stream_type(&mAttributes) : mStreamType,
@@ -2838,18 +2883,18 @@
status_t AudioTrack::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 (mOutput != AUDIO_IO_HANDLE_NONE) {
if (mDeviceCallback != 0) {
- ALOGW("%s callback already present!", __FUNCTION__);
+ ALOGW("%s(%d): callback already present!", __func__, mId);
AudioSystem::removeAudioDeviceCallback(this, mOutput);
}
status = AudioSystem::addAudioDeviceCallback(this, mOutput);
@@ -2862,12 +2907,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();
@@ -2973,7 +3018,7 @@
case STATE_FLUSHED:
return false; // we're not active
default:
- LOG_ALWAYS_FATAL("Invalid mState in hasStarted(): %d", mState);
+ LOG_ALWAYS_FATAL("%s(%d): Invalid mState in hasStarted(): %d", __func__, mId, mState);
break;
}
@@ -2989,7 +3034,8 @@
} else if (status == OK) {
wait = (ts.mPosition == 0 || ts.mPosition == mStartTs.mPosition);
}
- ALOGV("hasStarted wait:%d ts:%u start position:%lld",
+ ALOGV("%s(%d): hasStarted wait:%d ts:%u start position:%lld",
+ __func__, mId,
(int)wait,
ts.mPosition,
(long long)mStartTs.mPosition);
@@ -3010,7 +3056,8 @@
break;
}
}
- ALOGV("hasStarted wait:%d ets:%lld start position:%lld",
+ ALOGV("%s(%d): hasStarted wait:%d ets:%lld start position:%lld",
+ __func__, mId,
(int)wait,
(long long)ets.mPosition[location],
(long long)mStartEts.mPosition[location]);
@@ -3085,7 +3132,8 @@
ns = INT64_MAX;
// fall through
default:
- LOG_ALWAYS_FATAL_IF(ns < 0, "processAudioBuffer() returned %" PRId64, ns);
+ LOG_ALWAYS_FATAL_IF(ns < 0, "%s(%d): processAudioBuffer() returned %lld",
+ __func__, mReceiver.mId, (long long)ns);
pauseInternal(ns);
return true;
}