I believe that I have made a breakthrough with this problem, and have figured out a temporary workaround.
Given that you were able to run the same operating system and same camera with no issue, I figure that there must be some difference in configuration from one device to the next. I looked at your log files and noticed that your Raspberry Pi v4 was a 4GB model, while mine was an 8GB model. This is interesting because I would have thought that if there was going to be an issue, it would be with the model with less memory, not more.
I started poking around other areas of the system. While doing that, I checked dmesg
and noticed the following chunk of output:
[ 1992.819422] usb 1-1.2: new high-speed USB device number 5 using xhci_hcd
[ 1992.925118] usb 1-1.2: New USB device found, idVendor=04b4, idProduct=6572, bcdDevice=32.99
[ 1992.925135] usb 1-1.2: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 1992.925146] usb 1-1.2: Product: USB2.0 Hub
[ 1992.926855] hub 1-1.2:1.0: USB hub found
[ 1992.927283] hub 1-1.2:1.0: 4 ports detected
[ 1993.219546] usb 2-2: new SuperSpeed Gen 1 USB device number 3 using xhci_hcd
[ 1993.241026] usb 2-2: New USB device found, idVendor=03c3, idProduct=294e, bcdDevice= 0.00
[ 1993.241040] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 1993.241045] usb 2-2: Product: ASI294MM Pro
[ 1993.241052] usb 2-2: Manufacturer: ZWO
[ 2032.611067] usb 2-2: reset SuperSpeed Gen 1 USB device number 3 using xhci_hcd
[ 2032.782023] swiotlb_tbl_map_single: 94 callbacks suppressed
[ 2032.782034] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.782064] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.782447] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.782470] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.783196] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.784039] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.784803] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.784831] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.785286] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.785309] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.785682] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.785704] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.786175] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.786309] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.786691] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.786928] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.787836] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.788015] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.788904] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.789310] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.789969] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.790368] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.791411] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.791835] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.792262] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.792651] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.793092] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.793496] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.793885] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.795102] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.795970] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.796439] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.796879] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.797335] usb 2-2: usbfs: usb_submit_urb returned -11
[ 2032.798003] usb 2-2: usbfs: usb_submit_urb returned -11
The key lines here are:
[ 2032.782023] swiotlb_tbl_map_single: 94 callbacks suppressed
[ 2032.782034] xhci_hcd 0000:01:00.0: swiotlb buffer is full (sz: 16384 bytes), total 32768 (slots), used 32753 (slots)
[ 2032.782064] usb 2-2: usbfs: usb_submit_urb returned -11
SWIOTLB appears to refer to a memory management system which is responsible for allocating memory for (amongst other things) USB devices. There is a nice writeup here.
The error messages above appear to indicate that the swiotlb
buffer is being maxxed out. I grabbed a copy of the Raspberry Pi Kernel and discovered that error code -11
corresponds to -EAGAIN
. The kernel documentation for the USB subsystem indicates that this can occur for usb_submit_urb
if there are 'too many queued ISO transfers'.
This behaviour seems to match up with what is happening on the device. I poked around in /sys
and found that an entry for swiotlb
existed under /sys/kernel/debug/swiotlb
. There are two nodes within this folder: io_tlb_nslabs
and io_tlb_used
.
The value in io_tlb_nslabs
was 32768, which corresponds to the total 32768 (slots)
message above. The value in io_tlb_used
was 1
. When I ran the demo program and watched the content of io_tlb_used
, the value flapped between fully allocated (32768
) and not allocated (1
).
This appears to indicate that as the camera driver is attempting to perform USB transfers, it is maxxing out the available memory allocation for USB transfer operations in some way. I am not an expert in the kernel or USB allocation, but given the messages seen above, the research I have performed, and the behaviour that I am experiencing, this appears to be the case.
As I don't have access to the source code for the driver, I cannot alter the source code to fix this problem. Instead, I started to look to see if there was a way that I could increase the size of the swiotlb
buffer. It turns out that it can be done.
Increasing the swiotlb
Buffer
On a regular computer you can supply a kernel argument in the bootloader (e.g., in grub) to set the size of swiotlb
. Because the Raspberry Pi doesn't boot the same way, there is a different mechanism, which is the file /boot/cmdline.txt
. This file allows you to supply command line arguments which are passed to the kernel at boot time.
I added the following to the end of the existing command line arguments in my /boot/cmdline.txt
file:
swiotlb=131072
This number was chosen because it is the value of 128 * 1024 = 131072
. (The default size was 32 * 1024 = 32768
).
I restarted the Raspberry Pi, ran the demo program, and I WAS ABLE TO EXPOSE AN IMAGE AT 8288 x 5644 @ 16 BITS on the 64 bit operating system.
I checked the content of /sys/kernel/debug/swiotlb/io_tlb_used
and while it was still flapping up and down, it was only maxxing out at about 46000
(this is an eyeballed measurement, because it changes so rapidly), and it was not hitting the limit in /sys/kernel/debug/swiotlb/io_tlb_nslabs
listed as 131072
.
As far as I can tell, the above change has resolved the issue for me.
Checks For You To Perform
I would be interested to know why your Raspberry Pi 4 does not experience these problems while mine does.
I am particularly curious as to whether your Raspberry Pi 4 is attempting to use the swiotlb
buffer when allocating USB Request Blocks or not. I feel like this may be key to the reason why we are experiencing differences in the way that the devices work. My guess is that (for whatever reason) my Raspberry Pi 4 either has a smaller allocation to swiotlb
than yours, OR, your Raspberry Pi 4 is not using the swiotlb
buffer when allocating USB Request Blocks.
Either way, I think that this mechanism may be core to the reason that many ASI_EXP_FAILED
errors occur, not just for me, but probably for other customers too.
Could you please output the content of your /boot/cmdline.txt
file?
cat /boot/cmdline.txt
Could you please run this command to list the available swiotlb
buffer on your Raspberry Pi 4?
sudo cat /sys/kernel/debug/swiotlb/io_tlb_nslabs
While running one of the demo programs to capture an 8288 x 5644 @ 16 bit image/video, could you please run the following command to watch the amount of the swiotlb
buffer that is being used, and report the typical high allocation values?
watch -n 0.2 cat /sys/kernel/debug/swiotlb/io_tlb_used
I don't know if this problem indicates that there's an issue with the way that the Raspberry Pi 4 is configured by default (not enough buffer allocation) or if there is an issue with the way that your libASICamera2.so driver is allocating/submitting USB Request Blocks, but I believe that I have identified the source of these failures.