Re: imxvpudec crash with 3.14.28 and gstreamer1.0

[Carlos Rafael Giani <dv@pseudoterminal.org>]

No attached log file found here.

On 11/17/2015 05:55 PM, Vikas Patil wrote:
> Hi Carlos,
>
> Attached here the log file. I will check with the master branch. Is
> there any other component I need to upgrade as I have only upgraded
> gstreamer from fido to dizzy branch.
>
> Regards,
> Vikash
>
> On Tue, Nov 17, 2015 at 8:25 PM, Carlos Rafael Giani
> <dv@pseudoterminal.org> wrote:
>> Hi, first, please provide logs without word wrap, it is harder to read
>> otherwise.
>> Second, can you try the latest git master of gstreamer-imx? Read its readme,
>> since it has a new dependency.
>> Third, the interesting bit seems to be the memory allocation error.
>>
>>
>> On 11/17/2015 03:41 PM, Vikas Patil wrote:
>>> Hi,
>>>
>>> I am using following video pipeline and it works for random (1 or 2 or
>>> 3 maximum) times and crashes sometime 2nd time sometime 3rd time in
>>> imxvpudec
>>>
>>> gst-launch-1.0 filesrc location=/home/root/song.mp4 ! qtdemux !
>>> h264parse ! imxvpudec ! imxipuvideotransform ! imxeglvivsink
>>>
>>> Linux 3.14.28
>>> gstreamer-1.4.5
>>> gstreamer1.0-plugins-imx 0.11.1
>>> libfslvpuwrap 1.0.46
>>>
>>> See below the kernel log and gst log. Anyone faced the same issue? Any
>>> pointers/suggestions would be very helpful?
>>>
>>> Thanks & Regards,
>>> Vikash
>>>
>>>
>>>
>>> root@linux123:~# gst-launch-1.0 filesrc location=/home/root/song.mp4 !
>>> qtdemux ! h264parse ! imxvpudec ! imxipuvideotransform ! imxeglvivsink
>>> 0:00:00.221715666   359   0xd25e00 DEBUG   imxblittervideotransform
>>>
>>> video_transform.c:429:gst_imx_blitter_video_transform_transform_caps:<imxipuvideotransform0>
>>> transformed video/x-raw, format=(string){ RGB16, BGR, RGB, BGRx, BGRA,
>>> RGBx, RGBA, ABGR, UYVY, v308, NV12, YV12, I420, Y42B, Y444 },
>>> width=(int)[ 64, 2147483647 ], height=(int)[ 64, 2147483647 ],
>>> framerate=(fraction)[ 0/1, 2147483647/1 ], interlace-mode=(string){
>>> progressive, mixed, interleaved } into video/x-raw, width=(int)[ 64,
>>> 2147483647 ], height=(int)[ 64, 2147483647 ], framerate=(fraction)[
>>> 0/1, 2147483647/1 ], interlace-mode=(string){ progressive, mixed,
>>> interleaved }
>>> 0:00:00.222623000   359   0xd25e00 DEBUG   imxblittervideotransform
>>>
>>> video_transform.c:429:gst_imx_blitter_video_transform_transform_caps:<imxipuvideotransform0>
>>> transformed video/x-raw, format=(string){ RGB16, BGR, RGB, BGRx, BGRA,
>>> RGBx, RGBA, ABGR, UYVY, v308, NV12, YV12, I420, Y42B, Y444 },
>>> width=(int)[ 64, 2147483647 ], height=(int)[ 64, 2147483647 ],
>>> framerate=(fraction)[ 0/1, 2147483647/1 ], interlace-mode=(string){
>>> progressive, mixed, interleaved } into video/x-raw, width=(int)[ 64,
>>> 2147483647 ], height=(int)[ 64, 2147483647 ], framerate=(fraction)[
>>> 0/1, 2147483647/1 ], interlace-mode=(string){ progressive, mixed,
>>> interleaved }
>>> 0:00:00.223405333   359   0xd25e00 DEBUG   imxblittervideotransform
>>>
>>> video_transform.c:429:gst_imx_blitter_video_transform_transform_caps:<imxipuvideotransform0>
>>> transformed video/x-raw, format=(string){ I420, Y444 }, width=(int)[
>>> 64, 2147483647 ], height=(int)[ 64, 2147483647 ],
>>> framerate=(fraction)[ 0/1, 2147483647/1 ], interlace-mode=(string){
>>> progressive, interleaved } into video/x-raw, width=(int)[ 64,
>>> 2147483647 ], height=(int)[ 64, 2147483647 ], framerate=(fraction)[
>>> 0/1, 2147483647/1 ], interlace-mode=(string){ progressive, interleaved
>>> }
>>> 0:00:00.224174000   359   0xd25e00 DEBUG   imxblittervideotransform
>>>
>>> video_transform.c:429:gst_imx_blitter_video_transform_transform_caps:<imxipuvideotransform0>
>>> transformed video/x-raw, format=(string){ I420, Y444 }, width=(int)[
>>> 64, 2147483647 ], height=(int)[ 64, 2147483647 ],
>>> framerate=(fraction)[ 0/1, 2147483647/1 ], interlace-mode=(string){
>>> progressive, interleaved } into video/x-raw, width=(int)[ 64,
>>> 2147483647 ], height=(int)[ 64, 2147483647 ], framerate=(fraction)[
>>> 0/1, 2147483647/1 ], interlace-mode=(string){ progressive, interleaved
>>> }
>>> Setting pipeline to PAUSED ...
>>> 0:00:00.227993333   359   0xd25e00 LOG        imxeglplatform_wl
>>> egl_platform_wayland.c:210:output_mode: reported screen size: 800x480
>>> 0:00:00.242871000   359   0xd25e00 INFO       imxeglplatform_wl
>>> egl_platform_wayland.c:466:gst_imx_egl_viv_sink_egl_platform_create:
>>> Wayland EGL platform initialized, using EGL 1.4
>>> 0:00:00.244226000   359   0xd25e00 INFO     imxphysmemallocator
>>>
>>> phys_mem_allocator.c:62:gst_imx_phys_mem_allocator_init:<GstImxPhysMemAllocator@0xbf8110>
>>> initializing physical memory allocator
>>> 0:00:00.244878666   359   0xd25e00 INFO            imxipudevice
>>> device.c:61:gst_imx_ipu_open: IPU device opened
>>> 0:00:00.245432666   359   0xd25e00 INFO         imxipuallocator
>>> allocator.c:169:gst_imx_ipu_allocator_init:<GstImxIpuAllocator@0xbf8110>
>>> initialized IPU allocator
>>> 0:00:00.246598333   359   0xd25e00 TRACE             imxblitter
>>> blitter.c:65:gst_imx_blitter_init:<GstImxBlitter@0xe18000>
>>> initializing blitter base
>>> 0:00:00.248325333   359   0xd25e00 DEBUG    imxphysmemallocator
>>>
>>> phys_mem_allocator.c:117:gst_imx_phys_mem_allocator_alloc_internal:<imxipuallocator0>
>>> alloc_internal called: maxsize: 256, align: 0, offset: 0, size: 256
>>> 0:00:00.249794333   359   0xd25e00 DEBUG        imxipuallocator
>>> allocator.c:73:gst_imx_ipu_alloc_phys_mem:<imxipuallocator0> allocated
>>> 256 bytes of physical memory at address 0x10a5c000
>>> 0:00:00.250730000   359   0xd25e00 INFO     imxphysmemallocator
>>>
>>> phys_mem_allocator.c:152:gst_imx_phys_mem_allocator_alloc:<imxipuallocator0>
>>> allocated memory block 0xbf6630 at phys addr 0x10a5c000 with 256 bytes
>>> 0:00:00.252923000   359   0xd25e00 INFO               imxvpudec
>>> decoder.c:703:gst_imx_vpu_dec_start:<imxvpudec0> starting VPU decoder
>>> [INFO]  Product Info: i.MX6Q/D/S
>>> 0:00:00.259494333   359   0xd25e00 INFO               imxvpudec
>>> decoder.c:344:gst_imx_vpu_dec_load: VPU loaded
>>> 0:00:00.259635000   359   0xd25e00 INFO               imxvpudec
>>> decoder.c:345:gst_imx_vpu_dec_load: VPU firmware version 3.1.1_r46056
>>> 0:00:00.260003000   359   0xd25e00 INFO               imxvpudec
>>> decoder.c:346:gst_imx_vpu_dec_load: VPU library version 5.4.23
>>> 0:00:00.260127666   359   0xd25e00 INFO               imxvpudec
>>> decoder.c:347:gst_imx_vpu_dec_load: VPU wrapper version 1.0.46
>>> VPUWRAPPER_ARM_LINUX Build on Nov  6 2015 22:16:03
>>> 0:00:00.260775000   359   0xd25e00 INFO     imxphysmemallocator
>>>
>>> phys_mem_allocator.c:62:gst_imx_phys_mem_allocator_init:<GstImxPhysMemAllocator@0xbf8188>
>>> initializing physical memory allocator
>>> 0:00:00.261384000   359   0xd25e00 INFO               imxvpudec
>>> decoder.c:388:gst_imx_vpu_dec_alloc_dec_mem_blocks:<imxvpudec0> need
>>> to allocate 2 sub blocks for decoding
>>> 0:00:00.261520666   359   0xd25e00 INFO               imxvpudec
>>> decoder.c:392:gst_imx_vpu_dec_alloc_dec_mem_blocks:<imxvpudec0> sub
>>> block 0  type: virtual  size: 5672
>>> 0:00:00.261677666   359   0xd25e00 INFO         imxvpumemblocks
>>> mem_blocks.c:50:gst_imx_vpu_alloc_virt_mem_block: allocated 5672 bytes
>>> of heap memory at virt addr 0xe1b000
>>> 0:00:00.262215666   359   0xd25e00 INFO               imxvpudec
>>> decoder.c:392:gst_imx_vpu_dec_alloc_dec_mem_blocks:<imxvpudec0> sub
>>> block 1  type: physical  size: 5236744
>>> 0:00:00.262451333   359   0xd25e00 DEBUG    imxphysmemallocator
>>>
>>> phys_mem_allocator.c:117:gst_imx_phys_mem_allocator_alloc_internal:<imxvpudecallocator0>
>>> alloc_internal called: maxsize: 5236744, align: 0, offset: 0, size:
>>> 5236744
>>> [ERR]   mem allocation failed!
>>> 0:00:00.657658666   359   0xd25e00 WARN     imxphysmemallocator
>>>
>>> phys_mem_allocator.c:154:gst_imx_phys_mem_allocator_alloc:<imxvpudecallocator0>
>>> could not allocate memory block with 5236744 bytes
>>> 0:00:00.657818000   359   0xd25e00 WARN            videodecoder
>>> gstvideodecoder.c:2277:gst_video_decoder_change_state:<imxvpudec0>
>>> error: Failed to start decoder
>>> ERROR: Pipeline doesn't want to pause.
>>> ERROR: from element /GstPipeline:pipeline0/GstImxVpuDec:imxvpudec0:
>>> Could not initialize supporting library.
>>> Additional debug info:
>>>
>>> gstreamer1.0-plugins-base/1.4.5-r0/gst-plugins-base-1.4.5/gst-libs/gst/video/gstvideodecoder.c(2277):
>>> gst_video_decoder_change_state ():
>>> /GstPipeline:pipeline0/GstImxVpuDec:imxvpudec0:
>>> Failed to start decoder
>>> Setting pipeline to NULL ...
>>> 0:00:00.661850333   359   0xd25e00 INFO        imxgles2renderer
>>> gles2_renderer.c:922:gst_imx_egl_viv_sink_gles2_renderer_destroy:
>>> stopping renderer
>>> 0:00:00.661987666   359   0xd25e00 LOG         imxgles2renderer
>>> gles2_renderer.c:989:gst_imx_egl_viv_sink_gles2_renderer_stop: thread
>>> not running - nothing to stop
>>> 0:00:00.662083000   359   0xd25e00 INFO        imxgles2renderer
>>> gles2_renderer.c:927:gst_imx_egl_viv_sink_gles2_renderer_destroy:
>>> destroying EGL platform
>>> 0:00:00.664130666   359   0xd25e00 DEBUG        imxipuallocator
>>> allocator.c:93:gst_imx_ipu_free_phys_mem:<imxipuallocator0> freed
>>> physical memory at address 0x10a5c000
>>> 0:00:00.664316333   359   0xd25e00 INFO     imxphysmemallocator
>>>
>>> phys_mem_allocator.c:168:gst_imx_phys_mem_allocator_free:<imxipuallocator0>
>>> freed block 0xbf6630 at phys addr 0x10a5c000 with size: 256
>>> 0:00:00.664469666   359   0xd25e00 INFO         imxipuallocator
>>> allocator.c:175:gst_imx_ipu_allocator_finalize:<imxipuallocator0>
>>> shutting down IPU allocator
>>> 0:00:00.664576333   359   0xd25e00 INFO     imxphysmemallocator
>>>
>>> phys_mem_allocator.c:75:gst_imx_phys_mem_allocator_finalize:<imxipuallocator0>
>>> shutting down physical memory allocator
>>> 0:00:00.664710000   359   0xd25e00 INFO            imxipudevice
>>> device.c:82:gst_imx_ipu_close: IPU device closed
>>> Freeing pipeline ...
>>>
>>>
>>>
>>> root@linux123:~# dmesg -c
>>> [  109.517131] gst-launch-1.0: page allocation failure: order:11,
>>> mode:0xd1
>>> [  109.524345] CPU: 0 PID: 359 Comm: gst-launch-1.0 Not tainted 3.14.28 #1
>>> [  109.531468] Backtrace:
>>> [  109.534211] [<80011e58>] (dump_backtrace) from [<80012098>]
>>> (show_stack+0x20/0x24)
>>> [  109.542110]  r6:000000d1 r5:8de42000 r4:00000000 r3:00404000
>>> [  109.548140] [<80012078>] (show_stack) from [<804458a0>]
>>> (dump_stack+0x70/0x8c)
>>> [  109.555440] [<80445830>] (dump_stack) from [<800cc350>]
>>> (warn_alloc_failed+0xe8/0x10c)
>>> [  109.563696]  r4:00000001 r3:60010013
>>> [  109.567407] [<800cc26c>] (warn_alloc_failed) from [<800cf270>]
>>> (__alloc_pages_nodemask+0x804/0x894)
>>> [  109.576756]  r3:8de43d9e r2:00000000
>>> [  109.580372]  r8:806d4080 r7:0000000b r6:00000040 r5:00000000
>>> r4:000000d1
>>> [  109.587768] [<800cea6c>] (__alloc_pages_nodemask) from [<80018f60>]
>>> (__dma_alloc_buffer.isra.17+0x3c/0xf8)
>>> [  109.597517]  r10:00000000 r9:00000000 r8:ffffffff r7:00000647
>>> r6:8de43e3c r5:004ff000
>>> [  109.606105]  r4:0000000b
>>> [  109.608875] [<80018f24>] (__dma_alloc_buffer.isra.17) from
>>> [<80019040>] (__alloc_remap_buffer.isra.20+0x24/0xc8)
>>> [  109.619374]  r7:00000647 r6:8de43e3c r5:004ff000 r4:00000000
>>> [  109.625464] [<8001901c>] (__alloc_remap_buffer.isra.20) from
>>> [<800193e4>] (__dma_alloc+0x24c/0x2d4)
>>> [  109.634574]  r8:ffffffff r7:8de3c10c r6:000000d1 r5:004ff000
>>> r4:00000000 r3:8de43e3c
>>> [  109.642963] [<80019198>] (__dma_alloc) from [<800195a4>]
>>> (arm_dma_alloc+0x94/0xa0)
>>> [  109.650791]  r10:00000000 r9:8036ab4c r8:000000d1 r7:00000000
>>> r6:004ff000 r5:8de3c10c
>>> [  109.659116]  r4:00000647
>>> [  109.661758] [<80019510>] (arm_dma_alloc) from [<8036ab4c>]
>>> (vpu_alloc_dma_buffer+0x50/0x88)
>>> [  109.670390]  r9:8de42000 r8:8de42000 r7:8de3c108 r6:8de3c100
>>> r5:8de3c108 r4:00000000
>>> [  109.678764] [<8036aafc>] (vpu_alloc_dma_buffer) from [<8036b3c8>]
>>> (vpu_ioctl+0xec/0x880)
>>> [  109.686944]  r5:7ee14570 r4:7ee14570
>>> [  109.690874] [<8036b2dc>] (vpu_ioctl) from [<80117ce4>]
>>> (do_vfs_ioctl+0x498/0x590)
>>> [  109.698428]  r8:0000000b r7:00005600 r6:8d1386c0 r5:8c5a08f8
>>> r4:7ee14570
>>> [  109.705758] [<8011784c>] (do_vfs_ioctl) from [<80117e20>]
>>> (SyS_ioctl+0x44/0x6c)
>>> [  109.713135]  r10:00000000 r9:8de42000 r8:0000000b r7:00005600
>>> r6:8d1386c0 r5:8d1386c1
>>> [  109.721498]  r4:7ee14570
>>> [  109.724151] [<80117ddc>] (SyS_ioctl) from [<8000e0a0>]
>>> (ret_fast_syscall+0x0/0x30)
>>> [  109.731779]  r8:8000e2c4 r7:00000036 r6:00019c54 r5:7673f394
>>> r4:7ee14570 r3:766fba9c
>>> [  109.740058] Mem-info:
>>> [  109.742655] DMA per-cpu:
>>> [  109.745214] CPU    0: hi:   90, btch:  15 usd:   0
>>> [  109.750270] CPU    1: hi:   90, btch:  15 usd:  25
>>> [  109.755154] active_anon:11163 inactive_anon:236 isolated_anon:0
>>> [  109.755154]  active_file:3002 inactive_file:20423 isolated_file:0
>>> [  109.755154]  unevictable:0 dirty:0 writeback:0 unstable:0
>>> [  109.755154]  free:10061 slab_reclaimable:1462 slab_unreclaimable:1352
>>> [  109.755154]  mapped:11150 shmem:494 pagetables:519 bounce:0
>>> [  109.755154]  free_cma:0
>>> [  109.787296] DMA free:40244kB min:2004kB low:2504kB high:3004kB
>>> active_anon:44652kB inactive_anon:944kB active_file:12008kB
>>> inactive_file:81692kB unevictable:0kB isolated(anon):0kB
>>> isolated(file):0kB present:262144kB managed:251904kB mlocked:0kB
>>> dirty:0kB writeback:0kB mapped:44600kB shmem:1976kB
>>> slab_reclaimable:5848kB slab_unreclaimable:5408kB kernel_stack:1672kB
>>> pagetables:2076kB unstable:0kB bounce:0kB free_cma:0kB
>>> writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
>>> [  109.829243] lowmem_reserve[]: 0 0 0
>>> [  109.832871] DMA: 151*4kB (UEMR) 163*8kB (UEMR) 36*16kB (UEMR)
>>> 18*32kB (UEMR) 15*64kB (UER) 15*128kB (UER) 6*256kB (UER) 10*512kB
>>> (UER) 3*1024kB (R) 4*2048kB (R) 2*4096kB (R) 1*8192kB (R) 0*16384kB
>>> 0*32768kB = 40244kB
>>> [  109.852730] 23917 total pagecache pages
>>> [  109.856663] 0 pages in swap cache
>>> [  109.860013] Swap cache stats: add 0, delete 0, find 0/0
>>> [  109.865305] Free swap  = 0kB
>>> [  109.868192] Total swap = 0kB
>>> [  109.876717] 65536 pages of RAM
>>> [  109.879786] 10426 free pages
>>> [  109.882740] 3671 reserved pages
>>> [  109.885898] 2271 slab pages
>>> [  109.888720] 286701 pages shared
>>> [  109.891910] 0 pages swap cached
>>> [  109.895073] mxc_vpu 2040000.vpu: Physical memory allocation error!
>>> [  109.901331] mxc_vpu 2040000.vpu: Physical memory allocation error!
>>