ringbuffer write timeout

jh4xsy commented 1 year ago

Hi!

I tried your driver with gainmode=1 and got "ringbuffer write timeout".

It happended sometime.

Log with timeout:

Nov 15 06:04:22 gs2107 satnogs-client[4599]: [INFO] Using format CF32.
Nov 15 06:05:22 gs2107 satnogs-client[4599]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 15 06:05:23 gs2107 satnogs-client[4599]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 15 06:05:23 gs2107 satnogs-client[4599]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 15 06:05:23 gs2107 satnogs-client[4599]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 15 06:08:04 gs2107 satnogs-client[4599]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 15 06:08:04 gs2107 satnogs-client[4599]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 15 06:09:53 gs2107 satnogs-client[3100]: netrigctl_close: done status=Command completed successfully
Nov 15 06:09:54 gs2107 satnogs-client[4674]: POST OBSERVATION SCRIPT RUNNING

Log NO timeout:

Sep 16 15:58:44 gs2107 satnogs-client[3876]: [INFO] Using format CF32.
Sep 16 16:06:50 gs2107 satnogs-client[3876]: OOOOOsOsOsOsOsO
Sep 16 16:06:50 gs2107 satnogs-client[2124]: netrigctl_close: done status=Command completed successfully
Sep 16 16:06:53 gs2107 satnogs-client[3949]: POST OBSERVATION SCRIPT RUNNING

I'm using Raspberry Pi 4B with SatNOGS client 1.8.1/Raspbian SatNOGS Image(Release: 2022091000) Airspy Mini(v1.0.0-rc10-6) is connected to USB2.

Driver setting:

satnogs_soapy_rx_device: driver=airspy,gainmode=1
satnogs_rx_samp_rate: 3e6
satnogs_antenna: RX
satnogs_gain_mode: Settings Field
satnogs_other_settings: SENS=14

janvgils commented 1 year ago

Thank you very much for taking the time to test this driver and share your experiences.

One thing that already is indication of possible hardware configuration issues, is the fact that OOOOOsOsOsOsOsO are showing. This is an indication that samples are dropped on the USB interface.

Looking at https://airspy.com/quickstart/ there are some best practices when using a Pi3 and I am not sure if they also apply to a Pi4.

Other options that help solve this:

Connect the SDR to a USB2 interface and not the USB3
Connect the SDR to a dedicated port and not via a USB hub.

I guess this is the SatNOGS ground station that you use: https://network.satnogs.org/stations/2107/

@ast Maybe you can also add some information and or question.

ast commented 1 year ago

Some additional random advice in no particular order.

If you application uses Volk (if it's built on gnuradio, it does), remember to run volk_profile. Use a proper heatsink and make sure there's no thermal throttling. Use a USB cable of good quality. The Raspberry Pi 4 is much faster than Raspberry Pi 3, in particular USB and Ethernet throughput, but needs cooling.

General performance will be much better and more reliable if you use an SSD over USB3 instead of an SD card (this won't affect SDR throughput, just general performance).

janvgils commented 1 year ago

Good idea regarding volk_profile, there is only one thing, the config is saved in the users profile, so we need to execute the command within its profile.

This is what I do to make sure that in this case it will be saved in the profile that belongs to the satnogs user.

sudo -H -u satnogs volk_profile this will save the output in the directory /usr/lib/satnogs/.volk

cd ~satnogs
user@hostname:/var/lib/satnogs$ cd .volk/
user@hostname:/var/lib/satnogs/.volk$ ls -l
-rw-r--r-- 1 satnogs satnogs 4668 Sep 24 12:25 volk_config

jh4xsy commented 1 year ago

Hi, janvgils. This is ground station ID=2107.

Today, I connect Mini to USB3. Then NO overrun! but still got timeout.

Thanks advice, ast.

I have already tried:

boot from USB3 with USB3 memory.
use cooling fan.
don't use USB Hub.
use USB2 shielded cable.
ran volk_profile.

make volk_config for satnogs user
change scaling_governor from ondemand to performance.

jh4xsy commented 1 year ago

I made volk_config for satnogs user, use “performance” governor(CPU freq=1.50GHz) and disabled the “FIQ Fix” in cmdline.txt. But same result: sometimes OK, sometimes timeout.

janvgils commented 1 year ago

Thank you very much for all the testing and information shared.

Just to be sure, did you restart or reboot the Pi after you made the modifications?

When it give the error do you also see the OOOOOsOsOsOsOsO (samples dropped)?

Can you share what kind of observation is running, FSK CW, BPSK etc. when you see the error?

jh4xsy commented 1 year ago

Ok, I did restart my Pi4 just in case and made some observations.

I will share some observation with timeout. There were NO sample dropped in other cases.

FSK

Nov 20 06:32:01 gs2107 satnogs-client[2862]: [INFO] Using format CF32.
Nov 20 06:33:50 gs2107 satnogs-client[2862]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 06:33:50 gs2107 satnogs-client[2862]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 06:33:50 gs2107 satnogs-client[2862]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 06:33:51 gs2107 satnogs-client[2862]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 06:33:51 gs2107 satnogs-client[2862]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 06:37:36 gs2107 satnogs-client[428]: netrigctl_close: done status=Command completed successfully
Nov 20 06:37:39 gs2107 satnogs-client[2927]: POST OBSERVATION SCRIPT RUNNING

BPSK

Nov 20 09:30:29 gs2107 satnogs-client[3628]: [INFO] Using format CF32.
Nov 20 09:32:02 gs2107 satnogs-client[3628]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 09:34:11 gs2107 satnogs-client[428]: netrigctl_close: done status=Command completed successfully
Nov 20 09:34:13 gs2107 satnogs-client[3683]: POST OBSERVATION SCRIPT RUNNING

APT

Nov 20 08:47:14 gs2107 satnogs-client[3433]: [INFO] Using format CF32.
Nov 20 08:49:42 gs2107 satnogs-client[3433]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 08:51:53 gs2107 satnogs-client[3433]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 08:51:53 gs2107 satnogs-client[3433]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 08:51:53 gs2107 satnogs-client[3433]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 08:51:53 gs2107 satnogs-client[3433]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 08:51:54 gs2107 satnogs-client[3433]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 08:51:54 gs2107 satnogs-client[3433]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 08:51:54 gs2107 satnogs-client[3433]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 08:51:54 gs2107 satnogs-client[3433]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 20 08:52:19 gs2107 satnogs-client[428]: netrigctl_close: done status=Command completed successfully
Nov 20 08:52:22 gs2107 satnogs-client[3490]: POST OBSERVATION SCRIPT RUNNING

Sorry, timestamp is localtime (JST/GMT+9).

janvgils commented 1 year ago

Thank you, for sharing this.

This is still with gainmode=1 (sensitive) ?

If I remember correctly this is with a Airspy Mini, currently I have one in share and will connect it to my Pi3 and see if I can reproduce this behavior.

Scrolled back and found this:

satnogs_soapy_rx_device: driver=airspy,gainmode=1
satnogs_rx_samp_rate: 3e6
satnogs_antenna: RX
satnogs_gain_mode: Settings Field
satnogs_other_settings: SENS=14

Is this still your setup?

janvgils commented 1 year ago

Here is what I did on my Raspberry Pi 3 Model B Rev 1.2 to test the Airspy Mini with this repositories driver code.

OS/Distribution information:

cat /etc/os-release 
PRETTY_NAME="Raspbian GNU/Linux 11 (bullseye)"
NAME="Raspbian GNU/Linux"
VERSION_ID="11"
VERSION="11 (bullseye)"
VERSION_CODENAME=bullseye
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

The CPU governor:

cat /sys/devices/system/cpu/cpu*/cpufreq/scaling_governor
ondemand
ondemand
ondemand
ondemand

Installed the latest airspyone_host driver https://github.com/airspy/airspyone_host.git Build and installed the latest SoapyAirspy driver https://github.com/ast/SoapyAirspy.git

Information about the installed Airspy:

airspy_info 
airspy_lib_version: 1.0.9

Found AirSpy board 1
Board ID Number: 0 (AIRSPY)
Firmware Version: AirSpy MINI v1.0.0-rc10-6-g4008185 2020-05-08
Part ID Number: 0x6906002B 0x00000030
Serial Number: 0x04A464C83670830B
Supported sample rates:
    6.000000 MSPS
    3.000000 MSPS
Close board 1

Testing the sample rate performance on 3e6 and 6e6:

airspy_rx -a 3000000 -r /dev/null -t 2 looking good no samples dropped.

Total time: 30.3574 s
Average speed 3.0010 MSPS IQ
done

airspy_rx -a 6000000 -r /dev/null -t 2 also looking good.

Total time: 53.6865 s
Average speed 6.0009 MSPS IQ
done

Settings the satnogs-client config:

SATNOGS_SOAPY_RX_DEVICE="driver=airspy,serial=04A464C83670830B,gainmode=0,biastee=false"
SATNOGS_GAIN_MODE="Settings Field"
SATNOGS_OTHER_SETTINGS="LIN=13"
SATNOGS_RX_SAMP_RATE="3e6"

The Airspy isn't connected to an antenna, but has a dummy load connected. I am using https://network.satnogs.org/stations/1696/ for testing.

Looking at the log information with the following command sudo journalctl -f -u satnogs-client -n 512 Scheduling some observations, here an example: https://network.satnogs.org/observations/6770077/

The log information from this observation:

AFSK Aausat-II

Nov 20 17:35:25 svalbard systemd[1]: Started SatNOGS client.
Nov 20 17:46:15 svalbard satnogs-client[1470]: gr-satellites: Observation: 6770077, Norad: 32788, Name: AAUSAT-II, Script: satnogs_afsk1200_ax25.py
Nov 20 17:46:15 svalbard satnogs-client[1470]: gr-satellites: Generating satellite list
Nov 20 17:46:26 svalbard satnogs-client[1470]: gr-satellites: Satellite not supported
Nov 20 17:46:26 svalbard satnogs-client[1359]: rot_init called
Nov 20 17:46:26 svalbard satnogs-client[1359]: initrots4_dummy: _init called
Nov 20 17:46:26 svalbard satnogs-client[1359]: rot_register (1)
Nov 20 17:46:26 svalbard satnogs-client[1359]: rot_register (2)
Nov 20 17:46:26 svalbard satnogs-client[1359]: dummy_rot_init called
Nov 20 17:46:26 svalbard satnogs-client[1359]: rig_init: rig does not have rx_range!!
Nov 20 17:46:26 svalbard satnogs-client[1359]: network_open: hoststr=127.0.0.1, portstr=4532
Nov 20 17:46:29 svalbard satnogs-client[1501]: [INFO] Using format CF32.

BPSK Metop-B

Nov 20 17:52:16 svalbard satnogs-client[1615]: gr-satellites: Observation: 6770088, Norad: 38771, Name: 0_METOP-B, Script: satnogs_bpsk.py
Nov 20 17:52:16 svalbard satnogs-client[1615]: gr-satellites: Satellite not supported
Nov 20 17:52:16 svalbard satnogs-client[1359]: rig_init: rig does not have rx_range!!
Nov 20 17:52:16 svalbard satnogs-client[1359]: network_open: hoststr=127.0.0.1, portstr=4532
Nov 20 17:52:19 svalbard satnogs-client[1632]: [INFO] Using format CF32.
Nov 20 18:03:35 svalbard satnogs-client[1359]: netrigctl_close: done status=Command completed successfully
Nov 20 18:03:37 svalbard satnogs-client[1720]: gr-satellites: Observation: 6770088, Norad: 38771, Name: 0_METOP-B, Script: satnogs_bpsk.py

Everything seems to be fine, no errors or warnings in the log output.

Is there anything else I can try to recreate the error that is seen on the Pi4?

jh4xsy commented 1 year ago

Thanks for your Pi3 test.

OS information is the same: Raspbian(bullseye), Airspy_lib is the same version: 1.0.9.

$ uname -a
Linux gs2107 5.15.76-v7l+ #1597 SMP Fri Nov 4 12:14:58 GMT 2022 armv7l GNU/Linux

So I copied your settings. The CPU governor: ondemand, the satnogs-client config: gainmode=0

SATNOGS_SOAPY_RX_DEVICE="driver=airspy,gainmode=0,biastee=false"
SATNOGS_GAIN_MODE="Settings Field"
SATNOGS_OTHER_SETTINGS="LIN=13"
SATNOGS_RX_SAMP_RATE="3e6"

airspy_rx test is OK, no samples dropped.

$ airspy_rx -a 3000000 -r /dev/null -t 2
...
User cancel, exiting...
Total time: 29.1736 s
Average speed 3.0001 MSPS IQ
done

But today's observation (FSK:GRIFEX) with above setting has "write timeout". I also checked syslog, but NO other process logged at this time.

Nov 21 09:57:37 gs2107 satnogs-client[441]: rig_init: rig does not have rx_range!!
Nov 21 09:57:37 gs2107 satnogs-client[441]: network_open: hoststr=127.0.0.1, portstr=4532
Nov 21 09:57:39 gs2107 satnogs-client[1533]: [INFO] Using format CF32.
Nov 21 10:01:18 gs2107 satnogs-client[1533]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 21 10:01:19 gs2107 satnogs-client[1533]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 21 10:01:19 gs2107 satnogs-client[1533]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 21 10:01:19 gs2107 satnogs-client[1533]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 21 10:01:19 gs2107 satnogs-client[1533]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 21 10:01:19 gs2107 satnogs-client[1533]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 21 10:01:19 gs2107 satnogs-client[1533]: [INFO] SoapyAirspy::rx_callback: ringbuffer write timeout
Nov 21 10:01:33 gs2107 satnogs-client[441]: netrigctl_close: done status=Command completed successfully
Nov 21 10:01:34 gs2107 satnogs-client[1616]: POST OBSERVATION SCRIPT RUNNING
Nov 21 10:01:34 gs2107 satnogs-client[1616]: POST OBSERVATION SCRIPT FINISHED

jh4xsy commented 1 year ago

After replacing the USB cable, the number of observations that timeout occurred decreased dramatically. I think this problem was on my hardware.

janvgils commented 1 year ago

Very good to see you are going in the right direction to solve the behavior. Please lets us know after more observations that this was indeed the solution to your error/warning messages.

jh4xsy commented 1 year ago

This was not the solution. Timeout never went to zero.

I changed "IQ_DUMP_FILENAME" from /tmp/iq.dat (USB3 disk) to /tmp/.satnogs/iq.dat (tmpfs) at this morning. Then NO errors today, so keep watching.

janvgils commented 1 year ago

Thanks for the update, this points towards multiple USB devices sharing the USB bus and interfere with one another. By selecting /tmp/.satnogs you write to memory and no longer directly use the USB bus.

I was in the impression that a Pi4 had USB2 and USB3 are those separate usb busses or just one.

Looking at lsbusb -t it seems a separate bus. What is your output of lsusb andlsusb -t` ?

Example:

lsusb -t

/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/4p, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 3: Dev 3, If 0, Class=Human Interface Device, Driver=usbhid, 1.5M
        |__ Port 3: Dev 3, If 1, Class=Human Interface Device, Driver=usbhid, 1.5M

jh4xsy commented 1 year ago

Thanks comments.

Here is my Pi4 outputs. Pi4 has separete USB buses. Airspy Mini and USB storage are on separate buses, but I plugged them into the USB3 port.

Maybe I should not use Airspy & USB storage simultaneously under heavy load.

$ lsusb
Bus 002 Device 002: ID 0781:5583 SanDisk Corp. Ultra Fit
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 005: ID 1d50:60a1 OpenMoko, Inc. Airspy
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

$ lsusb -t
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/4p, 5000M
    |__ Port 1: Dev 2, If 0, Class=Mass Storage, Driver=usb-storage, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 2: Dev 5, If 0, Class=Vendor Specific Class, Driver=, 480M

PS. Continuing NO Errors!

janvgils commented 1 year ago

The best performance of the Airspy SDR are mostly when connecting them to the USB2 port, so I would advice to connect the Mini to a USB2 and the disk to a USB3

Having a better look at the output, this seems already the case.

jh4xsy commented 1 year ago

I haven't had any errors since then. Closing.

ast / SoapyAirspy

ringbuffer write timeout #5