Hello,
after trying many workarounds I still get a strange bug using video_decode on my drone project using a rPi3. Because of the data transmission method I use, the decoder is oftenly fed with corrupted data, most of the time the result is just a choppy image, but for no apparent reason the decoder stops triggering EmptyBufferDone event.
Here is the code (workarounds I tried are still present) : https://github.com/dridri/OpenMaxIL-cpp ... e.cpp#L110 (fillInput() is called as soon as new data, containing a complete frame, is received)
Is there any way to enable verbose debug in IL and vcos ? 'vcdbg log msg' shows nothing about the problem when it occurs, nor 'dmesg'. I would like to enable every possible verbose loggings as the bug is really hard to reproduce.
-
6by9
- Raspberry Pi Engineer & Forum Moderator
- Posts: 6428
- Joined: Wed Dec 04, 2013 11:27 am
- Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.
Re: video_decode stalls when fed with corrupted data
You appear to be missing any code that sucks the data out of the decoder and does something with it.
The most likely reason for EmptyThisBuffer not resulting in EmptyBufferDone is that the internal FIFO of the codec is full so it can't process any more data. That would most likely be because you haven't serviced the output port in a timely manner - the codec will not drop frames so will just wait for output buffers. Most often I see that when people have assumed one buffer in, one buffer out, but that can easily be a false assumption (even the hello_encode example is making that assumption - ought to fix it at some point!). Are you actually framing the data before feeding it to the codec, or just feeding in a raw bitstream?
First suggestion is to add "start_debug=1" to /boot/config.txt. That should then enable asserts on the GPU, and you can read those with "sudo vcdbg log assert".
Codec logging is at two levels. "vcgencmd set_logging level=0xc0" is the verbose IL level. The codec is more likely to throw asserts than anything usable in the logging to those without firmware source, but "level=0xc" would turn on the codec logging instead. Be a little cautious in turning all logging on - it's logging to a circular buffer, so the useful information can get overwritten pretty fast if you turn on too much.
The most likely reason for EmptyThisBuffer not resulting in EmptyBufferDone is that the internal FIFO of the codec is full so it can't process any more data. That would most likely be because you haven't serviced the output port in a timely manner - the codec will not drop frames so will just wait for output buffers. Most often I see that when people have assumed one buffer in, one buffer out, but that can easily be a false assumption (even the hello_encode example is making that assumption - ought to fix it at some point!). Are you actually framing the data before feeding it to the codec, or just feeding in a raw bitstream?
First suggestion is to add "start_debug=1" to /boot/config.txt. That should then enable asserts on the GPU, and you can read those with "sudo vcdbg log assert".
Codec logging is at two levels. "vcgencmd set_logging level=0xc0" is the verbose IL level. The codec is more likely to throw asserts than anything usable in the logging to those without firmware source, but "level=0xc" would turn on the codec logging instead. Be a little cautious in turning all logging on - it's logging to a circular buffer, so the useful information can get overwritten pretty fast if you turn on too much.
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.
I'm not interested in doing contracts for bespoke functionality - please don't ask.
Re: video_decode stalls when fed with corrupted data
The output is directly tunneled into a video_render component, and it doesn't look like to be a FIFO overhead because there is no increase in the output latency (I suppose there should be lag if the buffer queue is full, no?). And yes, each time EmptyThisBuffer() is called, the buffer contains exactly one encoded frame (you can find the video_encode settings in the same repo in VideoEncode.cpp file).
Thank you for explaining debugging levels, I will give it a try
Thank you for explaining debugging levels, I will give it a try
Re: video_decode stalls when fed with corrupted data
Looks like there is some kind of deadlock when looking at threads' backtraces (and as you can see most of the stack frames are broken) :
/opt/vc/bin/vcdbg log assert -f
/opt/vc/bin/vcdbg log msg -f
If you see anything relevant that can help me...
Edit: I just discovered that the top-right low power icon (yellow lightning) is continuously displayed (was hidden by HDMI overscan), can it be the cause of all of this ?
EDIT 2 : Okay I have a different bug now, my thread is not blocked, but the video_render frame is freezed (it seems that the video_decode does not output anything)
log msg is tatally different, :
Don't know if another backtrace can help :
Code: Select all
Thread 12 (Thread 0x705ff450 (LWP 524)):
#0 0x76cfa518 in do_futex_wait.constprop () from /lib/libpthread.so.0
#1 0x76cfa64c in __new_sem_wait_slow.constprop.0 () from /lib/libpthread.so.0
Cannot access memory at address 0x0
#2 0x769b307c in ?? () from /lib/libvcilcs.so
Cannot access memory at address 0x0
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 11 (Thread 0x71607450 (LWP 523)):
#0 0x76cfa518 in do_futex_wait.constprop () from /lib/libpthread.so.0
#1 0x76cfa64c in __new_sem_wait_slow.constprop.0 () from /lib/libpthread.so.0
#2 0x76d5abd0 in vchiu_queue_pop () from /lib/libvchiq_arm.so
Cannot access memory at address 0x54
#3 0x769b3530 in ?? () from /lib/libvcilcs.so
Cannot access memory at address 0x54
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 10 (Thread 0x71e07450 (LWP 522)):
#0 0x76cf80b4 in pthread_cond_wait@@GLIBC_2.4 () from /lib/libpthread.so.0
#1 0x76d66e6c in ?? () from /lib/libvcos.so
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 9 (Thread 0x72cf4450 (LWP 521)):
#0 0x76a74990 in nanosleep () from /lib/libc.so.6
#1 0x72cf4910 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 8 (Thread 0x734f4450 (LWP 520)):
#0 0x76cfa518 in do_futex_wait.constprop () from /lib/libpthread.so.0
#1 0x76cfa64c in __new_sem_wait_slow.constprop.0 () from /lib/libpthread.so.0
#2 0x76d8d3ec in eglSwapBuffers () from /lib/libEGL.so
#3 0x76fc1340 in GE::BaseWindow::SwapBuffersBase (this=0x72300e58) at /home/drich/projects/GammaEngine/src/egl/BaseWindow.cpp:160
#4 0x745b74b0 in OpenGLES20Window::SwapBuffers (this=0x72300e50)
at /home/drich/projects/GammaEngine/backends/opengles20/src/OpenGLES20Window.cpp:146
#5 0x0005a2b0 in Stream::run (this=0x1616a0) at /home/drich/projects/BCFlight/controller_rpi/Stream.cpp:185
#6 0x00092494 in Thread::ThreadEntry (this=0x1616a0) at /home/drich/projects/BCFlight/libcontroller/Thread.cpp:121
#7 0x76cf1e1c in start_thread () from /lib/libpthread.so.0
#8 0x76aa7e60 in ?? () from /lib/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 7 (Thread 0x73cf4450 (LWP 519)):
Cannot access memory at address 0x1
#0 0x76a9ea80 in poll () from /lib/libc.so.6
#1 0x73cf4910 in ?? ()
Cannot access memory at address 0x1
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 5 (Thread 0x74fff450 (LWP 517)):
#0 0x76cfa518 in do_futex_wait.constprop () from /lib/libpthread.so.0
#1 0x76cfa64c in __new_sem_wait_slow.constprop.0 () from /lib/libpthread.so.0
Cannot access memory at address 0xbcCode: Select all
1730622.085: assert( h ) failed; ../../../../../vcfw/rtos/common/rtos_common_mem.c::mem_unlock line 5149
1730622.134: assert( is_aligned_32(g_mgr.handles[handle].header) ) failed; ../../../../../vcfw/rtos/common/rtos_common_mem.c::get_header line 872
1730622.173: assert( pPrivate->allocator->valid(h, buffer->nAllocLen) ) failed; ../../../../../middleware/openmaxil/core/ril_top.c::process_ril_buffer line 2252
1730622.225: assert( is_aligned_32(g_mgr.handles[handle].header) ) failed; ../../../../../vcfw/rtos/common/rtos_common_mem.c::get_header line 872
1730622.269: assert( pPrivate->allocator->lock_count((RIL_MEM_HANDLE_T)buffer->pBuffer) == 0 ) failed; ../../../../../middleware/openmaxil/core/ril_top.c::process_ril_buffer line 2255
1730622.335: assert( is_aligned_32(g_mgr.handles[handle].header) ) failed; ../../../../../vcfw/rtos/common/rtos_common_mem.c::get_header line 872
1730640.165: assert( is_aligned_32(g_mgr.handles[handle].header) ) failed; ../../../../../vcfw/rtos/common/rtos_common_mem.c::get_header line 872
1730640.278: assert( h ) failed; ../../../../../vcfw/rtos/common/rtos_common_mem.c::lock_big_internal line 4856
1730640.337: assert( h && h->ref_count != 0 ) failed; ../../../../../vcfw/rtos/common/rtos_common_mem.c::lock_big_internal line 4857
1730640.421: assert( is_aligned_32(g_mgr.handles[handle].header) ) failed; ../../../../../vcfw/rtos/common/rtos_common_mem.c::get_header line 872
1730640.498: assert( h ) failed; ../../../../../vcfw/rtos/common/rtos_common_mem.c::lock_big_internal line 4856
1730640.614: assert( h && h->ref_count != 0 ) failed; ../../../../../vcfw/rtos/common/rtos_common_mem.c::lock_big_internal line 4857Code: Select all
[......]
1730592.475: video_decode:24:EmptyThisBuffer(3e730480,11207,0->130)
1730592.498: video_decode:24: queueBuffer (input : 11207)
1730592.515: video_decode:24:qb RIL:2
1730592.559: video_decode:24:RIL: extract from fifo: len:11207 flags:118 time:0
1730592.594: video_decode:24:RIL: decoding 11207 bytes, 0us, flags 118, (cb:0x3e7c1400)
1730592.620: video_decode:24:RIL: asking for more
1730592.822: video_decode:24:cb:consumed_input_buffer(3e730480,0b,0f) RIL:2
1730600.261: video_decode:24:RIL:cb:entered with buffer = 0x3e7c9d50, frame_info = 0x3e7d9564, status = 0, cb= 0x3e7c1400
1730600.284: video_decode:24:RIL:cb:next_frame_time:0
1730600.357: video_decode:24:RIL:cb:IDR time:0, cb:0x3e7c1400, ar:0/0, crop:0x0 1024x576, interval:16666666, interlace:0,0,0
1730600.411: video_decode:24:RIL:output dec_frames_full:3e7c3770 out:0
1730600.460: decode: display frame 3e7c9d50 T=0 sts=0
1730600.486: video_render:25:RIL:display_image 3e7c9d50 state 4
1730600.571: video_render:25:RIL: update arrived, dst 912 x 914
1730600.609: video_render:25:RIL: cb:0 tx:-1 cb=[img:3e7c9d10 t:-1] inuse=[10]
1730600.672: video_render:25:RIL: doing update on dn:0 img:3e7c9d50,other fs:0 tx:2 1024x576-(24x83)912x914
1730600.849: video_render:25:RIL:return omx buffers:free 0
1730600.879: video_render:27:RIL:display_image 3e7c9d50 state 4
1730600.953: video_render:27:RIL: update arrived, dst 912 x 914
1730600.991: video_render:27:RIL: cb:0 tx:-1 cb=[img:3e7c9d10 t:-1] inuse=[10]
1730601.051: video_render:27:RIL: doing update on dn:0 img:3e7c9d50,other fs:0 tx:2 1024x576-(984x83)912x914
1730601.208: video_render:27:RIL:return omx buffers:free 0
1730601.245: video_decode:24:RIL: disp_cb passed 3e7c9d50/0/0x118
1730605.496: video_decode:24:EmptyThisBuffer(3e730480,2821,0->130)
1730605.515: video_decode:24: queueBuffer (input : 2821)
1730605.528: video_decode:24:qb RIL:2
1730605.567: video_decode:24:RIL: extract from fifo: len:2821 flags:118 time:0
1730605.600: video_decode:24:RIL: decoding 2821 bytes, 0us, flags 118, (cb:0x3e7c1cf8)
1730605.624: video_decode:24:RIL: asking for more
1730605.738: video_decode:24:cb:consumed_input_buffer(3e730480,0b,0f) RIL:2
1730606.188: video_render:25:RIL:cb:freeing cb:0 b:3e7c9d10 t:-1
1730606.204: video_render:25:RIL:cb:sending 3e7c9d10 to disp queue
1730606.229: video_render:25:RIL:cb:use=[00]
1730606.258: video_render:27:RIL:cb:freeing cb:0 b:3e7c9d10 t:-1
1730606.278: video_render:27:RIL:cb:sending 3e7c9d10 to disp queue
1730606.297: video_render:27:RIL:cb:use=[00]
1730606.329: video_render:25:RIL:release_images:releasing 3e7c9d10
1730606.350: video_render:25:RIL:return omx buffers:free 0
1730606.379: video_render:27:RIL:release_images:releasing 3e7c9d10
1730606.412: video_render:27:RIL:return omx buffers:free 0
1730611.861: video_decode:24:RIL:cb:entered with buffer = 0x3e7c9d90, frame_info = 0x3e7d9564, status = 0, cb= 0x3e7c1cf8
1730611.878: video_decode:24:RIL:cb:next_frame_time:0
1730611.949: video_decode:24:RIL:cb:P time:0, cb:0x3e7c1cf8, ar:0/0, crop:0x0 1024x576, interval:16666666, interlace:0,0,0
1730611.997: video_decode:24:RIL:output dec_frames_full:3e7c37e4 out:0
1730612.048: decode: display frame 3e7c9d90 T=0 sts=0
1730612.074: video_render:25:RIL:display_image 3e7c9d90 state 4
1730612.156: video_render:25:RIL: update arrived, dst 912 x 914
1730612.191: video_render:25:RIL: cb:0 tx:-1 cb=[img:3e7c9d50 t:-1] inuse=[10]
1730612.254: video_render:25:RIL: doing update on dn:0 img:3e7c9d90,other fs:0 tx:2 1024x576-(24x83)912x914
1730612.438: video_render:25:RIL:return omx buffers:free 0
1730612.470: video_render:27:RIL:display_image 3e7c9d90 state 4
1730612.543: video_render:27:RIL: update arrived, dst 912 x 914
1730612.581: video_render:27:RIL: cb:0 tx:-1 cb=[img:3e7c9d50 t:-1] inuse=[10]
1730612.637: video_render:27:RIL: doing update on dn:0 img:3e7c9d90,other fs:0 tx:2 1024x576-(984x83)912x914
1730612.792: video_render:27:RIL:return omx buffers:free 0
1730612.825: video_decode:24:RIL: disp_cb passed 3e7c9d90/0/0x118
1730617.391: video_decode:24:EmptyThisBuffer(3e730480,1734,0->130)
1730617.413: video_decode:24: queueBuffer (input : 1734)
1730617.425: video_decode:24:qb RIL:2
1730617.468: video_decode:24:RIL: extract from fifo: len:1734 flags:118 time:0
1730617.501: video_decode:24:RIL: decoding 1734 bytes, 0us, flags 118, (cb:0x3e7c1b54)
1730617.573: video_decode:24:RIL: asking for more
1730619.032: video_decode:24:EmptyThisBuffer(3e730480,0,0->130)
1730619.214: video_decode:24: queueBuffer (input : 0)
1730619.280: video_decode:24:saveBuffer(130,3e730480) Held:1
1730619.328: video_decode:24:cb:consumed_input_buffer(3e730480,0b,0f) RIL:2
1730620.371: video_decode:24:EmptyThisBuffer(3e730480,9,0->130)
1730620.420: video_decode:24: queueBuffer (input : 9)
1730620.445: video_decode:24:qb RIL:2
1730620.507: video_decode:24:RIL: extract from fifo: len:9 flags:118 time:0
1730620.550: video_decode:24:RIL: decoding 9 bytes, 0us, flags 118, (cb:0x3e7c1898)
1730620.589: video_decode:24:RIL: asking for more
1730620.673: video_decode:24:timer retry on 130
1730620.742: video_decode:24:sendBuffers(130):3e730480 9/118
1730621.018: video_decode:24:RIL: extract from fifo: len:9 flags:118 time:0
1730621.078: video_decode:24:RIL: decoding 9 bytes, 0us, flags 118, (cb:0x3e7c1780)
1730621.119: video_decode:24:RIL: asking for more
1730621.413: video_decode:24:cb:consumed_input_buffer(3e730480,0b,0f) RIL:3
1730622.407: video_decode:24:cb:consumed_input_buffer(3e730480,0b,0f) RIL:2
1730622.848: video_render:25:RIL:cb:freeing cb:0 b:3e7c9d50 t:-1
1730622.868: video_render:25:RIL:cb:sending 3e7c9d50 to disp queue
1730622.894: video_render:25:RIL:cb:use=[00]
1730622.924: video_render:27:RIL:cb:freeing cb:0 b:3e7c9d50 t:-1
1730622.939: video_render:27:RIL:cb:sending 3e7c9d50 to disp queue
1730622.964: video_render:27:RIL:cb:use=[00]
1730622.996: video_render:25:RIL:release_images:releasing 3e7c9d50
1730623.019: video_render:25:RIL:return omx buffers:free 0
1730623.047: video_render:27:RIL:release_images:releasing 3e7c9d50
1730623.082: video_render:27:RIL:return omx buffers:free 0
1730626.638: video_decode:24:RIL:cb:entered with buffer = 0x3e7c9d10, frame_info = 0x3e7d9564, status = 0, cb= 0x3e7c1b54
1730626.662: video_decode:24:RIL:cb:next_frame_time:0
1730626.733: video_decode:24:RIL:cb:P time:0, cb:0x3e7c1b54, ar:0/0, crop:0x0 1024x576, interval:16666666, interlace:0,0,0
1730626.788: video_decode:24:RIL:output dec_frames_full:3e7c3858 out:0
1730626.842: decode: display frame 3e7c9d10 T=0 sts=0
1730626.869: video_render:25:RIL:display_image 3e7c9d10 state 4
1730626.955: video_render:25:RIL: update arrived, dst 912 x 914
1730626.998: video_render:25:RIL: cb:0 tx:-1 cb=[img:3e7c9d90 t:-1] inuse=[10]
1730627.057: video_render:25:RIL: doing update on dn:0 img:3e7c9d10,other fs:0 tx:2 1024x576-(24x83)912x914
1730627.231: video_render:25:RIL:return omx buffers:free 0
1730627.261: video_render:27:RIL:display_image 3e7c9d10 state 4
1730627.341: video_render:27:RIL: update arrived, dst 912 x 914
1730627.377: video_render:27:RIL: cb:0 tx:-1 cb=[img:3e7c9d90 t:-1] inuse=[10]
1730627.435: video_render:27:RIL: doing update on dn:0 img:3e7c9d10,other fs:0 tx:2 1024x576-(984x83)912x914
1730627.591: video_render:27:RIL:return omx buffers:free 0
1730627.623: video_decode:24:RIL: disp_cb passed 3e7c9d10/0/0x118
1730639.527: video_render:25:RIL:cb:freeing cb:0 b:3e7c9d90 t:-1
1730639.543: video_render:25:RIL:cb:sending 3e7c9d90 to disp queue
1730639.568: video_render:25:RIL:cb:use=[00]
1730639.603: video_render:27:RIL:cb:freeing cb:0 b:3e7c9d90 t:-1
1730639.632: video_render:27:RIL:cb:sending 3e7c9d90 to disp queue
1730639.664: video_render:27:RIL:cb:use=[00]
1730639.720: video_render:25:RIL:release_images:releasing 3e7c9d90
1730639.758: video_render:25:RIL:return omx buffers:free 0
1730639.793: video_render:27:RIL:release_images:releasing 3e7c9d90
1730639.836: video_render:27:RIL:return omx buffers:free 0Edit: I just discovered that the top-right low power icon (yellow lightning) is continuously displayed (was hidden by HDMI overscan), can it be the cause of all of this ?
EDIT 2 : Okay I have a different bug now, my thread is not blocked, but the video_render frame is freezed (it seems that the video_decode does not output anything)
log msg is tatally different, :
Code: Select all
2364351.320: video_decode:4:qb RIL:304001
2364351.355: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364369.618: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364374.961: video_decode:4:EmptyThisBuffer(3e7301a0,8400,0->130)
2364374.982: video_decode:4: queueBuffer (input : 8400)
2364375.003: video_decode:4:qb RIL:304002
2364375.039: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364378.635: video_decode:4:EmptyThisBuffer(3e7301a0,3763,0->130)
2364378.657: video_decode:4: queueBuffer (input : 3763)
2364378.674: video_decode:4:qb RIL:304003
2364378.707: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364389.602: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364397.856: video_decode:4:EmptyThisBuffer(3e7301a0,2800,0->130)
2364397.877: video_decode:4: queueBuffer (input : 2800)
2364397.895: video_decode:4:qb RIL:304004
2364397.928: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364400.232: video_decode:4:EmptyThisBuffer(3e7301a0,41,0->130)
2364400.252: video_decode:4: queueBuffer (input : 41)
2364400.269: video_decode:4:qb RIL:304005
2364400.302: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364400.680: video_decode:4:EmptyThisBuffer(3e7301a0,9,0->130)
2364400.699: video_decode:4: queueBuffer (input : 9)
2364400.713: video_decode:4:qb RIL:304006
2364400.745: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364414.058: video_decode:4:EmptyThisBuffer(3e7301a0,8520,0->130)
2364414.078: video_decode:4: queueBuffer (input : 8520)
2364414.095: video_decode:4:qb RIL:304007
2364414.135: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364426.468: video_decode:4:EmptyThisBuffer(3e7301a0,4908,0->130)
2364426.489: video_decode:4: queueBuffer (input : 4908)
2364426.507: video_decode:4:qb RIL:304008
2364426.540: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364438.510: video_decode:4:EmptyThisBuffer(3e7301a0,3165,0->130)
2364438.531: video_decode:4: queueBuffer (input : 3165)
2364438.547: video_decode:4:qb RIL:304009
2364438.580: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364439.006: video_decode:4:EmptyThisBuffer(3e7301a0,41,0->130)
2364439.026: video_decode:4: queueBuffer (input : 41)
2364439.060: video_decode:4:qb RIL:304010
2364439.096: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364449.617: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364452.594: video_decode:4:EmptyThisBuffer(3e7301a0,10137,0->130)
2364452.617: video_decode:4: queueBuffer (input : 10137)
2364452.633: video_decode:4:qb RIL:304011
2364452.668: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364465.255: video_decode:4:EmptyThisBuffer(3e7301a0,3544,0->130)
2364465.276: video_decode:4: queueBuffer (input : 3544)
2364465.293: video_decode:4:qb RIL:304012
2364465.326: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364477.118: video_decode:4:EmptyThisBuffer(3e7301a0,3201,0->130)
2364477.138: video_decode:4: queueBuffer (input : 3201)
2364477.156: video_decode:4:qb RIL:304013
2364477.189: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364477.872: video_decode:4:EmptyThisBuffer(3e7301a0,41,0->130)
2364477.891: video_decode:4: queueBuffer (input : 41)
2364477.907: video_decode:4:qb RIL:304014
2364477.940: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364478.352: video_decode:4:EmptyThisBuffer(3e7301a0,9,0->130)
2364478.372: video_decode:4: queueBuffer (input : 9)
2364478.388: video_decode:4:qb RIL:304015
2364478.421: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364489.601: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364491.878: video_decode:4:EmptyThisBuffer(3e7301a0,8631,0->130)
2364491.900: video_decode:4: queueBuffer (input : 8631)
2364491.916: video_decode:4:qb RIL:304016
2364491.951: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364504.754: video_decode:4:EmptyThisBuffer(3e7301a0,3817,0->130)
2364504.775: video_decode:4: queueBuffer (input : 3817)
2364504.793: video_decode:4:qb RIL:304017
2364504.834: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364517.279: video_decode:4:EmptyThisBuffer(3e7301a0,2648,0->130)
2364517.297: video_decode:4: queueBuffer (input : 2648)
2364517.315: video_decode:4:qb RIL:304018
2364517.351: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364518.336: video_decode:4:EmptyThisBuffer(3e7301a0,542,0->130)
2364518.357: video_decode:4: queueBuffer (input : 542)
2364518.372: video_decode:4:qb RIL:304019
2364518.406: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364518.834: video_decode:4:EmptyThisBuffer(3e7301a0,41,0->130)
2364518.853: video_decode:4: queueBuffer (input : 41)
2364518.873: video_decode:4:qb RIL:304020
2364518.906: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364519.317: video_decode:4:EmptyThisBuffer(3e7301a0,9,0->130)
2364519.335: video_decode:4: queueBuffer (input : 9)
2364519.349: video_decode:4:qb RIL:304021
2364519.383: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364529.605: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364532.885: video_decode:4:EmptyThisBuffer(3e7301a0,8616,0->130)
2364532.904: video_decode:4: queueBuffer (input : 8616)
2364532.921: video_decode:4:qb RIL:304022
2364532.953: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0
2364545.665: video_decode:4:EmptyThisBuffer(3e7301a0,5091,0->130)
2364545.684: video_decode:4: queueBuffer (input : 5091)
2364545.700: video_decode:4:qb RIL:304023
2364545.732: video_decode:4:RIL:output dec_frames_full:3e7c67fc out:0Code: Select all
Thread 12 (Thread 0x705ff450 (LWP 328)):
#0 0x76aa0bac in ioctl () from /lib/libc.so.6
#1 0x76d58cac in vchiq_queue_message () from /lib/libvchiq_arm.so
Cannot access memory at address 0x0
#2 0x769b3028 in ?? () from /lib/libvcilcs.so
Cannot access memory at address 0x0
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 11 (Thread 0x70fdb450 (LWP 327)):
#0 0x76cfa518 in do_futex_wait.constprop () from /lib/libpthread.so.0
#1 0x76cfa64c in __new_sem_wait_slow.constprop.0 () from /lib/libpthread.so.0
#2 0x76d5abd0 in vchiu_queue_pop () from /lib/libvchiq_arm.so
Cannot access memory at address 0x8
#3 0x769b3530 in ?? () from /lib/libvcilcs.so
Cannot access memory at address 0x8
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 10 (Thread 0x71bb4450 (LWP 326)):
#0 0x76cf80b4 in pthread_cond_wait@@GLIBC_2.4 () from /lib/libpthread.so.0
#1 0x76d66e6c in ?? () from /lib/libvcos.so
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 9 (Thread 0x72cf4450 (LWP 325)):
#0 0x76a74990 in nanosleep () from /lib/libc.so.6
#1 0x72cf4910 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 8 (Thread 0x734f4450 (LWP 324)):
#0 0x76a46d00 in ?? () from /lib/libc.so.6
#1 0x76c4c28c in std::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() () from /lib/libstdc++.so.6
#2 0x00000258 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 7 (Thread 0x73cf4450 (LWP 323)):
Cannot access memory at address 0x1
#0 0x76a9ea80 in poll () from /lib/libc.so.6
#1 0x73cf4910 in ?? ()
Cannot access memory at address 0x1
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 6 (Thread 0x744f4450 (LWP 322)):
#0 0x76a74990 in nanosleep () from /lib/libc.so.6
#1 0x744f4910 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Thread 5 (Thread 0x74fff450 (LWP 321)):
#0 0x76cfa518 in do_futex_wait.constprop () from /lib/libpthread.so.0
#1 0x76cfa64c in __new_sem_wait_slow.constprop.0 () from /lib/libpthread.so.0
Cannot access memory at address 0xbcCode: Select all
vcgencmd version
Nov 16 2016 12:27:23
Copyright (c) 2012 Broadcom
version 14ca844c69c2883572677a5cd7b02443eb653e4e (clean) (release)-
6by9
- Raspberry Pi Engineer & Forum Moderator
- Posts: 6428
- Joined: Wed Dec 04, 2013 11:27 am
- Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.
Re: video_decode stalls when fed with corrupted data
Low power isn't great. Typically the SoC itself will probably be happy enough (others have run their Pi on about 3V IIRC), but any USB peripherals are very likely to be getting unhappy.
Your first backtrace implies you're using OpenGLES - you hadn't mentioned that bit, and potentially may be affecting decode. It might be worth checking that you can reproduce the issue without GL in the mix, though I suspect it is a slightly deeper issue than that. The slew of asserts all match up with the end of the logging, so something has gone quite badly wrong in the buffer handling.
Is there any chance of you capturing one of the corrupt streams and posting it somewhere for analysis?
Your first backtrace implies you're using OpenGLES - you hadn't mentioned that bit, and potentially may be affecting decode. It might be worth checking that you can reproduce the issue without GL in the mix, though I suspect it is a slightly deeper issue than that. The slew of asserts all match up with the end of the logging, so something has gone quite badly wrong in the buffer handling.
Is there any chance of you capturing one of the corrupt streams and posting it somewhere for analysis?
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.
I'm not interested in doing contracts for bespoke functionality - please don't ask.
Re: video_decode stalls when fed with corrupted data
Yes I forgot to mention that there is an OpenGLES context running in another thread on one dispmanx layer above the video_render.
After disabling this GL thread (and all the others actually, letting only the decoder), the problem still remains. Each time, the "crash" has two possible results (but never both) :
- EmptyThisBuffer blocks and never returns (and the stack seems broken according to the stack traces)
- or the buffer's pBuffer pointer is completely messed, and contains a single-byte random value (I tried to store the initial pointer value then back it up in pBuffer when the value becomes broken, but it doesn't help). Then all the next calls to EmptyThisBuffer return 0x80001018
I can upload one of the streams, but I tried to play them using the exact same implementation (same code) but it ends normally without any crash..
I'm starting to think that my Pi just has got a severe problem somewhere else (considering that the "low-power" logo is visible, with a 6A power input..), I will give it a try with a brand new one.
Edit: is the MMAL implementation different enough from OMX one to expect it to bypass this bug ?
Edit2: just discovered that EmptyThisBuffer sometimes generate 0x80001009 (OMX_ErrorHardware), but with this one the decoder can continue working
Edit3(again): it looks like that totally reallocating the input buffer when pBuffer goes wrong does the trick, but I suppose that it will quickly bloat the VRAM even if I manually call vcos_free() on the allocated buffers that the decoder has lost..
After disabling this GL thread (and all the others actually, letting only the decoder), the problem still remains. Each time, the "crash" has two possible results (but never both) :
- EmptyThisBuffer blocks and never returns (and the stack seems broken according to the stack traces)
- or the buffer's pBuffer pointer is completely messed, and contains a single-byte random value (I tried to store the initial pointer value then back it up in pBuffer when the value becomes broken, but it doesn't help). Then all the next calls to EmptyThisBuffer return 0x80001018
I can upload one of the streams, but I tried to play them using the exact same implementation (same code) but it ends normally without any crash..
I'm starting to think that my Pi just has got a severe problem somewhere else (considering that the "low-power" logo is visible, with a 6A power input..), I will give it a try with a brand new one.
Edit: is the MMAL implementation different enough from OMX one to expect it to bypass this bug ?
Edit2: just discovered that EmptyThisBuffer sometimes generate 0x80001009 (OMX_ErrorHardware), but with this one the decoder can continue working
Edit3(again): it looks like that totally reallocating the input buffer when pBuffer goes wrong does the trick, but I suppose that it will quickly bloat the VRAM even if I manually call vcos_free() on the allocated buffers that the decoder has lost..
Re: video_decode stalls when fed with corrupted data
So, sorry about this whole topic as it was irrelevant. I found the cause of all of this somewhere else: it looks like the combo MAX / MMAL + GLES + FBdev was the source.
I'm using a SPI TFT screen as a second display, and writing to it using a mmap'ed framebuffer on / dev / fb1, and for an obscure reason writing to it randomly causes all the process threads to stall. I'm now using a single write() call to fill the fbdev, and all my problems are just gone.
I'm using a SPI TFT screen as a second display, and writing to it using a mmap'ed framebuffer on / dev / fb1, and for an obscure reason writing to it randomly causes all the process threads to stall. I'm now using a single write() call to fill the fbdev, and all my problems are just gone.