RTSP timestamping problem with imxvpudec ?

[guillerodriguez]

I am using gstreamer-imx to fetch live video from IP cameras (RTSP / H.264). The pipeline looks like this (note that I am handling video only; audio is ignored):

gst-launch-1.0 rtspsrc latency=200 location=.... ! rtph264depay ! h264parse ! imxvpudec ! videoconvert ! imxg2dvideosink

In some cases I am seeing stuttering video with many dropped frames. The debug output warns about dropped buffers and says "There may be a timestamping problem, or this computer is too slow.":

Setting pipeline to PAUSED ...
Pipeline is live and does not need PREROLL ...
Progress: (open) Opening Stream
Progress: (connect) Connecting to rtsp://192.168.0.241
Progress: (open) Retrieving server options
Progress: (open) Retrieving media info
Progress: (request) SETUP stream 0
Progress: (request) SETUP stream 1
Progress: (open) Opened Stream
Setting pipeline to PLAYING ...
New clock: GstSystemClock
Progress: (request) Sending PLAY request
0:00:00.506588667   374 0x6d207ec0 FIXME                default gstutils.c:3981:gst_pad_create_stream_id_internal:<fakesrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
Progress: (request) Sending PLAY request
0:00:00.507630000   374 0x6d207e90 FIXME                default gstutils.c:3981:gst_pad_create_stream_id_internal:<fakesrc1:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
Progress: (request) Sent PLAY request
0:00:00.752410333   374   0x4f2750 FIXME           videodecoder gstvideodecoder.c:944:gst_video_decoder_drain_out:<imxvpudecoder0> Sub-class should implement drain()
0:00:00.752645333   374   0x4f2750 FIXME               basesink gstbasesink.c:3248:gst_base_sink_default_event:<imxg2dvideosink0> stream-start event without group-id. Consider implementing group-id handling in the upstream elements
0:00:00.754043667   374 0x6d207fb0 WARN                 basesrc gstbasesrc.c:3072:gst_base_src_loop:<udpsrc0> error: Internal data stream error.
0:00:00.754232000   374 0x6d207fb0 WARN                 basesrc gstbasesrc.c:3072:gst_base_src_loop:<udpsrc0> error: streaming stopped, reason not-linked (-1)
0:00:03.454572334   374   0x4f2750 WARN                basesink gstbasesink.c:3005:gst_base_sink_is_too_late:<imxg2dvideosink0> warning: A lot of buffers are being dropped.
0:00:03.454752334   374   0x4f2750 WARN                basesink gstbasesink.c:3005:gst_base_sink_is_too_late:<imxg2dvideosink0> warning: There may be a timestamping problem, or this computer is too slow.
[INFO]	bitstreamMode 1, chromaInterleave 0, mapType 0, tiled2LinearEnable 0
[INFO]	bitstreamMode 1, chromaInterleave 0, mapType 0, tiled2LinearEnable 0
[WARN]	VPU iram is less than needed, some parts don't use iram
WARNING: from element /GstPipeline:pipeline0/GstImxG2DVideoSink:imxg2dvideosink0: A lot of buffers are being dropped.
Additional debug info:
../gstreamer-1.16.2/libs/gst/base/gstbasesink.c(3005): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstImxG2DVideoSink:imxg2dvideosink0:
There may be a timestamping problem, or this computer is too slow.
0:00:05.171367334   374   0x4f2750 WARN                basesink gstbasesink.c:3005:gst_base_sink_is_too_late:<imxg2dvideosink0> warning: A lot of buffers are being dropped.
0:00:05.171542000   374   0x4f2750 WARN                basesink gstbasesink.c:3005:gst_base_sink_is_too_late:<imxg2dvideosink0> warning: There may be a timestamping problem, or this computer is too slow.
WARNING: from element /GstPipeline:pipeline0/GstImxG2DVideoSink:imxg2dvideosink0: A lot of buffers are being dropped.
Additional debug info:
../gstreamer-1.16.2/libs/gst/base/gstbasesink.c(3005): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstImxG2DVideoSink:imxg2dvideosink0:
There may be a timestamping problem, or this computer is too slow.
0:00:06.888669001   374   0x4f2750 WARN                basesink gstbasesink.c:3005:gst_base_sink_is_too_late:<imxg2dvideosink0> warning: A lot of buffers are being dropped.
0:00:06.888847334   374   0x4f2750 WARN                basesink gstbasesink.c:3005:gst_base_sink_is_too_late:<imxg2dvideosink0> warning: There may be a timestamping problem, or this computer is too slow.
WARNING: from element /GstPipeline:pipeline0/GstImxG2DVideoSink:imxg2dvideosink0: A lot of buffers are being dropped.
Additional debug info:
../gstreamer-1.16.2/libs/gst/base/gstbasesink.c(3005): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstImxG2DVideoSink:imxg2dvideosink0:
There may be a timestamping problem, or this computer is too slow.
0:00:08.603114667   374   0x4f2750 WARN                basesink gstbasesink.c:3005:gst_base_sink_is_too_late:<imxg2dvideosink0> warning: A lot of buffers are being dropped.
0:00:08.603292334   374   0x4f2750 WARN                basesink gstbasesink.c:3005:gst_base_sink_is_too_late:<imxg2dvideosink0> warning: There may be a timestamping problem, or this computer is too slow.
WARNING: from element /GstPipeline:pipeline0/GstImxG2DVideoSink:imxg2dvideosink0: A lot of buffers are being dropped.
Additional debug info:
../gstreamer-1.16.2/libs/gst/base/gstbasesink.c(3005): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstImxG2DVideoSink:imxg2dvideosink0:
There may be a timestamping problem, or this computer is too slow.
handling interrupt.
Interrupt: Stopping pipeline ...
Execution ended after 0:00:08.278721668
Setting pipeline to PAUSED ...
Setting pipeline to READY ...
Setting pipeline to NULL ...
Freeing pipeline ...

Despite the messages, this doesn't look like a performance issue:

• Sometimes the problem will go away if I increase the image resolution, frame rate, or bit rate at the source (shouldn't happen if this was really a performance problem)
• The problem does not happen if I replace imxvpudec and use avdec_h264 instead

It seems to be related to imxvpudec; any hints on what may be wrong or how to debug this further ?

[dv1]

This might have been happening because of an internal condition variable that was necessary to keep the VPU's buffer pool happy. The code in v2 works differently, and might behave better. Try it again with the elements in the v2 branch or in the upcoming release.

[guillerodriguez]

This might have been happening because of an internal condition variable that was necessary to keep the VPU's buffer pool happy. The code in v2 works differently, and might behave better. Try it again with the elements in the v2 branch or in the upcoming release.

Been looking into this but switching to v2 is problematic -- this forces us to update the galcore driver and all libraries (with the version we're using right now we get a compile error: "'G2D_AMPHION_TILED' undeclared"). Updating the libraries in turn requires a newer glibc (since the libs are compiled against glibc-2.29). That in turn forces us to update the toolchain and the kernel. So basically we have to update everything to be able to upgrade to gstreamer-imx v2, which is problematic.

Any chance this could be solved in v1? Can you provide more information about the internal condition variable you mentioned in your reply, and whether a workaround would be possible?

[guillerodriguez]

@dv1 Still trying to test this but we're hitting some issues with imxvpudec; please see #293

[guillerodriguez]

@dv1 Since v2 does not seem to be an option for us at the moment (#293), is there any chance you could elaborate on this:

This might have been happening because of an internal condition variable that was necessary to keep the VPU's buffer pool happy. The code in v2 works differently, and might behave better. Try it again with the elements in the v2 branch or in the upcoming release.

Can you provide more information about the internal condition variable you mentioned in your reply, and whether a workaround would be possible?

[dv1]

@guillerodriguez I might have a lead on what is causing #293 , so try that first please.

[guillerodriguez]

@dv1 Since we don't seem to be making progress on #293, is there a chance this could be revisited? 1.x works fine for me except for this specific issue.

[dv1]

Well... late update, but here we go.

I've tried to see if this could be revisited in 1.x, but, no way, not feasible. However, if you are still working on this, I could in theory add a configuration check for the presence of G2D_AMPHION_TILED, and if not present, disable the related code paths. Then v2 should work for you.

[guillerodriguez]

Well... late update, but here we go.

I've tried to see if this could be revisited in 1.x, but, no way, not feasible. However, if you are still working on this, I could in theory add a configuration check for the presence of G2D_AMPHION_TILED, and if not present, disable the related code paths. Then v2 should work for you.

I would be very happy to test this if you can give it a go!

[dv1]

To be exact, the problem you have is the build error in gst-libs/imx2d/backend/g2d/g2d_blitter.c. Correct?

If so, check out latest git master. I just pushed a change that checks for the Amphion enums, and disables associated code paths in g2d_blitter.c if they are not present.

[guillerodriguez]

Hi,

The G2D_AMPHION_TILED error went away but now it fails here:

../gstreamer-imx-2b42f1a46558054345ea9fd245c2d8dca22046d2/gst-libs/imx2d/backend/g2d/g2d_blitter.c: In function 'colorimetry_to_g2d_cap_mode':
../gstreamer-imx-2b42f1a46558054345ea9fd245c2d8dca22046d2/gst-libs/imx2d/backend/g2d/g2d_blitter.c:153:41: error: 'G2D_YUV_BT_601' undeclared (first use in this function)
   case IMX2D_COLORIMETRY_BT_601: return G2D_YUV_BT_601;
                                         ^
../gstreamer-imx-2b42f1a46558054345ea9fd245c2d8dca22046d2/gst-libs/imx2d/backend/g2d/g2d_blitter.c:153:41: note: each undeclared identifier is reported only once for each function it appears in
../gstreamer-imx-2b42f1a46558054345ea9fd245c2d8dca22046d2/gst-libs/imx2d/backend/g2d/g2d_blitter.c:154:41: error: 'G2D_YUV_BT_709' undeclared (first use in this function)
   case IMX2D_COLORIMETRY_BT_709: return G2D_YUV_BT_709;
                                         ^
../gstreamer-imx-2b42f1a46558054345ea9fd245c2d8dca22046d2/gst-libs/imx2d/backend/g2d/g2d_blitter.c:155:52: error: 'G2D_YUV_BT_601FR' undeclared (first use in this function)
   case IMX2D_COLORIMETRY_BT_601_FULL_RANGE: return G2D_YUV_BT_601FR;
                                                    ^
../gstreamer-imx-2b42f1a46558054345ea9fd245c2d8dca22046d2/gst-libs/imx2d/backend/g2d/g2d_blitter.c:156:52: error: 'G2D_YUV_BT_709FR' undeclared (first use in this function)
   case IMX2D_COLORIMETRY_BT_709_FULL_RANGE: return G2D_YUV_BT_709FR;
                                                    ^

[dv1]

Ah, of course :) Colorimetry was added later. You can do a hack: Comment out the contents of the function (not the entire function!) imx_2d_backend_g2d_blitter_set_colorimetry, then comment out the entire function colorimetry_to_g2d_cap_mode.

[guillerodriguez]

OK.

Next errors are in gstimxv4l2amphionde.c. Since I don't need V4L, I just disabled this.

After this, the build succeeds. I will be testing over the next few days.

[dv1]

@guillerodriguez I just posted updates that perform the Amphion tile layout checks in the G2D blitter and the Amphion decoder code. The hacks should no longer be needed.

[dv1]

@guillerodriguez Can you confirm that this is fixed? Do note the checks I mentioned above.

[guillerodriguez]

@dv1 Will test and come back to you asap.

[guillerodriguez]

@dv1

@guillerodriguez Can you confirm that this is fixed? Do note the checks I mentioned above.

Sorry for the delay.

The original issue does not seem to happen with the latest code in v2 for "normal" resolutions. However while testing whether I would be able to migrate from v1 to v2 I noticed that there are issues with low resolutions, which do not seem to happen in v1.

This is reproducible with the same pipeline, specifically I was using the following:

gst-launch-1.0 rtspsrc location=... ! rtph264depay ! h264parse ! imxvpudec_h264 ! imxg2dvideosink clear-at-null=true

With low resolutions (176x144) I see the following:

[...]
0:00:02.313815334   456 0x750032f0 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)byte-stream, alignment=(string)au, width=(int)176, height=(int)144, framerate=(fraction)0/1, interlace-mode=(string)progressive, chroma-format=(string)4:2:0, bit-depth-luma=(uint)8, bit-depth-chroma=(uint)8, parsed=(boolean)true, profile=(string)baseline, level=(string)3
0:00:02.315441334   456 0x750032f0 INFO               imxvpuapi imxvpuapi2_imx6_coda.c:236:imx_coda_vpu_load: libimxvpuapi version 2.2.2 vpulib backend
0:00:02.328535334   456 0x750032f0 INFO            videodecoder gstvideodecoder.c:1312:gst_video_decoder_sink_event_default:<imxvpudech264-0> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)";
0:00:02.329313667   456 0x750032f0 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event video/x-raw, format=(string)NV12, width=(int)176, height=(int)144, interlace-mode=(string)progressive, multiview-mode=(string)mono, multiview-flags=(GstVideoMultiviewFlagsSet)0:ffffffff:/right-view-first/left-flipped/left-flopped/right-flipped/right-flopped/half-aspect/mixed-mono, pixel-aspect-ratio=(fraction)1/1, chroma-site=(string)jpeg, colorimetry=(string)bt601, framerate=(fraction)0/1
0:00:02.345336001   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda_ipu.c:126:imx_vpu_api_imx6_coda_detile_and_copy_frame_with_ipu_vdoa: queuing IPU task failed: Invalid argument (22)
0:00:02.345415001   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda.c:2518:imx_vpu_api_dec_get_decoded_frame: could not detile and copy decoded frame pixels
0:00:02.345470334   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:1514:gst_imx_vpu_dec_decode_queued_frames:<imxvpudech264-0> could not retrieve decoded frame: error
0:00:02.352951001   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda_ipu.c:126:imx_vpu_api_imx6_coda_detile_and_copy_frame_with_ipu_vdoa: queuing IPU task failed: Invalid argument (22)
0:00:02.352998334   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda.c:2518:imx_vpu_api_dec_get_decoded_frame: could not detile and copy decoded frame pixels
0:00:02.353040001   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:1514:gst_imx_vpu_dec_decode_queued_frames:<imxvpudech264-0> could not retrieve decoded frame: error
0:00:02.360031334   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda_ipu.c:126:imx_vpu_api_imx6_coda_detile_and_copy_frame_with_ipu_vdoa: queuing IPU task failed: Invalid argument (22)
0:00:02.360080667   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda.c:2518:imx_vpu_api_dec_get_decoded_frame: could not detile and copy decoded frame pixels
0:00:02.360120334   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:1514:gst_imx_vpu_dec_decode_queued_frames:<imxvpudech264-0> could not retrieve decoded frame: error
0:00:02.367350001   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda_ipu.c:126:imx_vpu_api_imx6_coda_detile_and_copy_frame_with_ipu_vdoa: queuing IPU task failed: Invalid argument (22)
0:00:02.367389001   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda.c:2518:imx_vpu_api_dec_get_decoded_frame: could not detile and copy decoded frame pixels
0:00:02.367432334   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:1514:gst_imx_vpu_dec_decode_queued_frames:<imxvpudech264-0> could not retrieve decoded frame: error
0:00:02.374737334   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda_ipu.c:126:imx_vpu_api_imx6_coda_detile_and_copy_frame_with_ipu_vdoa: queuing IPU task failed: Invalid argument (22)
0:00:02.374782667   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda.c:2518:imx_vpu_api_dec_get_decoded_frame: could not detile and copy decoded frame pixels
0:00:02.374823667   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:1514:gst_imx_vpu_dec_decode_queued_frames:<imxvpudech264-0> could not retrieve decoded frame: error
0:00:02.382037001   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda_ipu.c:126:imx_vpu_api_imx6_coda_detile_and_copy_frame_with_ipu_vdoa: queuing IPU task failed: Invalid argument (22)
0:00:02.382214001   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda.c:2518:imx_vpu_api_dec_get_decoded_frame: could not detile and copy decoded frame pixels
0:00:02.382268667   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:1514:gst_imx_vpu_dec_decode_queued_frames:<imxvpudech264-0> could not retrieve decoded frame: error
0:00:02.389391667   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda_ipu.c:126:imx_vpu_api_imx6_coda_detile_and_copy_frame_with_ipu_vdoa: queuing IPU task failed: Invalid argument (22)
0:00:02.389446334   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda.c:2518:imx_vpu_api_dec_get_decoded_frame: could not detile and copy decoded frame pixels
0:00:02.389487334   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:1514:gst_imx_vpu_dec_decode_queued_frames:<imxvpudech264-0> could not retrieve decoded frame: error
0:00:02.390340667   456 0x750032f0 ERROR              imxvpuapi imxvpuapi2_imx6_coda.c:2346:imx_vpu_api_dec_decode: internal error; not enough output framebuffers were available even though enough were added prior to decoding
0:00:02.390403001   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:981:gst_imx_vpu_dec_decode_queued_frames:<imxvpudech264-0> decoding frames failed: error
0:00:02.390764001   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:551:gst_imx_vpu_dec_handle_frame:<imxvpudech264-0> fatal error previously recorded; cannot decode
0:00:02.391165334   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:551:gst_imx_vpu_dec_handle_frame:<imxvpudech264-0> fatal error previously recorded; cannot decode
0:00:02.391516667   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:551:gst_imx_vpu_dec_handle_frame:<imxvpudech264-0> fatal error previously recorded; cannot decode
0:00:02.391974334   456 0x750032f0 ERROR              imxvpudec gstimxvpudec.c:551:gst_imx_vpu_dec_handle_frame:<imxvpudech264-0> fatal error previously recorded; cannot decode
[...]

There are also low level errors:

[ 1919.818637] mxc_ipu mxc_ipu: ERR: no-0x0,ipu_queue_task err:-22
[ 1919.826121] mxc_ipu mxc_ipu: ERR: no-0x0,ipu_queue_task err:-22
[ 1919.833116] mxc_ipu mxc_ipu: ERR: no-0x0,ipu_queue_task err:-22
[ 1919.840573] mxc_ipu mxc_ipu: ERR: no-0x0,ipu_queue_task err:-22
[ 1919.847932] mxc_ipu mxc_ipu: ERR: no-0x0,ipu_queue_task err:-22
[ 1919.855472] mxc_ipu mxc_ipu: ERR: no-0x0,ipu_queue_task err:-22

[dv1]

This looks like an IPU problem. The IPU, or at least the linux-imx IPU driver, is picky about resolutions and other parameters, but it is needed as part of the detiling and frame transfer process inside libimxvpuapi. I'll try out that low resolution.