CMdaAudioOutputStream unexpected playback pauses on Nokia E51

[pkolaczk]

Hello,

We are developing a player for Symbian and we are stuck with a strange problem.
On emulator, everything works perfectly, but when run on a real device (E51), the player plays for 2 seconds,
then pauses for about half a second, then plays again for about 0.5 - 1s, and then pauses and so on. These pauses seem to be quite regular.

We logged to a file all MMdaAudioOutputStreamCallback callbacks as well as our requests to write the buffers and here it is:

29/07/2009	9:57:50	Syncing...
29/07/2009	9:57:50	GOT SYNC
29/07/2009	9:57:50	Initializing decoder with 194 bytes
29/07/2009	9:57:50	Decoding 194 bytes
29/07/2009	9:57:50	Allocating memory for hybrids.
29/07/2009	9:57:50	FRAME DECODED
29/07/2009	9:57:50	Setting audio samplerate to 44100
29/07/2009	9:57:50	Write: Prebuffering... Filled buffer: 0.
29/07/2009	9:57:50	Write: Prebuffering... Filled buffer: 1.
29/07/2009	9:57:50	Write: Prebuffering... Filled buffer: 2.
29/07/2009	9:57:50	Write: Prebuffering... Filled buffer: 3.
29/07/2009	9:57:50	Write: Prebuffering... Filled buffer: 4.
29/07/2009	9:57:50	Write: Prebuffering... Filled buffer: 5.
..........................
29/07/2009	9:57:52	Write: Prebuffering... Filled buffer: 56.
29/07/2009	9:57:53	Write: Prebuffering... Filled buffer: 57.
29/07/2009	9:57:53	Write: Prebuffering... Filled buffer: 58.
29/07/2009	9:57:53	Write: Prebuffering... Filled buffer: 59.
29/07/2009	9:57:54	Starting play...
29/07/2009	9:57:54	Write: Prebuffering... Filled buffer: 60.
29/07/2009	9:57:54	Audio buffer open. Error code: 0
29/07/2009	9:57:54	Open: Started async copying of buffer: 0.
29/07/2009	9:57:54	Open: Started async copying of buffer: 1.
29/07/2009	9:57:54	Open: Started async copying of buffer: 2.
29/07/2009	9:57:54	Open: Started async copying of buffer: 3.
29/07/2009	9:57:54	Open: Started async copying of buffer: 4.
29/07/2009	9:57:54	Open: Started async copying of buffer: 5.
29/07/2009	9:57:54	Open: Started async copying of buffer: 6.
..........................
29/07/2009	9:57:54	Open: Started async copying of buffer: 55.
29/07/2009	9:57:54	Open: Started async copying of buffer: 56.
29/07/2009	9:57:54	Open: Started async copying of buffer: 57.
29/07/2009	9:57:54	Open: Started async copying of buffer: 58.
29/07/2009	9:57:54	Open: Started async copying of buffer: 59.
29/07/2009	9:57:54	Open: Started async copying of buffer: 60.
29/07/2009	9:57:54	Successfully copied buffer: 0
29/07/2009	9:57:54	Successfully copied buffer: 1
29/07/2009	9:57:54	Successfully copied buffer: 2
29/07/2009	9:57:54	Successfully copied buffer: 3
29/07/2009	9:57:54	Successfully copied buffer: 4
29/07/2009	9:57:54	Successfully copied buffer: 5
29/07/2009	9:57:54	Successfully copied buffer: 6
29/07/2009	9:57:54	Successfully copied buffer: 7
29/07/2009	9:57:54	Successfully copied buffer: 8
29/07/2009	9:57:54	Successfully copied buffer: 9
29/07/2009	9:57:54	Write: Started async copying of buffer: 61
29/07/2009	9:57:54	Successfully copied buffer: 10
29/07/2009	9:57:54	Successfully copied buffer: 11
29/07/2009	9:57:54	Successfully copied buffer: 12
29/07/2009	9:57:54	Successfully copied buffer: 13
29/07/2009	9:57:54	Successfully copied buffer: 14
29/07/2009	9:57:54	Successfully copied buffer: 15
29/07/2009	9:57:54	Successfully copied buffer: 16
29/07/2009	9:57:54	Successfully copied buffer: 17
29/07/2009	9:57:54	Successfully copied buffer: 18
29/07/2009	9:57:54	Write: Started async copying of buffer: 62
29/07/2009	9:57:54	Successfully copied buffer: 19
29/07/2009	9:57:54	Successfully copied buffer: 20
29/07/2009	9:57:54	Successfully copied buffer: 21
29/07/2009	9:57:54	Successfully copied buffer: 22
29/07/2009	9:57:54	Successfully copied buffer: 23
29/07/2009	9:57:55	Successfully copied buffer: 24
29/07/2009	9:57:55	Successfully copied buffer: 25
29/07/2009	9:57:55	Successfully copied buffer: 26
29/07/2009	9:57:55	Successfully copied buffer: 27
29/07/2009	9:57:55	Write: Started async copying of buffer: 63
29/07/2009	9:57:55	Successfully copied buffer: 28
29/07/2009	9:57:55	Successfully copied buffer: 29
29/07/2009	9:57:55	Successfully copied buffer: 30
29/07/2009	9:57:55	Successfully copied buffer: 31
29/07/2009	9:57:55	Successfully copied buffer: 32
29/07/2009	9:57:55	Successfully copied buffer: 33
29/07/2009	9:57:55	Successfully copied buffer: 34
29/07/2009	9:57:55	Write: Started async copying of buffer: 0
29/07/2009	9:57:55	Write: Started async copying of buffer: 1
29/07/2009	9:57:55	Write: Started async copying of buffer: 2
29/07/2009	9:57:55	Write: Started async copying of buffer: 3
29/07/2009	9:57:55	Successfully copied buffer: 35
29/07/2009	9:57:55	Successfully copied buffer: 36
29/07/2009	9:57:55	Successfully copied buffer: 37
29/07/2009	9:57:55	Successfully copied buffer: 38
29/07/2009	9:57:55	Successfully copied buffer: 39
29/07/2009	9:57:55	Successfully copied buffer: 40
29/07/2009	9:57:55	Successfully copied buffer: 41
29/07/2009	9:57:55	Successfully copied buffer: 42
29/07/2009	9:57:55	Successfully copied buffer: 43
29/07/2009	9:57:55	Write: Started async copying of buffer: 4
29/07/2009	9:57:55	Write: Started async copying of buffer: 5
29/07/2009	9:57:55	Write: Started async copying of buffer: 6
29/07/2009	9:57:55	Write: Started async copying of buffer: 7
29/07/2009	9:57:55	Write: Started async copying of buffer: 8
29/07/2009	9:57:55	Write: Started async copying of buffer: 9
29/07/2009	9:57:55	Write: Started async copying of buffer: 10
29/07/2009	9:57:55	Write: Started async copying of buffer: 11
29/07/2009	9:57:55	Write: Started async copying of buffer: 12
29/07/2009	9:57:55	Successfully copied buffer: 44
29/07/2009	9:57:55	Successfully copied buffer: 45
29/07/2009	9:57:55	Successfully copied buffer: 46
29/07/2009	9:57:56	Successfully copied buffer: 47
29/07/2009	9:57:56	Successfully copied buffer: 48
29/07/2009	9:57:56	Successfully copied buffer: 49
29/07/2009	9:57:56	Successfully copied buffer: 50
29/07/2009	9:57:56	Successfully copied buffer: 51
29/07/2009	9:57:56	Write: Started async copying of buffer: 13
29/07/2009	9:57:56	Write: Started async copying of buffer: 14
29/07/2009	9:57:56	Write: Started async copying of buffer: 15
29/07/2009	9:57:56	Write: Started async copying of buffer: 16
29/07/2009	9:57:56	Write: Started async copying of buffer: 17
29/07/2009	9:57:56	Write: Started async copying of buffer: 18
29/07/2009	9:57:56	Write: Started async copying of buffer: 19
29/07/2009	9:57:56	Write: Started async copying of buffer: 20
29/07/2009	9:57:56	Successfully copied buffer: 52
29/07/2009	9:57:56	Successfully copied buffer: 53
29/07/2009	9:57:56	Successfully copied buffer: 54
29/07/2009	9:57:56	Successfully copied buffer: 55
29/07/2009	9:57:56	Successfully copied buffer: 56
29/07/2009	9:57:56	Successfully copied buffer: 57
29/07/2009	9:57:56	Successfully copied buffer: 58
29/07/2009	9:57:56	Write: Started async copying of buffer: 21
29/07/2009	9:57:56	Write: Started async copying of buffer: 22
29/07/2009	9:57:56	Write: Started async copying of buffer: 23
29/07/2009	9:57:56	Write: Started async copying of buffer: 24
29/07/2009	9:57:56	Write: Started async copying of buffer: 25
29/07/2009	9:57:56	Write: Started async copying of buffer: 26
29/07/2009	9:57:56	Write: Started async copying of buffer: 27
29/07/2009	9:57:56	Successfully copied buffer: 59
29/07/2009	9:57:56	Successfully copied buffer: 60
29/07/2009	9:57:56	Successfully copied buffer: 61
29/07/2009	9:57:56	Successfully copied buffer: 62
29/07/2009	9:57:56	Successfully copied buffer: 63
29/07/2009	9:57:56	Successfully copied buffer: 0
29/07/2009	9:57:56	Successfully copied buffer: 1
29/07/2009	9:57:56	Write: Started async copying of buffer: 28
29/07/2009	9:57:56	Write: Started async copying of buffer: 29
29/07/2009	9:57:56	Write: Started async copying of buffer: 30
29/07/2009	9:57:56	Write: Started async copying of buffer: 31
29/07/2009	9:57:56	Write: Started async copying of buffer: 32
29/07/2009	9:57:56	Write: Started async copying of buffer: 33
29/07/2009	9:57:56	Write: Started async copying of buffer: 34
29/07/2009	9:57:56	Successfully copied buffer: 2
29/07/2009	9:57:56	Successfully copied buffer: 3
29/07/2009	9:57:56	Successfully copied buffer: 4
29/07/2009	9:57:57	Successfully copied buffer: 5

No buffer underflows are reported (by MaoscPlayComplete with error = KErrUnderrflow), and also you can see
that always several buffers are successfully copied before the playback. We use 64 buffers of 8192 bytes each,
filled cyclically. We tried this also with 16 buffers of 40kB each and we got no difference


Our algorithm is as follows:
1. The input layer waits for data from the stream. It sends data in packs of 1400-5000 bytes to the underlying decoding layer.
2. The decoding layer buffers the compressed data in a cyclic buffer (~64 kB) so that full AAC frames can be read.
3. It searches for the first full frame and then decodes frames one by one, as they appear in the buffer. For decoding we use an open source AAC library. The decoder manages to decompress frames in real time on the phone (otherwise we would get buffer underflows).
4. Each uncompressed frame is sent to our audio layer.
5. The audio layer appends the data to the current buffer, and as soon as it is filled fully, it is sent by a call to the WriteL function, and next buffer is being filled.

Everything is in a single thread with the lowes possible priority (we also checked normal and real-time priorities - also no difference).

We don't expect the exact solution to the problem, but only some hints, where and what to check for, because we ran out ideas.

[chenziteng]

Hello,
...

Hi,

I'd like to share some of my foundings regarding the CMdaAudioOutputStream, and hope they can help you.

I found that the CMdaAudioOutputStream::WriteL(data) is actually sending data to lower layer (DevSound?) by cooperative multitasking - I guess it will split the data into small chunks and use AO to send them one by one. Thus if a CPU intensive task is running in the same thread then the CMdaAudioOutputStream will have no chance to continue sending data, and user will hear that the audio playing is interrupted. The problem can be resolved by preemptive multitasking, i.e. create a new thread to own the CMdaAudioOutputStream object and do the audio playing, and then the playing will not stop as long as you keep feeding data to the thread.

Another finding is that the MaoscPlayComplete() seems never called...

"KIS000622 - MaoscPlayCompete() callback not received after output stream underflow"
http://wiki.forum.nokia.com/index.ph...ream_underflow

Regards

Ziteng Chen