1187817 - Move more code of AudioSink into the audio thread

Status: RESOLVED FIXED

(Core :: Audio/Video: Playback, defect)

Description

[JW Wang [:jwwang] [:jw_wang]]

After bug 1187763 is landed, we are able to move most of the code into the audio thread so it can run without lock held to improve concurrency.

Comment 1

[JW Wang [:jwwang] [:jw_wang]]

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=193029d39179

Comment 2

[JW Wang [:jwwang] [:jw_wang]]

Try again. https://treeherder.mozilla.org/#/jobs?repo=try&revision=15fcc853705b

Comment 3

[JW Wang [:jwwang] [:jw_wang]]

Attachment: MozReview Request: Bug 1187817. Part 1 - Move Set{Volume,PlaybackRate,PreservesPitch} to the audio thread.

Bug 1187817. Part 1 - Move Set{Volume,PlaybackRate,PreservesPitch} to the audio thread.

Comment 4

[JW Wang [:jwwang] [:jw_wang]]

Attachment: MozReview Request: Bug 1187817. Part 2 - remove unused code.

Bug 1187817. Part 2 - remove unused code.

Comment 5

[JW Wang [:jwwang] [:jw_wang]]

Attachment: MozReview Request: Bug 1187817. Part 3 - move SetPlaying to the audio thread.

Bug 1187817. Part 3 - move SetPlaying to the audio thread.

Comment 6

[JW Wang [:jwwang] [:jw_wang]]

Attachment: MozReview Request: Bug 1187817. Part 4 - move some code in Shutdown to the audio thread.

Bug 1187817. Part 4 - move some code in Shutdown to the audio thread.

Comment 7

[JW Wang [:jwwang] [:jw_wang]]

Attachment: MozReview Request: Bug 1187817. Part 5 - assert some code in the audio thread and don't enter the monitor.

Bug 1187817. Part 5 - assert some code in the audio thread and don't enter the monitor.

Comment 8

[JW Wang [:jwwang] [:jw_wang]]

Too bad that we still can't remove the monitor because mAudioStream is accessed from 2 threads...

Comment 9

[Matthew Gregan [:kinetik]]

Comment on attachment 8639773 [details]
MozReview Request: Bug 1187817. Part 1 - Move Set{Volume,PlaybackRate,PreservesPitch} to the audio thread.

https://reviewboard.mozilla.org/r/14235/#review12867

Ship It!

Comment 10

[Matthew Gregan [:kinetik]]

Comment on attachment 8639774 [details]
MozReview Request: Bug 1187817. Part 2 - remove unused code.

https://reviewboard.mozilla.org/r/14237/#review12869

Ship It!

Comment 11

[Matthew Gregan [:kinetik]]

Comment on attachment 8639775 [details]
MozReview Request: Bug 1187817. Part 3 - move SetPlaying to the audio thread.

https://reviewboard.mozilla.org/r/14239/#review12871

Ship It!

Comment 12

[Matthew Gregan [:kinetik]]

Comment on attachment 8639776 [details]
MozReview Request: Bug 1187817. Part 4 - move some code in Shutdown to the audio thread.

https://reviewboard.mozilla.org/r/14241/#review12873

Ship It!

Comment 13

[Matthew Gregan [:kinetik]]

Comment on attachment 8639777 [details]
MozReview Request: Bug 1187817. Part 5 - assert some code in the audio thread and don't enter the monitor.

https://reviewboard.mozilla.org/r/14243/#review12875

Ship It!

Comment 14

[JW Wang [:jwwang] [:jw_wang]]

Thanks for the review!

Comment 15

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/264dad192c22
https://hg.mozilla.org/integration/mozilla-inbound/rev/cf38bd59eb44
https://hg.mozilla.org/integration/mozilla-inbound/rev/d31a0c93969f
https://hg.mozilla.org/integration/mozilla-inbound/rev/74386997e5fb
https://hg.mozilla.org/integration/mozilla-inbound/rev/ae2e2dda1eec

Comment 16

[Ryan VanderMeulen [:RyanVM]]

Backed out for making test_mediatrack_consuming_mediaresource.html extremely failure-prone on B2G.
https://treeherder.mozilla.org/logviewer.html#?job_id=12202970&repo=mozilla-inbound

Comment 17

[Pulsebot]

Backout:
https://hg.mozilla.org/mozilla-central/rev/42521959e9b9

Comment 18

[JW Wang [:jwwang] [:jw_wang]]

This is interesting. I've been tracking this crash for a long time and haven't found a reliable way to reproduce it. Now we have one.

We have similiar issues here:
https://bugzilla.mozilla.org/show_bug.cgi?id=682385#c23
https://bugzilla.mozilla.org/show_bug.cgi?id=996464#c4
https://bugzilla.mozilla.org/show_bug.cgi?id=1020707#c113
https://bugzilla.mozilla.org/show_bug.cgi?id=1092609#c0

I will file another bug to track this issue.

Comment 19

[JW Wang [:jwwang] [:jw_wang]]

After adding some logs, the logs suggest that bufferqueue_callback were called from 2 threads and we got SL_RESULT_BUFFER_INSUFFICIENT because the queue was full. How is that possible?

code:
LOG("suro bufferqueue_callback, %p, tid=%p\n", user_ptr, (void*)gettid());

logs:
I(  510:0x262) suro bufferqueue_callback, 0x47a7d780, tid=0x262
I(  510:0x262) suro bufferqueue_callback, 0x47a7d780, tid=0x262
I(  510:0x260) suro bufferqueue_callback, 0x47a7d780, tid=0x260
I(  510:0x260) suro bufferqueue_callback, 0x47a7d780, tid=0x260

Comment 20

[Matthew Gregan [:kinetik]]

Good question... I don't understand the OpenSL backend as well as the others, so just guessing/poking around in the code here.  I think we need more logging to see what's going on...

It looks like OpenSLES/AudioTrack only use a single thread (AudioTrackThread instance) to call the callback that ultimately ends up in bufferqueue_callback, so where does the other thread come from?  Is it where we call bufferqueue_callback directly in opensl_stream_start to prefill or are we ending up in a state where two AudioTracks are calling back with the same user_ptr?  If it's the former, we should only see a single bufferqueue_callback from opensl_stream_start (unless opensl_stream_stop is called).

It looks like the following sequence may be possible:
1. opensl_stream_start -> calls bufferqueue_callback and Enqueues buffers
2. Play long enough that at least one buffer becomes free -> OpenSL calls bufferqueue_callback
3. We call opensl_stream_stop for some reason, which sets SL_PLAYSTATE_PAUSED
   (it appears this could happen while the callback is running on the other (AudioTrackThread) thread)
4. We call opensl_stream_start -> calls bufferqueue_callback to prefill

Where the bufferqueue_callback in step 2 is running while steps 3 and 4 run on the other thread.  Since the code appears to be written assuming bufferqueue_callback runs on a single thread at a time, it's possible both threads get a value from GetState that causes them to refill multiple buffers, thus hitting the Enqueue error SL_RESULT_BUFFER_INSUFFICIENT because the two threads are effectively trying to Enqueue more than NBUFS buffers.

Comment 21

[JW Wang [:jwwang] [:jw_wang]]

Thanks for the reply. I will add more logs to investigate the connection between opensl_stream_{start,stop} and the buffer callback.

Comment 22

[JW Wang [:jwwang] [:jw_wang]]

Hi kinetik,
You are right. The blame goes to bufferqueue_callback() is called in opensl_stream_start(). I wonder if it is really needed though it was already there in the 1st version of cubeb_opensl.c.

https://hg.mozilla.org/mozilla-central/diff/8eee25223a3e/media/libcubeb/src/cubeb_opensl.c#l1.269

I wonder if we can remove it because we will be able to remove most locks in bufferqueue_callback() for those variables will be only accessed in the buffer callback thread.

Comment 23

[Matthew Gregan [:kinetik]]

(In reply to JW Wang [:jwwang] from comment #22)
> Hi kinetik,
> You are right. The blame goes to bufferqueue_callback() is called in
> opensl_stream_start(). I wonder if it is really needed though it was already
> there in the 1st version of cubeb_opensl.c.

We must enqueue buffers for initial playback.  If there are none enqueued and we start playback, OpenSL will be in a playing-but-waiting-for-buffers state, i.e. the bufferqueue_callback is only called after a previously enqueued buffer becomes free.

We could check if any buffers are already queued, and only prefill from opensl_stream_start if there are none already queued.  We'd need to verify that it's not possible to have a situation where there are 0 buffers queued but the other thread is calling bufferqueue_callback to refill, though, otherwise we'd just be making the bug rarer rather than fixing it.

Curiously, GStreamer's openslringqueue.c pause/play/prefill works in a similar way to libcubeb (except they changed to enqueue only a single buffer when starting/resuming from pause, but for efficient reasons rather than to fix a bug).  c.f. http://cgit.freedesktop.org/gstreamer/gst-plugins-bad/tree/sys/opensles/openslesringbuffer.c

(Unrelated: that also led me to http://cgit.freedesktop.org/gstreamer/gst-plugins-bad/commit/sys/opensles/openslesringbuffer.c?id=c842df1c3dd8bb76d139b9808dc4ed00a53eb62e which we might need a similar hack to solve)

I think we either need to introduce synchronization in bufferqueue_callback or find a way to wait for OpenSL to reach the stable pause state after pausing.  Scanning the OpenSL ES API, I don't see a way to do the latter...

A slightly hackish way to solve this might be to enqueue a single sample of silence when starting/resuming, but that would cause a small glitch when resuming with a partially full buffer queue.

Comment 24

[Matthew Gregan [:kinetik]]

Forgot to add:

We could also use PLAYSTATE_STOPPED instead of PLAYSTATE_PAUSED.  That would allow us to unregister the callback, which should guarantee that it's not running when we go to start playback again.  But PLAYSTATE_STOPPED resets the playback position within the current buffer, so we'd need to save and restore that when resuming.

Comment 25

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ecf03b35eac0
https://hg.mozilla.org/integration/mozilla-inbound/rev/f8721ef7b2b2
https://hg.mozilla.org/integration/mozilla-inbound/rev/6ea02f2b59af
https://hg.mozilla.org/integration/mozilla-inbound/rev/9e795629afc2
https://hg.mozilla.org/integration/mozilla-inbound/rev/b0c6d424125a

Comment 26

[JW Wang [:jwwang] [:jw_wang]]

re-land. Bug 1189197 should fix the crash.

Comment 27

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/ecf03b35eac0
https://hg.mozilla.org/mozilla-central/rev/f8721ef7b2b2
https://hg.mozilla.org/mozilla-central/rev/6ea02f2b59af
https://hg.mozilla.org/mozilla-central/rev/9e795629afc2
https://hg.mozilla.org/mozilla-central/rev/b0c6d424125a