Bug 927

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

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 ..

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

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

(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 ..

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'

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

(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 .

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!

Created attachment 596 [details]
2nd-run-RuntimeException: Couldn't find stream information.log

Created attachment 597 [details]
3rd-run-stream-initialized-despite warnings-and-playback-work.log

Created attachment 598 [details]
4th-run-crash-in-avformat_find_stream_info+0x278-using-29-parallel-players.log

Created attachment 599 [details]
hs_err_pid21931.log generated during 4th-run-crash-in-avformat_find_stream_info+0x278-using-29-parallel-players.log

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()

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.

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!

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

Reopened .. due to Comment 17

(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.