Skip to content
This repository has been archived by the owner on Nov 15, 2023. It is now read-only.

Intermittent crash while encoding images #115

Closed
lnihlen opened this issue May 8, 2020 · 8 comments
Closed

Intermittent crash while encoding images #115

lnihlen opened this issue May 8, 2020 · 8 comments

Comments

@lnihlen
Copy link
Member

lnihlen commented May 8, 2020

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
Copy link
Member Author

lnihlen commented May 13, 2020 •
edited

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
Copy link
Member Author

lnihlen commented May 14, 2020 

[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
Copy link
Member Author

lnihlen commented May 26, 2020

#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
Copy link
Member Author

lnihlen commented May 26, 2020

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
Copy link
Member Author

lnihlen commented Jul 12, 2020

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 lnihlen mentioned this issue Jul 21, 2020
Merged
3 tasks
@lnihlen
Copy link
Member Author

lnihlen commented Jul 23, 2020

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
Copy link
Member Author

lnihlen commented Jul 23, 2020

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 added a commit to lnihlen/Scintillator that referenced this issue Jul 23, 2020
@lnihlen
fix osx build and hopefully crash ScintillatorSynth#115
d5274e7
@lnihlen
Copy link
Member Author

lnihlen commented Jul 23, 2020

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

@lnihlen lnihlen closed this as completed Jul 23, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@lnihlen