495352 - Audio stream polling runs amok

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Rich Walsh]

Mozilla/5.0 (OS/2; U; Warp 4.5; en-US; rv:1.9.2a1pre) Gecko/20090527 Minefield/3.6a1pre

Normally, between each sequence of calls into sydney_audio that results in data being written (sa_stream_get_position/get_write_size/write), there are 0-5 such sequences that write no data.  I'm calling this "polling" though I don't know what purpose these calls serve (if any).

In a completely random and erratic manner, this polling activity goes haywire.  Suddenly, there will be anywhere from 700 to over 30,000 of these polling sequences between non-zero-byte writes.  For a CD-quality http stream, there are typically 14-18,000;  for a low-quality stream, there may be 23-30,000.  This behavior may occur only once every 20-50 writes, or in spates of 5-10 occurrences, or it may become continuous.  When this occurs at length, it consumes 100% of the CPU's cycles and renders the machine nearly unusable.

This polling is definitely not the result of waiting for a buffer to become free.  In my OS/2 implementation, there are usually 5 16k buffers available & 6 in use.  Though I haven't tested versions for other platforms, I don't believe this is an OS/2 issue since the code that generates these calls is (all?) cross-platform.

Comment 1

[cajbir (:cajbir)]

I'm not seeing this on Linux using Alsa. Do you have an example video/stream that you can point me to where you see the issue?

Comment 2

[cajbir (:cajbir)]

I've managed to duplicate this issue on Linux now. Not to the extreme case you're seeing but I do see a number of calls with 0 size progressively getting longer on some videos.

Comment 3

[Rich Walsh]

The less busy the CPU is, the more likely it is to happen.  With video, I may see 1700 calls once every 50 writes.  With audio streams like those below, it may be 24,000 calls 6-8 times in a row every 10-20 writes.

http://217.150.130.173:8000/jazzradio56.ogg
http://wbur-ogg.streamguys.com:80/wburlive.ogg
http://vorbis.nm.cbc.ca:80/cbcr1-toronto.ogg

FYI... The i/o required to log these occurrences reduces their frequency.  I didn't get a good feel for the scope of the problem until I established a zero-write counter that is only displayed when a valid write occurs. My count of zero-byte writes then increased 30-fold.

Comment 4

[Rich Walsh]

Attachment: fixes nsOggDecodeStateMachine::PlayFrame()

The problem is caused by errors in the timing loop in nsOggDecodeStateMachine::PlayFrame().

The code converts the difference of two floating point time values to an integer then passes it to mon.Wait().  If the difference between these f.p. values is very small, the integer value works out to zero.  This makes mon.Wait() effectively a no-op and leaves the loop is free to execute as many times as it can.

On platforms where the timestamp returned by mAudioStream->GetPosition() is updated in real-time (e.g. Windows & Linux), the loop has little time to execute many iterations.  However, on OS X and OS/2, the timestamp is only updated when the platform's audio system invokes a buffer-empty callback.  This gives the loop plenty of time to rack up thousands of iterations before the timestamp is updated and the loop exits.

The patch fixes the issue by evaluating the delay time after it's been converted to a signed integer, exiting the loop if it's l.t.e. zero.

Comment 5

[Peter Weilbacher]

sr does not seem to be necessary for small media patches, so I guess this just needs to be pushed.

Comment 6

[Peter Weilbacher]

Had time to push it to trunk just now:
http://hg.mozilla.org/mozilla-central/rev/7664835987fd

(I applied the patch to content/media/ogg/nsOggDecoder.cpp instead of content/media/video/src/nsOggDecoder.cpp.)

Comment 7

[Rich Walsh]

Now that this is in place, I'll be filing another bug which involves the exact same code.  OS/2 builders should already have the patch ("ogg-fix").  Without it, video won't play more than a few frames.  More later...

Comment 8

[Peter Weilbacher]

This should land on 1.9.1, right? Is there any risk that the branch drivers should know about?

Comment 9

[Peter Weilbacher]

Comment on attachment 383598 [details] [diff] [review]
fixes nsOggDecodeStateMachine::PlayFrame()

From reports especially in the OS/2 newsgroup, people are seeing the CPU usage problem and have to kill FF to be able to work again.

This has been tested on trunk (and 1.9.2 branch) since the checkin end of July, so should be a pretty safe stability update for 1.9.1.

Comment 10

[Daniel Veditz [:dveditz]]

Comment on attachment 383598 [details] [diff] [review]
fixes nsOggDecodeStateMachine::PlayFrame()

The previous code used to "continue" from the top of the loop if it scheduled a wait, now it will fall into the mDecodedFrames.Pop() etc code.

Is this fix really conservative enough to be one of the 50 or so patches we take in 1.9.1.5?

Comment 11

[Rich Walsh]

(In reply to comment #10)
> The previous code used to "continue" from the top of the loop if it
> scheduled a wait, now it will fall into the mDecodedFrames.Pop() etc code.
> Is this fix really conservative enough to be one of the 50 or so patches we
> take in 1.9.1.5?

There's absolutely no change in the logic, only the way it's laid-out.  Notice that in the old code the 'continue' is followed immediately by a 'break'.  Previously, it was "if time's not up, continue, otherwise break";  now it's "if time's up, break" - the 'continue' is implicit when the bottom of the loop is reached.

In any case, this patch and two related ones in Bug 496147 & Bug 506434 probably should not be committed to the v1.9.1 branch.  Instead see my consolidated patch, Bug 523770.