Bad video output performance of arv-viewer

[mikekml]

Describe the bug

There is error message on the screen while accessing the camera

(arv-viewer-0.8:6438): WARNING : 18:26:00.964: Failed to make stream thread high priority

arv-viewer-0.8 is running with 66MB/s and 44 FPS and visible latency between object movement and display on the screen.

moreover while monitoring in top or jtop ( for jetson ) - arv-viewer consumes 250% CPU in user mode while pylon only 45%

To Reproduce Compile and run arv-viewer on AGX Xavier with latest jetpack with Basler camera connected to USB3 port. All default settings.

install basler pylon 5.2 and run on the same system to see the difference in FPS

Expected behavior

Basler Pylon 5.2 proprietary software works with the same camera on the same board with 300MB/s read and 200 FPS frame rate and no visible latency.

Camera description:

• Basler
• acA1440-220um
• USB3

Platform description:

• Aravis version 0.8 ( aravis-0.7.3 build )
• OS: Jetpack [L4T 32.2.3] / Ubuntu 18.04 provided by Nvidia JetPack
• NVIDIA Jetson AGX Xavier

Additional context Add any other context about the problem here.

[EmmanuelP]

Yes, the performance of the video display in arv-viewer is really lacking, not only on ARM platform like AGX Xavier. It is mostly an issue in gtksink gstreamer element. You should be able to obtain better performances using a gstreamer pipeline with autovideosink or ximagesink.

I would be interested in the performance figures of the data streaming (buffer read without any display or processing). What is the CPU use of arv-camera-test with the maximum FPS ?

[mikekml]

Hi Emanuel,

here is the log of arv-camera-test

Looking for the first available camera vendor name = Basler model name = acA1440-220um device id = (null) image width = 1440 image height = 1024 horizontal binning = 1 vertical binning = 1 payload = 1474560 bytes exposure = 1000 µs gain = 11 dB uv bandwidth limit = -1 [524288..419430400] Frame rate = 110 Hz Frame rate = 125 Hz Frame rate = 124 Hz Frame rate = 124 Hz ^CFrame rate = 124 Hz Completed buffers = 607 Failures = 0 Underruns = 0

It looks like the framerate is now better, but it is still around half of what PylonViewer can pull of the camera

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 24679 argos 20 0 199724 83444 6132 S 55.1 0.5 0:16.93 arv-camera-test

CPU usage is less, but kernel load is still way higher then in pylon case.

%Cpu(s): 1.7 us, 7.8 sy, 0.0 ni, 83.3 id, 0.0 wa, 7.1 hi, 0.1 si, 0.0 st

Im new to gstreamer and Aravis. can you please provide more info on how to use

gstreamer pipeline with autovideosink or ximagesink and Aravis viewer

thanks and regards, -Mike

[jajberni]

I came across the same issue and the poor CPU performance on a Jetson TX2. What I noticed is that the root process "ksoftirqd/0" is using a core on its own at 100%.

That seems to cause missing packets.

[GvDevice::new] Packet resend = yes
[GvDevice::new] Write memory = yes
[GvDevice::new] Legacy endianess handling = yes
[ArvCamera:_update_status] node 'ChunkModeActive' not found (Status changed)
vendor name           = Photonfocus AG
model name            = MV1-D2048x1088-HS05-96-G2-10
device id             = ...
image width           = 2048
image height          = 1088
horizontal binning    = 1
vertical binning      = 1
payload               = 2228224 bytes
exposure              = 2511.56 µs
gain                  = 1 dB
gv n_stream channels  = 1
gv current channel    = 0
gv packet delay       = 0 ns
gv packet size        = 1476 bytes
[GvDevice::create_stream] Number of stream channels = 1
[GvStream::stream_new] Packet size = 1476 byte(s)
[GvStream::stream_new] Destination stream port = 60153
[GvStream::stream_new] Source stream port = 20202
[GvStream::stream_thread] Packet timeout = 20 ms
[GvStream::stream_thread] Frame retention = 100 ms
[GvStream::loop] Standard socket method
[GvStream::process_packet] Error packet at dt = 50162, packet id = 1549 frame id = 4
packet_type  =   (null) (0x4004)
content_type =  trailer (0x0002)

[GvStream::process_packet] Error packet at dt = 48492, packet id = 1549 frame id = 5
packet_type  =   (null) (0x4004)
content_type =  trailer (0x0002)

[GvStream::process_packet] Error packet at dt = 47343, packet id = 1549 frame id = 6
packet_type  =   (null) (0x4004)
content_type =  trailer (0x0002)

[GvStream::check_frame_completion] Timeout for frame 4 at dt = 150164
[GvStream::process_packet] Error packet at dt = 47604, packet id = 1549 frame id = 7
packet_type  =   (null) (0x4004)
content_type =  trailer (0x0002)

[GvStream::check_frame_completion] Timeout for frame 5 at dt = 148704
[GvStream::process_packet] Error packet at dt = 47733, packet id = 1549 frame id = 8
packet_type  =   (null) (0x4004)
content_type =  trailer (0x0002)

[GvStream::check_frame_completion] Timeout for frame 6 at dt = 147569
[GvStream::process_packet] Error packet at dt = 49136, packet id = 1549 frame id = 9
packet_type  =   (null) (0x4004)
content_type =  trailer (0x0002)

[GvStream::check_frame_completion] Timeout for frame 7 at dt = 147979
[GvStream::process_packet] Error packet at dt = 48062, packet id = 1549 frame id = 10
packet_type  =   (null) (0x4004)
content_type =  trailer (0x0002)

[GvStream::check_frame_completion] Timeout for frame 8 at dt = 147774
[GvStream::process_packet] Error packet at dt = 48208, packet id = 1549 frame id = 11
packet_type  =   (null) (0x4004)
content_type =  trailer (0x0002)

[GvStream::check_frame_completion] Timeout for frame 9 at dt = 149481
[GvStream::process_packet] Error packet at dt = 47749, packet id = 1549 frame id = 12
packet_type  =   (null) (0x4004)
content_type =  trailer (0x0002)
...
[GvStream::finalize] n_completed_buffers    = 3
[GvStream::finalize] n_failures             = 34
[GvStream::finalize] n_timeouts             = 34
[GvStream::finalize] n_aborteds             = 3
[GvStream::finalize] n_underruns            = 0
[GvStream::finalize] n_missing_frames       = 0
[GvStream::finalize] n_size_mismatch_errors = 0
[GvStream::finalize] n_received_packets     = 61690
[GvStream::finalize] n_missing_packets      = 34
[GvStream::finalize] n_error_packets        = 36
[GvStream::finalize] n_ignored_packets      = 0
[GvStream::finalize] n_resend_requests      = 155
[GvStream::finalize] n_resent_packets       = 151
[GvStream::finalize] n_duplicated_packets   = 0
[Stream::finalize] Flush 47 buffer[s] in input queue
[Stream::finalize] Flush 3 buffer[s] in output queue

I am using a Photonfocus camera (runs on Pleora eBUS) with direct Ethernet connection (no switch). I have tested that iperf from the jetson to a computer yields 935Mbit/s without any CPU issues.

I hope this helps.

Thanks for the amazing work put into this project! Berni

[jajberni]

I found out that the intensive CPU issue was due to the small packet size (1476 bytes by default). Increasing it to 8192 decreased dramatically the CPU usage (about 7% with arv-camera-test):

arv-tool-0.8 control GevSCPSPacketSize=8192

However, I am still getting the weird packet errors that I posted before and timeouts, especially when using the viewer.

[EmmanuelP]

@jajberni Please open another issue, GigEVision and USB3Vision aravis codes have nothing in common.

[EmmanuelP]

@mikekml could you try with arv-camera-test -f 200 ?

[EmmanuelP]

Im new to gstreamer and Aravis. can you please provide more info on how to use gstreamer pipeline with autovideosink or ximagesink and Aravis viewer

@mikekml from the meson build directory, try: ./gst/gst-aravis-launch aravissrc ! videoconvert ! ximagesink

[to266]

I have a similarly pool performance of the aravis-viewer on Nvidia Jetson TX2 with JAI GO-5100M via usb3.

Could post the arv-camera-test a bit later, as currently the CPU is super loaded by other things, and it would bias..

[to266]

On a desktop hardware the same camera was able to support around 73fps at the same full resolution, and thus the test:

$ ./arv-camera-test -f 75
Looking for the first available camera
vendor name           = JAI Corporation
model name            = GO-5100M-USB
device id             = (null)
image width           = 2464
image height          = 2056
horizontal binning    = 1
vertical binning      = 1
payload               = 5065984 bytes
exposure              = 1286 µs
gain                  = 10 dB
uv bandwidth limit     = 0 [0..-1]
Frame rate = 43 Hz
Frame rate = 37 Hz
Frame rate = 32 Hz
Frame rate = 34 Hz
^CFrame rate = 30 Hz
Completed buffers = 176
Failures          = 0
Underruns         = 0

$ ./gst/gst-aravis-launch aravissrc ! videoconvert ! ximagesink
Setting pipeline to PAUSED ...
Pipeline is live and does not need PREROLL ...
Setting pipeline to PLAYING ...
New clock: GstSystemClock
/GstPipeline:pipeline0/GstAravis:aravis0.GstPad:src: caps = video/x-raw, format=(string)GRAY8, width=(int)2464, height=(int)2056, framerate=(fraction)74/1, pixel-aspect-ratio=(fraction)1/1
/GstPipeline:pipeline0/GstVideoConvert:videoconvert0.GstPad:src: caps = video/x-raw, width=(int)2464, height=(int)2056, framerate=(fraction)74/1, pixel-aspect-ratio=(fraction)1/1, format=(string)BGRx
/GstPipeline:pipeline0/GstXImageSink:ximagesink0.GstPad:sink: caps = video/x-raw, width=(int)2464, height=(int)2056, framerate=(fraction)74/1, pixel-aspect-ratio=(fraction)1/1, format=(string)BGRx
/GstPipeline:pipeline0/GstVideoConvert:videoconvert0.GstPad:sink: caps = video/x-raw, format=(string)GRAY8, width=(int)2464, height=(int)2056, framerate=(fraction)74/1, pixel-aspect-ratio=(fraction)1/1
WARNING: from element /GstPipeline:pipeline0/GstXImageSink:ximagesink0: A lot of buffers are being dropped.
Additional debug info:
gstbasesink.c(2902): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstXImageSink:ximagesink0:
There may be a timestamping problem, or this computer is too slow.
/GstPipeline:pipeline0/GstAravis:aravis0.GstPad:src: caps = video/x-raw, format=(string)GRAY8, width=(int)2145, height=(int)1578, framerate=(fraction)74/1, pixel-aspect-ratio=(fraction)1/1
/GstPipeline:pipeline0/GstVideoConvert:videoconvert0.GstPad:src: caps = video/x-raw, width=(int)2145, height=(int)1578, framerate=(fraction)74/1, pixel-aspect-ratio=(fraction)1/1, format=(string)BGRx
/GstPipeline:pipeline0/GstXImageSink:ximagesink0.GstPad:sink: caps = video/x-raw, width=(int)2145, height=(int)1578, framerate=(fraction)74/1, pixel-aspect-ratio=(fraction)1/1, format=(string)BGRx
/GstPipeline:pipeline0/GstVideoConvert:videoconvert0.GstPad:sink: caps = video/x-raw, format=(string)GRAY8, width=(int)2145, height=(int)1578, framerate=(fraction)74/1, pixel-aspect-ratio=(fraction)1/1
WARNING: from element /GstPipeline:pipeline0/GstXImageSink:ximagesink0: A lot of buffers are being dropped.
Additional debug info:
gstbasesink.c(2902): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstXImageSink:ximagesink0:
There may be a timestamping problem, or this computer is too slow.
WARNING: from element /GstPipeline:pipeline0/GstXImageSink:ximagesink0: A lot of buffers are being dropped.
Additional debug info:
gstbasesink.c(2902): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstXImageSink:ximagesink0:
There may be a timestamping problem, or this computer is too slow.
WARNING: from element /GstPipeline:pipeline0/GstXImageSink:ximagesink0: A lot of buffers are being dropped.
Additional debug info:
gstbasesink.c(2902): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstXImageSink:ximagesink0:
There may be a timestamping problem, or this computer is too slow.
ERROR: from element /GstPipeline:pipeline0/GstXImageSink:ximagesink0: Output window was closed
Additional debug info:
ximagesink.c(697): gst_x_image_sink_handle_xevents (): /GstPipeline:pipeline0/GstXImageSink:ximagesink0
Execution ended after 0:00:39.192048720
Setting pipeline to PAUSED ...
Setting pipeline to READY ...
Setting pipeline to NULL ...
Freeing pipeline ...

Not sure if the computer is actually too slow as the warning above says?

[mikekml]

@mikekml could you try with arv-camera-test -f 200 ?

Hi Emanuel,

we found in one of the older versions of aravis implementation of asynchronous bulk request handling which, in our case, worked better than the latest version synchronous implementation.

when we traced libusb during pylon execution - we noticed asynchronous bulk request handling as well.

once we ran the older version, we got maximal frame rate from our camera ( 227 FPS ), but the throughput that we saw ( using usbtop ) on respective usb end point was significantly lower than when running with pylon.

we managed to get to the throughput similar to pylon after changing the following constants

// #define ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE (102410241) // #define ARV_UV_STREAM_MAXIMUM_SUBMIT_TOTAL (810241024)

to

define ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE (65536) // similar to pylon

define ARV_UV_STREAM_MAXIMUM_SUBMIT_TOTAL (1555200) // similar to pylon

after the above changes + async bulk, arv-camera-test behaves exactly as pylon.

however, when we run arv-viewer, built from the same source, the frame-rate/ usb throughput drop x3 ..

additional observation: after the above changes there is no latency in real-time video in arv-viewer.

i haven't check the source code yet, but my assumption is that it somehow drops frames, but it is showing latest frames such that there is no visual latency in video. ( by visual latency i mean an effect when you wave your hand quickly in front of the camera and it appears tens of milliseconds after the actual waving - this is what happening with latest versions with synchronous bulk handling ).

so far so good.

the question is whether it will be possible to bring async bulk request handling to upstream versions ? it looks like it may be very useful for high speed cameras, like the one that we have.

thanks and regards, -mike

[mikekml]

Im new to gstreamer and Aravis. can you please provide more info on how to use gstreamer pipeline with autovideosink or ximagesink and Aravis viewer

@mikekml from the meson build directory, try: ./gst/gst-aravis-launch aravissrc ! videoconvert ! ximagesink

works only in latest ( meson ) versions. tried to run it - it looks like it works faster than arvplayer, but it does not support window resize, etc and in general is not as robust as viewer app.

also, observed that it is way less cpu hungry than the viewer.

from my perspective it will be interesting to test it with async bulk handling.

[dmitryalferov]

the throughput that we saw ( using usbtop ) on respective usb end point was significantly lower than when running with pylon.

Hi @mikekml, I think I've encountered similar behaviour and it turned out to be a bug in a libpcap (used by usbtop). Due to this bug packet lengths on the usbmon binary interface were delivered incorrectly, see this issue for more information about this bug.

In my case actual throughput was the same for both pylon and aravis (I've verified that via usbmon text interface), even though reported transmission via usbtop was 16 times less for aravis.

Ultimately I wouldn't rely on the usbtop readings that much.

[mikekml]

the throughput that we saw ( using usbtop ) on respective usb end point was significantly lower than when running with pylon.

Hi @mikekml, I think I've encountered similar behaviour and it turned out to be a bug in a libpcap (used by usbtop). Due to this bug packet lengths on the usbmon binary interface were delivered incorrectly, see this issue for more information about this bug.

In my case actual throughput was the same for both pylon and aravis (I've verified that via usbmon text interface), even though reported transmission via usbtop was 16 times less for aravis.

Ultimately I wouldn't rely on the usbtop readings that much.

we noticed that too, but it is till useful to see relative changes between different runs the main problem as i see it is in async bulk request vs sync bulk request handling. it looks like async works better

[EmmanuelP]

@mikekml , @crabsmaps Please comment on USB3Vision performance in https://github.com/AravisProject/aravis/issues/324