libimxvpuapi freezes with normal h264 decoding

[ttykkala]

I tested example/decode-example with given h264 test file (test-320x240.h264) and it seems to run but on third execuction time it fails.

Here's the log: ////////////////////////////////////////////////////////// /imxvpuapi/imxvpuapi_vpulib.c:1807 (imx_vpu_dec_decode) log: input info: 6214 byte ../imxvpuapi/imxvpuapi_vpulib.c:1846 (imx_vpu_dec_decode) log: pushing main frame data with 6214 byte ../imxvpuapi/imxvpuapi_vpulib.c:1691 (imx_vpu_dec_push_input_data) log: bitstream buffer status: read ptr 0x44c37090 write ptr 0x44c37093 num free bytes 3143676 ../imxvpuapi/imxvpuapi_vpulib.c:2063 (imx_vpu_dec_decode) log: waiting for decoding completion ../imxvpuapi/imxvpuapi_vpulib.c:2072 (imx_vpu_dec_decode) info: timeout after waiting 500 ms for frame completion ../imxvpuapi/imxvpuapi_vpulib.c:2072 (imx_vpu_dec_decode) info: timeout after waiting 500 ms for frame completion ../imxvpuapi/imxvpuapi_vpulib.c:2072 (imx_vpu_dec_decode) info: timeout after waiting 500 ms for frame completion ../imxvpuapi/imxvpuapi_vpulib.c:2072 (imx_vpu_dec_decode) info: timeout after waiting 500 ms for frame completion [ERR] fatal: VPU is busy in vpu_DecGetOutputInfo imx_vpu_dec_decode() failed: timeout ../imxvpuapi/imxvpuapi_vpulib.c:1104 (imx_vpu_dec_close) debug: closing decoder ////////////////////////////////////////////////////////////

Should the provided example work normally with any number of execution times? My goal is to decode h264 video on VPU.

The best, Tommi

[dv1]

Yes, this should work no matter how often it is executed. Check out https://github.com/Freescale/gstreamer-imx/blob/master/docs/faq.md#vpu-operation-freezes-and-vpu-blocking-timeout-messages-appear . Also let me know your platform, your kernel version, and your imx-vpu version.

[ttykkala]

Kernel version is 4.1.15:

Linux 10:0d:32:01:7e:d1 4.1.15-224156-g141e464 #3 SMP PREEMPT Thu Apr 21 11:34:38 EEST 2016 armv7l GNU/Linux

Its a custom platform, Freescale NXP IMX6 Yocto 2.0 Release vpu firmware: 3.1, release 1, lib 5.4, librelease: 33

Normally, I have CONFIG_MX6_VPU_352M kernel parameter set On because the example gets stuck worse without it. But now I disabled it so here's some tests:

Without CONFIG_MX6_VPU_352M flag, I get stuck like this (firmware 5.4.33):

10:0d:32:01:5f:aa:~/tmp/example$ ./decode-example2 -i test-320x240.h264 -o raaka.raw ../imxvpuapi/imxvpuapi_vpulib.c:293 (imx_vpu_load) log: VPU init instance counter: 0 ../imxvpuapi/imxvpuapi_vpulib.c:302 (imx_vpu_load) info: libimxvpuapi version 0.10.1 vpulib backend ../imxvpuapi/imxvpuapi_vpulib.c:306 (imx_vpu_load) debug: loaded VPU ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 5236736 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x76742000 aligned: 0x76742000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x45200000 aligned: 0x45200000 ../imxvpuapi/imxvpuapi_vpulib.c:961 (imx_vpu_dec_open) debug: opening decoder ../imxvpuapi/imxvpuapi_vpulib.c:1063 (imx_vpu_dec_open) debug: opening decoder, frame size: 0 x 0 pixel [INFO] bitstreamMode 1, chromaInterleave 0, mapType 0, tiled2LinearEnable 0 ../imxvpuapi/imxvpuapi_vpulib.c:1077 (imx_vpu_dec_open) debug: successfully opened decoder encoded input frame: frame id: 0x64 size: 6466 byte ../imxvpuapi/imxvpuapi_vpulib.c:1800 (imx_vpu_dec_decode) log: input info: 6466 byte ../imxvpuapi/imxvpuapi_vpulib.c:1839 (imx_vpu_dec_decode) log: pushing main frame data with 6466 byte ../imxvpuapi/imxvpuapi_vpulib.c:1684 (imx_vpu_dec_push_input_data) log: bitstream buffer status: read ptr 0x45200000 write ptr 0x45200000 num free bytes 3143679

With firmware version 5.4.31 I get this kind of result:

10:0d:32:01:5f:aa:~/tmp/example$ ./decode-example2 -i test-320x240.h264 -o raaka.raw ../imxvpuapi/imxvpuapi_vpulib.c:293 (imx_vpu_load) log: VPU init instance counter: 0 ../imxvpuapi/imxvpuapi_vpulib.c:302 (imx_vpu_load) info: libimxvpuapi version 0.10.1 vpulib backend ../imxvpuapi/imxvpuapi_vpulib.c:306 (imx_vpu_load) debug: loaded VPU ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 5236736 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x76765000 aligned: 0x76765000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x45200000 aligned: 0x45200000 ../imxvpuapi/imxvpuapi_vpulib.c:961 (imx_vpu_dec_open) debug: opening decoder ../imxvpuapi/imxvpuapi_vpulib.c:1063 (imx_vpu_dec_open) debug: opening decoder, frame size: 0 x 0 pixel [INFO] bitstreamMode 1, chromaInterleave 0, mapType 0, tiled2LinearEnable 0 ../imxvpuapi/imxvpuapi_vpulib.c:1077 (imx_vpu_dec_open) debug: successfully opened decoder encoded input frame: frame id: 0x64 size: 6466 byte ../imxvpuapi/imxvpuapi_vpulib.c:1800 (imx_vpu_dec_decode) log: input info: 6466 byte ../imxvpuapi/imxvpuapi_vpulib.c:1839 (imx_vpu_dec_decode) log: pushing main frame data with 6466 byte ../imxvpuapi/imxvpuapi_vpulib.c:1684 (imx_vpu_dec_push_input_data) log: bitstream buffer status: read ptr 0x45200000 write ptr 0x45200000 num free bytes 3143679 initial info: size: 320x240 pixel rate: 2000000000/1 min num required framebuffers: 11 interlacing: 0 framebuffer alignment: 1 calculated sizes: frame width&height: 320x240 Y stride: 320 CbCr stride: 160 Y size: 76800 CbCr size: 19200 MvCol size: 19200 total size: 134401 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x76744000 aligned: 0x76744000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x457c0000 aligned: 0x457c0000 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x76723000 aligned: 0x76723000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x45800000 aligned: 0x45800000 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x76702000 aligned: 0x76702000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x45840000 aligned: 0x45840000 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x766e1000 aligned: 0x766e1000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x45880000 aligned: 0x45880000 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x766c0000 aligned: 0x766c0000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x458c0000 aligned: 0x458c0000 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x7669f000 aligned: 0x7669f000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x45900000 aligned: 0x45900000 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x7667e000 aligned: 0x7667e000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x45940000 aligned: 0x45940000 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x7665d000 aligned: 0x7665d000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x45980000 aligned: 0x45980000 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x7663c000 aligned: 0x7663c000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x459c0000 aligned: 0x459c0000 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x7661b000 aligned: 0x7661b000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x45a00000 aligned: 0x45a00000 ../imxvpuapi/imxvpuapi_vpulib.c:499 (default_dmabufalloc_allocate) debug: allocated 134401 bytes of physical memory ../imxvpuapi/imxvpuapi_vpulib.c:509 (default_dmabufalloc_allocate) debug: retrieved virtual address for physical memory ../imxvpuapi/imxvpuapi_vpulib.c:514 (default_dmabufalloc_allocate) debug: virtual address: 0x765fa000 aligned: 0x765fa000 ../imxvpuapi/imxvpuapi_vpulib.c:515 (default_dmabufalloc_allocate) debug: physical address: 0x45a40000 aligned: 0x45a40000 ../imxvpuapi/imxvpuapi_vpulib.c:1222 (imx_vpu_dec_register_framebuffers) debug: attempting to register 11 framebuffers ../imxvpuapi/imxvpuapi_vpulib.c:2055 (imx_vpu_dec_decode) log: waiting for decoding completion ../imxvpuapi/imxvpuapi_vpulib.c:2064 (imx_vpu_dec_decode) info: timeout after waiting 500 ms for frame completion ../imxvpuapi/imxvpuapi_vpulib.c:2064 (imx_vpu_dec_decode) info: timeout after waiting 500 ms for frame completion ../imxvpuapi/imxvpuapi_vpulib.c:2064 (imx_vpu_dec_decode) info: timeout after waiting 500 ms for frame completion ../imxvpuapi/imxvpuapi_vpulib.c:2064 (imx_vpu_dec_decode) info: timeout after waiting 500 ms for frame completion [ERR] fatal: VPU is busy in vpu_DecGetOutputInfo imx_vpu_dec_decode() failed: timeout ../imxvpuapi/imxvpuapi_vpulib.c:1097 (imx_vpu_dec_close) debug: closing decoder ^C

The best, Tommi

[ttykkala]

We found the reason for this timeout problem.

Seems to be due to our kernel configuration: CONFIG_IMX_IPUV3_CORE flag seems to cause problems for VPU decoding.

-T

[dv1]

Thanks! I added some notes about the VPU timeouts, and included your finding. Closing this now. Please reopen if you still have problems with the VPU.

[ttykkala]

Hi,

Additional info related to this problem.

The final real reason behind VPU timeouts was wrong input voltage to SMARC processor card. After changing from 3.3V -> 5V timeout problems disappeared.

-T

[dv1]

Excellent, thanks. Will add that to the documentation.

[ttykkala]

After even further debugging it was finally a device tree patch which fixed this issue,

here's a link to device tree patch: https://drive.google.com/file/d/0B2jrHa33l-ljSGVmLXMxZ0tONWM/view?usp=sharing

Cheers, Tommi