Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bug during the transfer that prevents the transmission of the complete payload #314

Open
richard-mccrae opened this issue Nov 21, 2019 · 17 comments
Labels
1. bug Problems, incorrect behavior or appearance 1. Performance Performance issue 4. Help wanted Help is welcome to resolve the issue 5. Usb3 Issue in USB3Vision implementation

Comments

@richard-mccrae
Copy link

Describe the bug
Bug during video transfer that prevents the transmission of the complete payload. Streaming from Allied Vision GeniCam with resolution greater than approx. 350x350 results in "Incomplete image received, dropping"

To Reproduce
Using an Allied Vision Alvium 1800-500c camera, attempt the following pipeline:
gst-launch-1.0 -e aravissrc camera-name="Allied Vision-xxxxx"
! video/x-raw,format=GRAY8,width=2592,height=1944,framerate=4/1
! videoconvert
! ximagesink

Expected behavior
A successfully displayed video stream at 4 frames per second

Camera description:

  • Manufacturer: Allied Vision
  • Model: Alvium 1800-500c
  • Interface: USB3

Platform description:

  • Aravis version: 0.7.3
  • OS: Ubuntu 18.04
  • Hardware: Nvidia Jetson TX2 dev kit:
    NVIDIA Pascal™ Architecture GPU
    2 Denver 64-bit CPUs + Quad-Core A57 Complex
    8 GB L128 bit DDR4 Memory
    32 GB eMMC 5.1 Flash Storage

Additional context
When running nearly the same pipeline with far less resolution (i.e. 200x200), the stream works fine. As the resolution increases, the displayed video becomes more and more choppy as if the USB bandwidth is reaching its maximum capacity. This threshold I have found to be around 350x350, where greater than this results in the incomplete image errors. The amount of data in such a stream should not be near enough to bog down USB3.0.

I have confirmed that my hardware is functioning properly by running a test stream with Allied Vision's example software (Vimba API built on top of GenICam API), which successfully captures frames at full resolution of 2592x1944 and framerates upwards of 24 fps.

arv-camera-test-output.txt

@EmmanuelP
Copy link
Contributor

Hi Richard,

Thanks for the report.

Could you rerun your test with this patch applied: 783a296

It will display the number of received bytes in case of incomplete transfers. Make sure the debug output is enabled.

@EmmanuelP EmmanuelP added 1. bug Problems, incorrect behavior or appearance 5. Usb3 Issue in USB3Vision implementation labels Nov 21, 2019
@EmmanuelP EmmanuelP changed the title Bug during the transfer that prevents the transmission of the complete payload. Bug during the transfer that prevents the transmission of the complete payload Nov 21, 2019
@richard-mccrae
Copy link
Author

richard-mccrae commented Nov 21, 2019

After applying your patch...

$ ./arv-camera-test -d all
Looking for the first available camera
Found 1 USB3Vision device (among 3 USB devices)
[UvDevice::new] Vendor  = Allied Vision
[UvDevice::new] Product = ALVIUM 1800 U-500c
[UvDevice::new] S/N     = 001G9
[UvDevice::new] Using control endpoint 1, interface 0
[UvDevice::new] Using data endpoint 5, interface 1
Get genicam
MANUFACTURER_NAME =        'Allied Vision'
MAX_DEVICE_RESPONSE_TIME = 0x0000012c
DEVICE_CAPABILITY        = 0x0000000000000f09
SRBM_ADDRESS =             0x0000000000010000
MANIFEST_TABLE_ADDRESS =   0x0000000000100000
U3VCP_CAPABILITY =         0x00000001
MAX_CMD_TRANSFER =         0x00000400
MAX_ACK_TRANSFER =         0x00000400
SIRM_OFFSET =              0x0000000000020000
SI_INFO =                  0x0a000000
SI_CONTROL =               0x00000000
SI_REQ_PAYLOAD_SIZE =      0x000000000015f900
SI_REQ_LEADER_SIZE =       0x00000034
SI_REQ_TRAILER_SIZE =      0x00000020
SI_MAX_LEADER_SIZE =       0x00000400
SI_PAYLOAD_SIZE =          0x00100000
SI_PAYLOAD_COUNT =         0x00000001
SI_TRANSFER1_SIZE =        0x0005fc00
SI_TRANSFER2_SIZE =        0x00000000
SI_MAX_TRAILER_SIZE =      0x00000400
MANIFEST_N_ENTRIES =       0x0000000000000001
MANIFEST ENTRY
00000000 00 00 00 01 00 04 01 01 00 00 20 00 00 00 00 00  .......... .....
00000010 54 c5 00 00 00 00 00 00 25 81 6f 8c 3b dc a7 08  T.......%.o.;...
00000020 39 9a 0a d9 6c 15 62 6e 9b f7 81 59 00 00 00 00  9...l.bn...Y....
00000030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................

genicam address =          0x0000000000200000
genicam size    =          0x000000000000c554
zip file =                 GenICam_Default.xml
........
[ArvCamera:_update_status] [ArvDevice::read_memory] Timeout
vendor name           = Allied Vision
model name            = 1800 U-500c
[ArvCamera:_update_status] node 'DeviceID' not found
device id             = (null)
image width           = 1200
image height          = 1200
horizontal binning    = 0
vertical binning      = 0
payload               = 1440000 bytes
exposure              = 39997.3 µs
gain                  = 7 dB
uv bandwidth limit     = 200000000 [32750000..450000000]
SI_INFO            =       0x0a000000
SI_REQ_PAYLOAD_SIZE =      0x000000000015f900
SI_REQ_LEADER_SIZE =       0x00000034
SI_REQ_TRAILER_SIZE =      0x00000020
Required alignment =       1024
SI_PAYLOAD_SIZE =          0x00100000
SI_PAYLOAD_COUNT =         0x00000001
SI_TRANSFER1_SIZE =        0x0005fc00
SI_TRANSFER2_SIZE =        0x00000000
SI_MAX_LEADER_SIZE =       0x00000400
SI_MAX_TRAILER_SIZE =      0x00000400
USB transfer error: LIBUSB_ERROR_IO
Incomplete image received, dropping (received 277948 / expected 1440000)
Incomplete image received, dropping (received 277960 / expected 1440000)
Incomplete image received, dropping (received 277944 / expected 1440000)
Incomplete image received, dropping (received 277944 / expected 1440000)
Incomplete image received, dropping (received 277952 / expected 1440000)
Incomplete image received, dropping (received 277952 / expected 1440000)
Incomplete image received, dropping (received 277944 / expected 1440000)
Incomplete image received, dropping (received 277960 / expected 1440000)
Incomplete image received, dropping (received 277948 / expected 1440000)
Incomplete image received, dropping (received 277948 / expected 1440000)
Incomplete image received, dropping (received 277948 / expected 1440000)
Incomplete image received, dropping (received 277940 / expected 1440000)
Incomplete image received, dropping (received 277940 / expected 1440000)
Incomplete image received, dropping (received 277960 / expected 1440000)
Incomplete image received, dropping (received 277944 / expected 1440000)
Incomplete image received, dropping (received 277960 / expected 1440000)
Incomplete image received, dropping (received 277948 / expected 1440000)
Incomplete image received, dropping (received 277956 / expected 1440000)
Incomplete image received, dropping (received 277948 / expected 1440000)
Incomplete image received, dropping (received 277952 / expected 1440000)
^CIncomplete image received, dropping (received 277956 / expected 1440000)
Incomplete image received, dropping (received 277956 / expected 1440000)
Incomplete image received, dropping (received 277960 / expected 1440000)
Incomplete image received, dropping (received 277952 / expected 1440000)
Incomplete image received, dropping (received 277948 / expected 1440000)
Incomplete image received, dropping (received 277948 / expected 1440000)
Frame rate = 0 Hz
Completed buffers = 0
Failures          = 26
Underruns         = 0
Incomplete image received, dropping (received 277960 / expected 1440000)
[UvStream::finalize] n_completed_buffers    = 0
[UvStream::finalize] n_failures             = 27
[UvStream::finalize] n_underruns            = 0
[Stream::finalize] Flush 49 buffer[s] in input queue
[Stream::finalize] Flush 1 buffer[s] in output queue

@EmmanuelP
Copy link
Contributor

The bug is due to the naive USB transfer parameters computation done in arvuvstream.c

To be compared to what is done in the National Instruments driver: https://github.com/ni/usb3vision/blob/ac1599d4ef58c61863839504adff37eaf61810a3/u3v_stream.c#L279

@EmmanuelP
Copy link
Contributor

Could you try to change the value of ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE and set it to 256*256 ?

#define ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE 1048576

@richard-mccrae
Copy link
Author

richard-mccrae commented Nov 21, 2019

Making said change enables a stream of 1200x1200 @ 25fps with arv-camera-test. It does not change the result of the gst pipeline however.

arv-camera-test output:
vendor name           = Allied Vision
model name            = 1800 U-500c
[ArvCamera:_update_status] node 'DeviceID' not found
device id             = (null)
image width           = 1200
image height          = 1200
horizontal binning    = 0
vertical binning      = 0
payload               = 1440000 bytes
exposure              = 39997.3 µs
gain                  = 7 dB
uv bandwidth limit     = 200000000 [32750000..450000000]
SI_INFO            =       0x0a000000
SI_REQ_PAYLOAD_SIZE =      0x000000000015f900
SI_REQ_LEADER_SIZE =       0x00000034
SI_REQ_TRAILER_SIZE =      0x00000020
Required alignment =       1024
SI_PAYLOAD_SIZE =          0x00010000
SI_PAYLOAD_COUNT =         0x00000015
SI_TRANSFER1_SIZE =        0x0000fc00
SI_TRANSFER2_SIZE =        0x00000000
SI_MAX_LEADER_SIZE =       0x00000400
SI_MAX_TRAILER_SIZE =      0x00000400
USB transfer error: LIBUSB_ERROR_IO
Frame rate = 18 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 24 Hz
Frame rate = 24 Hz
Frame rate = 25 Hz
Incomplete image received, dropping (received 1260980 / expected 1440000)
Frame rate = 23 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
Frame rate = 25 Hz
^CFrame rate = 25 Hz
Completed buffers = 590
Failures          = 1
Underruns         = 0
USB transfer error: LIBUSB_ERROR_TIMEOUT
[UvStream::finalize] n_completed_buffers    = 592
[UvStream::finalize] n_failures             = 1
[UvStream::finalize] n_underruns            = 0
[Stream::finalize] Flush 50 buffer[s] in input queue
[Stream::finalize] Flush 0 buffer[s] in output queue

@EmmanuelP
Copy link
Contributor

Ok, that is better, even if the incomplete warning is a bit worrying.

We have to find how to determine the optimum maximum transfer value, instead of using a #define.

@richard-mccrae
Copy link
Author

What is the UV stream by the way?

@EmmanuelP
Copy link
Contributor

I'm not sure to understand the question. ArvUvStream derives from ArvStream, and implements the USB3Vision streaming protocol.

@richard-mccrae
Copy link
Author

A better question would have been how does ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE affect the stream. As the name suggests, it defines the USB3vision maximum transfer size, simple enough. What puzzled me was how reducing this maximum from 2^20 to 2^16 made for successfully completed buffers when running arv-camera-test. I can test a range of values tomorrow, but it will be just blind guessing.

With my camera, the uv bandwidth limit can be controlled, but the current value of 200 MB is greater than the payload in the test stream of 1.44 MB. So I assume that the bandwidth limit is something else than the stream's max transfer size.

@EmmanuelP
Copy link
Contributor

A better question would have been how does ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE affect the stream.

This value is used for the computation of the USB3Vision streaming parameters.

aravis/src/arvuvstream.c

Lines 294 to 314 in 783a296

aligned_maximum_transfer_size = ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE / alignment * alignment;
if (si_req_leader_size < 1) {
arv_warning_stream ("Wrong SI_REQ_LEADER_SIZE value, using %d instead", aligned_maximum_transfer_size);
si_req_leader_size = aligned_maximum_transfer_size;
} else {
si_req_leader_size = align (si_req_leader_size, alignment);
}
if (si_req_trailer_size < 1) {
arv_warning_stream ("Wrong SI_REQ_TRAILER_SIZE value, using %d instead", aligned_maximum_transfer_size);
si_req_trailer_size = aligned_maximum_transfer_size;
} else {
si_req_trailer_size = align (si_req_trailer_size, alignment);
}
si_payload_size = aligned_maximum_transfer_size;
si_payload_count= si_req_payload_size / si_payload_size;
si_transfer1_size = align(si_req_payload_size % si_payload_size, alignment);
si_transfer2_size = 0;

It looks like on some system, there is a maximum transfer size that should not be exceeded. But I don't know how to determine this limit.

@EmmanuelP EmmanuelP added the 4. Help wanted Help is welcome to resolve the issue label Nov 25, 2019
@richard-mccrae
Copy link
Author

I've forwarded this issue to Allied Vision. This is their response:

DeviceLinkThroughputLimit in Byte/s effectively controls the transfer bandwidth.
It needs to be decreased down below 200 or 100 MB/s depending on the adapter and system performance to avoid missing packets and/or dropped frames.
Please let us know if it's helpful on this matter.

I will perform some testing with various levels of device link throughput in attempts to achieve a successful stream. I'll keep you posted.

@richard-mccrae
Copy link
Author

Hi again,

I've done some testing which found that by decreasing both the #define ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE inarvuvstream.c to 256x256 and setting my camera's DeviceLinkThroughputMode to 'On' and the DeviceLinkThroughputLimit to less than 185 000 000 bytes allowed for successfull streaming at 2592x1944, RGB, @ 4 fps.

Increasing the link throughput limit to allow for 25 fps is too much for my USB port, and thus causes missed frames. This happens with Allied Vision's simple frame grabber C program, so is not the fault of Aravis.

I have found that if #define ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE is set to its original value of 1048576 while setting the DeviceLinkThroughputLimit still amounts to missed frames.

Regarding this, I believe that having a aravissrc property that sets the device link throughput limit would be beneficial. Also, as a side note, I know that my camera when in ExposureAutoMode=Continuous it has a tendency to increase the exposure so much that the frame rate decreases. Could a plugin property be added which allows for the control of exposure auto limits?

@EmmanuelP
Copy link
Contributor

Thanks for your feedback.

Regarding aravissrc, I think we need a new property that would take a string containing a list a feature/value pairs, similar to the parameters of the arv-tool control command. I have created a new issue about this feature: #319

@schrammae
Copy link

Hi @EmmanuelP,

We're experimenting with Aravis and several camera models. For some older Basler cameras we also had to reduce ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE to 256*256 to make it work.
Currently, we tested a Basler daA1440-220um. The problem here is that it does not work with 256*256, but works well with 1024*1024 and 512*512 (ca. 72 - 85 fps).

Thus, it is currently not possible to find one value for ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE that works for all cameras. Unnecessarily decreasing ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE also leads to a decreased framerate which is not desirable and finding a working value for ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE is also very cumbersome, because one needs to recompile Aravis several times with different values.

So would it be an option to add a new method that can set ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE at runtime until a better solution for automatically calculating an optimal value is found? This would at least allow for a more efficient determination of ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE per camera and we could store in an internal list which value works for a specific camera model.

And is ARV_UV_STREAM_MAXIMUM_SUBMIT_TOTAL also related and should be set to the same base value as ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE, e.g. 8*256*256?

Our test program basically just uses arv_camera_software_trigger() and arv_buffer_get_data() in an endless loop. Testing the daA1440-220um with 256*256 under Ubuntu on an Intel Cannon Lake PCH USB 3.1 xHCI host controller results in an endless loop of EAGAIN.

$ ARV_DEBUG=all:3 aravis_test
...
[11:43:43.136] 🅳 genicam> [GcCommand::execute] TriggerSoftware (0x1)
[11:43:43.152] 🆆 sp> USB transfer error: LIBUSB_ERROR_TIMEOUT
[11:43:43.152] 🅳 sp> Asking for 65536 bytes
[11:43:43.202] 🆆 sp> USB transfer error: LIBUSB_ERROR_TIMEOUT
[11:43:43.202] 🅳 sp> Asking for 65536 bytes
[11:43:43.252] 🆆 sp> USB transfer error: LIBUSB_ERROR_TIMEOUT
...
$ LIBUSB_DEBUG=4 aravis_test
...
[ 1.450312] [00003c95] libusb: debug [libusb_alloc_transfer] transfer 0x21d0898
[ 1.450321] [00003c95] libusb: debug [libusb_submit_transfer] transfer 0x21d0898
[ 1.450330] [00003c95] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 1.450353] [00003c95] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 1.450440] [00003c97] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 1.450493] [00003c97] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 1.450504] [00003c97] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 1.450512] [00003c97] libusb: debug [handle_bulk_completion] all URBs in transfer reaped --> complete!
[ 1.450520] [00003c97] libusb: debug [usbi_handle_transfer_completion] transfer 0x21d0898 has callback 0x7f52144f1800
[ 1.450528] [00003c97] libusb: debug [sync_transfer_cb] actual_length=16
[ 1.450552] [00003c97] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.450560] [00003c97] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 100ms
[ 1.450593] [00003c98] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 1.450641] [00003c95] libusb: debug [libusb_free_transfer] transfer 0x21d0898
[ 1.497890] [00003c97] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 1.497925] [00003c97] libusb: debug [libusb_cancel_transfer] transfer 0x7f51fc011698
[ 1.498079] [00003c97] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 1.498126] [00003c97] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.498136] [00003c97] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 100ms
[ 1.498151] [00003c97] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 1.498167] [00003c97] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 1.498176] [00003c97] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 1.498184] [00003c97] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 1.498191] [00003c97] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 1.498189] [00003c98] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 1.498201] [00003c97] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 1.498249] [00003c97] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 1.498260] [00003c97] libusb: debug [usbi_handle_transfer_completion] transfer 0x7f51fc011698 has callback 0x7f52144f1800
[ 1.498268] [00003c97] libusb: debug [sync_transfer_cb] actual_length=0
[ 1.498287] [00003c97] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.498294] [00003c97] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 100ms
[ 1.498346] [00003c98] libusb: debug [libusb_free_transfer] transfer 0x7f51fc011698
...
$ ltrace -CfStt aravis_test
...
15296 11:15:46.767109 SYS_open("/dev/bus/usb/002/003", 524290, 010617160373)                                         = 9
...
15299 11:15:47.289018 <... SYS_restart_syscall resumed> )                                                            = 1
15299 11:15:47.289227 SYS_ioctl(9, 0x550b, 0x7f6f300108d0, 134)                                                      = 0
15299 11:15:47.289695 SYS_timerfd_settime(8, 0, 0x7f6f3cdd9c20, 0)                                                   = 0
15299 11:15:47.290120 SYS_futex(0x1855984, 132, 1, 0x7fffffff)                                                       = 1
15298 11:15:47.290458 <... SYS_restart_syscall resumed> )                                                            = 0
15299 11:15:47.290542 SYS_poll(0x186a980, 3, 60000 <unfinished ...>
15298 11:15:47.290610 SYS_futex(0x1855958, 129, 1, 0x7f6f3d5dadc0 <unfinished ...>
15299 11:15:47.290695 <... SYS_poll resumed> )                                                                       = 1
15298 11:15:47.290761 <... SYS_futex resumed> )                                                                      = 0
15299 11:15:47.290808 SYS_ioctl(9, 0x4008550d, 0x7f6f3cdd9ba8, 0x7fffffff <unfinished ...>
15298 11:15:47.290885 SYS_futex(0x1855984, 137, 1145, 0x7f6f3d5dadc0 <unfinished ...>
15299 11:15:47.290980 <... SYS_ioctl resumed> )                                                                      = 0
15299 11:15:47.291050 SYS_timerfd_settime(8, 0, 0x7f6f3cdd9b10, 0)                                                   = 0
15299 11:15:47.291209 SYS_ioctl(9, 0x4008550d, 0x7f6f3cdd9ba8, 0)                                                    = -11
15299 11:15:47.291364 SYS_futex(0x1855984, 132, 1, 0x7fffffff)                                                       = 1
15298 11:15:47.291526 <... SYS_futex resumed> )                                                                      = 0
15299 11:15:47.291574 SYS_timerfd_settime(8, 1, 0x7f6f3cdd9cf0, 0 <unfinished ...>
15298 11:15:47.291677 SYS_futex(0x1855958, 129, 1, 0x7f6f3d5dadc0 <unfinished ...>
15299 11:15:47.291773 <... SYS_timerfd_settime resumed> )                                                            = 0
15298 11:15:47.291837 <... SYS_futex resumed> )                                                                      = 0
15299 11:15:47.291881 SYS_ioctl(9, 0x8038550a, 0x7f6f300108d0, 0 <unfinished ...>
15298 11:15:47.291955 SYS_poll(0x186a980, 3, 100 <unfinished ...>
15299 11:15:47.292029 <... SYS_ioctl resumed> )                                                                      = 0
15299 11:15:47.292119 SYS_futex(0x1855984, 137, 1147, 0x7f6f3cdd9ca0 <unfinished ...>
15298 11:15:47.341635 <... SYS_poll resumed> )                                                                       = 1
15298 11:15:47.341703 SYS_ioctl(9, 0x550b, 0x7f6f300108d0, 0x7f6f3d5dad20)                                           = 0
15298 11:15:47.341973 SYS_timerfd_settime(8, 0, 0x7f6f3d5dad40, 0)                                                   = 0
15298 11:15:47.342220 SYS_futex(0x1855984, 132, 1, 0x7fffffff)                                                       = 1
15299 11:15:47.342427 <... SYS_futex resumed> )                                                                      = 0
15298 11:15:47.342476 SYS_poll(0x186a980, 3, 100 <unfinished ...>
15299 11:15:47.342545 SYS_futex(0x1855958, 129, 1, 0x7f6f3cdd9ca0 <unfinished ...>
15298 11:15:47.342624 <... SYS_poll resumed> )                                                                       = 1
15299 11:15:47.342689 <... SYS_futex resumed> )                                                                      = 0
15298 11:15:47.342734 SYS_ioctl(9, 0x4008550d, 0x7f6f3d5dacc8, 0x7fffffff <unfinished ...>
15299 11:15:47.342808 SYS_futex(0x1855984, 137, 1149, 0x7f6f3cdd9ca0 <unfinished ...>
15298 11:15:47.342901 <... SYS_ioctl resumed> )                                                                      = 0
15298 11:15:47.342964 SYS_timerfd_settime(8, 0, 0x7f6f3d5dac30, 0)                                                   = 0
15298 11:15:47.343123 SYS_ioctl(9, 0x4008550d, 0x7f6f3d5dacc8, 0)                                                    = -11
15298 11:15:47.343277 SYS_futex(0x1855984, 132, 1, 0x7fffffff)                                                       = 1
15299 11:15:47.343438 <... SYS_futex resumed> )                                                                      = 0
15298 11:15:47.343487 SYS_poll(0x186a980, 3, 100 <unfinished ...>
15299 11:15:47.343540 SYS_futex(0x1855958, 129, 1, 0x7f6f3cdd9ca0)                                                   = 0
15299 11:15:47.343742 SYS_timerfd_settime(8, 1, 0x7f6f3cdd9cf0, 0)                                                   = 0
15299 11:15:47.343904 SYS_ioctl(9, 0x8038550a, 0x7f6f300108d0, 0)                                                    = 0
15299 11:15:47.344093 SYS_futex(0x1855984, 137, 1151, 0x7f6f3cdd9ca0 <unfinished ...>
15298 11:15:47.393811 <... SYS_poll resumed> )                                                                       = 1
15298 11:15:47.393876 SYS_ioctl(9, 0x550b, 0x7f6f300108d0, 0x7f6f3d5dad20)                                           = 0
15298 11:15:47.394108 SYS_timerfd_settime(8, 0, 0x7f6f3d5dad40, 0)                                                   = 0
15298 11:15:47.394260 SYS_futex(0x1855984, 132, 1, 0x7fffffff)                                                       = 1
15299 11:15:47.394419 <... SYS_futex resumed> )                                                                      = 0
15298 11:15:47.394467 SYS_poll(0x186a980, 3, 100 <unfinished ...>
15299 11:15:47.394522 SYS_futex(0x1855958, 129, 1, 0x7f6f3cdd9ca0 <unfinished ...>
15298 11:15:47.394597 <... SYS_poll resumed> )                                                                       = 1
15299 11:15:47.394660 <... SYS_futex resumed> )                                                                      = 0
15298 11:15:47.394706 SYS_ioctl(9, 0x4008550d, 0x7f6f3d5dacc8, 0x7fffffff <unfinished ...>
15299 11:15:47.394781 SYS_futex(0x1855984, 137, 1153, 0x7f6f3cdd9ca0 <unfinished ...>
15298 11:15:47.394874 <... SYS_ioctl resumed> )                                                                      = 0
15298 11:15:47.394932 SYS_timerfd_settime(8, 0, 0x7f6f3d5dac30, 0)                                                   = 0
15298 11:15:47.395185 SYS_ioctl(9, 0x4008550d, 0x7f6f3d5dacc8, 0)                                                    = -11
...
$ strace -fy aravis_test
...
15172 11:14:03.514532 open("/dev/bus/usb/002/003", O_RDWR|O_CLOEXEC) = 9</dev/bus/usb/002/003>
...
15174 11:14:08.093452 ioctl(9</dev/bus/usb/002/003>, USBDEVFS_REAPURBNDELAY <unfinished ...>
15175 11:14:08.093491 timerfd_settime(8<anon_inode:[timerfd]>, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={164047, 235876799}}, NULL <unfinished ...>
15174 11:14:08.093535 <... ioctl resumed> , 0x7f29400cacc8) = -1 EAGAIN (Resource temporarily unavailable)
15174 11:14:08.093580 poll([{fd=7<anon_inode:[eventfd]>, events=POLLIN}, {fd=8<anon_inode:[timerfd]>, events=POLLIN}, {fd=9</dev/bus/usb/002/003>, events=POLLOUT}], 3, 100 <unfinished ...>
15175 11:14:08.093651 <... timerfd_settime resumed> ) = 0
15175 11:14:08.093750 ioctl(9</dev/bus/usb/002/003>, USBDEVFS_SUBMITURB, 0x7f29300108d0) = 0
15175 11:14:08.093864 futex(0x1ac5654, FUTEX_WAIT_BITSET_PRIVATE, 1539, {164107, 186246478}, ffffffff <unfinished ...>
15174 11:14:08.143540 <... poll resumed> ) = 1 ([{fd=8, revents=POLLIN}])
15174 11:14:08.143617 ioctl(9</dev/bus/usb/002/003>, USBDEVFS_DISCARDURB, 0x7f29300108d0) = 0
15174 11:14:08.143787 timerfd_settime(8<anon_inode:[timerfd]>, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
15174 11:14:08.143883 futex(0x1ac5654, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x1ac5628, 1540) = 1
15174 11:14:08.143968 poll([{fd=7<anon_inode:[eventfd]>, events=POLLIN}, {fd=8<anon_inode:[timerfd]>, events=POLLIN}, {fd=9</dev/bus/usb/002/003>, events=POLLOUT}], 3, 100 <unfinished ...>
15175 11:14:08.144040 <... futex resumed> ) = 0
15174 11:14:08.144068 <... poll resumed> ) = 1 ([{fd=9, revents=POLLOUT}])
15174 11:14:08.144122 ioctl(9</dev/bus/usb/002/003>, USBDEVFS_REAPURBNDELAY <unfinished ...>
15175 11:14:08.144161 futex(0x1ac5628, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
15174 11:14:08.144189 <... ioctl resumed> , 0x7f29400cacc8) = 0
15174 11:14:08.144231 timerfd_settime(8<anon_inode:[timerfd]>, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL <unfinished ...>
15175 11:14:08.144277 <... futex resumed> ) = 0
15174 11:14:08.144304 <... timerfd_settime resumed> ) = 0
15174 11:14:08.144345 ioctl(9</dev/bus/usb/002/003>, USBDEVFS_REAPURBNDELAY <unfinished ...>
15175 11:14:08.144385 timerfd_settime(8<anon_inode:[timerfd]>, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={164047, 286772003}}, NULL <unfinished ...>
15174 11:14:08.144429 <... ioctl resumed> , 0x7f29400cacc8) = -1 EAGAIN (Resource temporarily unavailable)
15174 11:14:08.144474 poll([{fd=7<anon_inode:[eventfd]>, events=POLLIN}, {fd=8<anon_inode:[timerfd]>, events=POLLIN}, {fd=9</dev/bus/usb/002/003>, events=POLLOUT}], 3, 100 <unfinished ...>
15175 11:14:08.144545 <... timerfd_settime resumed> ) = 0
15175 11:14:08.144644 ioctl(9</dev/bus/usb/002/003>, USBDEVFS_SUBMITURB, 0x7f29300108d0) = 0
15175 11:14:08.144818 futex(0x1ac5654, FUTEX_WAIT_BITSET_PRIVATE, 1541, {164107, 237200336}, ffffffff <unfinished ...>
15174 11:14:08.194464 <... poll resumed> ) = 1 ([{fd=8, revents=POLLIN}])
15174 11:14:08.194640 ioctl(9</dev/bus/usb/002/003>, USBDEVFS_DISCARDURB, 0x7f29300108d0) = 0
15174 11:14:08.194965 timerfd_settime(8<anon_inode:[timerfd]>, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
15174 11:14:08.195104 futex(0x1ac5654, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x1ac5628, 1542 <unfinished ...>
15175 11:14:08.195259 <... futex resumed> ) = 0
15174 11:14:08.195323 <... futex resumed> ) = 1
15175 11:14:08.195375 futex(0x1ac5628, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
15174 11:14:08.195425 futex(0x1ac5628, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
15175 11:14:08.195556 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
15174 11:14:08.195641 <... futex resumed> ) = 0
15175 11:14:08.195696 futex(0x1ac5628, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
15174 11:14:08.195756 poll([{fd=7<anon_inode:[eventfd]>, events=POLLIN}, {fd=8<anon_inode:[timerfd]>, events=POLLIN}, {fd=9</dev/bus/usb/002/003>, events=POLLOUT}], 3, 100 <unfinished ...>
15175 11:14:08.195870 <... futex resumed> ) = 0
15174 11:14:08.195944 <... poll resumed> ) = 1 ([{fd=9, revents=POLLOUT}])

I can also try to come up with some more debug info if you want - just tell me what you need.

@PolyVinalDistillate
Copy link

PolyVinalDistillate commented Mar 13, 2024

Hello - I am involved with the University of Aberdeen on a project where we use various monochrome machine vision cameras for the purposes of recording digital holograms of plankton. I used Aravis orginally under Linux to implement a holographic camera (weeHoloCam) when it was in release 0.6. with no issues, however I'm now using it under Windows for holography with an collection of different sensors.

I have found that various high-spec windows laptops have a tendency to drop frames with "ARV_BUFFER_STATUS_MISSING_PACKETS" and similar issues while other laptops are fine. This seems to be at least partly computer dependant. I had assumed it was bottlenecks in the USB subsystems, but now I'm not at all sure.

Due to the apparent dependency on different computers as well as different cameras, I would like to advocate the exposure of the ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE parameter via your API so it can be modified at runtime. Given the issues I've been experiencing, I would be inclined to implement an auto-tune of this parameter if I could access it at runtime.

For example, we have one laptop that works fine using a Jai GO-5100M with ARV_UV_STREAM_MAXIMUM_TRANSFER_SIZE set to 1024x1024, but on a higher spec'd laptop I have had to reduce this to 256x256 to get the sensor working reliably. As the syssem is currently with a customer, I have had to recompile aravis and have them replace libaravis-0.8-0.dll progressively until they found a version that worked.

@DxTa
Copy link

DxTa commented Nov 1, 2024

fyi, to make it work with basler cameras, I do need to change ARV_UV_STREAM_MAXIMUM_SUBMIT_TOTAL as well.

@EmmanuelP
Copy link
Contributor

@dxt , @PolyVinalDistillate , @schrammae , Hi.

Could you please test #958 ? This merge request implements a new maximum-transfer-size property.

@EmmanuelP EmmanuelP added the 1. Performance Performance issue label Nov 7, 2024
@EmmanuelP EmmanuelP moved this from To do to In progress in Performance Nov 7, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
1. bug Problems, incorrect behavior or appearance 1. Performance Performance issue 4. Help wanted Help is welcome to resolve the issue 5. Usb3 Issue in USB3Vision implementation
Projects
Status: In progress
Development

No branches or pull requests

5 participants