bmegli commented 1 year ago

Identified in:

https://github.com/Extend-Robotics/camera_aravis/issues/8#issuecomment-1653470487

With correct exposure for 3D sensor and higher framerate we end up with buffer timeouts

[ WARN] [1690459276.030151756]: (range_optical_frame (and possibly subframes)) Frame error: ARV_BUFFER_STATUS_TIMEOUT

bmegli commented 1 year ago

Potentially related:

https://github.com/AravisProject/aravis/issues/118

bmegli commented 1 year ago

A quick computation:

1120x800 depth + texture
- depth is float (4 Bpp)
- texture is Mono16 encoded subsampled YCoCg (2 Bpp)
fps is around 10 (#8)

1120800 (4 + 2) * 10 = 53760000 Bps ~= 53 MBps ~= 430 Mbps

which is roughly half the wire bandwidth (1 Gbps)

bmegli commented 1 year ago

Implemented simple mechanism for benchmarking buffer processing time.

After enabling symbol ARAVIS_BUFFER_PROCESSING_BENCHMARK

multipart 0 has very high variance in processing time
- it looks like YCoCg pixel format conversion is inefficient
multipart 1 is quick
but even processing time reaching 30 ms should not be a problem
- unless we are working from within aravis thread and blocking communication

[ INFO] [1690462739.665337492]: aravis stream 0 part 0 buffer processing time: 10.4707 ms
[ INFO] [1690462739.667313419]: aravis stream 0 part 1 buffer processing time: 1.91909 ms
[ INFO] [1690462739.667346820]: aravis stream 0 buffer processing time: 12.5076 ms
[ INFO] [1690462739.754681279]: aravis stream 0 part 0 buffer processing time: 25.9332 ms
[ INFO] [1690462739.756270984]: aravis stream 0 part 1 buffer processing time: 1.50684 ms
[ INFO] [1690462739.756333473]: aravis stream 0 buffer processing time: 27.6191 ms
[ INFO] [1690462739.879880420]: aravis stream 0 part 0 buffer processing time: 26.1639 ms
[ INFO] [1690462739.881452846]: aravis stream 0 part 1 buffer processing time: 1.49807 ms
[ INFO] [1690462739.881500740]: aravis stream 0 buffer processing time: 27.8209 ms
[ INFO] [1690462739.957829111]: aravis stream 0 part 0 buffer processing time: 11.8888 ms
[ INFO] [1690462739.959096585]: aravis stream 0 part 1 buffer processing time: 1.19573 ms
[ INFO] [1690462739.959156050]: aravis stream 0 buffer processing time: 13.2366 ms
[ INFO] [1690462740.056361011]: aravis stream 0 part 0 buffer processing time: 16.7299 ms
[ INFO] [1690462740.058637255]: aravis stream 0 part 1 buffer processing time: 2.13027 ms
[ INFO] [1690462740.058769919]: aravis stream 0 buffer processing time: 19.1655 ms
[ INFO] [1690462740.164435852]: aravis stream 0 part 0 buffer processing time: 26.8407 ms
[ INFO] [1690462740.166934048]: aravis stream 0 part 1 buffer processing time: 2.38548 ms
[ INFO] [1690462740.167036681]: aravis stream 0 buffer processing time: 29.4635 ms
[ INFO] [1690462740.251925277]: aravis stream 0 part 0 buffer processing time: 6.8609 ms
[ INFO] [1690462740.253082640]: aravis stream 0 part 1 buffer processing time: 1.10389 ms
[ INFO] [1690462740.253158388]: aravis stream 0 buffer processing time: 8.07912 ms
[ INFO] [1690462740.384299451]: aravis stream 0 part 0 buffer processing time: 29.7347 ms
[ INFO] [1690462740.386481826]: aravis stream 0 part 1 buffer processing time: 2.08076 ms
[ INFO] [1690462740.386583211]: aravis stream 0 buffer processing time: 32.038 ms
[ WARN] [1690462740.665368187]: (range_optical_frame (and possibly subframes)) Frame error: ARV_BUFFER_STATUS_TIMEOUT
[ INFO] [1690462740.682071662]: aravis stream 0 part 0 buffer processing time: 16.5571 ms
[ INFO] [1690462740.683372160]: aravis stream 0 part 1 buffer processing time: 1.2209 ms
[ INFO] [1690462740.683426432]: aravis stream 0 buffer processing time: 17.9261 ms
[ INFO] [1690462740.691184916]: aravis stream 0 part 0 buffer processing time: 7.68865 ms
[ INFO] [1690462740.692501232]: aravis stream 0 part 1 buffer processing time: 1.24227 ms
[ INFO] [1690462740.692587418]: aravis stream 0 buffer processing time: 9.086 ms
[ WARN] [1690462740.969725412]: (range_optical_frame (and possibly subframes)) Frame error: ARV_BUFFER_STATUS_TIMEOUT
[ INFO] [1690462741.005212123]: aravis stream 0 part 0 buffer processing time: 35.2781 ms
[ INFO] [1690462741.006940091]: aravis stream 0 part 1 buffer processing time: 1.65328 ms
[ INFO] [1690462741.007012881]: aravis stream 0 buffer processing time: 37.0995 ms
[ INFO] [1690462741.019608276]: aravis stream 0 part 0 buffer processing time: 12.5148 ms
[ INFO] [1690462741.020673910]: aravis stream 0 part 1 buffer processing time: 1.01912 ms
[ INFO] [1690462741.020727946]: aravis stream 0 buffer processing time: 13.6449 ms
[ WARN] [1690462741.242109397]: (range_optical_frame (and possibly subframes)) Frame error: ARV_BUFFER_STATUS_TIMEOUT
[ INFO] [1690462741.271582412]: aravis stream 0 part 0 buffer processing time: 29.3058 ms
[ INFO] [1690462741.273663954]: aravis stream 0 part 1 buffer processing time: 1.97053 ms
[ INFO] [1690462741.273763919]: aravis stream 0 buffer processing time: 31.5096 ms
[ INFO] [1690462741.385462820]: aravis stream 0 part 0 buffer processing time: 29.8288 ms
[ INFO] [1690462741.387391078]: aravis stream 0 part 1 buffer processing time: 1.85495 ms
[ INFO] [1690462741.387500258]: aravis stream 0 buffer processing time: 31.9499 ms
[ INFO] [1690462741.399952056]: aravis stream 0 part 0 buffer processing time: 12.3273 ms
[ INFO] [1690462741.401068366]: aravis stream 0 part 1 buffer processing time: 1.06743 ms
[ INFO] [1690462741.401112306]: aravis stream 0 buffer processing time: 13.5276 ms
[ WARN] [1690462741.671536913]: (range_optical_frame (and possibly subframes)) Frame error: ARV_BUFFER_STATUS_TIMEOUT
[ INFO] [1690462741.708128469]: aravis stream 0 part 0 buffer processing time: 36.3422 ms
[ INFO] [1690462741.709729606]: aravis stream 0 part 1 buffer processing time: 1.53228 ms
[ INFO] [1690462741.709790831]: aravis stream 0 buffer processing time: 38.0265 ms
[ INFO] [1690462741.721367279]: aravis stream 0 part 0 buffer processing time: 11.4566 ms
[ INFO] [1690462741.722490752]: aravis stream 0 part 1 buffer processing time: 1.074 ms
[ INFO] [1690462741.722528081]: aravis stream 0 buffer processing time: 12.659 ms
[ WARN] [1690462741.933148634]: (range_optical_frame (and possibly subframes)) Frame error: ARV_BUFFER_STATUS_TIMEOUT
[ INFO] [1690462741.940732913]: aravis stream 0 part 0 buffer processing time: 7.5115 ms
[ INFO] [1690462741.941961921]: aravis stream 0 part 1 buffer processing time: 1.18022 ms
[ INFO] [1690462741.942030225]: aravis stream 0 buffer processing time: 8.81158 ms
[ INFO] [1690462741.966729728]: aravis stream 0 part 0 buffer processing time: 8.72919 ms
[ INFO] [1690462741.967749869]: aravis stream 0 part 1 buffer processing time: 0.968633 ms
[ INFO] [1690462741.967794659]: aravis stream 0 buffer processing time: 9.81357 ms
[ INFO] [1690462742.077307619]: aravis stream 0 part 0 buffer processing time: 20.6872 ms
[ INFO] [1690462742.078820195]: aravis stream 0 part 1 buffer processing time: 1.44328 ms
[ INFO] [1690462742.078882009]: aravis stream 0 buffer processing time: 22.3139 ms
[ INFO] [1690462742.146145885]: aravis stream 0 part 0 buffer processing time: 8.43478 ms
[ INFO] [1690462742.147110904]: aravis stream 0 part 1 buffer processing time: 0.917262 ms
[ INFO] [1690462742.147149044]: aravis stream 0 buffer processing time: 9.45579 ms

bmegli commented 1 year ago

Buffer processing is done through glib signals callback

https://github.com/Extend-Robotics/camera_aravis/blob/9f8c029c69222fa4e72ea992717a858a5d1966f4/src/camera_aravis_nodelet.cpp#L1014

bmegli commented 1 year ago

Docs for g_signal_connect

https://github.com/GNOME/glib/blob/7e9db39996de5faf7c28cbea98909b6cd3caba73/gobject/gsignal.h#L497

The handler will be called synchronously, before the default handler of the signal. g_signal_emit() will not return control until all handlers are called.

In the context of my earlier comment

but even processing time reaching 30 ms should not be a problem

unless we are working from within aravis thread and blocking communication

The second condition case is probably happening and internal communication thread may be blocked

bmegli commented 1 year ago

aravis exmple that exactly covers this case

https://github.com/AravisProject/aravis-c-examples/blob/main/02-multiple-acquisition-signal.c#L23

And this is another confirmation or the problem diagnosis

    /* This code is called from the stream receiving thread, which means all the time spent there is less time
     * available for the reception of incoming packets */

bmegli commented 1 year ago

Problem Cause

"new-buffer" signal callback is called from aravis network processing thread
camera_aravis has complex logic with pixel format conversions and ROS publishing in signal handler
if spending too much time on processing we are blocking network processing thread

bmegli commented 1 year ago

Problem Solution

Decouple signal handler from buffer processing

buffer processing should happen in different thread

bmegli commented 1 year ago

Fixed in #12

ARV_BUFFER_STATUS_TIMEOUT no longer happens

bmegli commented 9 months ago

MotionCam bandwidth at 10 FPS with raw RGB

(11208004 + 19321096 2)* 10/1024/1024 = 74 MB ~= 600 Mb

Extend-Robotics / camera_aravis

aravis buffer timeouts #10

Problem Cause

Problem Solution