gstreamer pipeline is very slow to start

Autonomous Machines Jetson & Embedded Systems Jetson TX1
#1

I’ve encountered this issue with all complex gstreamer pipelines. After a fresh reboot the pipeline usually starts relatively quickly. For simpler pipelines it starts within 10 seconds. For the pipeline below it started within 30 seconds. After I shutdown the pipeline, it look ~8 minutes to start it again. Has anyone else experienced this?

gst-launch-1.0 -e videomixer name=mix \
		sink_0::xpos=0 sink_0::ypos=0 sink_0::zorder=0 \
		sink_1::xpos=50 sink_1::ypos=50 sink_1::zorder=1 \
		sink_2::xpos=950 sink_2::ypos=50 sink_2::zorder=2 \
		sink_3::xpos=515 sink_3::ypos=560 sink_3::zorder=3 \
	! queue ! omxvp8enc quality-level=2 ! video/x-vp8 ! queue ! rtpvp8pay ! udpsink host=127.0.0.1 port=5004 sync=false \
	v4l2src device=/dev/camera_front ! video/x-raw,width=1280,height=720 ! videorate ! video/x-raw,framerate=10/1 ! queue ! mix.sink_0 \
	v4l2src device=/dev/camera_left ! video/x-raw,framerate=30/1,width=640,height=480 ! queue ! videorate ! videoscale ! video/x-raw,width=320,height=240,framerate=10/1 ! videocrop bottom=100 top=0 left=50 right=50 ! queue ! mix.sink_1 \
	v4l2src device=/dev/camera_right ! video/x-raw,framerate=30/1,width=640,height=480 ! queue ! videorate ! videoscale ! video/x-raw,width=320,height=240,framerate=10/1 ! videocrop bottom=100 top=0 left=50 right=50 ! queue ! mix.sink_2 \
	v4l2src device=/dev/camera_back ! video/x-raw,framerate=30/1,width=640,height=480 ! queue ! videorate ! videoscale ! video/x-raw,width=320,height=240,framerate=10/1 ! videocrop bottom=0 top=100 left=50 right=50 ! queue ! mix.sink_3 \

Console output:

ubuntu@tegra-zac-1:~$ python start_composite_cameras.py
gst-launch-1.0 -e videomixer name=mix sink_0::xpos=0 sink_0::ypos=0 sink_0::zorder=0 sink_1::xpos=50 sink_1::ypos=50 sink_1::zorder=1 sink_2::xpos=950 sink_2::ypos=50 sink_2::zorder=2 sink_3::xpos=515 sink_3::ypos=560 sink_3::zorder=3 ! queue ! omxvp8enc quality-level=2 ! video/x-vp8 ! queue ! rtpvp8pay ! udpsink host=127.0.0.1 port=5004 sync=false v4l2src device=/dev/camera_front ! video/x-raw,width=1280,height=720 ! videorate ! video/x-raw,framerate=10/1 ! queue ! mix.sink_0 v4l2src device=/dev/camera_left ! video/x-raw,framerate=30/1,width=640,height=480 ! queue ! videorate ! videoscale ! video/x-raw,width=320,height=240,framerate=10/1 ! videocrop bottom=100 top=0 left=50 right=50 ! queue ! mix.sink_1 v4l2src device=/dev/camera_right ! video/x-raw,framerate=30/1,width=640,height=480 ! queue ! videorate ! videoscale ! video/x-raw,width=320,height=240,framerate=10/1 ! videocrop bottom=100 top=0 left=50 right=50 ! queue ! mix.sink_2 v4l2src device=/dev/camera_back ! video/x-raw,framerate=30/1,width=640,height=480 ! queue ! videorate ! videoscale ! video/x-raw,width=320,height=240,framerate=10/1 ! videocrop bottom=0 top=100 left=50 right=50 ! queue ! mix.sink_3
Setting pipeline to PAUSED ...
Inside NvxLiteH264DecoderLowLatencyInitNvxLiteH264DecoderLowLatencyInit set DPB and MjstreamingInside NvxLiteH265DecoderLowLatencyInitNvxLiteH265DecoderLowLatencyInit set DPB and MjstreamingPipeline is live and does not need PREROLL ...
Setting pipeline to PLAYING ...
New clock: GstSystemClock

(process pauses here for 30-480 seconds)

Framerate set to : 10 at NvxVideoEncoderSetParameterNvMMLiteOpen : Block : BlockType = 7
===== MSENC =====
NvMMLiteBlockCreate : Block : BlockType = 7
===== MSENC blits (mode: 1) into tiled surfaces =====

This pipeline has a similar behavior, although not quite as long start times

gst-launch-1.0 v4l2src device="/dev/video1" ! video/x-raw,width=640,height=480,framerate=30/1 ! queue ! videorate ! videoscale ! video/x-raw,width=320,height=240,framerate=10/1 ! queue ! omxvp8enc quality-level=2 ! video/x-vp8 ! queue ! rtpvp8pay ! udpsink host=127.0.0.1 port=5004 sync=false
#2

Hello,
I have not tried so many (4?) USB cameras. Maybe you can use GDB to check where the program stuck?

Or try with 2 or 3 USB cameras?

br
ChenJian

#3

Have you tried turning on debug logging with gstreamer? it will take a while but you will find out on the first run if you are looping or hanging.

#4

jachen, how might I run gstreamer with gdb? There are a lot of threads. It does start sooner the simpler the pipeline is, so less cameras does start faster. However, I still experience similar behavior where the pipeline takes longer to start the 2nd and 3rd time after system startup even with 1 camera.

sperok, I’ve looked at verbose output, but it doesn’t offer anything interesting during the time the process is hung.

A workaround I’ve found is to restart the tx1 before I start a new gstreamer pipeline. This makes the pipeline start up in a reasonable amount of time. Does that offer any clues?

#5

Here’s an example of verbose output. This simple pipeline took 48 seconds to start.

ubuntu@tegra-ubuntu:~$ gst-launch-1.0 -v v4l2src device="/dev/video0" ! video/x-raw,width=1280, height=720,framerate=30/1 ! videorate ! videoscale ! video/x-raw,width=640,height=360,framerate=10/1 ! omxvp8enc ! video/x-vp8 ! rtpvp8pay ! udpsink host=224.0.0.11 auto-multicast=true port=5004 sync=false
Setting pipeline to PAUSED ...
Inside NvxLiteH264DecoderLowLatencyInitNvxLiteH264DecoderLowLatencyInit set DPB and MjstreamingInside NvxLiteH265DecoderLowLatencyInitNvxLiteH265DecoderLowLatencyInit set DPB and MjstreamingPipeline is live and does not need PREROLL ...
Setting pipeline to PLAYING ...
New clock: GstSystemClock
/GstPipeline:pipeline0/GstV4l2Src:v4l2src0.GstPad:src: caps = "video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)1280\,\ height\=\(int\)720\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)30/1"
/GstPipeline:pipeline0/GstCapsFilter:capsfilter0.GstPad:src: caps = "video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)1280\,\ height\=\(int\)720\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)30/1"
/GstPipeline:pipeline0/GstVideoRate:videorate0.GstPad:src: caps = "video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)1280\,\ height\=\(int\)720\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)10/1"
/GstPipeline:pipeline0/GstVideoScale:videoscale0.GstPad:src: caps = "video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)640\,\ height\=\(int\)360\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)10/1"
/GstPipeline:pipeline0/GstCapsFilter:capsfilter1.GstPad:src: caps = "video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)640\,\ height\=\(int\)360\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)10/1"
Framerate set to : 10 at NvxVideoEncoderSetParameterNvMMLiteOpen : Block : BlockType = 7 
===== MSENC =====
NvMMLiteBlockCreate : Block : BlockType = 7 
/GstPipeline:pipeline0/GstOMXVP8Enc-omxvp8enc:omxvp8enc-omxvp8enc0.GstPad:sink: caps = "video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)640\,\ height\=\(int\)360\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)10/1"
/GstPipeline:pipeline0/GstCapsFilter:capsfilter1.GstPad:sink: caps = "video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)640\,\ height\=\(int\)360\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)10/1"
/GstPipeline:pipeline0/GstVideoScale:videoscale0.GstPad:sink: caps = "video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)1280\,\ height\=\(int\)720\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)10/1"
/GstPipeline:pipeline0/GstVideoRate:videorate0.GstPad:sink: caps = "video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)1280\,\ height\=\(int\)720\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)30/1"
/GstPipeline:pipeline0/GstCapsFilter:capsfilter0.GstPad:sink: caps = "video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)1280\,\ height\=\(int\)720\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)30/1"



===== MSENC blits (mode: 1) into tiled surfaces =====
/GstPipeline:pipeline0/GstOMXVP8Enc-omxvp8enc:omxvp8enc-omxvp8enc0.GstPad:src: caps = "video/x-vp8\,\ profile\=\(int\)0\,\ width\=\(int\)640\,\ height\=\(int\)360\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ framerate\=\(fraction\)10/1"
/GstPipeline:pipeline0/GstCapsFilter:capsfilter2.GstPad:src: caps = "video/x-vp8\,\ profile\=\(int\)0\,\ width\=\(int\)640\,\ height\=\(int\)360\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ framerate\=\(fraction\)10/1"
/GstPipeline:pipeline0/GstRtpVP8Pay:rtpvp8pay0.GstPad:src: caps = "application/x-rtp\,\ media\=\(string\)video\,\ clock-rate\=\(int\)90000\,\ encoding-name\=\(string\)VP8\,\ payload\=\(int\)96\,\ ssrc\=\(uint\)760568833\,\ timestamp-offset\=\(uint\)1651758615\,\ seqnum-offset\=\(uint\)29478\,\ a-framerate\=\(string\)10"
/GstPipeline:pipeline0/GstUDPSink:udpsink0.GstPad:sink: caps = "application/x-rtp\,\ media\=\(string\)video\,\ clock-rate\=\(int\)90000\,\ encoding-name\=\(string\)VP8\,\ payload\=\(int\)96\,\ ssrc\=\(uint\)760568833\,\ timestamp-offset\=\(uint\)1651758615\,\ seqnum-offset\=\(uint\)29478\,\ a-framerate\=\(string\)10"
/GstPipeline:pipeline0/GstRtpVP8Pay:rtpvp8pay0.GstPad:sink: caps = "video/x-vp8\,\ profile\=\(int\)0\,\ width\=\(int\)640\,\ height\=\(int\)360\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ framerate\=\(fraction\)10/1"
/GstPipeline:pipeline0/GstCapsFilter:capsfilter2.GstPad:sink: caps = "video/x-vp8\,\ profile\=\(int\)0\,\ width\=\(int\)640\,\ height\=\(int\)360\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ framerate\=\(fraction\)10/1"
/GstPipeline:pipeline0/GstRtpVP8Pay:rtpvp8pay0: timestamp = 1651758615
/GstPipeline:pipeline0/GstRtpVP8Pay:rtpvp8pay0: seqnum = 29478
#6

running the following pipeline:

ubuntu@tegra-ubuntu:~$ export GST_DEBUG=4
ubuntu@tegra-ubuntu:~$ gst-launch-1.0 v4l2src device="/dev/video1" ! video/x-raw,width=640, height=480 ! videorate ! videoscale ! video/x-raw,width=640,height=360,framerate=10/1 ! omxvp8enc ! video/x-vp8 ! rtpvp8pay ! udpsink host=192.168.254.66 auto-multicast=true port=5004 sync=false

will show me a critical point here:

{...}
0:00:00.137402761 13164       0x51d370 INFO          v4l2bufferpool gstv4l2bufferpool.c:575:gst_v4l2_buffer_pool_set_config:<v4l2src0:pool:src> can't allocate, setting maximum to minimum
0:00:03.187817276 13164       0x51d370 WARN          v4l2bufferpool gstv4l2bufferpool.c:1196:gst_v4l2_buffer_pool_dqbuf:<v4l2src0:pool:src> Driver should never set v4l2_buffer.field to ANY
{...}

thats 3.5 seconds delay. sometimes it just hangs up here waiting forever. seems to be a problem when changing the v4l2src from PAUSED to PLAYING. setting the framerate in the v4l2src caps does not change the behavior.

GST_DEBUG=5 shows that the pipeline is hanging here:

0:00:03.824756553 13278       0x51dd40 DEBUG                basesrc gstbasesrc.c:3146:gst_base_src_prepare_allocation:<v4l2src0> ALLOCATION (1) params: allocation query: 0x7fa40062d0, GstQueryAllocation, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)640\,\ height\=\(int\)480\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)60/1", need-pool=(boolean)true, pool=(GArray)NULL, allocator=(GArray)NULL, meta=(GArray)NULL;
0:00:03.824931031 13278       0x51dd40 DEBUG                basesrc gstbasesrc.c:2971:gst_base_src_set_allocation:<v4l2src0> activate pool
0:00:03.824962750 13278       0x51dd40 DEBUG             bufferpool gstbufferpool.c:519:gst_buffer_pool_set_active:<v4l2src0:pool:src> pool was in the right state
0:00:03.825003322 13278       0x51dd40 DEBUG                basesrc gstbasesrc.c:2456:gst_base_src_get_range:<v4l2src0> calling create offset 18446744073709551615 length 4096, time 0
0:00:03.825042020 13278       0x51dd40 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:1300:gst_v4l2_buffer_pool_acquire_buffer:<v4l2src0:pool:src> acquire
0:00:03.825074936 13278       0x51dd40 DEBUG               GST_POLL gstpoll.c:1195:gst_poll_wait: 0x7fa4006140: timeout :99:99:99.999999999

thats an odd timeout…seems to be luck to get behind this point in the pipeline at all in my case.

but there is a delay at this point in the pipeline:

0:00:03.554453481 13506       0x51df70 DEBUG               GST_POLL gstpoll.c:1195:gst_poll_wait: 0x7f74002540: timeout :99:99:99.999999999
0:00:03.821427373 13506       0x51df70 DEBUG               GST_POLL gstpoll.c:1066:gst_poll_fd_has_error: 0x7f74002540: fd (fd:12, idx:1) 0
0:00:06.583863662 13506       0x51df70 DEBUG          v4l2allocator gstv4l2allocator.c:1310:gst_v4l2_allocator_dqbuf:<v4l2src0:pool:src:allocator> driver pretends buffer is queued even if dequeue succeeded

seems to be an issue with the v4l2src element (in my case). maybe a camera problem??

do you use USB cameras? are they all on the same USB bus?

#7

Hello, zacwite:
when you run the GST pipeline @ #5, do you use on-board camera?
If you are using on-board camera, that’s not correct.
Jetson TX1 on-board camera (OV5693) is a raw sensor, and you need use nvcamerasrc.

if you are using USB camera, please make sure that the device node is correct.

br
Chenjian

#8

I’m re-opening this topic because I never really solved it, but I recently spent some more time diving into it.

I’m currently testing on the Connect Tech Astro carrier board, but I’ve seen the same behavior on the Connect Tech Orbitty and the nvidia TX1 dev board. All cameras are using the USB bus.

It seems like the problems I’m seeing are only with Leopard Imaging cameras and exist on the TX1, but not on my x86 machine. I have several leopard imaging cameras on hand and they all exhibit similar, but not identical behavior. I compared this with 2 other UVC cameras and did not see the slow start time behavior. It’s worth noting that the LI cameras are all USB3.0 and the other webcams are USB 2.0.

gstreamer version: 1.8.3 on all systems. USB3.0 memory size was tried at 16mb and 1000mb on the TX1 (no difference) and 16mb on the x86 using ubuntu 16.04 (jetpack 2.3)

My gstreamer pipeline is as basic as you can get:

gst-launch-1.0 --gst-debug-level=4 v4l2src device=/dev/video1 ! video/x-raw,width=1280,height=720,framerate=30/1 ! fakesink

The part of the logs that’s unique to the LI cameras is this:

0:00:01.213999488  2112       0x7e1630 INFO          v4l2bufferpool gstv4l2bufferpool.c:564:gst_v4l2_buffer_pool_set_config:<v4l2src0:pool:src> reducing maximum buffers to 32
0:00:01.214062670  2112       0x7e1630 INFO          v4l2bufferpool gstv4l2bufferpool.c:575:gst_v4l2_buffer_pool_set_config:<v4l2src0:pool:src> can't allocate, setting maximum to minimum
0:00:01.217868787  2112       0x7e1630 WARN          v4l2bufferpool gstv4l2bufferpool.c:748:gst_v4l2_buffer_pool_start:<v4l2src0:pool:src> Uncertain or not enough buffers, enabling copy threshold
0:00:01.394152979  2112       0x7e1630 WARN          v4l2bufferpool gstv4l2bufferpool.c:1196:gst_v4l2_buffer_pool_dqbuf:<v4l2src0:pool:src> Driver should never set v4l2_buffer.field to ANY
0:00:01.395029038  2112       0x7e1630 WARN          v4l2bufferpool gstv4l2bufferpool.c:1741:gst_v4l2_buffer_pool_process:<v4l2src0:pool:src> Invalid buffer size, this is likely due to a bug in your driver, dropping
0:00:01.395623006  2112       0x7e1630 WARN          v4l2bufferpool gstv4l2bufferpool.c:1958:gst_v4l2_buffer_pool_process:<v4l2src0:pool:src> Dropping corrupted buffer without payload
0:00:01.560146901  2112       0x7e1630 WARN          v4l2bufferpool gstv4l2bufferpool.c:1741:gst_v4l2_buffer_pool_process:<v4l2src0:pool:src> Invalid buffer size, this is likely due to a bug in your driver, dropping
0:00:01.560933139  2112       0x7e1630 WARN          v4l2bufferpool gstv4l2bufferpool.c:1958:gst_v4l2_buffer_pool_process:<v4l2src0:pool:src> Dropping corrupted buffer without payload
0:00:01.717875731  2112       0x7e1630 WARN          v4l2bufferpool gstv4l2bufferpool.c:1741:gst_v4l2_buffer_pool_process:<v4l2src0:pool:src> Invalid buffer size, this is likely due to a bug in your driver, dropping
0:00:01.718416603  2112       0x7e1630 WARN          v4l2bufferpool gstv4l2bufferpool.c:1958:gst_v4l2_buffer_pool_process:<v4l2src0:pool:src> Dropping corrupted buffer without payload

LI-10635
2nd time starting: ~20s
reboot
1st time starting: ~immediate
2nd time starting: 24s
3rd time starting: 38s
4th time starting: 43

Logitech C920
2fps, hi-res
1st time starting: 2s
2nd time starting: 2s
3rd time starting: 2s
reboot
1280x720x30fps
1st run failed - no /dev/video0 -> switched to /dev/video1
1st time starting: 0.5s
2nd time starting: 0.5s
3rd time starting: 0.5s

LI-AR023ZWDR
reboot
1280x720x30fps
1st time starting: 20 sec
2nd time starting: 76 sec

LI-M034-WDR
reboot
1280x720x30fps
1st time starting: 2s
2nd time starting: 19s
3rd time starting: 9s

SMI webcam
Reboot
640x480x30fps
1st start: 0.6s
2nd start: 1.2s
3rd start: 1.2s
4th start: 1.3s

Here’s a detailed log output of the LI-10635 camera on the TX1 followed by the same camera on x86_64 followed by the Logitech C920 log on the TX1

LI-10635 camera on the TX1 (2nd time starting in this boot session)
http://pastebin.com/Mge4YKHV

LI-10635 camera on x86_64 (2nd time starting in this boot session)
http://pastebin.com/kZ48yeYF

Logitech C920 on TX1
http://pastebin.com/2GLc4JDM

#9

Here’s another Leopard Imaging camera (LI-10640) starting with debug level 5

0:00:06.457329594  4837       0x62c630 DEBUG             GST_MEMORY gstmemory.c:138:gst_memory_init: new memory 0x429e50, maxsize:1843200 offset:0 size:1843200
0:00:06.457388551  4837       0x62c630 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:1378:gst_v4l2_buffer_pool_release_buffer:<v4l2src0:pool:src> release buffer 0x7fa800e030
0:00:06.457525111  4837       0x62c630 DEBUG             GST_MEMORY gstmemory.c:138:gst_memory_init: new memory 0x429ee0, maxsize:1843200 offset:0 size:1843200
0:00:06.457565735  4837       0x62c630 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:1378:gst_v4l2_buffer_pool_release_buffer:<v4l2src0:pool:src> release buffer 0x7fa800e140
0:00:06.457691721  4837       0x62c630 DEBUG             GST_MEMORY gstmemory.c:138:gst_memory_init: new memory 0x7fa8009070, maxsize:1843200 offset:0 size:1843200
0:00:06.457727345  4837       0x62c630 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:1378:gst_v4l2_buffer_pool_release_buffer:<v4l2src0:pool:src> release buffer 0x7fa800e250
0:00:06.457848957  4837       0x62c630 DEBUG             GST_MEMORY gstmemory.c:138:gst_memory_init: new memory 0x7fa8009100, maxsize:1843200 offset:0 size:1843200
0:00:06.457884634  4837       0x62c630 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:1378:gst_v4l2_buffer_pool_release_buffer:<v4l2src0:pool:src> release buffer 0x7fa800e360
0:00:06.457925987  4837       0x62c630 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:945:gst_v4l2_buffer_pool_flush_stop:<v4l2src0:pool:src> stop flushing
0:00:06.458671803  4837       0x62c630 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:623:gst_v4l2_buffer_pool_streamon:<v4l2src0:pool:src> Started streaming
0:00:06.458799404  4837       0x62c630 WARN               structure gststructure.c:1935:priv_gst_structure_append_to_gstring: No value transform to serialize field 'allocator' of type 'GArray'
0:00:06.458832841  4837       0x62c630 WARN               structure gststructure.c:1935:priv_gst_structure_append_to_gstring: No value transform to serialize field 'pool' of type 'GArray'
0:00:06.458863725  4837       0x62c630 WARN               structure gststructure.c:1935:priv_gst_structure_append_to_gstring: No value transform to serialize field 'meta' of type 'GArray'
0:00:06.458766696  4837       0x62c630 DEBUG                basesrc gstbasesrc.c:3146:gst_base_src_prepare_allocation:<v4l2src0> ALLOCATION (1) params: allocation query: 0x7fa8001f70, GstQueryAllocation, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)YUY2\,\ width\=\(int\)1280\,\ height\=\(int\)720\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive\,\ framerate\=\(fraction\)60/1", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL, meta=(GArray)NULL;
0:00:06.458929036  4837       0x62c630 DEBUG                basesrc gstbasesrc.c:2971:gst_base_src_set_allocation:<v4l2src0> activate pool
0:00:06.458956275  4837       0x62c630 DEBUG             bufferpool gstbufferpool.c:519:gst_buffer_pool_set_active:<v4l2src0:pool:src> pool was in the right state
0:00:06.458987212  4837       0x62c630 DEBUG                basesrc gstbasesrc.c:2456:gst_base_src_get_range:<v4l2src0> calling create offset 18446744073709551615 length 4096, time 0
0:00:06.459018930  4837       0x62c630 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:1300:gst_v4l2_buffer_pool_acquire_buffer:<v4l2src0:pool:src> acquire
0:00:06.459048930  4837       0x62c630 DEBUG               GST_POLL gstpoll.c:1195:gst_poll_wait: 0x7fa8001de0: timeout :99:99:99.999999999
0:00:46.637669794  4837       0x62c630 DEBUG               GST_POLL gstpoll.c:1066:gst_poll_fd_has_error: 0x7fa8001de0: fd (fd:5, idx:1) 0
0:00:46.638537279  4837       0x62c630 DEBUG          v4l2allocator gstv4l2allocator.c:1310:gst_v4l2_allocator_dqbuf:<v4l2src0:pool:src:allocator> driver pretends buffer is queued even if dequeue succeeded
0:00:46.638746234  4837       0x62c630 WARN          v4l2bufferpool gstv4l2bufferpool.c:1196:gst_v4l2_buffer_pool_dqbuf:<v4l2src0:pool:src> Driver should never set v4l2_buffer.field to ANY
0:00:46.638884513  4837       0x62c630 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:1704:gst_v4l2_buffer_pool_process:<v4l2src0:pool:src> process buffer 0x7fb1c31758
0:00:46.639291381  4837       0x62c630 DEBUG              GST_CLOCK gstclock.c:1056:gst_clock_get_internal_time:<GstSystemClock> internal time 0:05:45.844503172
0:00:46.639521273  4837       0x62c630 DEBUG              GST_CLOCK gstclock.c:1101:gst_clock_get_time:<GstSystemClock> adjusted time 0:05:45.844503172
0:00:46.639717207  4837       0x62c630 WARN                 v4l2src gstv4l2src.c:797:gst_v4l2src_create:<v4l2src0> Timestamp does not correlate with any clock, ignoring driver timestamps
0:00:46.639849289  4837       0x62c630 INFO                 v4l2src gstv4l2src.c:843:gst_v4l2src_create:<v4l2src0> sync to 0:00:00.016666666 out ts 0:00:40.292056254
#10

Hi zacwite,

We’re investigating this issue, and will do the update once we have the result.
Besides, have you contact with Leopard to ask for help on this issue?

Thanks

#11

We have tried talking to Leopard, but they’re not very responsive. And unfortunately we can’t find any other USB3 cameras that use the UVC driver with v4l2 so we can’t get a good comparison there. We do have 2 Point Grey blackfly cameras that we’ll try writing an equivalent test for later.

Here are a few more data points.

We’ve tried this same test on an nvidia dev board using L4T 23.2.0 and we don’t see the same long startup behavior. The same gstreamer command I used above starts within a few seconds almost every time.

We have also created a test that uses a raw v4l2 driver instead of gstreamer and we see the same behavior. This program is a hacked version of a v4l2 capture that counts frames and the time between frames because we’re seeing some inconsistency there. You can see that script and try it yourself here: http://pastebin.com/mZbecZ2S

When we try connecting several cameras at once we see very flaky behavior on the USB stack. Often the entire USB stack crashes, though the behavior is inconsistent. Here’s a syslog output of one such event on a TX1 using a connecttech astro carrier board running Jetpack 2.3.1.

[ 2383.501000] smmu_dump_pagetable(): fault_address=0x0000000000000000 pa=0xffffffffffffffff bytes=ffffffffffffffff #pte=0 in L2
[ 2383.512662] mc-err: (20) csr_xusb_hostr: EMEM decode error on PDE or PTE entry
[ 2383.520242] mc-err:   status = 0x6000004a; addr = 0x00000000
[ 2383.526143] mc-err:   secure: no, access-type: read, SMMU fault: nr-nw-s
[ 2386.705332] tegra-xhci tegra-xhci: Firmware reinit.
[ 2398.496804] tegra-xhci tegra-xhci: xHCI host not responding to stop endpoint command.
[ 2398.496923] tegra-xhci tegra-xhci: Assuming host is dying, halting host.
[ 2398.596603] tegra-xhci tegra-xhci: Host not halted after 16000 microseconds.
[ 2398.596901] tegra-xhci tegra-xhci: Non-responsive xHCI host is not halting.
[ 2398.596982] tegra-xhci tegra-xhci: Completing active URBs anyway.
[ 2398.597213] r8152 2-1:1.0 eth1: Stop submitting intr, status -108
[ 2398.598139] tegra-xhci tegra-xhci: HC died; cleaning up
[ 2398.603582] tegra_xhci_hcd_reinit: hcd_reinit is disabled
[ 2398.604411] usb 1-3: USB disconnect, device number 3
[ 2398.625644] usb 2-1: USB disconnect, device number 2
[ 2398.808854] usb 2-2: USB disconnect, device number 3
[ 2398.808931] usb 2-2.1: USB disconnect, device number 4
[ 2398.907802] usb 2-2.2: USB disconnect, device number 5
[ 2399.007234] usb 2-2.3: USB disconnect, device number 6
[ 2399.159797] usb 2-2.4: USB disconnect, device number 7
#12

Oh I forgot one more data point. I noticed that if I’m using a USB hub and I move the camera between different points for each test it starts immediately. But if I move it back to a port that has previously been used without rebooting the TX1 I get a long startup time again. It suggests to me that there may be some kind of cache or buffer associated with a specific USB port that gets corrupted or is not properly freed.

#13

Continuing to do more tests and will add more data here. I’m trying to nail down the difference between jetpack 2.1 and 2.3.1. I have 2 nvidia tx1 dev boards set up with the two versions of jetpack and L4T, freshly flashed. Setup is otherwise identical. I ran the v4l script I linked to above on both with 3 cameras and recorded the startup times and behavior. Previously I mentioned the camera seemed to start up instantly every time on Jetpack 2.1, which doesn’t strictly seem to be the case. With a single camera, after the first one or two times starting the camera I get exactly 4 frames, then a big pause, and finally it resumes again about 20-40 seconds later. On Jetpack 2.3.1 it simply waits 20-40 seconds before sending any frames at all.

In addition, when adding more cameras simultaneously Jetpack 2.1 performs more reliably than Jetpack 2.3.1.

Jetpack 2.1
Rebooted the TX1. On the 1st test 2 cameras started immediately and the 3rd started after 20 seconds, then all continued as normal. 2nd test I got 4 frames from all 3 cameras, then a 42, 57, 42 second gaps until the next frames when it continued without issue. 3rd test, all cameras started receiving frames immediately and continued without problems. No gaps this time. 4th test all cameras got 4 frames, then 40, 27, 34 sec gaps, then continued without issue. 5th test all cameras got 4 frames then 40, 40, 20 sec gaps.

Jetpack 2.3.1
Rebooted the TX1. On the 1st test 2 of the cameras started immediately, but with very inconsistent frame rates, then the 3rd camera started 20 seconds later, then all continued as normal with minimal slow frames. 2nd test completely timed out. 3rd test one camera started after 90 seconds but had several incidents with slow frames, another camera started after 125 seconds (no slow frames) and the final started after 135s (no slow frames). 4th test only 3rd camera started after 95s and the other 2 never started in the 150 sec test window. 5th test seems to have crashed the USB bus and network, forcing a hard reset.

#14

Hi zacwite,

Have you tried to Boost CPU to max performance and see if that resolves issue?
You can refer to http://elinux.org/Jetson/TX1_Controlling_Performance

Thanks

#15

Hi zacwite,
Please try the attachment with max performance.

(An issue in adding attachment; will upload once it gets resolved)
r24_2_1_usb3_pre_release.zip (78.3 KB)

#16

Thanks - I’m trying to download the file, but when I click on the link attachment I get a blank page.

#17

Hi,

We are experiencing the same problem, however I have not been able to download the .zip file.

Regards,

#18

Hi,

I have applied the patches and I have replaced the /lib/firmware/tegra21x_xusb_firmware file with the one provided in the zip file as follows:

Old firmware sha1sum:
ubuntu@tegra-ubuntu:~$ sha1sum tegra21x_xusb_firmware
c06c362abfc9ced19fbf0515f9403efec14078a0 tegra21x_xusb_firmware

New firmware sha1sum:
ubuntu@tegra-ubuntu:~$ sha1sum xusb_sil_rel_fw
503a93e01ee5230a9b6b13cb3ab0426ae6765d60 xusb_sil_rel_fw

Replaced firmware sha1sum:
ubuntu@tegra-ubuntu:~$ sha1sum /lib/firmware/tegra21x_xusb_firmware
503a93e01ee5230a9b6b13cb3ab0426ae6765d60 /lib/firmware/tegra21x_xusb_firmware

However after restarting the board the log still reports V50.16 instead of V50.18 as follows:

[    3.450349] tegra-xhci tegra-xhci: Firmware timestamp: 2016-06-16 13:21:43 UTC, Version: 50.16 release, Falcon state 0x20

One interesting thing is that I just tested removing the /lib/firmware/tegra21x_xusb_firmware file and restarted the board and it seems like the system is loading the firmware somehow from another place:

ubuntu@tegra-ubuntu:~$ dmesg | grep xhci
[    3.204360] tegra-xhci tegra-xhci: XUSB device id = 0xfac (T210)
[    3.211985] tegra-xhci tegra-xhci: Firmware File: tegra21x_xusb_firmware (124416 Bytes)
[    3.222208] tegra-xhci tegra-xhci: Firmware DMA Memory: dma 0x0000000080040000 mapped 0xffffff8000339000 (124416 Bytes)
[    3.448124] tegra-xhci tegra-xhci: num_hsic_port 0
[    3.455980] tegra-xhci tegra-xhci: Firmware timestamp: 2016-06-16 13:21:43 UTC, Version: 50.16 release, Falcon state 0x20
[    3.468855] tegra-xhci tegra-xhci: Nvidia xHCI Host Controller
[    3.475649] tegra-xhci tegra-xhci: new USB bus registered, assigned bus number 1
[    3.485668] tegra-xhci tegra-xhci: irq 71, io mem 0x70090000
[    3.516196] usb usb1: Manufacturer: Linux 3.10.96-tegra tegra-xhci
[    3.523546] usb usb1: SerialNumber: tegra-xhci
[    3.529387] xHCI xhci_add_endpoint called for root hub
[    3.529394] xHCI xhci_check_bandwidth called for root hub
[    3.612187] tegra-xhci tegra-xhci: Nvidia xHCI Host Controller
[    3.619193] tegra-xhci tegra-xhci: new USB bus registered, assigned bus number 2
[    3.654172] usb usb2: Manufacturer: Linux 3.10.96-tegra tegra-xhci
[    3.661822] usb usb2: SerialNumber: tegra-xhci
[    3.676641] xHCI xhci_add_endpoint called for root hub
[    3.676643] xHCI xhci_check_bandwidth called for root hub
[    4.001439] usb 2-2: new SuperSpeed USB device number 2 using tegra-xhci
[    5.661053] input: LI-10635 as /devices/platform/tegra-xhci/usb2/2-2/2-2:1.0/input/input0
[    5.937572] usb 2-1: new SuperSpeed USB device number 3 using tegra-xhci
[    6.892770] usb 2-1: reset SuperSpeed USB device number 3 using tegra-xhci
ubuntu@tegra-ubuntu:~$ ls /lib/firmware/
bcm4354.hcd  brcm  hp  tegra21x  tigon

So it seems like I am missing something there.

Regards,

#19

Hi all,

Please disregard my previous message I just realized I was using the XHCI driver built-in so the TX1 is using the firmware that is into the ramfs image. I will test with the module support.

Regards,

#20

Hi zacwite and MarcoMadrigal,

Any test result can be shared?
Does it work?

Thanks