Bug 927 - Multithreading (MT) issues with ALAudioSink (openal-soft) and minor MT issues w/ libav/ffmpeg
Summary: Multithreading (MT) issues with ALAudioSink (openal-soft) and minor MT issues...
Status: RESOLVED FIXED
Alias: None
Product: Jogl
Classification: JogAmp
Component: util (show other bugs)
Version: 2
Hardware: All all
: P3 normal
Assignee: Sven Gothel
URL:
Depends on:
Blocks:
 
Reported: 2013-12-18 16:39 CET by Xerxes Rånby
Modified: 2014-02-26 11:13 CET (History)
1 user (show)

See Also:
Type: DEFECT
SCM Refs:
b92a813063212130d6205a25b1f84662e8c4c0f9 938fbc9e4cb58c1ab6a6f66f128189ed7b634955 e685f79ec7071e266a1bd3d3ce3e742397b5372e b9e89c35dac3c19e026d2a0161649a065b3dceee 13d850c7bf93648dc24e3f01f6f8c9550fba0d97 c4368e89c0fc3ee4de659cd760bc812092bba054 c67de337a8aaf52e36104c3f13e273aa19d21f1f ac7de4a7b2cc939312cbeb88dd709a297c96c13c
Workaround: ---

Attachments
1st-run-RuntimeException: ALError 0xa001 while querying SOURCE_STATE.log (74.71 KB, text/plain)
2014-02-21 09:54 CET, Xerxes Rånby 		Details
2nd-run-RuntimeException: Couldn't find stream information.log (4.24 KB, text/plain)
2014-02-21 09:54 CET, Xerxes Rånby 		Details
3rd-run-stream-initialized-despite warnings-and-playback-work.log (22.65 KB, text/plain)
2014-02-21 09:55 CET, Xerxes Rånby 		Details
4th-run-crash-in-avformat_find_stream_info+0x278-using-29-parallel-players.log (11.65 KB, text/plain)
2014-02-21 10:15 CET, Xerxes Rånby 		Details
hs_err_pid21931.log generated during 4th-run-crash-in-avformat_find_stream_info+0x278-using-29-parallel-players.log (93.67 KB, text/x-log)
2014-02-21 10:16 CET, Xerxes Rånby 		Details
5th-run-deadlock-at-termination-while-running-40-parallel-players.log (137.25 KB, text/plain)
2014-02-25 13:44 CET, Xerxes Rånby 		Details
View All Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Xerxes Rånby 2013-12-18 16:39:43 CET 
Reproducer:
https://github.com/xranby/raspimusic/commit/1423e0c882d64b6cde914a41a9efe99cd602ef6a

#Checkout, build and run:
git clone https://github.com/xranby/raspimusic
cd raspimusic/raspberry/src
sh ./fetch-jogamp-build.sh
sh ./compile-crossfade.sh
./run-crossfade.sh /media/000000/nokiaN9/Music/Ranby/Easy\ to\ Fall\ for\ Love/Easy\ to\ Fall\ for\ Love.mpedia/000000/nokiaN9/Music/Ranby/Unbroken\ Heart/Unbroken\ Heart.mp3

Output:
https://gist.github.com/xranby/2975e05e7b144b64d434
Comment 1 Sven Gothel 2014-01-26 06:04:38 CET 
Tested on GNU/Linux x86_64, 

Result: Plays well here audio and video, i.e. audio is actually mixed from both movies.

Even if one movie (below) stops and restarts (AL buffer reset),
it didn't crash.
While you experience an AL exception (see below).

This may need to be investigated further,
however we need a unit test within JOGL to reproduce this.

Maybe you can add one, and if issue still exists,
please reopen the bug and we can solve this together, after FOSDEM..

Closing bug in the meantime ..

Thank you!

+++

LIB_AV Codec   : 54.92.100 [cc 54]
LIB_AV Format  : 54.63.104 [cc 54]
LIB_AV Util    : 52.18.100 [cc 52]
LIB_AV Resample: 1.0.1 [cc 1, loaded true]
LIB_SW Resample: 0.17.102 [cc 0, loaded true]
LIB_AV Device  : [loaded true]
LIB_AV Class   : FFMPEGv09Natives

+++

(enable MovieSimple in scripts/tests.sh)

bash scripts/tests-x64.sh -loop -windows 2 \
    -urlN 0 http://download.blender.org/peach/bigbuckbunny_movies/big_buck_bunny_720p_surround.avi \
    -urlN 1 http://video.webmfiles.org/elephants-dream.webm

+++

2 Streaming threads, i.e. decoder threads:

"Thread-5-StreamWorker_1" daemon prio=10 tid=0x00007f994c102000 nid=0x5826 in Object.wait() [0x00007f996fa37000]
        at jogamp.opengl.util.av.GLMediaPlayerImpl$StreamWorker.run(GLMediaPlayerImpl.java:1231)
"Thread-4-StreamWorker_0" daemon prio=10 tid=0x00007f99600ed000 nid=0x5825 in Object.wait() [0x00007f996cd09000]
        at jogamp.opengl.util.av.GLMediaPlayerImpl$StreamWorker.run(GLMediaPlayerImpl.java:1231)

+++
+++
+++

Your libav version:

+++
LIB_AV Codec : 53.35.0 [cc 53]
LIB_AV Format : 53.21.1 [cc 53]
LIB_AV Util : 51.22.1 [cc 51]
LIB_AV Resample: 0.0.0 [cc -1, loaded false]
LIB_SW Resample: 0.0.0 [cc -1, loaded false]
LIB_AV Device : [loaded false]
LIB_AV Class : FFMPEGv08Natives
+++

Your libav nagging:

initStream: p3 vid -2, sizes null, reqVideo -1x-1@-1, aid -1, aMaxChannelCount 8, aPrefSampleRate 44100
[NULL @ 0x89d20c60] insufficient thread locking around avcodec_open/close()
[NULL @ 0x89d20c60] insufficient thread locking around avcodec_open/close()
[NULL @ 0x89d20c60] insufficient thread locking around avcodec_open/close()

++

Your actual error:

Caused by: java.lang.RuntimeException: ALError 0xa001 while quering processed buffers at source. ALAudioSink[init true, playRequested true, device OpenAL Soft, ctx 0x2f2087, alSource 1, chosen AudioDataFormat[sampleRate 44100, sampleSize 16, channelCount 2, signed true, fixedP true, packed, little-endian], al[chan Stereo, type s16, fmt 0x1103, soft true], playSpeed 1.0, buffers[total 20, avail 19, queued[1, apts -2147483648, 26 ms, 4608 bytes], queue[g 20, l 39]
at jogamp.opengl.openal.av.ALAudioSink.dequeueBuffer(ALAudioSink.java:483)
at jogamp.opengl.openal.av.ALAudioSink.dequeueBuffer(ALAudioSink.java:549)
at jogamp.opengl.openal.av.ALAudioSink.enqueueData(ALAudioSink.java:601)
at jogamp.opengl.util.av.impl.FFMPEGMediaPlayer.pushSound(FFMPEGMediaPlayer.java:820)
at jogamp.opengl.util.av.impl.FFMPEGv08Natives.readNextPacket0(Native Method)
at jogamp.opengl.util.av.impl.FFMPEGMediaPlayer.getNextTextureImpl(FFMPEGMediaPlayer.java:809)
at jogamp.opengl.util.av.GLMediaPlayerImpl$StreamWorker.run(GLMediaPlayerImpl.java:1234)

+++++

Interesting that
Comment 2 Sven Gothel 2014-01-26 19:39:37 CET 
Updating openal-soft .. exposes even more ALAudioSink issues w/ dequeue buffers.

Note even though libav/ffmpeg complains about lack of synchronization .. 
the real issue is ALAudioSink.

Reopening ..
Comment 3 Sven Gothel 2014-02-15 09:19:31 CET 
938fbc9e4cb58c1ab6a6f66f128189ed7b634955
    Bug 927 - Multithreading (MT) issues with ALAudioSink (openal-soft)
    
    - Using update openal-soft (commit 7297c3214a4c648aaee81a9877da15b88f798197)
    
    - Analyzed openal-soft threading issues:
      - a global-lock would have removed the issue
    
      - turns out that using ALC_EXT_thread_local_context's alcSetThreadContext(..)
        instead of alcMakeContextCurrent(..) solves the issue
    
    - Cleaned up al*GetError() queries and handling
    
    - Simplified flush/dequeue buffers
Comment 4 Sven Gothel 2014-02-16 05:41:19 CET 
Minor MT issues w/ libav/ffmpeg reproduced w/ Debian 7 x64:

[NULL @ 0x35bde60] insufficient thread locking around avcodec_open/close()
[NULL @ 0x35ae1a0] insufficient thread locking around avcodec_open/close()
[NULL @ 0x35ae1a0] insufficient thread locking around avcodec_open/close()

LIB_AV Codec   : 53.35.0 [cc 53]
LIB_AV Format  : 53.21.1 [cc 53]
LIB_AV Util    : 51.22.2 [cc 51]
LIB_AV Resample: 0.0.0 [cc -1, loaded false]
LIB_SW Resample: 0.0.0 [cc -1, loaded false]
LIB_AV Device  : [loaded false]
LIB_AV Class   : FFMPEGv08Natives
Comment 5 Sven Gothel 2014-02-16 06:10:10 CET 
(In reply to comment #4)
> Minor MT issues w/ libav/ffmpeg reproduced w/ Debian 7 x64:
> 
> [NULL @ 0x35bde60] insufficient thread locking around avcodec_open/close()
> [NULL @ 0x35ae1a0] insufficient thread locking around avcodec_open/close()
> [NULL @ 0x35ae1a0] insufficient thread locking around avcodec_open/close()
> 
> LIB_AV Codec   : 53.35.0 [cc 53]
> LIB_AV Format  : 53.21.1 [cc 53]
> LIB_AV Util    : 51.22.2 [cc 51]
> LIB_AV Resample: 0.0.0 [cc -1, loaded false]
> LIB_SW Resample: 0.0.0 [cc -1, loaded false]
> LIB_AV Device  : [loaded false]
> LIB_AV Class   : FFMPEGv08Natives

sadly I could only produce this issue once on said machine ..
Comment 6 Sven Gothel 2014-02-16 06:13:21 CET 
e685f79ec7071e266a1bd3d3ce3e742397b5372e
    Bug 927: Fix minor MT issues w/ libav/ffmpeg
    
    Issue:
      [NULL @ 0x35bde60] insufficient thread locking around avcodec_open/close()
    
    Decorating said libav functions w/ mutex lock/release.
    
    Abstract impl. to either use pthread or JNI Monitor,
    but using the latter to reduce dependencies (ming64 windows).
    
    FFMPEGNatives is now an abstract class containing the
      'static final Object mutex_avcodec_openclose'
Comment 7 Xerxes Rånby 2014-02-21 01:01:14 CET 
https://github.com/xranby/jogl/commit/37b57106f4ef6d64b38cd9cbfccfcf5f332b5525

Parallel media player that demonstrate CrossFade of audio volume during playback.
This player also demonstrate audio only playback of the GLMediaPlayer.

The CrossFadePlayer is a reproducer for
FFMPEGMediaPlayer libav multithreading initialization errors.
[NULL @ 0x7ff904065280] insufficient thread locking around avcodec_open/close()

Initialization error are frequently seen when you playback 2 or more mp3 files in parallel. 
The player runs stable if you are lucky and initialization succeed without triggering the multithreaded initialization bugs.

reproducer:
java -cp gluegen/build/gluegen-rt.jar:jogl/build/jar/jogl-all-mobile.jar:jogl/build/jar/jogl-test.jar:joal/build/jar/joal.jar com.jogamp.opengl.test.junit.jogl.demos.es2.av.CrossFadePlayer *.mp3
Comment 8 Sven Gothel 2014-02-21 05:10:03 CET 
(In reply to comment #7)
> https://github.com/xranby/jogl/commit/
> 37b57106f4ef6d64b38cd9cbfccfcf5f332b5525

Thank you for the test, thats great!

> 
> Parallel media player that demonstrate CrossFade of audio volume during
> playback.
> This player also demonstrate audio only playback of the GLMediaPlayer.
> 
> The CrossFadePlayer is a reproducer for
> FFMPEGMediaPlayer libav multithreading initialization errors.
> [NULL @ 0x7ff904065280] insufficient thread locking around
> avcodec_open/close()

So went those MT issues away 
via commit e685f79ec7071e266a1bd3d3ce3e742397b5372e ?
How 'is it now' ?
Please keep in mind that the runtime behavior is not always reproducible 
on all machines.
Thank you!

I will also test w/ your test case .
Comment 9 Xerxes Rånby 2014-02-21 09:54:15 CET 
Created attachment 595 [details]
1st-run-RuntimeException: ALError 0xa001 while querying SOURCE_STATE.log

(In reply to comment #8)
> (In reply to comment #7)
> > https://github.com/xranby/jogl/commit/
> > 37b57106f4ef6d64b38cd9cbfccfcf5f332b5525
> 
> Thank you for the test, thats great!
> 
> > 
> > Parallel media player that demonstrate CrossFade of audio volume during
> > playback.
> > This player also demonstrate audio only playback of the GLMediaPlayer.
> > 
> > The CrossFadePlayer is a reproducer for
> > FFMPEGMediaPlayer libav multithreading initialization errors.
> > [NULL @ 0x7ff904065280] insufficient thread locking around
> > avcodec_open/close()
> 
> So went those MT issues away 
> via commit e685f79ec7071e266a1bd3d3ce3e742397b5372e ?

No the issue presist.
The commit e685f79ec7071e266a1bd3d3ce3e742397b5372e made playback work _after_ all streams are initialized.

> How 'is it now' ?

It is still possible to trigger native crashes in libav while initializing two or more stream in parallel using the GLMediaPlayer.

Attaching log example of various libav warning and runtime exceptions observed on my machine during parellel stream initialization.

> Please keep in mind that the runtime behavior is not always reproducible 
> on all machines.
> Thank you!
> 
> I will also test w/ your test case .

Thank you!
Comment 10 Xerxes Rånby 2014-02-21 09:54:41 CET 
Created attachment 596 [details]
2nd-run-RuntimeException: Couldn't find stream information.log
Comment 11 Xerxes Rånby 2014-02-21 09:55:08 CET 
Created attachment 597 [details]
3rd-run-stream-initialized-despite warnings-and-playback-work.log
Comment 12 Xerxes Rånby 2014-02-21 10:15:49 CET 
Created attachment 598 [details]
4th-run-crash-in-avformat_find_stream_info+0x278-using-29-parallel-players.log
Comment 13 Xerxes Rånby 2014-02-21 10:16:42 CET 
Created attachment 599 [details]
hs_err_pid21931.log generated during 4th-run-crash-in-avformat_find_stream_info+0x278-using-29-parallel-players.log
Comment 14 Sven Gothel 2014-02-22 08:08:40 CET 
b9e89c35dac3c19e026d2a0161649a065b3dceee
    FFMPEG Natives:
    
      - Move 'mutex_avcodec_openclose' to local static and initialize at initSymbols0
    
      - setStream0:
        - Add another locked mutex block around:
           - [ sp_avformat_open_input .. sp_avformat_find_stream_info ]
    
      This solves the issue of:
    
        [NULL @ 0x89d20c60] insufficient thread locking around avcodec_open/close()
Comment 15 Sven Gothel 2014-02-22 08:09:10 CET 
13d850c7bf93648dc24e3f01f6f8c9550fba0d97
    Bug 927 - Multithreading (MT) issues ALAudioSink
    
    Add global synchronization around ALAudioSink constructor code,
    which 'magically' solves the openal-soft multithreading issues ..
    
    This is a workaround.
Comment 16 Sven Gothel 2014-02-22 08:09:56 CET 
c4368e89c0fc3ee4de659cd760bc812092bba054
   ALAudioSink: Add thread-name to exceptions; stopImpl shall not throw an exception at destroy

c67de337a8aaf52e36104c3f13e273aa19d21f1f
  GLMediaPlayer.GLMediaEventListener: Remind that commands shall be off-loaded on another thread!
Comment 17 Xerxes Rånby 2014-02-25 13:44:40 CET 
Created attachment 600 [details]
5th-run-deadlock-at-termination-while-running-40-parallel-players.log

Initialization code no longer cause any warnings/issues, great success!
I can reproduce a dead-lock during termination if i run 40 players in parallel.
attached log and jstack output.
reproducer:
wget http://jogamp.org/deployment/archive/master/gluegen_777-joal_527-jogl_1232-jocl_938-signed/archive/jogamp-all-platforms.7z
7z x jogamp-all-platforms.7z
cd jogamp-all-platforms/jar
unzip joal-test.jar com/jogamp/openal/test/resources/lewiscarroll.wav
mv com/jogamp/openal/test/resources/lewiscarroll.wav .
java -cp joal.jar:jogl-test.jar:gluegen-rt.jar:jogl-all.jar com.jogamp.opengl.test.junit.jogl.demos.es2.av.CrossFadePlayer lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav lewiscarroll.wav
Comment 18 Sven Gothel 2014-02-25 14:19:22 CET 
Reopened .. due to Comment 17
Comment 19 Xerxes Rånby 2014-02-26 11:13:56 CET 
(In reply to comment #17)
> Created attachment 600 [details]
> 5th-run-deadlock-at-termination-while-running-40-parallel-players.log
> 
> Initialization code no longer cause any warnings/issues, great success!
> I can reproduce a dead-lock during termination if i run 40 players in
> parallel.

The deadlock is caused by a lock being held after thread death triggered by an openal context runtime exception:


mmap() failed: Kan inte allokera minne
AL lib: (EE) connect_context: pa_context_new() failed
AL lib: (EE) alcOpenDevice: Option 'format' is deprecated, please use 'channels' and 'sample-type'
Thread-51-StreamWorker_4: ALCError 0xa004 while makeCurrent. ALAudioSink[init true, playRequested true, device OpenAL Soft, ctx 0x1ab0d58, alSource 133, chosen AudioDataFormat[sampleRate 22050, sampleSize 8, channelCount 1, signed false, fixedP true, packed, little-endian], al[chan Mono, type u8, fmt 0x1100, soft true], playSpeed 0.0, buffers[total 32, avail 0, queued[32, apts 0, 5957 ms, 131072 bytes], queue[g 16, l 32]
java.lang.Exception: Stack trace
	at java.lang.Thread.dumpStack(Thread.java:1364)
	at jogamp.opengl.openal.av.ALAudioSink.lockContext(ALAudioSink.java:232)
	at jogamp.opengl.openal.av.ALAudioSink.dequeueBuffer(ALAudioSink.java:549)
	at jogamp.opengl.openal.av.ALAudioSink.dequeueBuffer(ALAudioSink.java:622)
	at jogamp.opengl.openal.av.ALAudioSink.enqueueData(ALAudioSink.java:668)
	at jogamp.opengl.util.av.impl.FFMPEGMediaPlayer.pushSound(FFMPEGMediaPlayer.java:822)
	at jogamp.opengl.util.av.impl.FFMPEGv08Natives.readNextPacket0(Native Method)
	at jogamp.opengl.util.av.impl.FFMPEGMediaPlayer.getNextTextureImpl(FFMPEGMediaPlayer.java:811)
	at jogamp.opengl.util.av.GLMediaPlayerImpl$StreamWorker.run(GLMediaPlayerImpl.java:1238)

The jogl commit ac7de4a7b2cc939312cbeb88dd709a297c96c13c resolves the deadlock and allows the application to terminate cleanly.

It appears OpenAL-soft currently got a limit to only handle 32 simultaneous sound playbacks and this is the cause of the openal runtime exception thus not our issue.