search

raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.15k stars 5k forks source link

RPi5 SPI transfers: CS isn't kept low during words #6354

Closed heeplr closed 1 month ago

heeplr commented 1 month ago

Describe the bug

On RPi5 with Linux mypi 6.6.31+rpt-rpi-2712 #1 SMP PREEMPT Debian 1:6.6.31-1+rpt1 (2024-05-29) aarch64 GNU/Linux and also custom Linux mypi 6.6.45-rt39-v8-16k+ #11 SMP Sat Aug 31 13:38:16 BST 2024 aarch64 GNU/Linux, the configured CS (in my case CS0 of SPI.0 and SPI.1) is pulled high after $wordlength clock cycles. It seems that earlier kernels/Pi models didn't show this behaviour.

Steps to reproduce the behaviour

Reads from peripherals like the ICM42605 IMU or the SC16IS752 UART won't work if CS is pulled high before reading an answer. (I'll use SC16IS752 on SPI1 as example, but also happens on SPI0):

connecting a logic analyzer shows the effect with an ICM42605: D0 - SCLK D1 = MISO D2 = MOSI D3 = CS

works

1725974537970644529

doesn't work

1725974620286612928

Device (s)

Raspberry Pi 5

System

System Information
------------------

Raspberry Pi 5 Model B Rev 1.0
PRETTY_NAME="Debian GNU/Linux 12 (bookworm)"
NAME="Debian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"

Raspberry Pi reference 2024-07-04
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 48efb5fc5485fafdc9de8ad481eb5c09e1182656, stage2

Linux ardupilot 6.6.45-rt39-v8-16k+ #11 SMP Sat Aug 31 13:38:16 BST 2024 aarch64 GNU/Linux
Revision    : c04170
Serial      : 68d12e48190205e8
Model       : Raspberry Pi 5 Model B Rev 1.0
Throttled flag  : throttled=0x0
Camera          : vc_gencmd_read_response returned -1 error=1 error_msg="Command not registered"

Videocore information
---------------------

2024/09/10 14:40:30 
Copyright (c) 2012 Broadcom
version 5be4f304 (release) (embedded)

vc_gencmd_read_response returned -1
error=1 error_msg="Command not registered"

Filesystem information
----------------------
Filesystem     1K-blocks    Used Available Use% Mounted on
udev             2037072       0   2037072   0% /dev
tmpfs             415248    4064    411184   1% /run
/dev/mmcblk0p2  14740420 5291648   8680580  38% /
tmpfs            2076160       0   2076160   0% /dev/shm
tmpfs               5120       0      5120   0% /run/lock
/dev/mmcblk0p1    522230   69398    452832  14% /boot/firmware
tmpfs             415232       0    415232   0% /run/user/1000

Filename                Type        Size        Used        Priority
/var/swap                               file        204784      0       -2

Package version information
---------------------------
raspberrypi-ui-mods:
  Installed: (none)
raspberrypi-sys-mods:
  Installed: 20240807
openbox:
  Installed: (none)
lxpanel:
  Installed: (none)
pcmanfm:
  Installed: (none)
rpd-plym-splash:
  Installed: (none)

Networking Information
----------------------

end0: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        ether m.m.m.m  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
        device interrupt 104  

lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536
        inet x.x.x.x  netmask x.x.x.x
        loop  txqueuelen 1000  (Local Loopback)
        RX packets 40  bytes 3240 (3.1 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 40  bytes 3240 (3.1 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

wlan0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet x.x.x.x  netmask x.x.x.x  broadcast x.x.x.x
        ether m.m.m.m  txqueuelen 1000  (Ethernet)
        RX packets 608  bytes 54346 (53.0 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 533  bytes 397528 (388.2 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

USB Information
---------------

/:  Bus 04.Port 1: Dev 1, Class=root_hub, Driver=xhci-hcd/1p, 5000M
/:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci-hcd/2p, 480M
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci-hcd/1p, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci-hcd/2p, 480M

Display Information
-------------------

Running Legacy framebuffer

Audio Information
-------------------

null
    Discard all samples (playback) or generate zero samples (capture)

pactl not installed

config.txt
----------

arm_64bit=1
arm_freq=800
arm_freq_min=800
arm_peri_high=1
audio_pwm_mode=2
auto_initramfs=1
avs_temp=49920
camera_auto_detect=-1
core_freq=910
core_freq_min=500
disable_commandline_tags=2
disable_fw_kms_setup=1
display_default_lcd=-1
display_hdmi_rotate=-1
display_lcd_rotate=-1
dvfs=4
enable_gic=1
enable_uart=1
force_eeprom_read=1
force_pwm_open=1
framebuffer_depth=16
framebuffer_ignore_alpha=1
framebuffer_swap=1
gpu_freq_min=500
hdmi_enable_4kp60=1
hevc_freq=910
hevc_freq_min=500
ignore_lcd=-1
init_uart_clock=0x2dc6c00
isp_freq=910
isp_freq_min=500
max_framebuffers=1
over_voltage_avs=0x1d1a0
pause_burst_frames=1
pciex4_reset=1
pmic_turbo_threshold=600
program_serial_random=1
total_mem=4096
usb_max_current_enable=1
v3d_freq=960
v3d_freq_min=500
vpred=8792
vpred_max=8792
hdmi_force_cec_address:0=65535
hdmi_force_cec_address:1=65535
device_tree=-
kernel=Image.gz
overlay_prefix=overlays/
hdmi_cvt:0=
hdmi_cvt:1=
hdmi_edid_filename:0=
hdmi_edid_filename:1=
hdmi_timings:0=
hdmi_timings:1=

cmdline.txt
-----------
reboot=w coherent_pool=1M 8250.nr_uarts=1 pci=pcie_bus_safe bcm2708_fb.fbwidth=640 bcm2708_fb.fbheight=480 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 smsc95xx.macaddr=D8:3A:DD:EC:C3:D6 vc_mem.mem_base=0x3fc00000 vc_mem.mem_size=0x40000000  console=tty1 root=PARTUUID=a0e44b74-02 rootfstype=ext4 fsck.repair=yes rootwait cfg80211.ieee80211_regdom=DE isolcpus=nohz,domain,1-3 nohz_full=1-3 nohz=on rcu_nocb_poll rcu_nocbs=1-3 kthread_cpus=0 irqaffinity=0 tsc=reliable

pin configuration
-----------------

 0: ip    pu | hi // ID_SDA/GPIO0 = input
 1: ip    pu | hi // ID_SCL/GPIO1 = input
 2: a3    pu | hi // GPIO2 = SDA1
 3: a3    pu | hi // GPIO3 = SCL1
 4: no    pu | -- // GPIO4 = none
 5: no    pu | -- // GPIO5 = none
 6: no    pu | -- // GPIO6 = none
 7: op dh pu | hi // GPIO7 = output
 8: a0    pu | hi // GPIO8 = SPI0_CE0
 9: a0    pn | lo // GPIO9 = SPI0_MISO
10: a0    pn | lo // GPIO10 = SPI0_MOSI
11: a0    pn | lo // GPIO11 = SPI0_SCLK
12: no    pd | -- // GPIO12 = none
13: no    pd | -- // GPIO13 = none
14: no    pd | -- // GPIO14 = none
15: no    pd | -- // GPIO15 = none
16: no    pd | -- // GPIO16 = none
17: a0    pd | hi // GPIO17 = SPI1_CE1
18: op dh pd | hi // GPIO18 = output
19: a0    pd | lo // GPIO19 = SPI1_MISO
20: a0    pd | lo // GPIO20 = SPI1_MOSI
21: a0    pd | lo // GPIO21 = SPI1_SCLK
22: no    pd | -- // GPIO22 = none
23: no    pd | -- // GPIO23 = none
24: ip    pn | hi // GPIO24 = input
25: no    pd | -- // GPIO25 = none
26: no    pd | -- // GPIO26 = none
27: no    pd | -- // GPIO27 = none
28: ip    pd | lo // PCIE_RP1_WAKE/GPIO28 = input
29: no    pu | hi // FAN_TACH/GPIO29 = none
30: no    pu | -- // HOST_SDA/GPIO30 = none
31: no    pu | -- // HOST_SCL/GPIO31 = none
32: op dh pd | hi // ETH_RST_N/GPIO32 = output
33: no    pd | lo // GPIO33 = none
34: op dl pd | lo // CD0_IO0_MICCLK/GPIO34 = output
35: no    pd | lo // CD0_IO0_MICDAT0/GPIO35 = none
36: no    pd | lo // RP1_PCIE_CLKREQ_N/GPIO36 = none
37: no    pd | lo // GPIO37 = none
38: no    pd | hi // CD0_SDA/GPIO38 = none
39: no    pd | hi // CD0_SCL/GPIO39 = none
40: no    pd | hi // CD1_SDA/GPIO40 = none
41: no    pd | hi // CD1_SCL/GPIO41 = none
42: a2    pd | hi // USB_VBUS_EN/GPIO42 = VBUS_EN1
43: a2    pu | hi // USB_OC_N/GPIO43 = VBUS_OC1
44: op dh pd | hi // RP1_STAT_LED/GPIO44 = output
45: ip    pd | lo // FAN_PWM/GPIO45 = input
46: op dl pd | lo // CD1_IO0_MICCLK/GPIO46 = output
47: no    pd | lo // 2712_WAKE/GPIO47 = none
48: no    pd | lo // CD1_IO1_MICDAT1/GPIO48 = none
49: op dh pd | hi // EN_MAX_USB_CUR/GPIO49 = output
50: no    pd | -- // GPIO50 = none
51: no    pd | -- // GPIO51 = none
52: no    pu | -- // GPIO52 = none
53: no    pu | hi // GPIO53 = none
100: ip    pd | lo // GPIO0 = input
101: op dh pu | hi // 2712_BOOT_CS_N/GPIO1 = output
102: a6    pn | hi // 2712_BOOT_MISO/GPIO2 = VC_SPI0_MISO
103: a5    pn | hi // 2712_BOOT_MOSI/GPIO3 = VC_SPI0_MOSI
104: a6    pn | lo // 2712_BOOT_SCLK/GPIO4 = VC_SPI0_SCLK
105: ip    pd | lo // GPIO5 = input
106: ip    pd | lo // GPIO6 = input
107: ip    pd | lo // GPIO7 = input
108: ip    pd | lo // GPIO8 = input
109: ip    pd | lo // GPIO9 = input
110: ip    pd | lo // GPIO10 = input
111: ip    pd | lo // GPIO11 = input
112: ip    pd | lo // GPIO12 = input
113: ip    pd | lo // GPIO13 = input
114: a1    pd | lo // PCIE_SDA/GPIO14 = SPI_S_MOSI_OR_BSC_S_SDA
115: a1    pd | lo // PCIE_SCL/GPIO15 = SPI_S_SCK_OR_BSC_S_SCL
116: ip    pd | lo // GPIO16 = input
117: ip    pd | lo // GPIO17 = input
118: ip    pd | lo // GPIO18 = input
119: ip    pd | lo // GPIO19 = input
120: ip    pu | hi // PWR_GPIO/GPIO20 = input
121: ip    pd | lo // 2712_G21_FS/GPIO21 = input
122: ip    pd | lo // GPIO22 = input
123: ip    pd | lo // GPIO23 = input
124: a3    pn | hi // BT_RTS/GPIO24 = UART_RTS_0
125: a4    pu | hi // BT_CTS/GPIO25 = UART_CTS_0
126: a4    pn | hi // BT_TXD/GPIO26 = UART_TXD_0
127: a4    pu | hi // BT_RXD/GPIO27 = UART_RXD_0
128: op dh pd | hi // WL_ON/GPIO28 = output
129: ip    pd | lo // BT_ON/GPIO29 = input
130: a4    pn | lo // WIFI_SDIO_CLK/GPIO30 = SD2_CLK
131: a4    pu | hi // WIFI_SDIO_CMD/GPIO31 = SD2_CMD
132: a4    pd | hi // WIFI_SDIO_D0/GPIO32 = SD2_DAT0
133: a3    pu | hi // WIFI_SDIO_D1/GPIO33 = SD2_DAT1
134: a4    pn | hi // WIFI_SDIO_D2/GPIO34 = SD2_DAT2
135: a3    pn | hi // WIFI_SDIO_D3/GPIO35 = SD2_DAT3
200: ip    pd | hi // RP1_SDA/AON_GPIO0 = input
201: ip    pd | hi // RP1_SCL/AON_GPIO1 = input
202: op dh pd | hi // RP1_RUN/AON_GPIO2 = output
203: op dl pd | lo // SD_IOVDD_SEL/AON_GPIO3 = output
204: op dh pd | hi // SD_PWR_ON/AON_GPIO4 = output
205: a6    pu | lo // SD_CDET_N/AON_GPIO5 = SD_CARD_PRES_G
206: ip    pd | hi // SD_FLG_N/AON_GPIO6 = input
207: ip    pd | lo // AON_GPIO7 = input
208: ip    pd | lo // 2712_WAKE/AON_GPIO8 = input
209: op dh pd | hi // 2712_STAT_LED/AON_GPIO9 = output
210: ip    pd | lo // AON_GPIO10 = input
211: ip    pd | lo // AON_GPIO11 = input
212: ip    pd | lo // PMIC_INT/AON_GPIO12 = input
213: a3    pu | hi // UART_TX_FS/AON_GPIO13 = VC_TXD0
214: a3    pu | hi // UART_RX_FS/AON_GPIO14 = VC_RXD0
215: ip    pd | lo // AON_GPIO15 = input
216: ip    pu | hi // AON_GPIO16 = input
232: a1    -- | hi // HDMI0_SCL/AON_SGPIO0 = HDMI_TX0_BSC_SCL
233: a1    -- | hi // HDMI0_SDA/AON_SGPIO1 = HDMI_TX0_BSC_SDA
234: a1    -- | hi // HDMI1_SCL/AON_SGPIO2 = HDMI_TX1_BSC_SCL
235: a1    -- | hi // HDMI1_SDA/AON_SGPIO3 = HDMI_TX1_BSC_SDA
236: a2    -- | hi // PMIC_SCL/AON_SGPIO4 = BSC_M2_SCL
237: a2    -- | hi // PMIC_SDA/AON_SGPIO5 = BSC_M2_SDA

vcdbg log messages
------------------

005633.639: Initial voltage 800000 temp 49370
005831.052: avs_2712: AVS pred 8792 879200 temp 49920
005831.063: vpred 879 mV +0
005835.514: FB framebuffer_swap 1
005853.048: Select resolution HDMI0/2 hotplug 0 max_mode 2
005853.064: Select resolution HDMI1/2 hotplug 0 max_mode 2
006480.531: dtb_file 'bcm2712-rpi-5-b.dtb'
006560.932: dtparam: spi=on
006602.080: Loaded overlay 'sc16is752-spi1'
006602.106: dtparam: i2c_arm=on
006614.207: dtparam: i2c_arm_baudrate=1000000
009013.800: Starting OS 9013 ms
009015.177: 00000040: -> 00000480
009015.194: 00000030: -> 00100080
009015.209: 00000034: -> 00100080
009015.225: 00000038: -> 00100080
009015.240: 0000003c: -> 00100080
009094.314: sdram: sdram refresh 2081->4162 (2)

dmesg log
---------

[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x414fd0b1]
[    0.000000] Linux version 6.6.45-rt39-v8-16k+ (root@ardupilot) (gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #11 SMP Sat Aug 31 13:38:16 BST 2024
[    0.000000] KASLR enabled
[    0.000000] random: crng init done
[    0.000000] Machine model: Raspberry Pi 5 Model B Rev 1.0
[    0.000000] Reserved memory: created CMA memory pool at 0x0000000002000000, size 64 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] OF: reserved mem: 0x0000000002000000..0x0000000005ffffff (65536 KiB) map reusable linux,cma
[    0.000000] OF: reserved mem: 0x0000000000000000..0x000000000007ffff (512 KiB) nomap non-reusable atf@0
[    0.000000] OF: reserved mem: 0x000000003fd16540..0x000000003fd16577 (0 KiB) nomap non-reusable nvram@0
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000000000-0x00000000ffffffff]
[    0.000000]   DMA32    empty
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x000000000007ffff]
[    0.000000]   node   0: [mem 0x0000000000080000-0x000000003fbfffff]
[    0.000000]   node   0: [mem 0x0000000040000000-0x00000000ffffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x00000000ffffffff]
[    0.000000] On node 0, zone DMA: 256 pages in unavailable ranges
[    0.000000] psci: probing for conduit method from DT.
[    0.000000] psci: PSCIv1.1 detected in firmware.
[    0.000000] psci: Using standard PSCI v0.2 function IDs
[    0.000000] psci: MIGRATE_INFO_TYPE not supported.
[    0.000000] psci: SMC Calling Convention v1.2
[    0.000000] percpu: Embedded 5 pages/cpu s35176 r8192 d38552 u81920
[    0.000000] pcpu-alloc: s35176 r8192 d38552 u81920 alloc=5*16384
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Detected PIPT I-cache on CPU0
[    0.000000] CPU features: detected: Virtualization Host Extensions
[    0.000000] CPU features: detected: Hardware dirty bit management
[    0.000000] CPU features: detected: Spectre-v4
[    0.000000] CPU features: detected: Spectre-BHB
[    0.000000] CPU features: kernel page table isolation forced ON by KASLR
[    0.000000] CPU features: detected: Kernel page table isolation (KPTI)
[    0.000000] alternatives: applying boot alternatives
[    0.000000] Kernel command line: reboot=w coherent_pool=1M 8250.nr_uarts=1 pci=pcie_bus_safe bcm2708_fb.fbwidth=640 bcm2708_fb.fbheight=480 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 smsc95xx.macaddr=m.m.m.m vc_mem.mem_base=0x3fc00000 vc_mem.mem_size=0x40000000  console=tty1 root=PARTUUID=a0e44b74-02 rootfstype=ext4 fsck.repair=yes rootwait cfg80211.ieee80211_regdom=DE isolcpus=nohz,domain,1-3 nohz_full=1-3 nohz=on rcu_nocb_poll rcu_nocbs=1-3 kthread_cpus=0 irqaffinity=0 tsc=reliable
[    0.000000] Unknown kernel command line parameters "kthread_cpus=0 tsc=reliable", will be passed to user space.
[    0.000000] Dentry cache hash table entries: 524288 (order: 8, 4194304 bytes, linear)
[    0.000000] Inode-cache hash table entries: 262144 (order: 7, 2097152 bytes, linear)
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 260864
[    0.000000] mem auto-init: stack:all(zero), heap alloc:off, heap free:off
[    0.000000] Memory: 4074144K/4190208K available (7744K kernel code, 932K rwdata, 2032K rodata, 1728K init, 959K bss, 50528K reserved, 65536K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] rcu:     RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] Root IRQ handler: gic_handle_irq
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] NO_HZ: Full dynticks CPUs: 1-3.
[    0.000000] rcu:     Offload RCU callbacks from CPUs: 1-3.
[    0.000000] rcu:     Poll for callbacks from no-CBs CPUs.
[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[    0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.000000] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000255] Console: colour dummy device 80x25
[    0.000263] printk: legacy console [tty1] enabled
[    0.000490] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=216000)
[    0.000503] pid_max: default: 32768 minimum: 301
[    0.000581] Mount-cache hash table entries: 8192 (order: 2, 65536 bytes, linear)
[    0.000603] Mountpoint-cache hash table entries: 8192 (order: 2, 65536 bytes, linear)
[    0.001084] cgroup: Disabling memory control group subsystem
[    0.001652] rcu: Hierarchical SRCU implementation.
[    0.001663] rcu:     Max phase no-delay instances is 1000.
[    0.002502] smp: Bringing up secondary CPUs ...
[    0.002709] Detected PIPT I-cache on CPU1
[    0.002775] CPU1: Booted secondary processor 0x0000000100 [0x414fd0b1]
[    0.003049] Detected PIPT I-cache on CPU2
[    0.003107] CPU2: Booted secondary processor 0x0000000200 [0x414fd0b1]
[    0.003357] Detected PIPT I-cache on CPU3
[    0.003410] CPU3: Booted secondary processor 0x0000000300 [0x414fd0b1]
[    0.003458] smp: Brought up 1 node, 4 CPUs
[    0.003487] SMP: Total of 4 processors activated.
[    0.003494] CPU features: detected: 32-bit EL0 Support
[    0.003499] CPU features: detected: Data cache clean to the PoU not required for I/D coherence
[    0.003507] CPU features: detected: Common not Private translations
[    0.003512] CPU features: detected: CRC32 instructions
[    0.003520] CPU features: detected: RCpc load-acquire (LDAPR)
[    0.003525] CPU features: detected: LSE atomic instructions
[    0.003531] CPU features: detected: Privileged Access Never
[    0.003537] CPU features: detected: RAS Extension Support
[    0.003544] CPU features: detected: Speculative Store Bypassing Safe (SSBS)
[    0.003595] CPU: All CPU(s) started at EL2
[    0.003600] alternatives: applying system-wide alternatives
[    0.005684] devtmpfs: initialized
[    0.010285] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.010304] futex hash table entries: 1024 (order: 2, 65536 bytes, linear)
[    0.010548] pinctrl core: initialized pinctrl subsystem
[    0.010930] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[    0.011660] DMA: preallocated 1024 KiB GFP_KERNEL pool for atomic allocations
[    0.011741] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.011829] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.011849] audit: initializing netlink subsys (disabled)
[    0.012082] thermal_sys: Registered thermal governor 'step_wise'
[    0.012097] audit: type=2000 audit(0.008:1): state=initialized audit_enabled=0 res=1
[    0.012116] cpuidle: using governor ladder
[    0.012126] cpuidle: using governor menu
[    0.012210] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.012259] ASID allocator initialised with 32768 entries
[    0.012761] Serial: AMBA PL011 UART driver
[    0.014118] bcm2835-mbox 107c013880.mailbox: mailbox enabled
[    0.014420] 107d001000.serial: ttyAMA10 at MMIO 0x107d001000 (irq = 15, base_baud = 0) is a PL011 rev2
[    0.021442] raspberrypi-firmware soc:firmware: Attached to firmware from 2024-09-10T13:40:30, variant start_cd
[    0.025445] raspberrypi-firmware soc:firmware: Firmware hash is 5be4f30400000000000000000000000000000000
[    0.033358] Modules: 2G module region forced by RANDOMIZE_MODULE_REGION_FULL
[    0.033368] Modules: 0 pages in range for non-PLT usage
[    0.033370] Modules: 130216 pages in range for PLT usage
[    0.033914] bcm2835-dma 1000010000.dma: DMA legacy API manager, dmachans=0x1
[    0.034472] iommu: Default domain type: Translated
[    0.034480] iommu: DMA domain TLB invalidation policy: strict mode
[    0.034601] SCSI subsystem initialized
[    0.034661] usbcore: registered new interface driver usbfs
[    0.034676] usbcore: registered new interface driver hub
[    0.034692] usbcore: registered new device driver usb
[    0.034794] pps_core: LinuxPPS API ver. 1 registered
[    0.034800] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.034811] PTP clock support registered
[    0.034912] ARM FF-A: FFA_VERSION returned not supported
[    0.035625] vgaarb: loaded
[    0.035780] clocksource: Switched to clocksource arch_sys_counter
[    0.035927] FS-Cache: Loaded
[    0.035977] CacheFiles: Loaded
[    0.038001] NET: Registered PF_INET protocol family
[    0.038146] IP idents hash table entries: 65536 (order: 5, 524288 bytes, linear)
[    0.040401] tcp_listen_portaddr_hash hash table entries: 2048 (order: 1, 32768 bytes, linear)
[    0.040443] Table-perturb hash table entries: 65536 (order: 4, 262144 bytes, linear)
[    0.040454] TCP established hash table entries: 32768 (order: 4, 262144 bytes, linear)
[    0.040710] TCP bind hash table entries: 32768 (order: 6, 1048576 bytes, linear)
[    0.041676] TCP: Hash tables configured (established 32768 bind 32768)
[    0.041746] UDP hash table entries: 2048 (order: 2, 65536 bytes, linear)
[    0.041844] UDP-Lite hash table entries: 2048 (order: 2, 65536 bytes, linear)
[    0.041983] NET: Registered PF_UNIX/PF_LOCAL protocol family
[    0.042006] PCI: CLS 0 bytes, default 64
[    0.042164] Trying to unpack rootfs image as initramfs...
[    0.053575] Initialise system trusted keyrings
[    0.055817] workingset: timestamp_bits=46 max_order=18 bucket_order=0
[    0.060190] Key type asymmetric registered
[    0.060207] Asymmetric key parser 'x509' registered
[    0.060236] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)
[    0.060245] io scheduler mq-deadline registered
[    0.060250] io scheduler kyber registered
[    0.060278] io scheduler bfq registered
[    0.060650] irq_brcmstb_l2: registered L2 intc (/soc/intc@7d503000, parent irq: 26)
[    0.060745] irq_brcmstb_l2: registered L2 intc (/soc/intc@7d508380, parent irq: 27)
[    0.060812] irq_brcmstb_l2: registered L2 intc (/soc/intc@7d508400, parent irq: 28)
[    0.060881] irq_brcmstb_l2: registered L2 intc (/soc/intc@7d517b00, parent irq: 29)
[    0.064461] bcm2708_fb soc:fb: Unable to determine number of FBs. Disabling driver.
[    0.064479] bcm2708_fb: probe of soc:fb failed with error -2
[    0.118289] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    0.118941] 107d50c000.serial: ttyS0 at MMIO 0x107d50c000 (irq = 31, base_baud = 6000000) is a Broadcom BCM7271 UART
[    0.119030] serial serial0: tty port ttyS0 registered
[    0.119403] iproc-rng200 107d208000.rng: hwrng registered
[    0.119514] vc-mem: phys_addr:0x00000000 mem_base=0x3fc00000 mem_size:0x40000000(1024 MiB)
[    0.119886] bcm2712-iommu-cache 1000005b00.iommuc: bcm2712_iommu_cache_probe
[    0.129331] brd: module loaded
[    0.130623] loop: module loaded
[    0.130846] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    0.132078] Loading iSCSI transport class v2.0-870.
[    0.140986] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.141036] dwc_otg: FIQ enabled
[    0.141039] dwc_otg: NAK holdoff enabled
[    0.141041] dwc_otg: FIQ split-transaction FSM enabled
[    0.141046] Module dwc_common_port init
[    0.143943] usbcore: registered new interface driver uas
[    0.143969] usbcore: registered new interface driver usb-storage
[    0.156013] rpi-rtc soc:rpi_rtc: registered as rtc0
[    0.157949] rpi-rtc soc:rpi_rtc: setting system clock to 2024-09-12T15:55:41 UTC (1726156541)
[    0.158511] bcm2835-wdt bcm2835-wdt: Poweroff handler already present!
[    0.158521] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    0.161309] sdhci: Secure Digital Host Controller Interface driver
[    0.161320] sdhci: Copyright(c) Pierre Ossman
[    0.161382] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.161729] ledtrig-cpu: registered to indicate activity on CPUs
[    0.161814] SMCCC: SOC_ID: ARCH_SOC_ID not implemented, skipping ....
[    0.161838] hid: raw HID events driver (C) Jiri Kosina
[    0.161867] usbcore: registered new interface driver usbhid
[    0.161873] usbhid: USB HID core driver
[    0.164253] hw perfevents: enabled with armv8_cortex_a76 PMU driver, 7 counters available
[    0.164800] NET: Registered PF_PACKET protocol family
[    0.180438] registered taskstats version 1
[    0.180458] Loading compiled-in X.509 certificates
[    0.188256] brcm-pcie 1000120000.pcie: host bridge /axi/pcie@120000 ranges:
[    0.188286] brcm-pcie 1000120000.pcie:   No bus range found for /axi/pcie@120000, using [bus 00-ff]
[    0.188310] brcm-pcie 1000120000.pcie:      MEM 0x1f00000000..0x1ffffffffb -> 0x0000000000
[    0.188325] brcm-pcie 1000120000.pcie:      MEM 0x1c00000000..0x1effffffff -> 0x0400000000
[    0.188344] brcm-pcie 1000120000.pcie:   IB MEM 0x1f00000000..0x1f003fffff -> 0x0000000000
[    0.188357] brcm-pcie 1000120000.pcie:   IB MEM 0x0000000000..0x0fffffffff -> 0x1000000000
[    0.192391] brcm-pcie 1000120000.pcie: Forcing gen 2
[    0.192669] brcm-pcie 1000120000.pcie: PCI host bridge to bus 0000:00
[    0.192678] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.192689] pci_bus 0000:00: root bus resource [mem 0x1f00000000-0x1ffffffffb] (bus address [0x00000000-0xfffffffb])
[    0.192700] pci_bus 0000:00: root bus resource [mem 0x1c00000000-0x1effffffff pref] (bus address [0x400000000-0x6ffffffff])
[    0.192726] pci 0000:00:00.0: [14e4:2712] type 01 class 0x060400
[    0.192767] pci 0000:00:00.0: PME# supported from D0 D3hot
[    0.194383] pci 0000:00:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[    0.304189] brcm-pcie 1000120000.pcie: link up, 5.0 GT/s PCIe x4 (!SSC)
[    0.304249] pci 0000:01:00.0: [1de4:0001] type 00 class 0x020000
[    0.304274] pci 0000:01:00.0: reg 0x10: [mem 0xffffc000-0xffffffff]
[    0.304290] pci 0000:01:00.0: reg 0x14: [mem 0xffc00000-0xffffffff]
[    0.304302] pci 0000:01:00.0: reg 0x18: [mem 0xffff0000-0xffffffff]
[    0.304395] pci 0000:01:00.0: supports D1
[    0.304403] pci 0000:01:00.0: PME# supported from D0 D1 D3hot D3cold
[    0.316182] pci_bus 0000:01: busn_res: [bus 01-ff] end is updated to 01
[    0.316225] pci 0000:00:00.0: BAR 8: assigned [mem 0x1f00000000-0x1f005fffff]
[    0.316237] pci 0000:01:00.0: BAR 1: assigned [mem 0x1f00000000-0x1f003fffff]
[    0.316248] pci 0000:01:00.0: BAR 2: assigned [mem 0x1f00400000-0x1f0040ffff]
[    0.316259] pci 0000:01:00.0: BAR 0: assigned [mem 0x1f00410000-0x1f00413fff]
[    0.316269] pci 0000:00:00.0: PCI bridge to [bus 01]
[    0.316277] pci 0000:00:00.0:   bridge window [mem 0x1f00000000-0x1f005fffff]
[    0.316289] pci 0000:00:00.0: Max Payload Size set to  256/ 512 (was  128), Max Read Rq  512
[    0.316306] pci 0000:01:00.0: Max Payload Size set to  256/ 256 (was  128), Max Read Rq  512
[    0.316455] pcieport 0000:00:00.0: enabling device (0000 -> 0002)
[    0.316537] pcieport 0000:00:00.0: PME: Signaling with IRQ 36
[    0.316714] pcieport 0000:00:00.0: AER: enabled with IRQ 36
[    0.316849] rp1 0000:01:00.0: bar0 len 0x4000, start 0x1f00410000, end 0x1f00413fff, flags, 0x40200
[    0.316862] rp1 0000:01:00.0: bar1 len 0x400000, start 0x1f00000000, end 0x1f003fffff, flags, 0x40200
[    0.316879] rp1 0000:01:00.0: enabling device (0000 -> 0002)
[    0.318027] rp1 0000:01:00.0: chip_id 0x20001927
[    0.322983] genirq: irq_chip rp1_irq_chip did not update eff. affinity mask of irq 98
[    0.333410] dw_axi_dmac_platform 1f00188000.dma: DesignWare AXI DMA Controller, 8 channels
[    0.333819] xhci-hcd xhci-hcd.0: xHCI Host Controller
[    0.333834] xhci-hcd xhci-hcd.0: new USB bus registered, assigned bus number 1
[    0.334318] xhci-hcd xhci-hcd.0: hcc params 0x0240fe6d hci version 0x110 quirks 0x0000008000000810
[    0.334341] xhci-hcd xhci-hcd.0: irq 129, io mem 0x1f00200000
[    0.334359] xhci-hcd xhci-hcd.0: xHCI Host Controller
[    0.334367] xhci-hcd xhci-hcd.0: new USB bus registered, assigned bus number 2
[    0.334377] xhci-hcd xhci-hcd.0: Host supports USB 3.0 SuperSpeed
[    0.334452] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.06
[    0.334463] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.334472] usb usb1: Product: xHCI Host Controller
[    0.334478] usb usb1: Manufacturer: Linux 6.6.45-rt39-v8-16k+ xhci-hcd
[    0.334485] usb usb1: SerialNumber: xhci-hcd.0
[    0.334683] hub 1-0:1.0: USB hub found
[    0.334705] hub 1-0:1.0: 2 ports detected
[    0.335958] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.06
[    0.335972] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.335980] usb usb2: Product: xHCI Host Controller
[    0.335987] usb usb2: Manufacturer: Linux 6.6.45-rt39-v8-16k+ xhci-hcd
[    0.335994] usb usb2: SerialNumber: xhci-hcd.0
[    0.336156] hub 2-0:1.0: USB hub found
[    0.336176] hub 2-0:1.0: 1 port detected
[    0.336629] xhci-hcd xhci-hcd.1: xHCI Host Controller
[    0.336642] xhci-hcd xhci-hcd.1: new USB bus registered, assigned bus number 3
[    0.337123] xhci-hcd xhci-hcd.1: hcc params 0x0240fe6d hci version 0x110 quirks 0x0000008000000810
[    0.337146] xhci-hcd xhci-hcd.1: irq 134, io mem 0x1f00300000
[    0.337162] xhci-hcd xhci-hcd.1: xHCI Host Controller
[    0.337170] xhci-hcd xhci-hcd.1: new USB bus registered, assigned bus number 4
[    0.337179] xhci-hcd xhci-hcd.1: Host supports USB 3.0 SuperSpeed
[    0.343746] Freeing initrd memory: 10928K
[    0.344134] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.06
[    0.344147] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.344156] usb usb3: Product: xHCI Host Controller
[    0.344162] usb usb3: Manufacturer: Linux 6.6.45-rt39-v8-16k+ xhci-hcd
[    0.344170] usb usb3: SerialNumber: xhci-hcd.1
[    0.344436] hub 3-0:1.0: USB hub found
[    0.344460] hub 3-0:1.0: 2 ports detected
[    0.344671] usb usb4: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.06
[    0.344682] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.344690] usb usb4: Product: xHCI Host Controller
[    0.344697] usb usb4: Manufacturer: Linux 6.6.45-rt39-v8-16k+ xhci-hcd
[    0.344703] usb usb4: SerialNumber: xhci-hcd.1
[    0.344855] hub 4-0:1.0: USB hub found
[    0.344873] hub 4-0:1.0: 1 port detected
[    0.346005] bcm2712-iommu 1000005100.iommu: bcm2712_iommu_init: DEBUG_INFO = 0x20804774
[    0.346557] platform 1000800000.codec: bcm2712_iommu_probe_device: MMU 1000005100.iommu
[    0.346570] platform 1000800000.codec: bcm2712_iommu_device_group: MMU 1000005100.iommu
[    0.346582] platform 1000800000.codec: Adding to iommu group 0
[    0.346602] platform 1000880000.pisp_be: bcm2712_iommu_probe_device: MMU 1000005100.iommu
[    0.346613] platform 1000880000.pisp_be: bcm2712_iommu_device_group: MMU 1000005100.iommu
[    0.346624] platform 1000880000.pisp_be: Adding to iommu group 0
[    0.346666] platform 1000800000.codec: bcm2712_iommu_attach_dev: MMU 1000005100.iommu
[    0.346675] platform 1000880000.pisp_be: bcm2712_iommu_attach_dev: MMU 1000005100.iommu
[    0.346686] bcm2712-iommu 1000005100.iommu: bcm2712_iommu_probe: Success
[    0.347291] bcm2712-iommu 1000005200.iommu: bcm2712_iommu_init: DEBUG_INFO = 0x20804774
[    0.347840] bcm2712-iommu 1000005200.iommu: bcm2712_iommu_probe: Success
[    0.348380] bcm2712-iommu 1000005280.iommu: bcm2712_iommu_init: DEBUG_INFO = 0x20804774
[    0.348911] bcm2712-iommu 1000005280.iommu: bcm2712_iommu_probe: Success
[    0.349535] sdhci-brcmstb 1000fff000.mmc: Got CD GPIO
[    0.349681] mmc0: CQHCI version 5.10
[    0.350355] mmc1: CQHCI version 5.10
[    0.350749] of_cfs_init
[    0.350797] of_cfs_init: OK
[    0.350853] clk: Disabling unused clocks
[    0.383895] mmc0: SDHCI controller on 1000fff000.mmc [1000fff000.mmc] using ADMA 64-bit
[    0.421487] mmc0: new high speed SDHC card at address 21a1
[    0.421775] mmcblk0: mmc0:21a1 APPSD 14.8 GiB
[    0.423381]  mmcblk0: p1 p2
[    0.423506] mmcblk0: mmc0:21a1 APPSD 14.8 GiB
[    0.535921] mmc1: SDHCI controller on 1001100000.mmc [1001100000.mmc] using ADMA 64-bit
[    0.536576] Freeing unused kernel memory: 1728K
[    0.536620] Run /init as init process
[    0.536625]   with arguments:
[    0.536628]     /init
[    0.536630]   with environment:
[    0.536633]     HOME=/
[    0.536635]     TERM=linux
[    0.536637]     kthread_cpus=0
[    0.536640]     tsc=reliable
[    0.569355] mmc1: new ultra high speed DDR50 SDIO card at address 0001
[    3.410280] EXT4-fs (mmcblk0p2): mounted filesystem 56f80fa2-e005-4cca-86e6-19da1069914d ro with ordered data mode. Quota mode: disabled.
[    4.198571] systemd[1]: systemd 252.26-1~deb12u2 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified)
[    4.198606] systemd[1]: Detected architecture arm64.
[    4.203412] systemd[1]: Hostname set to <ardupilot>.
[    4.755300] systemd[1]: Queued start job for default target multi-user.target.
[    4.757038] systemd[1]: Created slice system-getty.slice - Slice /system/getty.
[    4.757652] systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe.
[    4.758146] systemd[1]: Created slice system-systemd\x2dfsck.slice - Slice /system/systemd-fsck.
[    4.758469] systemd[1]: Created slice user.slice - User and Session Slice.
[    4.758656] systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch.
[    4.758813] systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch.
[    4.758948] systemd[1]: proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point was skipped because of an unmet condition check (ConditionPathExists=/proc/sys/fs/binfmt_misc).
[    4.758999] systemd[1]: Expecting device dev-disk-by\x2dpartuuid-a0e44b74\x2d01.device - /dev/disk/by-partuuid/a0e44b74-01...
[    4.759082] systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes.
[    4.759167] systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes.
[    4.759275] systemd[1]: Reached target paths.target - Path Units.
[    4.759359] systemd[1]: Reached target remote-fs.target - Remote File Systems.
[    4.759431] systemd[1]: Reached target slices.target - Slice Units.
[    4.759526] systemd[1]: Reached target swap.target - Swaps.
[    4.759619] systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes.
[    4.759904] systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket.
[    4.760081] systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe.
[    4.760556] systemd[1]: Listening on systemd-journald-audit.socket - Journal Audit Socket.
[    4.760831] systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log).
[    4.761095] systemd[1]: Listening on systemd-journald.socket - Journal Socket.
[    4.761401] systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket.
[    4.761626] systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket.
[    4.761938] systemd[1]: dev-hugepages.mount - Huge Pages File System was skipped because of an unmet condition check (ConditionPathExists=/sys/kernel/mm/hugepages).
[    4.763720] systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System...
[    4.764066] systemd[1]: sys-kernel-debug.mount - Kernel Debug File System was skipped because of an unmet condition check (ConditionPathExists=/sys/kernel/debug).
[    4.764272] systemd[1]: sys-kernel-tracing.mount - Kernel Trace File System was skipped because of an unmet condition check (ConditionPathExists=/sys/kernel/tracing).
[    4.766209] systemd[1]: Starting fake-hwclock.service - Restore / save the current clock...
[    4.771348] systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout...
[    4.775991] systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes...
[    4.777691] systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs...
[    4.782660] systemd[1]: Starting modprobe@dm_mod.service - Load Kernel Module dm_mod...
[    4.787624] systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm...
[    4.797564] systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore...
[    4.808011] systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse...
[    4.814637] systemd[1]: Starting modprobe@loop.service - Load Kernel Module loop...
[    4.814920] systemd[1]: systemd-fsck-root.service - File System Check on Root Device was skipped because of an unmet condition check (ConditionPathExists=!/run/initramfs/fsck-root).
[    4.815348] systemd[1]: systemd-journald.service: unit configures an IP firewall, but the local system does not support BPF/cgroup firewalling.
[    4.815365] systemd[1]: (This warning is only shown for the first unit using IP firewalling.)
[    4.828179] systemd[1]: Starting systemd-journald.service - Journal Service...
[    4.844068] systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules...
[    4.849766] systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems...
[    4.856171] systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices...
[    4.858546] systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System.
[    4.862677] systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes.
[    4.863376] systemd[1]: modprobe@configfs.service: Deactivated successfully.
[    4.867985] systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs.
[    4.868627] systemd[1]: modprobe@dm_mod.service: Deactivated successfully.
[    4.868886] systemd[1]: Finished modprobe@dm_mod.service - Load Kernel Module dm_mod.
[    4.869397] systemd[1]: modprobe@efi_pstore.service: Deactivated successfully.
[    4.874036] systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore.
[    4.874688] systemd[1]: modprobe@loop.service: Deactivated successfully.
[    4.875594] systemd[1]: Finished modprobe@loop.service - Load Kernel Module loop.
[    4.904243] systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System...
[    4.904466] systemd[1]: systemd-repart.service - Repartition Root Disk was skipped because no trigger condition checks were met.
[    4.905519] systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System.
[    4.914244] systemd[1]: Finished fake-hwclock.service - Restore / save the current clock.
[    4.927739] fuse: init (API version 7.39)
[    4.948041] systemd[1]: modprobe@fuse.service: Deactivated successfully.
[    4.948289] systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse.
[    4.952047] systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System...
[    4.961339] systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System.
[    4.975873] i2c_dev: i2c /dev entries driver
[    4.977014] systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules.
[    4.978707] systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables...
[    5.036831] systemd[1]: modprobe@drm.service: Deactivated successfully.
[    5.037084] systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm.
[    5.040238] systemd[1]: Started systemd-journald.service - Journal Service.
[    5.648986] EXT4-fs (mmcblk0p2): re-mounted 56f80fa2-e005-4cca-86e6-19da1069914d r/w. Quota mode: disabled.
[    5.718344] systemd-journald[203]: Received client request to flush runtime journal.
[   14.219553] rpi-gpiomem 107d508500.gpiomem: window base 0x107d508500 size 0x00000040
[   14.232899] rpi-gpiomem 107d508500.gpiomem: initialised 1 regions as /dev/gpiomem1
[   14.232995] rpi-gpiomem 107d517c00.gpiomem: window base 0x107d517c00 size 0x00000040
[   14.234159] rpi-gpiomem 107d517c00.gpiomem: initialised 1 regions as /dev/gpiomem2
[   14.234229] rpi-gpiomem 107d504100.gpiomem: window base 0x107d504100 size 0x00000020
[   14.235117] rpi-gpiomem 107d504100.gpiomem: initialised 1 regions as /dev/gpiomem3
[   14.235180] rpi-gpiomem 107d510700.gpiomem: window base 0x107d510700 size 0x00000020
[   14.238921] rpi-gpiomem 107d510700.gpiomem: initialised 1 regions as /dev/gpiomem4
[   14.239089] rpi-gpiomem 1f000d0000.gpiomem: window base 0x1f000d0000 size 0x00030000
[   14.243836] rpi-gpiomem 1f000d0000.gpiomem: initialised 1 regions as /dev/gpiomem0
[   14.397459] input: pwr_button as /devices/platform/pwr_button/input/input0
[   14.661031] macb 1f00100000.ethernet eth0: Cadence GEM rev 0x00070109 at 0x1f00100000 irq 104 (m.m.m.m)
[   14.960311] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[   14.970938] Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf'
[   14.971530] Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328'
[   14.972341] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[   14.972917] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'
[   15.015865] macb 1f00100000.ethernet end0: renamed from eth0
[   15.161935] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[   15.162251] usbcore: registered new interface driver brcmfmac
[   15.270824] spi1.0: ttySC0 at I/O 0x0 (irq = 163, base_baud = 921600) is a SC16IS752
[   15.285090] spi1.0: ttySC1 at I/O 0x1 (irq = 163, base_baud = 921600) is a SC16IS752
[   15.393366] brcmfmac: brcmf_c_process_txcap_blob: no txcap_blob available (err=-2)
[   15.394921] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Aug 29 2023 01:47:08 version 7.45.265 (28bca26 CY) FWID 01-b677b91b
[   16.071914] Adding 204784k swap on /var/swap.  Priority:-2 extents:12 across:761856k SS
[   17.569314] macb 1f00100000.ethernet end0: PHY [1f00100000.ethernet-ffffffff:01] driver [Broadcom BCM54213PE] (irq=POLL)
[   17.569328] macb 1f00100000.ethernet end0: configuring for phy/rgmii-id link mode
[   17.572373] pps pps0: new PPS source ptp0
[   17.575429] macb 1f00100000.ethernet: gem-ptp-timer ptp clock registered.
[   17.595388] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[  396.139520] systemd[641]: memfd_create() called without MFD_EXEC or MFD_NOEXEC_SEAL set
[  403.083104] sc16is7xx spi1.0: chip reports 255 free bytes in TX fifo, but it only has 64
[  403.083160] sc16is7xx spi1.0: chip reports 255 free bytes in TX fifo, but it only has 64
[  403.706563] sc16is7xx spi1.0: chip reports 255 free bytes in TX fifo, but it only has 64

Logs

No response

Additional context

No response

pelwell commented 1 month ago

There's something strange about your overlay, or perhaps some other software is changing the pinmux. When I load sc16is752-spi1 I get:

pi@phil-pi5:~ $ pinctrl 18-21
18: op dl pd | lo // GPIO18 = output
19: a0    pd | lo // GPIO19 = SPI1_MISO
20: a0    pd | lo // GPIO20 = SPI1_MOSI
21: a0    pd | lo // GPIO21 = SPI1_SCLK

This is correct - the CS line is driven as a GPIO by the kernel SPI framework. I get the same result whether the overlay is loaded by the firmware or at runtime using the dtoverlay command.

Try this:

  1. Comment out dtoverlay=sc16is752-spi1 in config.txt.
  2. Reboot the Pi.
  3. What does pinctrl 18-21 show?
  4. Run sudo dtoverlay sc16is752-spi1.
  5. What does pinctrl 18-21 show now?
heeplr commented 1 month ago

The results are strange indeed:

$ ls /dev/ttySC*
ls: cannot access '/dev/ttySC*': No such file or directory
$ pinctrl 18-21
18: a0    pd | hi // GPIO18 = SPI1_CE0
19: no    pd | -- // GPIO19 = none
20: no    pd | -- // GPIO20 = none
21: no    pd | -- // GPIO21 = none
$ sudo dtoverlay sc16is752-spi1
$ ls /dev/ttySC*
/dev/ttySC0  /dev/ttySC1
$ pinctrl 18-21
18: op dh pd | hi // GPIO18 = output
19: a0    pd | lo // GPIO19 = SPI1_MISO
20: a0    pd | lo // GPIO20 = SPI1_MOSI
21: a0    pd | lo // GPIO21 = SPI1_SCLK

The sc16is752-spi1-overlay.dts from 29f7f01091 i'm using is

dts-v1/;
/plugin/;

/ {
        compatible = "brcm,bcm2835";

        fragment@0 {
                target = <&gpio>;
                __overlay__ {
                        spi1_pins: spi1_pins {
                                brcm,pins = <19 20 21>;
                                brcm,function = <3>; /* alt4 */
                        };

                        spi1_cs_pins: spi1_cs_pins {
                                brcm,pins = <18>;
                                brcm,function = <1>; /* output */
                        };   

                        int_pins: int_pins@18 {
                                        brcm,pins = <24>;
                                        brcm,function = <0>; /* in */
                                        brcm,pull = <0>; /* none */
                        };
                };
        };

        fragment@1 {
                target = <&spi1>;
                __overlay__ {
                        #address-cells = <1>;
                        #size-cells = <0>;
                        pinctrl-names = "default";
                        pinctrl-0 = <&spi1_pins &spi1_cs_pins>;
                        cs-gpios = <&gpio 18 1>;
                        status = "okay";

                        sc16is752: sc16is752@0 {
                                compatible = "nxp,sc16is752";
                                reg = <0>; /* CE0 */
                                clocks = <&sc16is752_clk>;
                                interrupt-parent = <&gpio>;
                                interrupts = <24 2>; /* IRQ_TYPE_EDGE_FALLING */
                                pinctrl-0 = <&int_pins>;
                                pinctrl-names = "default";
                                gpio-controller;
                                #gpio-cells = <2>;
                                spi-max-frequency = <4000000>;
                        };
                };
        };

        fragment@2 {
                target = <&aux>;
                __overlay__ {
                        status = "okay";
                };
        };

        fragment@3 {
                target-path = "/";
                __overlay__ {
                        sc16is752_clk: sc16is752_spi1_0_clk {
                                compatible = "fixed-clock";
                                #clock-cells = <0>;
                                clock-frequency = <14745600>;
                        };
                };
        };

        __overrides__ {
                int_pin = <&sc16is752>,"interrupts:0", <&int_pins>,"brcm,pins:0",
                          <&int_pins>,"reg:0";
                xtal = <&sc16is752_clk>,"clock-frequency:0";
        };
};
pelwell commented 1 month ago

You must have a script etc. that is changing the pinmux for GPIO 18, perhaps using pinctrl. If the pin had been changed from Device Tree then the overlay would not have applied successfully at runtime.

heeplr commented 1 month ago

Indeed I can't reproduce this with a fresh image. That's strange since this is basically just vanilla raspbian-lite + custom realtime kernel. I'll close this. If it really affects other's too, it could be reopened.

@pelwell thanks for clarifying