search

ScintillatorSynth / Scintillator

A Video Synthesis Engine for SuperCollider
https://scintillatorsynth.org
56 stars 8 forks source link

Intermittent crash while encoding images #115

Closed lnihlen closed 4 years ago

lnihlen commented 4 years ago

As seen on Travis CI on the Linux release build:

[1588972510.310] 11396 [info] ScinthDef scinOsc parsed, validated, and added to Archetypes.
[1588972510.310] 11396 [info] Copying 64 bytes of vertex data to GPU for ScinthDef scinOsc
[1588972510.310] 11396 [info] copying 8 bytes of index data to GPU for ScinthDef scinOsc
[1588972510.450] 11396 [info] successfully compiled shader source scinOsc_cd416d6f_vertexShader.
[1588972510.452] 11396 [info] successfully compiled shader source scinOsc_cd416d6f_fragmentShader.
[1588972510.541] 11398 [debug] Async sync watcher threads idle, waiting for all staging completed.
[1588972510.541] 11398 [debug] Async sync watcher true idle, firing callbacks.
[1588972510.541] 11398 [debug] Async sync watcher exhausted callbacks.
queing screenShot at /home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_0.png
[1588972510.541] 11400 [warning] OSC ScinthNew got uneven pairs of control arguments, ignoring last pair.
[1588972510.543] 11400 [info] Scinth id 1003 from def scinOsc cueued.
[1588972510.544] 11400 [info] Encoder chose output format name 'image2', codec name 'png' for file '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_0.png', mime type 'image/png'
advancing frame by 1
[1588972510.544] 11400 [info] libav: [file @ 0x7f54ec0949c0] Setting default whitelist 'file,crypto,data'
[1588972510.544] 11400 [info] OSC ScreenShot '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_0.png' enqueued for encode.
[1588972510.545] 11383 [debug] rebuilding Compositor command buffer with 1 secondary command buffers
[1588972510.545] 11383 [debug] ImageEncoder queuing buffer for render at time 1.0, frame Number 2
[1588972511.687] 11383 [debug] ImageEncoder got callback to encode frame.
[1588972511.693] 11383 [trace] ImageEncoder through avcodec_send_frame.
[1588972511.693] 11383 [trace] ImageEncoder through avcodec_receive_packet.
[1588972511.693] 11383 [info] libav: [image2 @ 0x7f54ec00cd00] Opening '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_0.png' for writing
[1588972511.693] 11383 [info] libav: [file @ 0x564fbc0da700] Setting default whitelist 'file,crypto,data'
[1588972511.694] 11383 [info] libav: [AVIOContext @ 0x564fbc0dab00] Statistics: 0 seeks, 1 writeouts
[1588972511.695] 11383 [trace] ImageEncoder through av_write_frame.
[1588972511.695] 11383 [debug] Encoder finishing encode, valid: true
[1588972511.695] 11383 [debug] Encoder through avcodec_send_frame flush, valid: true
[1588972511.696] 11383 [debug] Encoder through avcodec_receive_packet flush, valid: true
[1588972511.696] 11383 [info] libav: [AVIOContext @ 0x7f54ec0d4c80] Statistics: 0 seeks, 0 writeouts
[1588972511.696] 11383 [info] Screenshot finished encode of '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_0.png', valid: true
[1588972511.697] 11383 [info] got callback from advanceFrame
queing screenShot at /home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_1.png
[1588972511.697] 11400 [info] Encoder chose output format name 'image2', codec name 'png' for file '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_1.png', mime type 'image/png'
advancing frame by 1
[1588972511.697] 11400 [info] libav: [file @ 0x7f54ec0c9000] Setting default whitelist 'file,crypto,data'
[1588972511.697] 11400 [info] OSC ScreenShot '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_1.png' enqueued for encode.
[1588972511.698] 11383 [debug] ImageEncoder queuing buffer for render at time 2.0, frame Number 3
[1588972511.704] 11383 [debug] ImageEncoder got callback to encode frame.
[1588972511.717] 11383 [trace] ImageEncoder through avcodec_send_frame.
[1588972511.718] 11383 [trace] ImageEncoder through avcodec_receive_packet.
[1588972511.718] 11383 [info] libav: [image2 @ 0x7f54ec00d440] Opening '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_1.png' for writing
[1588972511.718] 11383 [info] libav: [file @ 0x564fbc0e9340] Setting default whitelist 'file,crypto,data'
[1588972511.719] 11383 [info] libav: [AVIOContext @ 0x564fbc0e9640] Statistics: 0 seeks, 1 writeouts
[1588972511.719] 11383 [trace] ImageEncoder through av_write_frame.
[1588972511.719] 11383 [debug] Encoder finishing encode, valid: true
[1588972511.719] 11383 [debug] Encoder through avcodec_send_frame flush, valid: true
[1588972511.720] 11383 [debug] Encoder through avcodec_receive_packet flush, valid: true
[1588972511.720] 11383 [info] libav: [AVIOContext @ 0x7f54ec0c9240] Statistics: 0 seeks, 0 writeouts
[1588972511.720] 11383 [info] Screenshot finished encode of '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_1.png', valid: true
[1588972511.721] 11383 [info] got callback from advanceFrame
queing screenShot at /home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_2.png
[1588972511.721] 11400 [info] Encoder chose output format name 'image2', codec name 'png' for file '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_2.png', mime type 'image/png'
advancing frame by 1
[1588972511.721] 11400 [info] libav: [file @ 0x7f54ec0cd400] Setting default whitelist 'file,crypto,data'
[1588972511.721] 11400 [info] OSC ScreenShot '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_2.png' enqueued for encode.
Segmentation fault (core dumped)
RESULT = 139
*** scinsynth fatal error, code: 139
*** nonzero exit code nil on server, exiting.
*** SCRIPT FAILED ***
script failure caught, exiting.
The X11 connection broke (error 1). Did the X11 server die?
terminate called without an active exception
src/CMakeFiles/test_images.dir/build.make:57: recipe for target 'src/CMakeFiles/test_images' failed
make[3]: *** [src/CMakeFiles/test_images] Error 255
CMakeFiles/Makefile2:1950: recipe for target 'src/CMakeFiles/test_images.dir/all' failed
make[2]: *** [src/CMakeFiles/test_images.dir/all] Error 2
CMakeFiles/Makefile2:2136: recipe for target 'src/CMakeFiles/compare_images.dir/rule' failed
make[1]: *** [src/CMakeFiles/compare_images.dir/rule] Error 2
Makefile:828: recipe for target 'compare_images' failed
make: *** [compare_images] Error 2
The command "$TRAVIS_BUILD_DIR/.travis/script-$TRAVIS_OS_NAME.sh" exited with 2.
lnihlen commented 4 years ago

Also seen in another log:

[1589326898.862] 3312 [error] Vulkan : Validation error : [ UNASSIGNED-Threading-MultipleThreads ] Object 0: handle = 0x6269300000000015, type = VK_OBJECT_TYPE_COMMAND_POOL; | MessageID = 0x141cb623 | THREADING ERROR : vkFreeCommandBuffers(): object of type VkCommandPool is simultaneously used in thread 0x8cc and thread 0xcf0 [C:\Users\travis\build\ScintillatorSynth\Scintillator\build\src\test_images.vcxproj]
lnihlen commented 4 years ago 
[1589477243.183] 11609 [info] Screenshot finished encode of '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/params/paramParab_0.png', valid: true
[1589477243.184] 11609 [info] got callback from advanceFrame
queing screenShot at /home/travis/build/ScintillatorSynth/Scintillator/build/testing/params/paramParab_1.png
[1589477243.184] 11626 [info] Encoder chose output format name 'image2', codec name 'png' for file '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/params/paramParab_1.png', mime type 'image/png'
[1589477243.184] 11626 [info] libav: [file @ 0x7f98d022c740] Setting default whitelist 'file,crypto,data'
[1589477243.184] 11626 [info] OSC ScreenShot '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/params/paramParab_1.png' enqueued for encode.
advancing frame by 1
[1589477243.204] 11609 [info] libav: [image2 @ 0x7f98d00cc6c0] Opening '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/params/paramParab_1.png' for writing
[1589477243.204] 11609 [info] libav: [file @ 0x55915c5a3580] Setting default whitelist 'file,crypto,data'
[1589477243.206] 11609 [info] libav: [AVIOContext @ 0x55915c5a3940] Statistics: 0 seeks, 1 writeouts
[1589477243.206] 11609 [info] libav: [AVIOContext @ 0x7f98d0225700] Statistics: 0 seeks, 0 writeouts
[1589477243.207] 11609 [info] Screenshot finished encode of '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/params/paramParab_1.png', valid: true
[1589477243.207] 11609 [info] got callback from advanceFrame
queing screenShot at /home/travis/build/ScintillatorSynth/Scintillator/build/testing/params/paramParab_2.png
[1589477243.208] 11626 [info] Encoder chose output format name 'image2', codec name 'png' for file '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/params/paramParab_2.png', mime type 'image/png'
advancing frame by 1
[1589477243.208] 11626 [info] libav: [file @ 0x7f98d022c740] Setting default whitelist 'file,crypto,data'
[1589477243.208] 11626 [info] OSC ScreenShot '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/params/paramParab_2.png' enqueued for encode.
Segmentation fault (core dumped)
RESULT = 139
*** scinsynth fatal error, code: 139
*** nonzero exit code nil on server, exiting.
*** SCRIPT FAILED ***
script failure caught, exiting.
The X11 connection broke (error 1). Did the X11 server die?
terminate called without an active exception
src/CMakeFiles/test_images.dir/build.make:57: recipe for target 'src/CMakeFiles/test_images' failed
lnihlen commented 4 years ago

125 found a race in the StageManager object that was exacerbated by staging audio every frame. This may not have been the only race, as it would only happen during image read, so may not be the fix. Keeping this bug open for now to see if we get further reproduction of the issue.

lnihlen commented 4 years ago

Unfortunately, it does not seem like #125 fixed it, this is a build log from that PR:

[1590520304.985] 11771 [warning] OSC ScinthNew got uneven pairs of control arguments, ignoring last pair.
[1590520304.986] 11771 [info] Scinth id 1033 from def complexImage cueued.
[1590520304.986] 11771 [info] Encoder chose output format name 'image2', codec name 'png' for file '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/images/complexImage_0.png', mime type 'image/png'
[1590520304.986] 11771 [info] libav: [file @ 0x7fd3946c0f80] Setting default whitelist 'file,crypto,data'
[1590520304.986] 11771 [info] OSC ScreenShot '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/images/complexImage_0.png' enqueued for encode.
[1590520304.988] 11754 [info] mean fps: 2.5
[1590520305.986] 11754 [info] libav: [image2 @ 0x7fd394342dc0] Opening '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/images/complexImage_0.png' for writing
[1590520305.986] 11754 [info] libav: [file @ 0x55c137370640] Setting default whitelist 'file,crypto,data'
[1590520305.988] 11754 [info] libav: [AVIOContext @ 0x55c137378e00] Statistics: 0 seeks, 2 writeouts
[1590520305.988] 11754 [info] libav: [AVIOContext @ 0x7fd3946c1140] Statistics: 0 seeks, 0 writeouts
[1590520305.988] 11754 [info] Screenshot finished encode of '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/images/complexImage_0.png', valid: true
queing screenShot at /home/travis/build/ScintillatorSynth/Scintillator/build/testing/images/complexImage_1.png
[1590520305.989] 11771 [info] Encoder chose output format name 'image2', codec name 'png' for file '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/images/complexImage_1.png', mime type 'image/png'
advancing frame by 1
[1590520305.990] 11771 [info] libav: [file @ 0x7fd3943432c0] Setting default whitelist 'file,crypto,data'
[1590520305.990] 11771 [info] OSC ScreenShot '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/images/complexImage_1.png' enqueued for encode.
[1590520305.989] 11754 [info] got callback from advanceFrame
Segmentation fault (core dumped)
RESULT = 139
*** scinsynth fatal error, code: 139
*** nonzero exit code nil on server, exiting.
*** SCRIPT FAILED ***
script failure caught, exiting.
lnihlen commented 4 years ago

Linux release testing again:

advancing frame by 1
[1594594551.308] 11727 [info] OSC ScreenShot '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_1.png' enqueued for encode.
[1594594551.326] 11710 [info] libav: [image2 @ 0x7f05f800d540] Opening '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_1.png' for writing
[1594594551.327] 11710 [info] libav: [file @ 0x5563fe0ef380] Setting default whitelist 'file,crypto,data'
[1594594551.327] 11710 [info] libav: [AVIOContext @ 0x5563fe0fd900] Statistics: 0 seeks, 1 writeouts
[1594594551.327] 11710 [info] libav: [AVIOContext @ 0x7f05f80c9400] Statistics: 0 seeks, 0 writeouts
[1594594551.328] 11710 [info] Screenshot finished encode of '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_1.png', valid: true
[1594594551.328] 11710 [info] got callback from advanceFrame
queing screenShot at /home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_2.png
advancing frame by 1
[1594594551.329] 11727 [info] Encoder chose output format name 'image2', codec name 'png' for file '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_2.png', mime type 'image/png'
[1594594551.329] 11727 [info] libav: [file @ 0x7f05f80cd800] Setting default whitelist 'file,crypto,data'
[1594594551.329] 11727 [info] OSC ScreenShot '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_2.png' enqueued for encode.
[1594594551.352] 11710 [info] libav: [image2 @ 0x7f05f8094c80] Opening '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_2.png' for writing
[1594594551.352] 11710 [info] libav: [file @ 0x5563fe0ee380] Setting default whitelist 'file,crypto,data'
[1594594551.353] 11710 [info] libav: [AVIOContext @ 0x5563fe0e4840] Statistics: 0 seeks, 1 writeouts
[1594594551.353] 11710 [info] libav: [AVIOContext @ 0x7f05f80cda00] Statistics: 0 seeks, 0 writeouts
[1594594551.353] 11710 [info] Screenshot finished encode of '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_2.png', valid: true
[1594594551.354] 11710 [info] got callback from advanceFrame
queing screenShot at /home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_3.png
advancing frame by 1
[1594594551.354] 11727 [info] Encoder chose output format name 'image2', codec name 'png' for file '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_3.png', mime type 'image/png'
[1594594551.354] 11727 [info] libav: [file @ 0x7f05f80d1d40] Setting default whitelist 'file,crypto,data'
[1594594551.354] 11727 [info] OSC ScreenShot '/home/travis/build/ScintillatorSynth/Scintillator/build/testing/VOsc/scinOsc_3.png' enqueued for encode.
Segmentation fault (core dumped)
RESULT = 139
*** scinsynth fatal error, code: 139
*** nonzero exit code nil on server, exiting.
*** SCRIPT FAILED ***
script failure caught, exiting.
The X11 connection broke (error 1). Did the X11 server die?
terminate called without an active exception
src/CMakeFiles/test_images.dir/build.make:57: recipe for target 'src/CMakeFiles/test_images' failed
make[3]: *** [src/CMakeFiles/test_images] Error 255
CMakeFiles/Makefile2:2008: recipe for target 'src/CMakeFiles/test_images.dir/all' failed
make[2]: *** [src/CMakeFiles/test_images.dir/all] Error 2
CMakeFiles/Makefile2:2195: recipe for target 'src/CMakeFiles/compare_images.dir/rule' failed
make[1]: *** [src/CMakeFiles/compare_images.dir/rule] Error 2
Makefile:841: recipe for target 'compare_images' failed
make: *** [compare_images] Error 2
The command "$TRAVIS_BUILD_DIR/.travis/script-$TRAVIS_OS_NAME.sh" exited with 2.
lnihlen commented 4 years ago

Thanks to #137 we have this callstack:

Thread 0 (crashed)
 0  scinsynth!std::_Function_handler<void (unsigned long), scin::osc::commands::AdvanceFrame::processMessage(int, lo_arg**, char const*, void*)::{lambda(unsigned long)#1}>::_M_invoke(std::_Any_data const&, unsigned long&&) + 0x97
    rax = 0x0000000000000001   rdx = 0x0000000000000000
    rcx = 0x00007f05d53bf870   rbx = 0x0000558aab445a40
    rsi = 0x0000558aaa4e88f8   rdi = 0x00007f059c0d44d0
    rbp = 0x00007f059c0d44d0   rsp = 0x00007ffc7da4a300
     r8 = 0x0000000000000001    r9 = 0x0000558aab445530
    r10 = 0x0000000000000019   r11 = 0x00007f05d54b7550
    r12 = 0x0000000000000000   r13 = 0x00007ffc7da4a330
    r14 = 0x0000558aab28afd0   r15 = 0x0000000000000002
    rip = 0x0000558aa9ef3337
    Found by: given as instruction pointer in context
 1  scinsynth!scin::comp::Offscreen::threadMain(std::shared_ptr<scin::comp::Compositor>) + 0x999
    rbx = 0x0000558aab28ae80   rbp = 0x00007ffc7da4a720
    rsp = 0x00007ffc7da4a3d0   r12 = 0x00007f059c093010
    r13 = 0x0000558aab28ae90   r14 = 0x0000558aab28afd0
    r15 = 0x0000000000000002   rip = 0x0000558aa9ed0f29
    Found by: call frame info
 2  scinsynth!scin::comp::Offscreen::run(std::shared_ptr<scin::comp::Compositor>) + 0x5b
    rbx = 0x0000558aab28ae80   rbp = 0x00007ffc7da4a970
    rsp = 0x00007ffc7da4a730   r12 = 0x0000558aab28ae80
    r13 = 0x0000000000000000   r14 = 0x00007ffc7da4a970
    r15 = 0x00007ffc7da4aa00   rip = 0x0000558aa9ed18cb
    Found by: call frame info
 3  scinsynth!main + 0x1dda
    rbx = 0x00007ffc7da4abb0   rbp = 0x00007ffc7da4b030
    rsp = 0x00007ffc7da4a770   r12 = 0x0000558aab28ae80
    r13 = 0x0000000000000000   r14 = 0x00007ffc7da4a970
    r15 = 0x00007ffc7da4aa00   rip = 0x0000558aa9e998ba
    Found by: call frame info
 4  libc.so.6 + 0x21b97
    rbx = 0x0000000000000000   rbp = 0x0000558aaa4e2990
    rsp = 0x00007ffc7da4b040   r12 = 0x0000558aa9e9dad0
    r13 = 0x00007ffc7da4b110   r14 = 0x0000000000000000
    r15 = 0x0000000000000000   rip = 0x00007f05d5329b97
    Found by: call frame info
 5  scinsynth!fmt::v6::basic_format_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char>::on_error(char const*) [clone .isra.85] + 0x10
    rsp = 0x00007ffc7da4b060   rip = 0x0000558aa9e97ae0
    Found by: stack scanning
 6  scinsynth!_GLOBAL__sub_I__ZN4YAML3Exp8ParseHexERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKNS_4MarkE + 0x30
    rsp = 0x00007ffc7da4b078   rip = 0x0000558aa9e9dad0
    Found by: stack scanning
 7  ld-linux-x86-64.so.2 + 0x10733
    rsp = 0x00007ffc7da4b0c0   rip = 0x00007f05d9125733
    Found by: stack scanning
 8  libvulkan.so.1 + 0x25bc90
    rsp = 0x00007ffc7da4b0c8   rip = 0x00007f05d910bc90
    Found by: stack scanning
 9  libpthread.so.0 + 0x219bb0
    rsp = 0x00007ffc7da4b0d0   rip = 0x00007f05d5eb3bb0
    Found by: stack scanning
10  scinsynth!_GLOBAL__sub_I__ZN4YAML3Exp8ParseHexERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKNS_4MarkE + 0x30
    rsp = 0x00007ffc7da4b0f0   rip = 0x0000558aa9e9dad0
    Found by: stack scanning
11  scinsynth!_start + 0x2a
    rsp = 0x00007ffc7da4b100   rip = 0x0000558aa9e9dafa
    Found by: stack scanning
12  0x7ffc7da4b108
    rsp = 0x00007ffc7da4b108   rip = 0x00007ffc7da4b108
    Found by: call frame info
lnihlen commented 4 years ago

this code is suspect, in Offscreen.cpp:

if (flushCallback) {
  m_flushCallback()
}

That's access to a callback that's protected by a mutex. And the if condition is "iffy", will always evaluate to true I think.

lnihlen commented 4 years ago

Assuming this is fixed in #137. Will re-open if issue recurs.