Hi Liam, * I'm not sure whether a Pause command on DevSound is valid, if the current state is INIT_PENDING. Probably we might have to hold the message and issue pause once the PlayInit is complete and notify message complete.
* The code updating m_unplayedSampleCount is removed in your new change. But I don't see any other code that updates the value for m_unplayedSampleCount. Is that I'm missing something here ? And one more observation on the 6630: 6630 does not throw underflow error. But a pause on the DevSound on 6630 results in samplesPlayed count to be reset similar to what we see for underflow. I believe this case has to be handled. When a Play(ie Resume after pause) is issued in PAUSED state, we can set the m_sampleCountResetPending flag, update m_msTimePlayed and reset m_samplesWritten. Regards, Rajesh. -----Original Message----- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] Behalf Of ext Liam Murray Sent: Tuesday, March 22, 2005 8:17 PM To: [EMAIL PROTECTED] Cc: [EMAIL PROTECTED] Subject: [Audio-dev] CR: HXSymbianAudioSession fixes Summary ======== 1) Fix for handling valid calls in PLAYINIT_PENDING state in HXSymbianAudioSession. 2) Fix for double-reset observed with AMR audio in underflow condition. Thanks to Rajesh for help on this one too. Overview ======== HXSymbianAudioSession keeps private state in a member var to guard against bad use of the underlying CMMFDevSound. One state PLAYINIT_PENDING simply means PlayInit has been called but BufferToBeCopied has not. Once we get BufferToBeCopied we go to PLAYING. (Originally this was added because we thought this might indicate that the sample count returned from SamplesPlayed() thereafter might be reset. Alas, that was not the case. However, it may still be useful so I didn't do away with the state.) In some cases we were not handling calls to pause, stop, and write that are valid after PlayInit is called. The fix here is to handle these calls the same way we do when we are in PLAYING state. The other fix is to deal with observed behavior described in comments in the code in HXSymbianAudioSession::UpdateTimeSampleStats() (number 3). In certain cases we would get an underflow, the value returned from SamplesPlayed would go back to 0 and increase, then it would go back to 0 again. The second time would cause us to think we were seeing a wrap-around of the sample count. It appears values reported after the first reset but before the second reset are for samples that we wrote but were unplayed at the time of the underflow (at which time we call PlayInit). My fix is to ignore values that returned from SamplesPlayed() that are less than the last value returned, unless we have seen and underflow and are expecting a sample count reset. At the time we get the underflow we call SamplesPlayed() and see if there are unplayed samples (written - played). We add these samples at that time (because we don't know for sure that we will otherwise detect them playing out before the sample count resets). So we may jump ahead a bit in the time line. We may then jump ahead and re-add those samples if we happen to see SamplesPlayed() returning values for unplayed samples at the time of the underflow. Then when the sample count resets again we ignore values until they catch up to the last we saw. At that point on continueing forward we should be reporting accurate time. Note that in most cases where we get an underflow and SamplesPlayed() indicates some samples we wrote haven't played out, we see subsequent SamplesPlayed() values that monotonically increase over the value at the time of the underflow. Then we see one reset. That is what I usually see in the emulator and on the 6630. I only have observed the double-reset with amr audio so far. The cost of this is that 1) we may report time ahead for a short prior, but then we catch up; 2) we can't really detect wrap around of the sample count (which is about 27 hours with 44Khz audio, so not a great sacrifice in practice). Note: this does not completely fix amr audio issues with Symbian on HEAD. It still looks like we are not writing fast enough and in some cases AddData stops being called. (Audio time returned from device looks ok to me in these cases, that is, they monotonically increase in small steady increments.) Branch ====== HEAD, Cay150 Files modified ============ audio/device/platform/symbian/audiosvr/mmf/audio_session-mmf.cpp NOTE: whitespace (extra \r) removed in my local copy after generating the diff Builds tested/verified ================== Wins, thumb Liam // increase the priority of the audio thread Index: platform/symbian/audiosvr/mmf/audio_session-mmf.cpp =================================================================== RCS file: /cvsroot/audio/device/platform/symbian/audiosvr/mmf/audio_session-mmf.cpp,v retrieving revision 1.4 diff -u -w -r1.4 audio_session-mmf.cpp --- platform/symbian/audiosvr/mmf/audio_session-mmf.cpp 28 Jan 2005 23:49:04 -0000 1.4 +++ platform/symbian/audiosvr/mmf/audio_session-mmf.cpp 23 Mar 2005 01:02:38 -0000 @@ -58,9 +58,9 @@ #include "audio_session-mmf.h" #include "hxtick.h" #include "debug.h" +#include "hxtlogutil.h" #include <e32std.h> -#define D_SYMAUDIO D_INFO static const TInt KClientPriority = 69; #if defined(HELIX_CONFIG_CALYPSO_AUDIO_PREF) @@ -77,7 +77,11 @@ return (count * 1000) / rate; } -#if defined(HELIX_FEATURE_DPRINTF) +#if defined(HELIX_FEATURE_LOGLEVEL_3) || defined(HELIX_FEATURE_LOGLEVEL_ALL) +#define HELIX_LOCAL_FEATURE_DEBUG_LOG +#endif + +#if defined(HELIX_LOCAL_FEATURE_DEBUG_LOG) // stringify constants for easier interpretation of trace output #define MAKE_STATE_ENTRY(x) case HXSymbianAudioSession::x: return #x; static @@ -154,7 +158,7 @@ } #else -// do nothing (compile out) when !HELIX_FEATURE_DPRINTF +// do nothing (compile out) when !HELIX_LOCAL_FEATURE_DEBUG_LOG inline const char * StringifyState(HXSymbianAudioSession::State state) { return 0; } inline @@ -336,12 +340,12 @@ m_Settings.iChannels = channelCount; m_Settings.iEncoding = EMMFSoundEncoding16BitPCM; - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::Init(): rate = %ld; chan = %ld; sample frame = %lu bytes\n", m_sampleRate, m_Settings.iChannels, m_cbSample)); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::Init(): rate = %ld; chan = %ld; sample frame = %lu bytes", m_sampleRate, m_Settings.iChannels, m_cbSample); switch (m_state) { case STOPPED: - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::Init(): calling SetConfgL() with settings\n")); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::Init(): calling SetConfgL() with settings"); TRAP(err, (m_pStream->CMMFDevSound::SetConfigL(m_Settings))); Message().Complete(err); break; @@ -351,7 +355,7 @@ TRAP(err, (m_pStream = CMMFDevSound::NewL())); if(KErrNone == err) { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::Init(): calling InitializeL for newly allocated dev sound\n")); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::Init(): calling InitializeL for newly allocated dev sound"); m_InitMessage = Message(); TRAP(err, (m_pStream->InitializeL(*this, EMMFStatePlaying))); } @@ -373,7 +377,7 @@ // void HXSymbianAudioSession::Play() { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::Play(): state = %s\n", StringifyState(m_state) )); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::Play(): state = %s", StringifyState(m_state)); TInt err = KErrNone; switch (m_state) @@ -386,8 +390,8 @@ Trans(PLAYING); m_pStream->PlayData(); break; - case PLAYING: case PLAYINIT_PENDING: + case PLAYING: // do nothing break; default: @@ -405,11 +409,12 @@ // void HXSymbianAudioSession::Pause() { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::Pause(): state = %s\n", StringifyState(m_state))); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::Pause(): state = %s", StringifyState(m_state)); TInt err = KErrNone; switch (m_state) { + case PLAYINIT_PENDING: case PLAYING: Trans(PAUSED); HX_ASSERT(m_pStream); @@ -440,7 +445,7 @@ switch (m_state) { case STOPPED: - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::Write(): STOPPED; last err = %s\n", StringifyKErr(m_lastPlayError))); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::Write(): STOPPED; last err = %s", StringifyKErr(m_lastPlayError)); if (m_lastPlayError != KErrNone) { // we are stopped because of we got a call to PlayError @@ -448,6 +453,7 @@ break; } // fall through if no error + case PLAYINIT_PENDING: case PLAYING: case PAUSED: { @@ -466,7 +472,7 @@ break; } default: - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::Write(): called in unexpected state %s \n", StringifyState(m_state))); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::Write(): called in unexpected state %s ", StringifyState(m_state)); HX_ASSERT(false); err = KErrGeneral; break; @@ -476,7 +482,7 @@ if( KErrNone == err && m_pPendingFillBuffer ) { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::Write(): calling BufferToBeFilled\n")); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::Write(): calling BufferToBeFilled"); BufferToBeFilled(m_pPendingFillBuffer); HX_ASSERT(!m_pPendingFillBuffer); } @@ -518,10 +524,10 @@ if (m_sampleCountResetPending) { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::HandleSampleCountReset(): checking for reset (old base = %lu; samps played = %lu; samps written = %lu)\n", m_baseSampleCount, sampleCount, m_samplesWritten)); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::HandleSampleCountReset(): checking for reset (old base = %lu; samps played = %lu; samps written = %lu)", m_baseSampleCount, sampleCount, m_samplesWritten); if ( sampleCount < m_baseSampleCount || 0 == m_baseSampleCount /*0 = first play*/) { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::HandleSampleCountReset(): resetting base sample count\n")); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::HandleSampleCountReset(): resetting base sample count"); OnResetSampleCount(); } else @@ -537,7 +543,7 @@ // comparing the samples played with the number of unwritten samples at the time // of the underflow/stop. If the value is greater it must be from newly written // samples. - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::HandleSampleCountReset(): resetting base sample count (special case %lu > %lu)\n", sampleCount - m_baseSampleCount, m_unplayedSampleCount)); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::HandleSampleCountReset(): resetting base sample count (special case %lu > %lu)", sampleCount - m_baseSampleCount, m_unplayedSampleCount); OnResetSampleCount(); } } @@ -547,6 +553,26 @@ void HXSymbianAudioSession::UpdateTimeSampleStats() { + // We use some heuristics here because of the following observed behavior of values returned + // from CMMFDevSound::SamplesPlayed() around and after the time of an underflow. + // + // 1) Underflow occurs. At that time SamplesPlayed() is sometimes < samples written. Those appear + // to play out (they are not droppped). There probably is a low threshold value at which point + // the audio device generates an Underflow error, and we sometimes see the error before all + // samples actually play out. + // + // 2) We add time for unplayed samples at that time. We may get a bit ahead of actual time played. + // We do this because that sample count will be reset after we call PlayInit and we may miss + // detecting those samples otherwise. + // + // 3) We call PlayInit so that playing resumes after an underflow (the device implicitly stops). + // At some point thereafter the sample count (returned from SamplesPlayed()) will be reset, but that point + // is not deterministic. Sometimes we see sample count continue relative to last value before + // it resets. Sometimes we see a reset twice. The first reset appears to be for unplayed samples + // at time of the reset. Once those are played out the sample count is reset again. + // + + // determine how much time has elapsed since last time computation TUint sampleCount = m_pStream->SamplesPlayed(); @@ -557,12 +583,22 @@ return; } - HX_ASSERT(m_samplesWritten >= sampleCount); - m_unplayedSampleCount = m_samplesWritten - sampleCount; - +#if (0) // assert likely indicates error; wrap-around is rare case (occurs after ~27 hours for 44Khz) HX_ASSERT(m_baseSampleCount <= sampleCount); TUint samplesElapsed = WrapDiff(m_baseSampleCount, sampleCount); +#else + if (sampleCount < m_baseSampleCount ) + { + // assume this is not a wrap-around (~27 hours for 44Khz) + + // assume this is case where we see two resets, the first apparantly for + // for unplayed samples at time of underflow; see (3) above + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::UpdateTimeSampleStats(): oops: base = %lu > played = %lu; (unplayed = %lu)", m_baseSampleCount, sampleCount, m_unplayedSampleCount); + return; + } + TUint samplesElapsed = sampleCount - m_baseSampleCount; +#endif // convert samples-played to time-played TUint msElapsed = SamplesToMS(samplesElapsed, m_sampleRate); @@ -570,12 +606,13 @@ // update time m_msTimePlayed += msElapsed; - DPRINTF(D_INFO, ("HXSymbianAudioSession::UpdateTimeSampleStats(): base = %lu; played = %lu; (unplayed = %lu)\n", m_baseSampleCount, sampleCount, m_unplayedSampleCount)); - DPRINTF(D_INFO, ("HXSymbianAudioSession::UpdateTimeSampleStats(): adding %lu ms; total now %lu ms\n", msElapsed, m_msTimePlayed)); + HXLOGL4(HXLOG_ADEV, "HXSymbianAudioSession::UpdateTimeSampleStats(): base = %lu; played = %lu; (unplayed = %lu)", m_baseSampleCount, sampleCount, m_unplayedSampleCount); + HXLOGL4(HXLOG_ADEV, "HXSymbianAudioSession::UpdateTimeSampleStats(): adding %lu ms; total now %lu ms", msElapsed, m_msTimePlayed); // update base sample count for next time m_baseSampleCount = sampleCount; } + // // HXSymbianAudioSession::GetTime // @@ -593,8 +630,15 @@ // void HXSymbianAudioSession::GetBlocksBuffered() { - TInt nTmp = m_bufferList.GetCount(); - Message().Complete(nTmp); + TInt fullBlockCount = m_bufferList.GetCount(); + if (m_cbFrontBufferWritten > 0) + { + // don't include a partially written block in the count + HX_ASSERT(fullBlockCount > 0); + --fullBlockCount; + } + + Message().Complete(fullBlockCount); } // @@ -659,11 +703,14 @@ // void HXSymbianAudioSession::Stop() { - if (PLAYING == m_state || PAUSED == m_state || PLAYINIT_PENDING == m_state) + switch (m_state) { + case PLAYINIT_PENDING: + case PLAYING: + case PAUSED: // important: update stats before stopping UpdateTimeSampleStats(); - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::Stop(): %lu ms unplayed in audio device\n", SamplesToMS(m_unplayedSampleCount, m_sampleRate))); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::Stop(): %lu ms unplayed in audio device", SamplesToMS(m_unplayedSampleCount, m_sampleRate)); Trans(STOPPED); HX_ASSERT(m_pStream); @@ -674,6 +721,10 @@ HX_RELEASE(pBuf); } m_cbFrontBufferWritten = 0; + break; + default: + // nothing + break; } Message().Complete(KErrNone); @@ -682,7 +733,7 @@ void HXSymbianAudioSession::RequestDeviceTakenNotification() { - DPRINTF(D_INFO, ("HXSymbianAudioSession::RequestDeviceTakenNotification()\n")); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::RequestDeviceTakenNotification()"); m_wantsNotify = true; m_notifyRequest = Message(); } @@ -707,7 +758,7 @@ { if (m_wantsNotify) { - DPRINTF(D_INFO, ("HXSymbianAudioSession::NotifyDeviceTaken(): doing notify...\n")); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::NotifyDeviceTaken(): doing notify..."); m_notifyRequest.Complete(m_lastPlayError); m_wantsNotify = false; } @@ -719,7 +770,7 @@ { if (state != m_state) { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::Trans(): %s -> %s\n", StringifyState(m_state), StringifyState(state))); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::Trans(): %s -> %s", StringifyState(m_state), StringifyState(state)); m_state = state; switch (m_state) { @@ -775,7 +826,7 @@ void HXSymbianAudioSession::DoPlayInit() { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::DoPlayInit(): setting priority and calling PlayInitL\n")); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::DoPlayInit(): setting priority and calling PlayInitL"); HX_ASSERT(STOPPED == m_state); Trans(PLAYINIT_PENDING); @@ -788,7 +839,7 @@ m_pStream->SetPrioritySettings(prioritySettings); TRAPD(err, m_pStream->PlayInitL()); - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::DoPlayInit(): PlayInitL() result: %s\n", StringifyKErr(err))); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::DoPlayInit(): PlayInitL() result: %s", StringifyKErr(err)); if (err != KErrNone) { Trans(STOPPED); @@ -799,10 +850,10 @@ // MDevSoundObserver void HXSymbianAudioSession::InitializeComplete(TInt aError) { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::InitializeComplete(): err = %s\n", StringifyKErr(aError))); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::InitializeComplete(): err = %s", StringifyKErr(aError)); TRAPD(err, (m_pStream->CMMFDevSound::SetConfigL(m_Settings))); Trans((KErrNone == err) ? STOPPED : CLOSED); - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::InitializeComplete() SetConfgL(): err = %s\n", StringifyKErr(err))); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::InitializeComplete() SetConfgL(): err = %s", StringifyKErr(err)); m_InitMessage.Complete(err); } @@ -820,7 +871,7 @@ case PAUSED: case STOPPED: default: - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::BufferToBeFilled(): unexpected state %s\n", StringifyState(m_state))); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::BufferToBeFilled(): unexpected state %s", StringifyState(m_state)); case PLAYING: break; } @@ -831,7 +882,7 @@ dataDesc = TPtrC8(NULL, 0 ); // ensure descriptor is reset/clear TUint cbDest = aBuffer->RequestSize(); - //DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::BufferToBeFilled(): req size = %ld; dest buffer size = %lu; desc max = %lu; buffer list count = %ld\n", aBuffer->RequestSize(), aBuffer->BufferSize(), dataDesc.MaxSize(), m_bufferList.GetCount())); + //HXLOGL4(HXLOG_ADEV, "HXSymbianAudioSession::BufferToBeFilled(): req size = %ld; dest buffer size = %lu; desc max = %lu; buffer list count = %ld", aBuffer->RequestSize(), aBuffer->BufferSize(), dataDesc.MaxSize(), m_bufferList.GetCount()); while ( !m_bufferList.IsEmpty() && cbDest >= m_cbSample) { @@ -847,7 +898,7 @@ // m_cbFrontBufferWritten = bytes already written from front buffer HX_ASSERT(m_cbFrontBufferWritten < cbBuffer); - //DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::BufferToBeFilled(): next src buffer size = %lu; front buffer written = %lu\n", cbBuffer, m_cbFrontBufferWritten)); + //HXLOGL4(HXLOG_ADEV, "HXSymbianAudioSession::BufferToBeFilled(): next src buffer size = %lu; front buffer written = %lu", cbBuffer, m_cbFrontBufferWritten); // decide how much to write; we may not be able to write a full buffer UINT32 cbToWrite = pBuffer->GetSize() - m_cbFrontBufferWritten; @@ -884,7 +935,7 @@ if (dataDesc.Length() > 0) { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::BufferToBeFilled(): play buff = %ld bytes; samps written = %lu\n", dataDesc.Length(), m_samplesWritten)); + HXLOGL4(HXLOG_ADEV, "HXSymbianAudioSession::BufferToBeFilled(): play buff = %ld bytes; samps written = %lu", dataDesc.Length(), m_samplesWritten); if (PLAYING == m_state) { m_pStream->PlayData(); @@ -893,7 +944,7 @@ } else { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::BufferToBeFilled(): unable to fill buffer (no src data)\n")); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::BufferToBeFilled(): unable to fill buffer (no src data)"); // hold on to buffer; we'll fill it once we have more src data m_pPendingFillBuffer = aBuffer; } @@ -903,10 +954,10 @@ // MDevSoundObserver void HXSymbianAudioSession::PlayError(TInt aError) { - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::PlayError(): err = %s\n", StringifyKErr(aError))); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::PlayError(): err = %s", StringifyKErr(aError)); + HX_ASSERT(aError != KErrNone); // possible? if (aError != KErrNone) { - // update stats before stopping UpdateTimeSampleStats(); // stream is implicitly stopped when an error occurs @@ -917,31 +968,30 @@ // either we just played out or (more likely) we were not // writing to the device fast enough - // add unwritten (lost) samples to time played - TUint msDiscarded = SamplesToMS(m_unplayedSampleCount, m_sampleRate); - DPRINTF(D_SYMAUDIO, ("HXSymbianAudioSession::PlayError(): underflow discarded time = %lu\n", msDiscarded)); - m_msTimePlayed += msDiscarded; + // add unwritten samples to time played (note: reported time + // will be slightly ahead until we catch up) + TUint msPending = SamplesToMS(m_unplayedSampleCount, m_sampleRate); + HXLOGL3(HXLOG_ADEV, "HXSymbianAudioSession::PlayError(): underflow unplayed time = %lu (%lu samples)", msPending, m_unplayedSampleCount); + m_msTimePlayed += msPending; + // save current time so we preserve monotonically increasing time m_msReInitTimePlayed = m_msTimePlayed; - Trans(STOPPED); + // re-init so we resume (continue) audio playback + Trans(STOPPED); DoPlayInit(); } break; case KErrCancel: - { Trans(STOPPED); - } break; case KErrAccessDenied: case KErrInUse: case KErrDied: // incoming message notification on 6630 generates this default: - { m_lastPlayError = aError; Trans(STOPPED); NotifyDeviceTaken(); - } break; } } _______________________________________________ Audio-dev mailing list [email protected] http://lists.helixcommunity.org/mailman/listinfo/audio-dev _______________________________________________ Audio-dev mailing list [email protected] http://lists.helixcommunity.org/mailman/listinfo/audio-dev
