This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

AM625: Boot stall and RCU preempt stall

Part Number: AM625

Hello,

We are experiencing an issue where on around 5% of the boots the boot process completely stalls. We do have some lose indication that the issue is more frequent at low temperatures (less than -20 degrees celsius), but it seems to exist also at higher temperatures.

Currently running a 6.1 kernel based on 09 release from TI (the base SHA is 26d37f12c83158b8e5333e6d5dd14b2fb9cdeab7).

Here an example logs:

[    7.349065] m_can_platform 4e08000.can: m_can device registered (irq=0, version=32)
[    7.367509] m_can_platform 20701000.can: m_can device registered (irq=482, version=32)
[    7.521928] k3-m4-rproc 5000000.m4fss: assigned reserved memory node m4f-dma-memory@9cb00000
[    7.605120] k3-m4-rproc 5000000.m4fss: configured M4 for remoteproc mode
[    7.653426] k3-m4-rproc 5000000.m4fss: local reset is deasserted for device
[    7.677427] remoteproc remoteproc0: 5000000.m4fss is available
[    7.686150] remoteproc remoteproc0: Direct firmware load for am62-mcu-m4f0_0-fw failed with error -2
[    7.700849] remoteproc remoteproc0: powering up 5000000.m4fss
[    7.709319] rtc-ti-k3 2b1f0000.rtc: registered as rtc1
[    7.714620] remoteproc remoteproc0: Direct firmware load for am62-mcu-m4f0_0-fw failed with error -2
[    7.731199] remoteproc remoteproc0: request_firmware failed: -2
[    7.768996] platform 78000000.r5f: R5F core may have been powered on by a different host, programmed state (0) != actual state (1)
[    7.848688] pvrsrvkm: loading out-of-tree module taints kernel.
[    7.885142] platform 78000000.r5f: configured R5F for IPC-only mode
[    7.927615] platform 78000000.r5f: assigned reserved memory node r5f-dma-memory@9da00000
[    7.941600] [drm] Initialized tidss 1.0.0 20180215 for 30200000.dss on minor 0
[    7.950494] tidss 30200000.dss: [drm] Cannot find any crtc or sizes
[    7.982989] remoteproc remoteproc1: 78000000.r5f is available
[    7.989990] remoteproc remoteproc1: attaching to 78000000.r5f
[    8.029364] PVR_K:  185: Device: fd00000.gpu
[    8.032917] platform 78000000.r5f: R5F core initialized in IPC-only mode
[    8.038425] PVR_K:  185: Read BVNC 33.15.11.3 from HW device registers
[    8.064949] PVR_K:  185: RGX Device registered with BVNC 33.15.11.3
[    8.082352] [drm] Initialized pvr 23.1.6404501 20170530 for fd00000.gpu on minor 1
[    8.107479] rproc-virtio rproc-virtio.4.auto: assigned reserved memory node r5f-dma-memory@9da00000
[    8.126466] virtio_rpmsg_bus virtio0: rpmsg host is online
[    8.127037] virtio_rpmsg_bus virtio0: creating channel ti.ipc4.ping-pong addr 0xd
[    8.134870] rproc-virtio rproc-virtio.4.auto: registered virtio0 (type 7)
[    8.144601] virtio_rpmsg_bus virtio0: creating channel rpmsg_chrdev addr 0xe
[    8.158043] remoteproc remoteproc1: remote processor 78000000.r5f is now attached
[*     ] A start job is running for Wait for…vice Initialization (5s / 3min 1s)
M
[**    ] A start job is running for Wait for…vice Initialization (5s / 3min 1s)
[   30.828716] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[   30.834860] rcu: 	1-...!: (0 ticks this GP) idle=9bf4/1/0x4000000000000000 softirq=5095/5095 fqs=0
[   30.843814] rcu: 	Tasks blocked on level-0 rcu_node (CPUs 0-1): P177/1:b..l
[   30.850779] 	(detected by 0, t=5256 jiffies, g=1881, q=329 ncpus=2)
[   30.857039] Task dump for CPU 1:
[   30.860261] task:systemd-udevd   state:R  running task     stack:0     pid:186   ppid:173    flags:0x00000a0e
[   30.870170] Call trace:
[   30.872612]  __switch_to+0xe4/0x160
[   30.876114]  lock_timer_base+0x64/0xa4
[   30.879862]  del_timer_sync+0x4c/0xd0
[   30.883519]  schedule_timeout+0x88/0xf0
[   30.887350]  wait_for_completion_timeout+0x74/0x144
[   30.892222]  tx_tick+0x44/0xa4
[   30.895279] task:systemd-udevd   state:R  running task     stack:0     pid:177   ppid:173    flags:0x00000a04
[   30.905185] Call trace:
[   30.907624]  __switch_to+0xe4/0x160
[   30.911109]  __schedule+0x22c/0x660
[   30.914593]  preempt_schedule+0x4c/0x70
[   30.918424]  _raw_spin_unlock_irqrestore+0x30/0x50
[   30.923209]  __wake_up_common_lock+0x90/0xd0
[   30.927476]  __wake_up_sync_key+0x20/0x30
[   30.931480]  sock_def_readable+0x40/0x80
[   30.935403]  unix_dgram_sendmsg+0x3f8/0x880
[   30.939584]  sock_write_iter+0xa4/0x110
[   30.943415]  vfs_write+0x254/0x2b0
[   30.946816]  ksys_write+0xdc/0xf4
[   30.950127]  __arm64_sys_write+0x1c/0x2c
[   30.954045]  invoke_syscall+0x48/0x114
[   30.957793]  el0_svc_common.constprop.0+0xd4/0xfc
[   30.962492]  do_el0_svc+0x30/0xd0
[   30.965804]  el0_svc+0x2c/0x84
[   30.968855]  el0t_64_sync_handler+0xbc/0x140
[   30.973119]  el0t_64_sync+0x18c/0x190
[   30.976779] rcu: rcu_preempt kthread timer wakeup didn't happen for 5255 jiffies! g1881 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
[   30.988069] rcu: 	Possible timer handling issue on cpu=1 timer-softirq=555
[   30.994933] rcu: rcu_preempt kthread starved for 5256 jiffies! g1881 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=1
[   31.005269] rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
[   31.014388] rcu: RCU grace-period kthread stack dump:
[   31.019430] task:rcu_preempt     state:I stack:0     pid:14    ppid:2      flags:0x00000008
[   31.027775] Call trace:
[   31.030214]  __switch_to+0xe4/0x160
[   31.033699]  __schedule+0x22c/0x660
[   31.037183]  schedule+0x5c/0xd0
[   31.040320]  schedule_timeout+0x80/0xf0
[   31.044149]  rcu_gp_fqs_loop+0x124/0x3dc
[   31.048071]  rcu_gp_kthread+0x128/0x164
[   31.051901]  kthread+0x10c/0x110
[   31.055129]  ret_from_fork+0x10/0x20
[   31.058699] rcu: Stack dump where RCU GP kthread last ran:
[   31.064174] Task dump for CPU 1:
[   31.067393] task:systemd-udevd   state:R  running task     stack:0     pid:186   ppid:173    flags:0x00000a0e
[   31.077298] Call trace:
[   31.079736]  __switch_to+0xe4/0x160
[   31.083221]  lock_timer_base+0x64/0xa4
[   31.086965]  del_timer_sync+0x4c/0xd0
[   31.090622]  schedule_timeout+0x88/0xf0
[   31.094450]  wait_for_completion_timeout+0x74/0x144
[   31.099322]  tx_tick+0x44/0xa4

Here a couple of complete logs:

23-08-26_20-59-39-Fail.txt
Climate Chamber:       VT 7021
Start Temperature:     -36.6�C
End Temperature:       -39.2�C
Measured Temperature:  -36.6�C
Shelf Temperature:     -34.6�C
Shelf Name:            Shelf_19
Module Serial Number:  15133546
Module Location:       Shelf 2, Carrier Board 2
Test duration:         399.15s

Test Log
********
20:59:39.61 15->16 Waited 300.00s
20:54:39.47 14->15 Set Reset Low
20:54:39.34 13->14 Power Off
20:54:39.23 7->13 Not found, time out: "login:"
20:53:09.03 6->7 Message found: "Starting kernel"
20:53:05.14 5->6 Message found: "U-Boot"
20:53:02.45 4->5 Reset is High
20:53:02.34 3->4 Cycle time 1.652s is less than 20.00s
20:53:02.20 2->3 Waited 1.00s
20:53:00.97 1->2 Set Reset High
20:53:00.86 0->1 Power On

Search Strings
**************
PASS : U-Boot
PASS : Starting kernel
0001 Q2J55L 7.09 GiB  : mmcblk0: mmc0:
PASS : mmcblk0: p1 p2
OK : cut here
PASS : hwclock
PASS : I/O error
PASS : Internal error
FAIL : Starting CPU stress
FAIL : successful run
PASS : unsuccessful run
FAIL : connected with
N/A : eth0: Link is Up - 
N/A : connect failed: 
PASS : IPERF stuck
N/A : 0.0-10
PASS : memtester failed
FAIL : memtester version
PASS : FAILURE
FAIL : Done.
PASS : bonnie\+\+ failed
0 : OAK ERROR
0 : UART ERROR
OK : rtc-ds1307 0-0032: registered as rtc0
OK : rtc-ti-k3 2b1f0000.rtc: registered as rtc1
OK : xception stack
N/A : Device life time estimation type A
N/A : Device life time estimation type B 
N/A : Pre EOL information
0 : USB hub found
0 : xception stack
Disabled : 0000.sai mapping ok
Disabled : sgtl5000 revision 0x11
4 : U-Boot
0 : page allocation failure
Not OK : WLAN FW is active
0 : Disabled wifi
0 : Disabled bluetooth
Not OK : Scan completed for wifi
Disabled : Discovery started
PASS : suspend md5sum failed
Disabled : suspend succeeded
Disabled : /tmp/memfile:
FAIL : Waiting for power-cycle
0 : Bus 00
0 : :00.0 
0 : bus I2C
0 : the audio card
FAIL : CPU stress passed
FAIL : reboot: Power down
PASS : 0 packets received
N/A : Speed:
N/A : number of warnings in the dmesg boot:
N/A : number of errors in the dmesg boot:
0 : USB hub found
0 : unexpected event for opcode
PASS : Firmware wakeup failed
PASS : thermal_zone1: critical temperature reached
PASS : rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:

Terminal
********

U-Boot SPL 2023.04-6.4.0-devel+git.6eec39f33231 (Aug 03 2023 - 18:01:08 +0000)
SYSFW ABI: 3.1 (firmware rev 0x0009 '9.0.5--v09.00.05 (Kool Koala)')
SPL initial stack usage: 13376 bytes
Trying to boot from MMC1
Authentication passed
Authentication passed
Authentication passed
Authentication passed
Authentication passed
Starting ATF on ARM64 core...

NOTICE:  BL31: v2.8(release):v2.8-226-g2fcd408bb3-dirty
NOTICE:  BL31: Built : 00:42:57, Jan 13 2023

U-Boot SPL 2023.04-6.4.0-devel+git.6eec39f33231 (Aug 03 2023 - 18:01:08 +0000)
SYSFW ABI: 3.1 (firmware rev 0x0009 '9.0.5--v09.00.05 (Kool Koala)')
SPL initial stack usage: 1856 bytes
Trying to boot from MMC1
Authentication passed
Authentication passed


U-Boot 2023.04-6.4.0-devel+git.6eec39f33231 (Aug 03 2023 - 18:01:08 +0000)

SoC:   AM62X SR1.0 HS-FS
DRAM:  1 GiB
Core:  142 devices, 30 uclasses, devicetree: separate
MMC:   mmc@fa10000: 0, mmc@fa00000: 1
Loading Environment from MMC... OK
In:    serial@2800000
Out:   serial@2800000
Err:   serial@2800000
Model: Toradex 0074 Verdin AM62 Dual 1GB IT V1.1A
Serial#: 15133546
MISSING TORADEX CARRIER CONFIG BLOCKS
am65_cpsw_nuss ethernet@8000000: K3 CPSW: nuss_ver: 0x6BA01103 cpsw_ver: 0x6BA81103 ale_ver: 0x00290105 Ports:2 mdio_freq:1000000
Setting variant to nonwifi
Net:   
Warning: ethernet@8000000port@1 MAC addresses don't match:
Address in ROM is		28:b5:e8:cb:53:a5
Address in environment is	00:14:2d:e6:eb:6a
eth0: ethernet@8000000port@1 [PRIME]Could not get PHY for ethernet@8000000port@1: addr 7
am65_cpsw_nuss_port ethernet@8000000port@2: phy_connect() failed

Hit any key to stop autoboot:  1  0 
MMC: no card present
switch to partitions #0, OK
mmc0(part 0) is current device
Scanning mmc 0:1...
Found U-Boot script /boot.scr
6003 bytes read in 10 ms (585.9 KiB/s)
## Executing script at 90280000
Loading DeviceTree: k3-am625-verdin-nonwifi-dev.dtb
67698 bytes read in 11 ms (5.9 MiB/s)
82 bytes read in 9 ms (8.8 KiB/s)
Working FDT set to 90200000
Applying Overlay: verdin-am62_dsi-to-hdmi_overlay.dtbo
3213 bytes read in 9 ms (348.6 KiB/s)
Applying Overlay: verdin-am62_spidev_overlay.dtbo
560 bytes read in 10 ms (54.7 KiB/s)
7769854 bytes read in 62 ms (119.5 MiB/s)
Bootargs: root=PARTUUID=88a818b9-02 ro rootwait console=tty1 console=ttyS2,115200 consoleblank=0 earlycon=ns16550a,mmio32,0x02800000
   Uncompressing Kernel Image
## Flattened Device Tree blob at 90200000
   Booting using the fdt blob at 0x90200000
Working FDT set to 90200000
ERROR: reserving fdt memory region failed (addr=9cb00000 size=100000 flags=4)
ERROR: reserving fdt memory region failed (addr=9cc00000 size=e00000 flags=4)
ERROR: reserving fdt memory region failed (addr=9da00000 size=100000 flags=4)
ERROR: reserving fdt memory region failed (addr=9db00000 size=c00000 flags=4)
ERROR: reserving fdt memory region failed (addr=9e780000 size=80000 flags=4)
ERROR: reserving fdt memory region failed (addr=9e800000 size=1800000 flags=4)
   Loading Device Tree to 0000000098eae000, end 0000000098ee1fff ... OK
Working FDT set to 98eae000

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd034]
[    0.000000] Linux version 6.1.38-6.4.0-devel+git.725e74990ab5 (oe-user@oe-host) (aarch64-tdx-linux-gcc (GCC) 11.3.0, GNU ld (GNU Binutils) 2.38.20220708) #1 SMP PREEMPT Wed Aug  2 09:29:06 UTC 2023
[    0.000000] Machine model: Toradex Verdin AM62 on Verdin Development Board
[    0.000000] earlycon: ns16550a0 at MMIO32 0x0000000002800000 (options '')
[    0.000000] printk: bootconsole [ns16550a0] enabled
[    0.000000] efi: UEFI not found.
[    0.000000] Reserved memory: created DMA memory pool at 0x000000009cb00000, size 1 MiB
[    0.000000] OF: reserved mem: initialized node m4f-dma-memory@9cb00000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x000000009cc00000, size 14 MiB
[    0.000000] OF: reserved mem: initialized node m4f-memory@9cc00000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x000000009da00000, size 1 MiB
[    0.000000] OF: reserved mem: initialized node r5f-dma-memory@9da00000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x000000009db00000, size 12 MiB
[    0.000000] OF: reserved mem: initialized node r5f-memory@9db00000, compatible id shared-dma-pool
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000080000000-0x00000000bfffffff]
[    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 0x0000000080000000-0x000000009cafffff]
[    0.000000]   node   0: [mem 0x000000009cb00000-0x000000009e6fffff]
[    0.000000]   node   0: [mem 0x000000009e700000-0x000000009e77ffff]
[    0.000000]   node   0: [mem 0x000000009e780000-0x000000009fffffff]
[    0.000000]   node   0: [mem 0x00000000a0000000-0x00000000bfffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000080000000-0x00000000bfffffff]
[    0.000000] cma: Reserved 128 MiB at 0x00000000b6c00000
[    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: Trusted OS migration not required
[    0.000000] psci: SMC Calling Convention v1.2
[    0.000000] percpu: Embedded 19 pages/cpu s38376 r8192 d31256 u77824
[    0.000000] Detected VIPT I-cache on CPU0
[    0.000000] CPU features: detected: GIC system register CPU interface
[    0.000000] CPU features: detected: ARM erratum 845719
[    0.000000] alternatives: applying boot alternatives
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 258048
[    0.000000] Kernel command line: root=PARTUUID=88a818b9-02 ro rootwait console=tty1 console=ttyS2,115200 consoleblank=0 earlycon=ns16550a,mmio32,0x02800000
[    0.000000] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[    0.000000] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 824136K/1048576K available (11136K kernel code, 1386K rwdata, 3784K rodata, 2240K init, 489K bss, 93368K reserved, 131072K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu: 	RCU event tracing is enabled.
[    0.000000] rcu: 	RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=2.
[    0.000000] 	Trampoline variant of Tasks RCU enabled.
[    0.000000] 	Tracing variant of Tasks RCU enabled.
[    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=2
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] GICv3: GIC: Using split EOI/Deactivate mode
[    0.000000] GICv3: 256 SPIs implemented
[    0.000000] GICv3: 0 Extended SPIs implemented
[    0.000000] Root IRQ handler: gic_handle_irq
[    0.000000] GICv3: GICv3 features: 16 PPIs
[    0.000000] GICv3: CPU0: found redistributor 0 region 0:0x0000000001880000
[    0.000000] ITS [mem 0x01820000-0x0182ffff]
[    0.000000] GIC: enabling workaround for ITS: Socionext Synquacer pre-ITS
[    0.000000] ITS@0x0000000001820000: Devices Table too large, reduce ids 20->19
[    0.000000] ITS@0x0000000001820000: allocated 524288 Devices @80800000 (flat, esz 8, psz 64K, shr 0)
[    0.000000] ITS: using cache flushing for cmd queue
[    0.000000] GICv3: using LPI property table @0x0000000080030000
[    0.000000] GIC: using cache flushing for LPI property table
[    0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000080040000
[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[    0.000000] arch_timer: cp15 timer(s) running at 200.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0x3ffffffffffffff max_cycles: 0x2e2049d3e8, max_idle_ns: 440795210634 ns
[    0.000000] sched_clock: 58 bits at 200MHz, resolution 5ns, wraps every 4398046511102ns
[    0.008608] Console: colour dummy device 80x25
[    0.013681] printk: console [tty1] enabled
[    0.017922] Calibrating delay loop (skipped), value calculated using timer frequency.. 400.00 BogoMIPS (lpj=800000)
[    0.028618] pid_max: default: 32768 minimum: 301
[    0.033403] LSM: Security Framework initializing
[    0.038280] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)
[    0.045867] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)
[    0.055873] cblist_init_generic: Setting adjustable number of callback queues.
[    0.063365] cblist_init_generic: Setting shift to 1 and lim to 1.
[    0.069674] cblist_init_generic: Setting shift to 1 and lim to 1.
[    0.076110] rcu: Hierarchical SRCU implementation.
[    0.081027] rcu: 	Max phase no-delay instances is 1000.
[    0.087094] Platform MSI: msi-controller@1820000 domain created
[    0.093768] EFI services will not be available.
[    0.098746] smp: Bringing up secondary CPUs ...
[    0.104126] Detected VIPT I-cache on CPU1
[    0.104267] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[    0.104287] GICv3: CPU1: using allocated LPI pending table @0x0000000080050000
[    0.104353] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[    0.104487] smp: Brought up 1 node, 2 CPUs
[    0.133925] SMP: Total of 2 processors activated.
[    0.138746] CPU features: detected: 32-bit EL0 Support
[    0.144027] CPU features: detected: CRC32 instructions
[    0.149354] CPU: All CPU(s) started at EL2
[    0.153547] alternatives: applying system-wide alternatives
[    0.160939] devtmpfs: initialized
[    0.173889] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.183939] futex hash table entries: 512 (order: 3, 32768 bytes, linear)
[    0.196442] pinctrl core: initialized pinctrl subsystem
[    0.202662] DMI not present or invalid.
[    0.207341] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[    0.214636] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations
[    0.221988] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.230002] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.238207] audit: initializing netlink subsys (disabled)
[    0.244029] audit: type=2000 audit(0.156:1): state=initialized audit_enabled=0 res=1
[    0.244587] thermal_sys: Registered thermal governor 'step_wise'
[    0.251976] thermal_sys: Registered thermal governor 'power_allocator'
[    0.258327] cpuidle: using governor menu
[    0.269247] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.276262] ASID allocator initialised with 65536 entries
[    0.294105] platform 30200000.dss: Fixed dependency cycle(s) with /bus@f0000/i2c@20000000/dsi@e
[    0.306313] KASLR disabled due to lack of seed
[    0.317359] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages
[    0.324363] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page
[    0.330784] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages
[    0.337730] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page
[    0.344144] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages
[    0.351091] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page
[    0.357505] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages
[    0.364451] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page
[    0.372846] k3-chipinfo 43000014.chipid: Family:AM62X rev:SR1.0 JTAGID[0x0bb7e02f] Detected
[    0.382705] iommu: Default domain type: Translated 
[    0.387731] iommu: DMA domain TLB invalidation policy: strict mode 
[    0.394461] SCSI subsystem initialized
[    0.398719] usbcore: registered new interface driver usbfs
[    0.404381] usbcore: registered new interface driver hub
[    0.409851] usbcore: registered new device driver usb
[    0.415644] pps_core: LinuxPPS API ver. 1 registered
[    0.420733] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.430094] PTP clock support registered
[    0.434257] EDAC MC: Ver: 3.0.0
[    0.438552] omap-mailbox 29000000.mailbox: omap mailbox rev 0x66fc9100
[    0.445774] FPGA manager framework
[    0.449369] Advanced Linux Sound Architecture Driver Initialized.
[    0.456680] clocksource: Switched to clocksource arch_sys_counter
[    0.463247] VFS: Disk quotas dquot_6.6.0
[    0.467314] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.480493] NET: Registered PF_INET protocol family
[    0.485778] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
[    0.494531] tcp_listen_portaddr_hash hash table entries: 512 (order: 1, 8192 bytes, linear)
[    0.503183] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.511132] TCP established hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.519124] TCP bind hash table entries: 8192 (order: 6, 262144 bytes, linear)
[    0.526855] TCP: Hash tables configured (established 8192 bind 8192)
[    0.533567] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    0.540378] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    0.547805] NET: Registered PF_UNIX/PF_LOCAL protocol family
[    0.554203] RPC: Registered named UNIX socket transport module.
[    0.560309] RPC: Registered udp transport module.
[    0.565126] RPC: Registered tcp transport module.
[    0.569941] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.576541] NET: Registered PF_XDP protocol family
[    0.582326] hw perfevents: enabled with armv8_cortex_a53 PMU driver, 7 counters available
[    0.592578] Initialise system trusted keyrings
[    0.597449] workingset: timestamp_bits=46 max_order=18 bucket_order=0
[    0.609945] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.616787] NFS: Registering the id_resolver key type
[    0.622016] Key type id_resolver registered
[    0.626299] Key type id_legacy registered
[    0.630470] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.637335] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[    0.645160] 9p: Installing v9fs 9p2000 file system support
[    0.685246] Key type asymmetric registered
[    0.689446] Asymmetric key parser 'x509' registered
[    0.694496] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 245)
[    0.702277] io scheduler mq-deadline registered
[    0.706927] io scheduler kyber registered
[    0.714676] pinctrl-single 4084000.pinctrl: 34 pins, size 136
[    0.721538] pinctrl-single f4000.pinctrl: 171 pins, size 684
[    0.734667] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.751645] brd: module loaded
[    0.759755] loop: module loaded
[    0.768062] tun: Universal TUN/TAP device driver, 1.6
[    0.774167] VFIO - User Level meta-driver version: 0.3
[    0.779894] usbcore: registered new interface driver usb-storage
[    0.786950] i2c_dev: i2c /dev entries driver
[    0.794086] sdhci: Secure Digital Host Controller Interface driver
[    0.800479] sdhci: Copyright(c) Pierre Ossman
[    0.805472] Synopsys Designware Multimedia Card Interface Driver
[    0.812085] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.818811] ledtrig-cpu: registered to indicate activity on CPUs
[    0.825182] SMCCC: SOC_ID: ARCH_SOC_ID not implemented, skipping ....
[    0.832180] usbcore: registered new interface driver usbhid
[    0.837896] usbhid: USB HID core driver
[    0.843335] optee: probing for conduit method.
[    0.847969] optee: revision 3.20 (8e74d476)
[    0.848322] optee: dynamic shared memory is enabled
[    0.857901] optee: initialized driver
[    0.863859] Initializing XFRM netlink socket
[    0.868324] NET: Registered PF_PACKET protocol family
[    0.873665] 9pnet: Installing 9P2000 support
[    0.878124] Key type dns_resolver registered
[    0.882969] registered taskstats version 1
[    0.887216] Loading compiled-in X.509 certificates
[    0.901953] ti-sci 44043000.system-controller: ABI: 3.1 (firmware rev 0x0009 '9.0.5--v09.00.05 (Kool Koala)')
[    0.969311] omap_i2c 4900000.i2c: bus 3 rev0.12 at 100 kHz
[    0.976185] i2c 0-000e: Fixed dependency cycle(s) with /bus@f0000/i2c@20010000/hdmi@48
[    1.017165] input: tps65219-pwrbutton as /devices/platform/bus@f0000/20000000.i2c/i2c-0/0-0030/tps65219-pwrbutton.2.auto/input/input0
[    1.031132] rtc-ds1307 0-0032: oscillator failed, set time!
[    1.037044] rtc-ds1307 0-0032: registered as rtc0
[    1.042009] rtc-ds1307 0-0032: hctosys: unable to read the hardware clock
[    1.051098] at24 0-0050: supply vcc not found, using dummy regulator
[    1.058092] at24 0-0050: 256 byte 24c02 EEPROM, writable, 16 bytes/write
[    1.065027] omap_i2c 20000000.i2c: bus 0 rev0.12 at 400 kHz
[    1.072562] platform hdmi-connector: Fixed dependency cycle(s) with /bus@f0000/i2c@20010000/hdmi@48
[    1.082669] pca953x 1-0021: supply vcc not found, using dummy regulator
[    1.089586] pca953x 1-0021: using no AI
[    1.116822] pca953x 1-0021: failed writing register
[    1.122028] pca953x: probe of 1-0021 failed with error -121
[    1.128329] at24 1-0057: supply vcc not found, using dummy regulator
[    1.135574] at24 1-0057: 256 byte 24c02 EEPROM, writable, 16 bytes/write
[    1.142517] omap_i2c 20010000.i2c: bus 1 rev0.12 at 100 kHz
[    1.149708] omap_i2c 20020000.i2c: bus 2 rev0.12 at 100 kHz
[    1.156416] omap_i2c 20030000.i2c: bus 4 rev0.12 at 100 kHz
[    1.162433] ti-sci-intr 4210000.interrupt-controller: Interrupt Router 5 domain created
[    1.170816] ti-sci-intr bus@f0000:interrupt-controller@a00000: Interrupt Router 3 domain created
[    1.180108] ti-sci-inta 48000000.interrupt-controller: Interrupt Aggregator domain 28 created
[    1.190405] ti-udma 485c0100.dma-controller: Number of rings: 82
[    1.198686] ti-udma 485c0100.dma-controller: Channels: 48 (bchan: 18, tchan: 12, rchan: 18)
[    1.209903] ti-udma 485c0000.dma-controller: Number of rings: 150
[    1.220105] ti-udma 485c0000.dma-controller: Channels: 35 (tchan: 20, rchan: 15)
[    1.230672] 4a00000.serial: ttyS3 at MMIO 0x4a00000 (irq = 291, base_baud = 3000000) is a 8250
[    1.240902] 2800000.serial: ttyS2 at MMIO 0x2800000 (irq = 292, base_baud = 3000000) is a 8250
[    1.249839] printk: console [ttyS2] enabled
[    1.249839] printk: console [ttyS2] enabled
[    1.258304] printk: bootconsole [ns16550a0] disabled
[    1.258304] printk: bootconsole [ns16550a0] disabled
[    1.269571] 2810000.serial: ttyS0 at MMIO 0x2810000 (irq = 293, base_baud = 3000000) is a 8250
[    1.281743] davinci_mdio 8000f00.mdio: Configuring MDIO in manual mode
[    1.328686] davinci_mdio 8000f00.mdio: davinci mdio revision 9.7, bus freq 1000000
[    1.337590] am65-cpsw-nuss 8000000.ethernet: initializing am65 cpsw nuss version 0x6BA01103, cpsw version 0x6BA81103 Ports: 3 quirks:00000006
[    1.350533] am65-cpsw-nuss 8000000.ethernet: initialized cpsw ale version 1.5
[    1.357679] am65-cpsw-nuss 8000000.ethernet: ALE Table size 512
[    1.364442] am65-cpsw-nuss 8000000.ethernet: CPTS ver 0x4e8a010c, freq:500000000, add_val:1 pps:0
[    1.374888] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[    1.490652] mmc0: CQHCI version 5.10
[    1.492963] gpio-427 (CTRL_SLEEP_MOCI#): hogged as output/high
[    1.507446] davinci_mdio 8000f00.mdio: Configuring MDIO in manual mode
[    1.535397] mmc0: SDHCI controller on fa10000.mmc [fa10000.mmc] using ADMA 64-bit
[    1.552696] davinci_mdio 8000f00.mdio: davinci mdio revision 9.7, bus freq 1000000
[    1.565230] mdio_bus 8000f00.mdio: MDIO device at address 7 is missing.
[    1.571946] davinci_mdio 8000f00.mdio: phy[0]: device 8000f00.mdio:00, driver TI DP83867
[    1.582556] debugfs: Directory 'pd:182' with parent 'pm_genpd' already present!
[    1.582556] mmc1: CQHCI version 5.10
[    1.585515] input: gpio-keys as /devices/platform/gpio-keys/input/input1
[    1.608151] mmc0: new HS200 MMC card at address 0001
[    1.612969] ALSA device list:
[    1.614185] mmcblk0: mmc0:0001 Q2J55L 7.09 GiB 
[    1.616112]   No soundcards found.
[    1.625826]  mmcblk0: p1 p2
[    1.629554] mmcblk0boot0: mmc0:0001 Q2J55L 16.0 MiB 
[    1.636055] mmcblk0boot1: mmc0:0001 Q2J55L 16.0 MiB 
[    1.642255] mmcblk0rpmb: mmc0:0001 Q2J55L 4.00 MiB, chardev (241:0)
[    3.125874] sdhci-am654 fa00000.mmc: Power on failed
[    3.162110] mmc1: SDHCI controller on fa00000.mmc [fa00000.mmc] using ADMA 64-bit
[    3.181304] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Quota mode: none.
[    3.189974] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    3.200395] devtmpfs: mounted
[    3.205224] Freeing unused kernel memory: 2240K
[    3.209968] Run /sbin/init as init process
[    3.351231] systemd[1]: System time before build time, advancing clock.
[    3.398055] NET: Registered PF_INET6 protocol family
[    3.404985] Segment Routing with IPv6
[    3.408740] In-situ OAM (IOAM) with IPv6
[    3.439523] systemd[1]: systemd 250.5+ 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 -BZIP2 -LZ4 -XZ -ZLIB +ZSTD -BPF_FRAMEWORK +XKBCOMMON +UTMP +SYSVINIT default-hierarchy=hybrid)
[    3.471929] systemd[1]: Detected architecture arm64.

Welcome to TDX Wayland with XWayland 6.4.0-devel-20230823+build.367 (kirkstone)!

[    3.553901] systemd[1]: Hostname set to <verdin-am62-15133546>.
[    4.028181] systemd[1]: Queued start job for default target Graphical Interface.
[    4.082445] systemd[1]: Created slice Slice /system/getty.
[  OK  ] Created slice Slice /system/getty.
[    4.107282] systemd[1]: Created slice Slice /system/modprobe.
[  OK  ] Created slice Slice /system/modprobe.
[    4.131538] systemd[1]: Created slice Slice /system/serial-getty.
[  OK  ] Created slice Slice /system/serial-getty.
[    4.155194] systemd[1]: Created slice User and Session Slice.
[  OK  ] Created slice User and Session Slice.
[    4.177535] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[  OK  ] Started Dispatch Password …ts to Console Directory Watch.
[    4.201322] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[  OK  ] Started Forward Password R…uests to Wall Directory Watch.
[    4.225549] systemd[1]: Reached target Host and Network Name Lookups.
[  OK  ] Reached target Host and Network Name Lookups.
[    4.248908] systemd[1]: Reached target Path Units.
[  OK  ] Reached target Path Units.
[    4.269100] systemd[1]: Reached target Remote File Systems.
[  OK  ] Reached target Remote File Systems.
[    4.288996] systemd[1]: Reached target Slice Units.
[  OK  ] Reached target Slice Units.
[    4.309146] systemd[1]: Reached target Swaps.
[  OK  ] Reached target Swaps.
[    4.387175] systemd[1]: Listening on RPCbind Server Activation Socket.
[  OK  ] Listening on RPCbind Server Activation Socket.
[    4.409438] systemd[1]: Reached target RPC Port Mapper.
[  OK  ] Reached target RPC Port Mapper.
[    4.434647] systemd[1]: Listening on Syslog Socket.
[  OK  ] Listening on Syslog Socket.
[    4.459132] systemd[1]: Listening on initctl Compatibility Named Pipe.
[  OK  ] Listening on initctl Compatibility Named Pipe.
[    4.484860] systemd[1]: Listening on Journal Audit Socket.
[  OK  ] Listening on Journal Audit Socket.
[    4.511338] systemd[1]: Listening on Journal Socket (/dev/log).
[  OK  ] Listening on Journal Socket (/dev/log).
[    4.535692] systemd[1]: Listening on Journal Socket.
[  OK  ] Listening on Journal Socket.
[    4.556849] systemd[1]: Listening on Network Service Netlink Socket.
[  OK  ] Listening on Network Service Netlink Socket.
[    4.584009] systemd[1]: Listening on udev Control Socket.
[  OK  ] Listening on udev Control Socket.
[    4.607107] systemd[1]: Listening on udev Kernel Socket.
[  OK  ] Listening on udev Kernel Socket.
[    4.631390] systemd[1]: Listening on User Database Manager Socket.
[  OK  ] Listening on User Database Manager Socket.
[    4.685451] systemd[1]: Mounting Huge Pages File System...
         Mounting Huge Pages File System...
[    4.707805] systemd[1]: Mounting POSIX Message Queue File System...
         Mounting POSIX Message Queue File System...
[    4.739428] systemd[1]: Mounting Kernel Debug File System...
         Mounting Kernel Debug File System...
[    4.762244] systemd[1]: Kernel Trace File System was skipped because of a failed condition check (ConditionPathExists=/sys/kernel/tracing).
[    4.801477] systemd[1]: Mounting Temporary Directory /tmp...
         Mounting Temporary Directory /tmp...
[    4.857953] systemd[1]: Starting Create List of Static Device Nodes...
         Starting Create List of Static Device Nodes...
[    4.896046] systemd[1]: Starting Load Kernel Module configfs...
         Starting Load Kernel Module configfs...
[    4.945940] systemd[1]: Starting Load Kernel Module drm...
         Starting Load Kernel Module drm...
[    4.980974] systemd[1]: Starting Load Kernel Module fuse...
         Starting Load Kernel Module fuse...
[    4.995519] fuse: init (API version 7.37)
[    5.026071] systemd[1]: Starting RPC Bind...
         Starting RPC Bind...
[    5.053675] systemd[1]: Starting File System Check on Root Device...
         Starting File System Check on Root Device...
[    5.103831] systemd[1]: Starting Journal Service...
         Starting Journal Service...
[    5.124179] systemd[1]: Starting Load Kernel Modules...
         Starting Load Kernel Modules...
[    5.156543] systemd[1]: Starting Generate network units from Kernel command line...
         Starting Generate network …ts from Kernel command line...
[    5.178361] systemd[1]: Starting Coldplug All udev Devices...
         Starting Coldplug All udev Devices...
[    5.202413] systemd[1]: Started RPC Bind.
[  OK  ] Started RPC Bind.
[    5.225026] systemd[1]: Mounted Huge Pages File System.
[  OK  ] Mounted Huge Pages File System.
[    5.246087] systemd[1]: Mounted POSIX Message Queue File System.
[  OK  ] Mounted POSIX Message Queue File System.
[    5.273862] systemd[1]: Mounted Kernel Debug File System.
[  OK  ] Mounted Kernel Debug File System.
[    5.297912] systemd[1]: Started Journal Service.
[  OK  ] Started Journal Service.
[  OK  ] Mounted Temporary Directory /tmp.
[  OK  ] Finished Create List of Static Device Nodes.
[  OK  ] Finished Load Kernel Module configfs.
[  OK  ] Finished Load Kernel Module drm.
[  OK  ] Finished Load Kernel Module fuse.
[  OK  ] Finished File System Check on Root Device.
[  OK  ] Finished Load Kernel Modules.
[  OK  ] Finished Generate network units from Kernel command line.
         Mounting FUSE Control File System...
         Mounting Kernel Configuration File System...
         Starting Remount Root and Kernel File Systems...
         Starting Apply Kernel Variables...
[  OK  ] Mounted FUSE Control File System.
[    5.647962] EXT4-fs (mmcblk0p2): re-mounted. Quota mode: none.
[  OK  ] Mounted Kernel Configuration File System.
[  OK  ] Finished Remount Root and Kernel File Systems.
[  OK  ] Finished Apply Kernel Variables.
         Starting Flush Journal to Persistent Storage...
[    5.751978] systemd-journald[153]: Received client request to flush runtime journal.
         Starting Create Static Device Nodes in /dev...
[  OK  ] Finished Flush Journal to Persistent Storage.
[  OK  ] Finished Create Static Device Nodes in /dev.
[  OK  ] Reached target Preparation for Local File Systems.
         Mounting /var/volatile...
[    5.898098] audit: type=1334 audit(1651167747.544:2): prog-id=5 op=LOAD
         Starting Rule-based Manage…for Device Events[    5.910020] audit: type=1334 audit(1651167747.552:3): prog-id=6 op=LOAD
 and Files...
[  OK  ] Finished Coldplug All udev Devices.
[  OK  ] Mounted /var/volatile.
         Starting Wait for udev To …plete Device Initialization...
         Starting Load/Save Random Seed...
[  OK  ] Reached target Local File Systems.
         Starting Create Volatile Files and Directories...
[  OK  ] Started Rule-based Manager for Device Events and Files.
[  OK  ] Finished Create Volatile Files and Directories.
         Starting Network Time Synchronization...
         Starting Record System Boot/Shutdown in UTMP...
[  OK  ] Finished Record System Boot/Shutdown in UTMP.
[  OK  ] Started Network Time Synchronizatio[    6.678828] systemd-journald[153]: Oldest entry in /run/log/journal/bed90d19bbc34c8baf3e2dc044b233ff/system.journal is older than the configured file retention duration (1month), suggesting rotation.
n.
[    6.703374] systemd-journald[153]: /run/log/journal/bed90d19bbc34c8baf3e2dc044b233ff/system.journal: Journal header limits reached or header out-of-date, rotating.
[  OK  ] Reached target System Time Set.
[    7.016937] lm75 0-0048: supply vs not found, using dummy regulator
[    7.028730] random: crng init done
[    7.044226] hwmon hwmon0: temp1_input not attached to any thermal zone
[  OK  ] Finished Load/Save Random Seed.
[    7.058077] lm75 0-0048: hwmon0: sensor 'tmp1075'
[    7.073186] lm75 1-004f: supply vs not found, using dummy regulator
[    7.097081] nau8822 1-001a: Failed to issue reset: -121
[    7.109656] nau8822: probe of 1-001a failed with error -121
[    7.127410] ina2xx 1-0040: error configuring the device: -121
[    7.151739] CAN device driver interface
[    7.164196] hwmon hwmon1: temp1_input not attached to any thermal zone
[    7.187446] lm75 1-004f: hwmon1: sensor 'tmp75c'
[    7.209041] m_can_platform 4e08000.can: m_can device registered (irq=0, version=32)
[    7.233030] m_can_platform 20701000.can: m_can device registered (irq=482, version=32)
[    7.404616] k3-m4-rproc 5000000.m4fss: assigned reserved memory node m4f-dma-memory@9cb00000
[    7.438421] k3-m4-rproc 5000000.m4fss: configured M4 for remoteproc mode
[    7.494007] k3-m4-rproc 5000000.m4fss: local reset is deasserted for device
[    7.519109] remoteproc remoteproc0: 5000000.m4fss is available
[    7.537684] remoteproc remoteproc0: Direct firmware load for am62-mcu-m4f0_0-fw failed with error -2
[    7.547635] remoteproc remoteproc0: powering up 5000000.m4fss
[    7.555691] remoteproc remoteproc0: Direct firmware load for am62-mcu-m4f0_0-fw failed with error -2
[    7.570389] remoteproc remoteproc0: request_firmware failed: -2
[    7.600620] rtc-ti-k3 2b1f0000.rtc: registered as rtc1
[    7.652815] platform 78000000.r5f: R5F core may have been powered on by a different host, programmed state (0) != actual state (1)
[    7.703632] platform 78000000.r5f: configured R5F for IPC-only mode
[    7.729638] platform 78000000.r5f: assigned reserved memory node r5f-dma-memory@9da00000
[    7.740648] remoteproc remoteproc1: 78000000.r5f is available
[    7.752610] [drm] Initialized tidss 1.0.0 20180215 for 30200000.dss on minor 0
[    7.770756] tidss 30200000.dss: [drm] Cannot find any crtc or sizes
[    7.773871] pvrsrvkm: loading out-of-tree module taints kernel.
[    7.799051] remoteproc remoteproc1: attaching to 78000000.r5f
[    7.833321] platform 78000000.r5f: R5F core initialized in IPC-only mode
[    7.840610] rproc-virtio rproc-virtio.4.auto: assigned reserved memory node r5f-dma-memory@9da00000
[    7.863320] virtio_rpmsg_bus virtio0: rpmsg host is online
[    7.869014] virtio_rpmsg_bus virtio0: creating channel ti.ipc4.ping-pong addr 0xd
[    7.878739] PVR_K:  178: Device: fd00000.gpu
[    7.883616] virtio_rpmsg_bus virtio0: creating channel rpmsg_chrdev addr 0xe
[    7.893826] PVR_K:  178: Read BVNC 33.15.11.3 from HW device registers
[    7.906595] rproc-virtio rproc-virtio.4.auto: registered virtio0 (type 7)
[    7.916371] PVR_K:  178: RGX Device registered with BVNC 33.15.11.3
[    7.925628] remoteproc remoteproc1: remote processor 78000000.r5f is now attached
[    7.939762] [drm] Initialized pvr 23.1.6404501 20170530 for fd00000.gpu on minor 1
[*     ] A start job is running for Wait for…vice Initialization (5s / 3min 1s)
M
[**    ] A start job is running for Wait for…vice Initialization (5s / 3min 1s)

23-08-26_04-34-08-Fail.txt
Climate Chamber:       VT 7021
Start Temperature:     -40.1�C
End Temperature:       -40.0�C
Measured Temperature:  -40.1�C
Shelf Temperature:     -38.9�C
Shelf Name:            Shelf_19
Module Serial Number:  15133546
Module Location:       Shelf 2, Carrier Board 2
Test duration:         399.85s

Test Log
********
04:34:07.80 15->16 Waited 300.00s
04:29:07.63 14->15 Set Reset Low
04:29:07.51 13->14 Power Off
04:29:07.41 7->13 Not found, time out: "login:"
04:27:37.22 6->7 Message found: "Starting kernel"
04:27:33.23 5->6 Message found: "U-Boot"
04:27:30.81 4->5 Reset is High
04:27:30.70 3->4 Cycle time 2.530s is less than 20.00s
04:27:30.59 2->3 Waited 1.00s
04:27:29.57 4->2 Reset is Low
04:27:29.57 3->4 Cycle time 1.402s is less than 20.00s
04:27:29.51 2->3 Waited 1.00s
04:27:28.39 1->2 Set Reset High
04:27:28.28 0->1 Power On

Search Strings
**************
PASS : U-Boot
PASS : Starting kernel
0001 Q2J55L 7.09 GiB  : mmcblk0: mmc0:
PASS : mmcblk0: p1 p2
OK : cut here
PASS : hwclock
PASS : I/O error
PASS : Internal error
FAIL : Starting CPU stress
FAIL : successful run
PASS : unsuccessful run
FAIL : connected with
N/A : eth0: Link is Up - 
N/A : connect failed: 
PASS : IPERF stuck
N/A : 0.0-10
PASS : memtester failed
FAIL : memtester version
PASS : FAILURE
FAIL : Done.
PASS : bonnie\+\+ failed
0 : OAK ERROR
0 : UART ERROR
OK : rtc-ds1307 0-0032: registered as rtc0
OK : rtc-ti-k3 2b1f0000.rtc: registered as rtc1
OK : xception stack
N/A : Device life time estimation type A
N/A : Device life time estimation type B 
N/A : Pre EOL information
0 : USB hub found
0 : xception stack
Disabled : 0000.sai mapping ok
Disabled : sgtl5000 revision 0x11
4 : U-Boot
0 : page allocation failure
Not OK : WLAN FW is active
0 : Disabled wifi
0 : Disabled bluetooth
Not OK : Scan completed for wifi
Disabled : Discovery started
PASS : suspend md5sum failed
Disabled : suspend succeeded
Disabled : /tmp/memfile:
FAIL : Waiting for power-cycle
0 : Bus 00
0 : :00.0 
0 : bus I2C
0 : the audio card
FAIL : CPU stress passed
FAIL : reboot: Power down
PASS : 0 packets received
N/A : Speed:
N/A : number of warnings in the dmesg boot:
N/A : number of errors in the dmesg boot:
0 : USB hub found
0 : unexpected event for opcode
PASS : Firmware wakeup failed
PASS : thermal_zone1: critical temperature reached
FAIL : rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:

Terminal
********

U-Boot SPL 2023.04-6.4.0-devel+git.6eec39f33231 (Aug 03 2023 - 18:01:08 +0000)
SYSFW ABI: 3.1 (firmware rev 0x0009 '9.0.5--v09.00.05 (Kool Koala)')
SPL initial stack usage: 13376 bytes
Trying to boot from MMC1
Authentication passed
Authentication passed
Authentication passed
Authentication passed
Authentication passed
Starting ATF on ARM64 core...

NOTICE:  BL31: v2.8(release):v2.8-226-g2fcd408bb3-dirty
NOTICE:  BL31: Built : 00:42:57, Jan 13 2023

U-Boot SPL 2023.04-6.4.0-devel+git.6eec39f33231 (Aug 03 2023 - 18:01:08 +0000)
SYSFW ABI: 3.1 (firmware rev 0x0009 '9.0.5--v09.00.05 (Kool Koala)')
SPL initial stack usage: 1856 bytes
Trying to boot from MMC1
Authentication passed
Authentication passed


U-Boot 2023.04-6.4.0-devel+git.6eec39f33231 (Aug 03 2023 - 18:01:08 +0000)

SoC:   AM62X SR1.0 HS-FS
DRAM:  1 GiB
Core:  142 devices, 30 uclasses, devicetree: separate
MMC:   mmc@fa10000: 0, mmc@fa00000: 1
Loading Environment from MMC... OK
In:    serial@2800000
Out:   serial@2800000
Err:   serial@2800000
Model: Toradex 0074 Verdin AM62 Dual 1GB IT V1.1A
Serial#: 15133546
MISSING TORADEX CARRIER CONFIG BLOCKS
am65_cpsw_nuss ethernet@8000000: K3 CPSW: nuss_ver: 0x6BA01103 cpsw_ver: 0x6BA81103 ale_ver: 0x00290105 Ports:2 mdio_freq:1000000
Setting variant to nonwifi
Net:   
Warning: ethernet@8000000port@1 MAC addresses don't match:
Address in ROM is		28:b5:e8:cb:53:a5
Address in environment is	00:14:2d:e6:eb:6a
eth0: ethernet@8000000port@1 [PRIME]Could not get PHY for ethernet@8000000port@1: addr 7
am65_cpsw_nuss_port ethernet@8000000port@2: phy_connect() failed

Hit any key to stop autoboot:  1  0 
MMC: no card present
switch to partitions #0, OK
mmc0(part 0) is current device
Scanning mmc 0:1...
Found U-Boot script /boot.scr
6003 bytes read in 10 ms (585.9 KiB/s)
## Executing script at 90280000
Loading DeviceTree: k3-am625-verdin-nonwifi-dev.dtb
67698 bytes read in 11 ms (5.9 MiB/s)
82 bytes read in 9 ms (8.8 KiB/s)
Working FDT set to 90200000
Applying Overlay: verdin-am62_dsi-to-hdmi_overlay.dtbo
3213 bytes read in 10 ms (313.5 KiB/s)
Applying Overlay: verdin-am62_spidev_overlay.dtbo
560 bytes read in 10 ms (54.7 KiB/s)
7769854 bytes read in 62 ms (119.5 MiB/s)
Bootargs: root=PARTUUID=88a818b9-02 ro rootwait console=tty1 console=ttyS2,115200 consoleblank=0 earlycon=ns16550a,mmio32,0x02800000
   Uncompressing Kernel Image
## Flattened Device Tree blob at 90200000
   Booting using the fdt blob at 0x90200000
Working FDT set to 90200000
ERROR: reserving fdt memory region failed (addr=9cb00000 size=100000 flags=4)
ERROR: reserving fdt memory region failed (addr=9cc00000 size=e00000 flags=4)
ERROR: reserving fdt memory region failed (addr=9da00000 size=100000 flags=4)
ERROR: reserving fdt memory region failed (addr=9db00000 size=c00000 flags=4)
ERROR: reserving fdt memory region failed (addr=9e780000 size=80000 flags=4)
ERROR: reserving fdt memory region failed (addr=9e800000 size=1800000 flags=4)
   Loading Device Tree to 0000000098eae000, end 0000000098ee1fff ... OK
Working FDT set to 98eae000

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd034]
[    0.000000] Linux version 6.1.38-6.4.0-devel+git.725e74990ab5 (oe-user@oe-host) (aarch64-tdx-linux-gcc (GCC) 11.3.0, GNU ld (GNU Binutils) 2.38.20220708) #1 SMP PREEMPT Wed Aug  2 09:29:06 UTC 2023
[    0.000000] Machine model: Toradex Verdin AM62 on Verdin Development Board
[    0.000000] earlycon: ns16550a0 at MMIO32 0x0000000002800000 (options '')
[    0.000000] printk: bootconsole [ns16550a0] enabled
[    0.000000] efi: UEFI not found.
[    0.000000] Reserved memory: created DMA memory pool at 0x000000009cb00000, size 1 MiB
[    0.000000] OF: reserved mem: initialized node m4f-dma-memory@9cb00000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x000000009cc00000, size 14 MiB
[    0.000000] OF: reserved mem: initialized node m4f-memory@9cc00000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x000000009da00000, size 1 MiB
[    0.000000] OF: reserved mem: initialized node r5f-dma-memory@9da00000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x000000009db00000, size 12 MiB
[    0.000000] OF: reserved mem: initialized node r5f-memory@9db00000, compatible id shared-dma-pool
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000080000000-0x00000000bfffffff]
[    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 0x0000000080000000-0x000000009cafffff]
[    0.000000]   node   0: [mem 0x000000009cb00000-0x000000009e6fffff]
[    0.000000]   node   0: [mem 0x000000009e700000-0x000000009e77ffff]
[    0.000000]   node   0: [mem 0x000000009e780000-0x000000009fffffff]
[    0.000000]   node   0: [mem 0x00000000a0000000-0x00000000bfffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000080000000-0x00000000bfffffff]
[    0.000000] cma: Reserved 128 MiB at 0x00000000b6c00000
[    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: Trusted OS migration not required
[    0.000000] psci: SMC Calling Convention v1.2
[    0.000000] percpu: Embedded 19 pages/cpu s38376 r8192 d31256 u77824
[    0.000000] Detected VIPT I-cache on CPU0
[    0.000000] CPU features: detected: GIC system register CPU interface
[    0.000000] CPU features: detected: ARM erratum 845719
[    0.000000] alternatives: applying boot alternatives
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 258048
[    0.000000] Kernel command line: root=PARTUUID=88a818b9-02 ro rootwait console=tty1 console=ttyS2,115200 consoleblank=0 earlycon=ns16550a,mmio32,0x02800000
[    0.000000] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[    0.000000] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 824136K/1048576K available (11136K kernel code, 1386K rwdata, 3784K rodata, 2240K init, 489K bss, 93368K reserved, 131072K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu: 	RCU event tracing is enabled.
[    0.000000] rcu: 	RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=2.
[    0.000000] 	Trampoline variant of Tasks RCU enabled.
[    0.000000] 	Tracing variant of Tasks RCU enabled.
[    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=2
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] GICv3: GIC: Using split EOI/Deactivate mode
[    0.000000] GICv3: 256 SPIs implemented
[    0.000000] GICv3: 0 Extended SPIs implemented
[    0.000000] Root IRQ handler: gic_handle_irq
[    0.000000] GICv3: GICv3 features: 16 PPIs
[    0.000000] GICv3: CPU0: found redistributor 0 region 0:0x0000000001880000
[    0.000000] ITS [mem 0x01820000-0x0182ffff]
[    0.000000] GIC: enabling workaround for ITS: Socionext Synquacer pre-ITS
[    0.000000] ITS@0x0000000001820000: Devices Table too large, reduce ids 20->19
[    0.000000] ITS@0x0000000001820000: allocated 524288 Devices @80800000 (flat, esz 8, psz 64K, shr 0)
[    0.000000] ITS: using cache flushing for cmd queue
[    0.000000] GICv3: using LPI property table @0x0000000080030000
[    0.000000] GIC: using cache flushing for LPI property table
[    0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000080040000
[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[    0.000000] arch_timer: cp15 timer(s) running at 200.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0x3ffffffffffffff max_cycles: 0x2e2049d3e8, max_idle_ns: 440795210634 ns
[    0.000000] sched_clock: 58 bits at 200MHz, resolution 5ns, wraps every 4398046511102ns
[    0.008607] Console: colour dummy device 80x25
[    0.013684] printk: console [tty1] enabled
[    0.017926] Calibrating delay loop (skipped), value calculated using timer frequency.. 400.00 BogoMIPS (lpj=800000)
[    0.028621] pid_max: default: 32768 minimum: 301
[    0.033405] LSM: Security Framework initializing
[    0.038281] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)
[    0.045868] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)
[    0.055867] cblist_init_generic: Setting adjustable number of callback queues.
[    0.063359] cblist_init_generic: Setting shift to 1 and lim to 1.
[    0.069674] cblist_init_generic: Setting shift to 1 and lim to 1.
[    0.076109] rcu: Hierarchical SRCU implementation.
[    0.081026] rcu: 	Max phase no-delay instances is 1000.
[    0.087109] Platform MSI: msi-controller@1820000 domain created
[    0.093792] EFI services will not be available.
[    0.098770] smp: Bringing up secondary CPUs ...
[    0.104143] Detected VIPT I-cache on CPU1
[    0.104281] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[    0.104301] GICv3: CPU1: using allocated LPI pending table @0x0000000080050000
[    0.104370] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[    0.104503] smp: Brought up 1 node, 2 CPUs
[    0.133943] SMP: Total of 2 processors activated.
[    0.138764] CPU features: detected: 32-bit EL0 Support
[    0.144045] CPU features: detected: CRC32 instructions
[    0.149373] CPU: All CPU(s) started at EL2
[    0.153565] alternatives: applying system-wide alternatives
[    0.160931] devtmpfs: initialized
[    0.173871] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.183920] futex hash table entries: 512 (order: 3, 32768 bytes, linear)
[    0.196490] pinctrl core: initialized pinctrl subsystem
[    0.202695] DMI not present or invalid.
[    0.207372] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[    0.214664] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations
[    0.222018] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.230030] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.238234] audit: initializing netlink subsys (disabled)
[    0.244061] audit: type=2000 audit(0.156:1): state=initialized audit_enabled=0 res=1
[    0.244621] thermal_sys: Registered thermal governor 'step_wise'
[    0.252008] thermal_sys: Registered thermal governor 'power_allocator'
[    0.258359] cpuidle: using governor menu
[    0.269275] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.276297] ASID allocator initialised with 65536 entries
[    0.294168] platform 30200000.dss: Fixed dependency cycle(s) with /bus@f0000/i2c@20000000/dsi@e
[    0.306411] KASLR disabled due to lack of seed
[    0.317421] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages
[    0.324421] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page
[    0.330838] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages
[    0.337785] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page
[    0.344200] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages
[    0.351146] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page
[    0.357560] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages
[    0.364506] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page
[    0.372913] k3-chipinfo 43000014.chipid: Family:AM62X rev:SR1.0 JTAGID[0x0bb7e02f] Detected
[    0.382785] iommu: Default domain type: Translated 
[    0.387811] iommu: DMA domain TLB invalidation policy: strict mode 
[    0.394543] SCSI subsystem initialized
[    0.398801] usbcore: registered new interface driver usbfs
[    0.404470] usbcore: registered new interface driver hub
[    0.409939] usbcore: registered new device driver usb
[    0.415725] pps_core: LinuxPPS API ver. 1 registered
[    0.420814] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.430173] PTP clock support registered
[    0.434336] EDAC MC: Ver: 3.0.0
[    0.438621] omap-mailbox 29000000.mailbox: omap mailbox rev 0x66fc9100
[    0.445835] FPGA manager framework
[    0.449428] Advanced Linux Sound Architecture Driver Initialized.
[    0.456726] clocksource: Switched to clocksource arch_sys_counter
[    0.463279] VFS: Disk quotas dquot_6.6.0
[    0.467348] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.480494] NET: Registered PF_INET protocol family
[    0.485774] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
[    0.494523] tcp_listen_portaddr_hash hash table entries: 512 (order: 1, 8192 bytes, linear)
[    0.503182] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.511132] TCP established hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.519124] TCP bind hash table entries: 8192 (order: 6, 262144 bytes, linear)
[    0.526836] TCP: Hash tables configured (established 8192 bind 8192)
[    0.533552] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    0.540364] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    0.547794] NET: Registered PF_UNIX/PF_LOCAL protocol family
[    0.554179] RPC: Registered named UNIX socket transport module.
[    0.560283] RPC: Registered udp transport module.
[    0.565100] RPC: Registered tcp transport module.
[    0.569914] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.576514] NET: Registered PF_XDP protocol family
[    0.582314] hw perfevents: enabled with armv8_cortex_a53 PMU driver, 7 counters available
[    0.592546] Initialise system trusted keyrings
[    0.597432] workingset: timestamp_bits=46 max_order=18 bucket_order=0
[    0.609930] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.616770] NFS: Registering the id_resolver key type
[    0.621996] Key type id_resolver registered
[    0.626280] Key type id_legacy registered
[    0.630450] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.637315] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[    0.645134] 9p: Installing v9fs 9p2000 file system support
[    0.684535] Key type asymmetric registered
[    0.688736] Asymmetric key parser 'x509' registered
[    0.693788] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 245)
[    0.701567] io scheduler mq-deadline registered
[    0.706218] io scheduler kyber registered
[    0.713976] pinctrl-single 4084000.pinctrl: 34 pins, size 136
[    0.721023] pinctrl-single f4000.pinctrl: 171 pins, size 684
[    0.734140] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.751044] brd: module loaded
[    0.759162] loop: module loaded
[    0.767449] tun: Universal TUN/TAP device driver, 1.6
[    0.773603] VFIO - User Level meta-driver version: 0.3
[    0.779334] usbcore: registered new interface driver usb-storage
[    0.786396] i2c_dev: i2c /dev entries driver
[    0.793557] sdhci: Secure Digital Host Controller Interface driver
[    0.799933] sdhci: Copyright(c) Pierre Ossman
[    0.804953] Synopsys Designware Multimedia Card Interface Driver
[    0.811565] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.818284] ledtrig-cpu: registered to indicate activity on CPUs
[    0.824646] SMCCC: SOC_ID: ARCH_SOC_ID not implemented, skipping ....
[    0.831642] usbcore: registered new interface driver usbhid
[    0.837354] usbhid: USB HID core driver
[    0.842772] optee: probing for conduit method.
[    0.847402] optee: revision 3.20 (8e74d476)
[    0.847764] optee: dynamic shared memory is enabled
[    0.857342] optee: initialized driver
[    0.863272] Initializing XFRM netlink socket
[    0.867747] NET: Registered PF_PACKET protocol family
[    0.873090] 9pnet: Installing 9P2000 support
[    0.877553] Key type dns_resolver registered
[    0.882389] registered taskstats version 1
[    0.886633] Loading compiled-in X.509 certificates
[    0.901273] ti-sci 44043000.system-controller: ABI: 3.1 (firmware rev 0x0009 '9.0.5--v09.00.05 (Kool Koala)')
[    0.968615] omap_i2c 4900000.i2c: bus 3 rev0.12 at 100 kHz
[    0.975564] i2c 0-000e: Fixed dependency cycle(s) with /bus@f0000/i2c@20010000/hdmi@48
[    1.017218] input: tps65219-pwrbutton as /devices/platform/bus@f0000/20000000.i2c/i2c-0/0-0030/tps65219-pwrbutton.2.auto/input/input0
[    1.031175] rtc-ds1307 0-0032: oscillator failed, set time!
[    1.037086] rtc-ds1307 0-0032: registered as rtc0
[    1.042054] rtc-ds1307 0-0032: hctosys: unable to read the hardware clock
[    1.051153] at24 0-0050: supply vcc not found, using dummy regulator
[    1.058148] at24 0-0050: 256 byte 24c02 EEPROM, writable, 16 bytes/write
[    1.065083] omap_i2c 20000000.i2c: bus 0 rev0.12 at 400 kHz
[    1.072592] platform hdmi-connector: Fixed dependency cycle(s) with /bus@f0000/i2c@20010000/hdmi@48
[    1.082703] pca953x 1-0021: supply vcc not found, using dummy regulator
[    1.089624] pca953x 1-0021: using no AI
[    1.116871] pca953x 1-0021: failed writing register
[    1.122068] pca953x: probe of 1-0021 failed with error -121
[    1.128379] at24 1-0057: supply vcc not found, using dummy regulator
[    1.135628] at24 1-0057: 256 byte 24c02 EEPROM, writable, 16 bytes/write
[    1.142570] omap_i2c 20010000.i2c: bus 1 rev0.12 at 100 kHz
[    1.149760] omap_i2c 20020000.i2c: bus 2 rev0.12 at 100 kHz
[    1.156471] omap_i2c 20030000.i2c: bus 4 rev0.12 at 100 kHz
[    1.162504] ti-sci-intr 4210000.interrupt-controller: Interrupt Router 5 domain created
[    1.170890] ti-sci-intr bus@f0000:interrupt-controller@a00000: Interrupt Router 3 domain created
[    1.180179] ti-sci-inta 48000000.interrupt-controller: Interrupt Aggregator domain 28 created
[    1.190446] ti-udma 485c0100.dma-controller: Number of rings: 82
[    1.198740] ti-udma 485c0100.dma-controller: Channels: 48 (bchan: 18, tchan: 12, rchan: 18)
[    1.209980] ti-udma 485c0000.dma-controller: Number of rings: 150
[    1.220172] ti-udma 485c0000.dma-controller: Channels: 35 (tchan: 20, rchan: 15)
[    1.230690] 4a00000.serial: ttyS3 at MMIO 0x4a00000 (irq = 291, base_baud = 3000000) is a 8250
[    1.240906] 2800000.serial: ttyS2 at MMIO 0x2800000 (irq = 292, base_baud = 3000000) is a 8250
[    1.249857] printk: console [ttyS2] enabled
[    1.249857] printk: console [ttyS2] enabled
[    1.258325] printk: bootconsole [ns16550a0] disabled
[    1.258325] printk: bootconsole [ns16550a0] disabled
[    1.269589] 2810000.serial: ttyS0 at MMIO 0x2810000 (irq = 293, base_baud = 3000000) is a 8250
[    1.281738] davinci_mdio 8000f00.mdio: Configuring MDIO in manual mode
[    1.324733] davinci_mdio 8000f00.mdio: davinci mdio revision 9.7, bus freq 1000000
[    1.333623] am65-cpsw-nuss 8000000.ethernet: initializing am65 cpsw nuss version 0x6BA01103, cpsw version 0x6BA81103 Ports: 3 quirks:00000006
[    1.346562] am65-cpsw-nuss 8000000.ethernet: initialized cpsw ale version 1.5
[    1.353708] am65-cpsw-nuss 8000000.ethernet: ALE Table size 512
[    1.360456] am65-cpsw-nuss 8000000.ethernet: CPTS ver 0x4e8a010c, freq:500000000, add_val:1 pps:0
[    1.370892] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[    1.486680] mmc0: CQHCI version 5.10
[    1.488943] gpio-427 (CTRL_SLEEP_MOCI#): hogged as output/high
[    1.503477] davinci_mdio 8000f00.mdio: Configuring MDIO in manual mode
[    1.531442] mmc0: SDHCI controller on fa10000.mmc [fa10000.mmc] using ADMA 64-bit
[    1.548743] davinci_mdio 8000f00.mdio: davinci mdio revision 9.7, bus freq 1000000
[    1.561276] mdio_bus 8000f00.mdio: MDIO device at address 7 is missing.
[    1.567991] davinci_mdio 8000f00.mdio: phy[0]: device 8000f00.mdio:00, driver TI DP83867
[    1.578413] debugfs: Directory 'pd:182' with parent 'pm_genpd' already present!
[    1.578580] mmc1: CQHCI version 5.10
[    1.589200] input: gpio-keys as /devices/platform/gpio-keys/input/input1
[    1.603199] mmc0: new HS200 MMC card at address 0001
[    1.607834] ALSA device list:
[    1.609242] mmcblk0: mmc0:0001 Q2J55L 7.09 GiB 
[    1.611186]   No soundcards found.
[    1.619487]  mmcblk0: p1 p2
[    1.623267] mmcblk0boot0: mmc0:0001 Q2J55L 16.0 MiB 
[    1.629817] mmcblk0boot1: mmc0:0001 Q2J55L 16.0 MiB 
[    1.635977] mmcblk0rpmb: mmc0:0001 Q2J55L 4.00 MiB, chardev (241:0)
[    3.122075] sdhci-am654 fa00000.mmc: Power on failed
[    3.158105] mmc1: SDHCI controller on fa00000.mmc [fa00000.mmc] using ADMA 64-bit
[    3.175709] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Quota mode: none.
[    3.184526] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    3.194839] devtmpfs: mounted
[    3.199557] Freeing unused kernel memory: 2240K
[    3.208838] Run /sbin/init as init process
[    3.358361] systemd[1]: System time before build time, advancing clock.
[    3.405458] NET: Registered PF_INET6 protocol family
[    3.412257] Segment Routing with IPv6
[    3.416032] In-situ OAM (IOAM) with IPv6
[    3.447733] systemd[1]: systemd 250.5+ 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 -BZIP2 -LZ4 -XZ -ZLIB +ZSTD -BPF_FRAMEWORK +XKBCOMMON +UTMP +SYSVINIT default-hierarchy=hybrid)
[    3.479693] systemd[1]: Detected architecture arm64.

Welcome to TDX Wayland with XWayland 6.4.0-devel-20230823+build.367 (kirkstone)!

[    3.549887] systemd[1]: Hostname set to <verdin-am62-15133546>.
[    4.027233] systemd[1]: Queued start job for default target Graphical Interface.
[    4.082195] systemd[1]: Created slice Slice /system/getty.
[  OK  ] Created slice Slice /system/getty.
[    4.107372] systemd[1]: Created slice Slice /system/modprobe.
[  OK  ] Created slice Slice /system/modprobe.
[    4.131610] systemd[1]: Created slice Slice /system/serial-getty.
[  OK  ] Created slice Slice /system/serial-getty.
[    4.155273] systemd[1]: Created slice User and Session Slice.
[  OK  ] Created slice User and Session Slice.
[    4.177577] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[  OK  ] Started Dispatch Password …ts to Console Directory Watch.
[    4.201438] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[  OK  ] Started Forward Password R…uests to Wall Directory Watch.
[    4.225680] systemd[1]: Reached target Host and Network Name Lookups.
[  OK  ] Reached target Host and Network Name Lookups.
[    4.248971] systemd[1]: Reached target Path Units.
[  OK  ] Reached target Path Units.
[    4.265162] systemd[1]: Reached target Remote File Systems.
[  OK  ] Reached target Remote File Systems.
[    4.289119] systemd[1]: Reached target Slice Units.
[  OK  ] Reached target Slice Units.
[    4.305196] systemd[1]: Reached target Swaps.
[  OK  ] Reached target Swaps.
[    4.376336] systemd[1]: Listening on RPCbind Server Activation Socket.
[  OK  ] Listening on RPCbind Server Activation Socket.
[    4.401458] systemd[1]: Reached target RPC Port Mapper.
[  OK  ] Reached target RPC Port Mapper.
[    4.426798] systemd[1]: Listening on Syslog Socket.
[  OK  ] Listening on Syslog Socket.
[    4.441979] systemd[1]: Listening on initctl Compatibility Named Pipe.
[  OK  ] Listening on initctl Compatibility Named Pipe.
[    4.468958] systemd[1]: Listening on Journal Audit Socket.
[  OK  ] Listening on Journal Audit Socket.
[    4.495405] systemd[1]: Listening on Journal Socket (/dev/log).
[  OK  ] Listening on Journal Socket (/dev/log).
[    4.519838] systemd[1]: Listening on Journal Socket.
[  OK  ] Listening on Journal Socket.
[    4.540921] systemd[1]: Listening on Network Service Netlink Socket.
[  OK  ] Listening on Network Service Netlink Socket.
[    4.568204] systemd[1]: Listening on udev Control Socket.
[  OK  ] Listening on udev Control Socket.
[    4.591188] systemd[1]: Listening on udev Kernel Socket.
[  OK  ] Listening on udev Kernel Socket.
[    4.615396] systemd[1]: Listening on User Database Manager Socket.
[  OK  ] Listening on User Database Manager Socket.
[    4.673464] systemd[1]: Mounting Huge Pages File System...
         Mounting Huge Pages File System...
[    4.695830] systemd[1]: Mounting POSIX Message Queue File System...
         Mounting POSIX Message Queue File System...
[    4.745588] systemd[1]: Mounting Kernel Debug File System...
         Mounting Kernel Debug File System...
[    4.762289] systemd[1]: Kernel Trace File System was skipped because of a failed condition check (ConditionPathExists=/sys/kernel/tracing).
[    4.784436] systemd[1]: Mounting Temporary Directory /tmp...
         Mounting Temporary Directory /tmp...
[    4.813723] systemd[1]: Starting Create List of Static Device Nodes...
         Starting Create List of Static Device Nodes...
[    4.865990] systemd[1]: Starting Load Kernel Module configfs...
         Starting Load Kernel Module configfs...
[    4.899158] systemd[1]: Starting Load Kernel Module drm...
         Starting Load Kernel Module drm...
[    4.929444] systemd[1]: Starting Load Kernel Module fuse...
         Starting Load Kernel Module fuse...
[    4.948094] fuse: init (API version 7.37)
[    4.974052] systemd[1]: Starting RPC Bind...
         Starting RPC Bind...
[    5.001920] systemd[1]: Starting File System Check on Root Device...
         Starting File System Check on Root Device...
[    5.054655] systemd[1]: Starting Journal Service...
         Starting Journal Service...
[    5.076326] systemd[1]: Starting Load Kernel Modules...
         Starting Load Kernel Modules...
[    5.126268] systemd[1]: Starting Generate network units from Kernel command line...
         Starting Generate network …ts from Kernel command line...
[    5.147678] systemd[1]: Starting Coldplug All udev Devices...
         Starting Coldplug All udev Devices...
[    5.183299] systemd[1]: Started RPC Bind.
[  OK  ] Started RPC Bind.
[    5.201916] systemd[1]: Mounted Huge Pages File System.
[  OK  ] Mounted Huge Pages File System.
[    5.229905] systemd[1]: Mounted POSIX Message Queue File System.
[  OK  ] Mounted POSIX Message Queue File System.
[    5.253852] systemd[1]: Started Journal Service.
[  OK  ] Started Journal Service.
[  OK  ] Mounted Kernel Debug File System.
[  OK  ] Mounted Temporary Directory /tmp.
[  OK  ] Finished Create List of Static Device Nodes.
[  OK  ] Finished Load Kernel Module configfs.
[  OK  ] Finished Load Kernel Module drm.
[  OK  ] Finished Load Kernel Module fuse.
[  OK  ] Finished File System Check on Root Device.
[  OK  ] Finished Load Kernel Modules.
[  OK  ] Finished Generate network units from Kernel command line.
         Mounting FUSE Control File System...
         Mounting Kernel Configuration File System...
         Starting Remount Root and Kernel File Systems...
[    5.589483] EXT4-fs (mmcblk0p2): re-mounted. Quota mode: none.
         Starting Apply Kernel Variables...
[  OK  ] Mounted FUSE Control File System.
[  OK  ] Mounted Kernel Configuration File System.
[  OK  ] Finished Remount Root and Kernel File Systems.
[  OK  ] Finished Apply Kernel Variables.
         Starting Flush Journal to Persistent Storage...
[    5.729800] systemd-journald[152]: Received client request to flush runtime journal.
         Starting Create Static Device Nodes in /dev...
[  OK  ] Finished Flush Journal to Persistent Storage.
[  OK  ] Finished Create Static Device Nodes in /dev.
[  OK  ] Finished Coldplug All udev Devices.
[  OK  ] Reached target Preparation for Local File Systems.
         Mounting /var/volatile...
         Starting Wait for udev To …plete Device Initialization...
[    5.958278] audit: type=1334 audit(1651167747.596:2): prog-id=5 op=LOAD
[    5.965110] audit: type=1334 audit(1651167747.604:3): prog-id=6 op=LOAD
         Starting Rule-based Manage…for Device Events and Files...
[  OK  ] Mounted /var/volatile.
         Starting Load/Save Random Seed...
[  OK  ] Reached target Local File Systems.
         Starting Create Volatile Files and Directories...
[  OK  ] Started Rule-based Manager for Device Events and Files.
[  OK  ] Finished Create Volatile Files and Directories.
         Starting Network Time Synchronization...
         Starting Record System Boot/Shutdown in UTMP...
[  OK  ] Finished Record System Boot/Shutdown in UTMP.
[  OK  ] Started Network Time Synchronizatio[    6.661123] systemd-journald[152]: Oldest entry in /run/log/journal/bed90d19bbc34c8baf3e2dc044b233ff/system.journal is older than the configured file retention duration (1month), suggesting rotation.
n.
[  OK  ] Reached target System Time Set.[    6.696334] systemd-journald[152]: /run/log/journal/bed90d19bbc34c8baf3e2dc044b233ff/system.journal: Journal header limits reached or header out-of-date, rotating.

[    7.124786] random: crng init done
[    7.129907] lm75 0-0048: supply vs not found, using dummy regulator
[    7.145458] hwmon hwmon0: temp1_input not attached to any thermal zone
[  OK  ] Finished Load/Save Random Seed.[    7.162273] lm75 0-0048: hwmon0: sensor 'tmp1075'

[    7.175637] nau8822 1-001a: Failed to issue reset: -121
[    7.213286] nau8822: probe of 1-001a failed with error -121
[    7.228570] lm75 1-004f: supply vs not found, using dummy regulator
[    7.249186] hwmon hwmon1: temp1_input not attached to any thermal zone
[    7.257006] lm75 1-004f: hwmon1: sensor 'tmp75c'
[    7.264668] ina2xx 1-0040: error configuring the device: -121
[    7.307228] CAN device driver interface
[    7.349065] m_can_platform 4e08000.can: m_can device registered (irq=0, version=32)
[    7.367509] m_can_platform 20701000.can: m_can device registered (irq=482, version=32)
[    7.521928] k3-m4-rproc 5000000.m4fss: assigned reserved memory node m4f-dma-memory@9cb00000
[    7.605120] k3-m4-rproc 5000000.m4fss: configured M4 for remoteproc mode
[    7.653426] k3-m4-rproc 5000000.m4fss: local reset is deasserted for device
[    7.677427] remoteproc remoteproc0: 5000000.m4fss is available
[    7.686150] remoteproc remoteproc0: Direct firmware load for am62-mcu-m4f0_0-fw failed with error -2
[    7.700849] remoteproc remoteproc0: powering up 5000000.m4fss
[    7.709319] rtc-ti-k3 2b1f0000.rtc: registered as rtc1
[    7.714620] remoteproc remoteproc0: Direct firmware load for am62-mcu-m4f0_0-fw failed with error -2
[    7.731199] remoteproc remoteproc0: request_firmware failed: -2
[    7.768996] platform 78000000.r5f: R5F core may have been powered on by a different host, programmed state (0) != actual state (1)
[    7.848688] pvrsrvkm: loading out-of-tree module taints kernel.
[    7.885142] platform 78000000.r5f: configured R5F for IPC-only mode
[    7.927615] platform 78000000.r5f: assigned reserved memory node r5f-dma-memory@9da00000
[    7.941600] [drm] Initialized tidss 1.0.0 20180215 for 30200000.dss on minor 0
[    7.950494] tidss 30200000.dss: [drm] Cannot find any crtc or sizes
[    7.982989] remoteproc remoteproc1: 78000000.r5f is available
[    7.989990] remoteproc remoteproc1: attaching to 78000000.r5f
[    8.029364] PVR_K:  185: Device: fd00000.gpu
[    8.032917] platform 78000000.r5f: R5F core initialized in IPC-only mode
[    8.038425] PVR_K:  185: Read BVNC 33.15.11.3 from HW device registers
[    8.064949] PVR_K:  185: RGX Device registered with BVNC 33.15.11.3
[    8.082352] [drm] Initialized pvr 23.1.6404501 20170530 for fd00000.gpu on minor 1
[    8.107479] rproc-virtio rproc-virtio.4.auto: assigned reserved memory node r5f-dma-memory@9da00000
[    8.126466] virtio_rpmsg_bus virtio0: rpmsg host is online
[    8.127037] virtio_rpmsg_bus virtio0: creating channel ti.ipc4.ping-pong addr 0xd
[    8.134870] rproc-virtio rproc-virtio.4.auto: registered virtio0 (type 7)
[    8.144601] virtio_rpmsg_bus virtio0: creating channel rpmsg_chrdev addr 0xe
[    8.158043] remoteproc remoteproc1: remote processor 78000000.r5f is now attached
[*     ] A start job is running for Wait for…vice Initialization (5s / 3min 1s)
M
[**    ] A start job is running for Wait for…vice Initialization (5s / 3min 1s)
[   30.828716] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[   30.834860] rcu: 	1-...!: (0 ticks this GP) idle=9bf4/1/0x4000000000000000 softirq=5095/5095 fqs=0
[   30.843814] rcu: 	Tasks blocked on level-0 rcu_node (CPUs 0-1): P177/1:b..l
[   30.850779] 	(detected by 0, t=5256 jiffies, g=1881, q=329 ncpus=2)
[   30.857039] Task dump for CPU 1:
[   30.860261] task:systemd-udevd   state:R  running task     stack:0     pid:186   ppid:173    flags:0x00000a0e
[   30.870170] Call trace:
[   30.872612]  __switch_to+0xe4/0x160
[   30.876114]  lock_timer_base+0x64/0xa4
[   30.879862]  del_timer_sync+0x4c/0xd0
[   30.883519]  schedule_timeout+0x88/0xf0
[   30.887350]  wait_for_completion_timeout+0x74/0x144
[   30.892222]  tx_tick+0x44/0xa4
[   30.895279] task:systemd-udevd   state:R  running task     stack:0     pid:177   ppid:173    flags:0x00000a04
[   30.905185] Call trace:
[   30.907624]  __switch_to+0xe4/0x160
[   30.911109]  __schedule+0x22c/0x660
[   30.914593]  preempt_schedule+0x4c/0x70
[   30.918424]  _raw_spin_unlock_irqrestore+0x30/0x50
[   30.923209]  __wake_up_common_lock+0x90/0xd0
[   30.927476]  __wake_up_sync_key+0x20/0x30
[   30.931480]  sock_def_readable+0x40/0x80
[   30.935403]  unix_dgram_sendmsg+0x3f8/0x880
[   30.939584]  sock_write_iter+0xa4/0x110
[   30.943415]  vfs_write+0x254/0x2b0
[   30.946816]  ksys_write+0xdc/0xf4
[   30.950127]  __arm64_sys_write+0x1c/0x2c
[   30.954045]  invoke_syscall+0x48/0x114
[   30.957793]  el0_svc_common.constprop.0+0xd4/0xfc
[   30.962492]  do_el0_svc+0x30/0xd0
[   30.965804]  el0_svc+0x2c/0x84
[   30.968855]  el0t_64_sync_handler+0xbc/0x140
[   30.973119]  el0t_64_sync+0x18c/0x190
[   30.976779] rcu: rcu_preempt kthread timer wakeup didn't happen for 5255 jiffies! g1881 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
[   30.988069] rcu: 	Possible timer handling issue on cpu=1 timer-softirq=555
[   30.994933] rcu: rcu_preempt kthread starved for 5256 jiffies! g1881 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=1
[   31.005269] rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
[   31.014388] rcu: RCU grace-period kthread stack dump:
[   31.019430] task:rcu_preempt     state:I stack:0     pid:14    ppid:2      flags:0x00000008
[   31.027775] Call trace:
[   31.030214]  __switch_to+0xe4/0x160
[   31.033699]  __schedule+0x22c/0x660
[   31.037183]  schedule+0x5c/0xd0
[   31.040320]  schedule_timeout+0x80/0xf0
[   31.044149]  rcu_gp_fqs_loop+0x124/0x3dc
[   31.048071]  rcu_gp_kthread+0x128/0x164
[   31.051901]  kthread+0x10c/0x110
[   31.055129]  ret_from_fork+0x10/0x20
[   31.058699] rcu: Stack dump where RCU GP kthread last ran:
[   31.064174] Task dump for CPU 1:
[   31.067393] task:systemd-udevd   state:R  running task     stack:0     pid:186   ppid:173    flags:0x00000a0e
[   31.077298] Call trace:
[   31.079736]  __switch_to+0xe4/0x160
[   31.083221]  lock_timer_base+0x64/0xa4
[   31.086965]  del_timer_sync+0x4c/0xd0
[   31.090622]  schedule_timeout+0x88/0xf0
[   31.094450]  wait_for_completion_timeout+0x74/0x144
[   31.099322]  tx_tick+0x44/0xa4

  • One more comment, looking at past test execution this is not something new, we had a similar issue also with 08.06.00.007 release.

    Just to give you some hint that it does not seems to be a regression (assuming this is exactly the same problem - that we do not know for sure - of course).

    [   68.926933] rcu: INFO: rcu_preempt self-detected stall on CPU
    [   68.933079] rcu: 	0-....: (1 GPs behind) idle=fae/1/0x4000000000000004 softirq=3150/3151 fqs=2052 
    [   68.942082] 	(t=5253 jiffies g=2069 q=85)
    [   68.946106] Task dump for CPU 0:
    [   68.949354] task:systemd         state:R  running task     stack:    0 pid:    1 ppid:     0 flags:0x00000002
    [   68.959297] Call trace:
    [   68.961897]  dump_backtrace+0x0/0x1e0
    [   68.965589]  show_stack+0x18/0x40
    [   68.968926]  sched_show_task+0x154/0x17c
    [   68.972906]  dump_cpu_task+0x44/0x58
    [   68.976496]  rcu_dump_cpu_stacks+0xb0/0xf0
    [   68.980636]  rcu_sched_clock_irq+0xa34/0xd60
    [   68.984912]  update_process_times+0x60/0xa0
    [   68.989107]  tick_sched_timer+0x58/0xd0
    [   68.992955]  __hrtimer_run_queues+0x138/0x1d0
    [   68.997320]  hrtimer_interrupt+0xe8/0x2c0
    [   69.001343]  arch_timer_handler_phys+0x34/0x44
    [   69.005800]  handle_percpu_devid_irq+0x84/0x140
    [   69.010343]  __handle_domain_irq+0x7c/0xe0
    [   69.014455]  gic_handle_irq+0xc0/0x140
    [   69.018217]  el1_irq+0xcc/0x180
    [   69.021368]  efi_header_end+0xa4/0x290
    [   69.025127]  irq_exit+0xdc/0xfc
    [   69.028280]  __handle_domain_irq+0x80/0xe0
    [   69.032390]  gic_handle_irq+0xc0/0x140
    [   69.036150]  el1_irq+0xcc/0x180
    [   69.039303]  preempt_schedule_irq+0x3c/0xd0
    [   69.043498]  arm64_preempt_schedule_irq+0x14/0x30
    [   69.048210]  el1_irq+0xe4/0x180
    [   69.051365]  omap_8250_startup+0xe8/0x220
    [   69.055384]  serial8250_startup+0x18/0x34
    [   69.059405]  uart_startup.part.0+0x148/0x32c
    [   69.063686]  uart_port_activate+0x60/0xa4
    [   69.067709]  tty_port_open+0x90/0x130
    [   69.071380]  uart_open+0x1c/0x30
    [   69.074618]  tty_open+0x13c/0x680
    [   69.077944]  chrdev_open+0xc0/0x22c
    [   69.081446]  do_dentry_open+0x12c/0x3e4
    [   69.085363]  vfs_open+0x2c/0x40
    [   69.088598]  path_openat+0x8a8/0xca0
    [   69.092202]  do_filp_open+0x78/0x124
    [   69.095813]  do_sys_openat2+0xb4/0x160
    [   69.099572]  __arm64_sys_openat+0x60/0xb0
    [   69.103646]  el0_svc_common.constprop.0+0x78/0x1c4
    [   69.108454]  do_el0_svc+0x28/0xac
    [   69.111814]  el0_svc+0x14/0x20
    [   69.114874]  el0_sync_handler+0xa4/0x130
    [   69.118807]  el0_sync+0x180/0x1c0

    23-06-16_18-27-04-Fail.txt

  • Hey fd,

    You said this was also an issue in the SDK 8.6 release; was that already reported somewhere?

    Is this a custom board or one of our EVM/SKs?

    This stall seems to occur around initialization/hand-off of the remote processor in these logs, does that match your other testing? Could you try blacklisting the remoteproc driver and see if that changes anything?

    Regards,

    Randolph

  • > You said this was also an issue in the SDK 8.6 release; was that already reported somewhere?

    directly reported to a TI engineer (I can provide details if needed, just contact me directly in private).

    > Is this a custom board or one of our EVM/SKs?

    it's a custom board.

    This stall seems to occur around initialization/hand-off of the remote processor in these logs, does that match your other testing?

    difficult to say ... 

    Could you try blacklisting the remoteproc driver and see if that changes anything?

    yes, we can. however it's quite expensive to set-up the whole test. I have some more logs to share to double check if this is a reasonable hypothesis first.

  • Fd,

    Cool, please share those logs when you get a chance. This issue has previously been related to DDR timing issues, but this seems like it may be a little different.

    Regards,

    Randolph

  • I have some additional information.

    The issues seems to appear only when the temperature is lower than -20 degrees celsius and is more frequent when we are close to -40 degrees celsius.

    This issue has previously been related to DDR timing issues

    Would an issue on the DDR Memory Configuration and timing be present only at low temperatures? I would normally expect issue when the board is hot. Could be something related to the drive strength of the DDR signals? Anything specific in your mind to check?

    One more log (this happened multiple times) that might give some hint:

    [   37.307749] rcu: INFO: rcu_preempt self-detected stall on CPU
    [   37.310713] platform sound: deferred probe pending
    [   37.313535] rcu: 	1-...!: (1 ticks this GP) idle=6bc4/1/0x4000000000000000 softirq=4799/4799 fqs=0
    [   37.313549] 	(t=6911 jiffies g=1741 q=174 ncpus=2)
    [   37.313557] rcu: rcu_preempt kthread timer wakeup didn't happen for 6910 jiffies! g1741 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
    [   37.313563] rcu: 	Possible timer handling issue on cpu=1 timer-softirq=684
    [   37.313567] rcu: rcu_preempt kthread starved for 6911 jiffies! g1741 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=1
    [   37.313573] rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
    [   37.313577] rcu: RCU grace-period kthread stack dump:
    [   37.313581] task:rcu_preempt     state:I stack:0     pid:14    ppid:2      flags:0x00000008
    [   37.313595] Call trace:
    [   37.313599]  __switch_to+0xe4/0x160
    [   37.389048]  __schedule+0x22c/0x660
    [   37.389073]  schedule+0x5c/0xd0
    [   37.389080]  schedule_timeout+0x80/0xf0
    [   37.389086]  rcu_gp_fqs_loop+0x124/0x3dc
    [   37.389100]  rcu_gp_kthread+0x128/0x164
    [   37.389106]  kthread+0x10c/0x110
    [   37.389116]  ret_from_fork+0x10/0x20
    [   37.389128] rcu: Stack dump where RCU GP kthread last ran:
    [   37.389137] CPU: 1 PID: 176 Comm: systemd-udevd Tainted: G           O       6.1.38-6.4.0-devel+git.725e74990ab5 #1
    [   37.389147] Hardware name: Toradex Verdin AM62 on Verdin Development Board (DT)
    M
    [***   ] A start job is run[   37.389152] pstate: 00000005 (nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
    ning for Wait for…ice Initialization (33s / 3min 1s)
    [   37.389159] pc : el1_abort+0x30/0x6c
    [   37.389166] lr : el1_abort+0x24/0x6c
    [   37.389171] sp : ffff8000096cb460
    [   37.389174] x29: ffff8000096cb460 x28: ffff00000217b900 x27: ffff800000cf41b8
    [   37.389187] x26: ffff000003607800 x25: ffff000003607a40 x24: 0000000000000000
    [   37.389196] x23: 0000000060000005 x22: ffff800000d0a00c x21: ffff8000097c7040
    [   37.389206] x20: 0000000096000010 x19: ffff8000096cb4a0 x18: 0000000000000000
    [   37.389215] x17: ffff800036e55000 x16: ffff800008008000 x15: 0000b44b547200cc
    [   37.389224] x14: 0000000000000002 x13: 0000000000000002 x12: 0000000000000001
    [   37.389233] x11: 0000000000000001 x10: 00000000000009b0 x9 : ffff8000096cb1e0
    [   37.389242] x8 : ffff00003fda3180 x7 : 0000040001000000 x6 : ffff000000c06190
    [   37.389251] x5 : ffff8000096cb4a0 x4 : 0000002000000000 x3 : 0000000000000025
    [   37.389260] x2 : 0000002200000000 x1 : 0000000096000010 x0 : 0000000000000000
    [   37.389269] Call trace:
    [   37.389272]  el1_abort+0x30/0x6c
    [   37.389278]  el1h_64_sync_handler+0xd8/0xe4
    [   37.389285]  el1h_64_sync+0x64/0x68
    [   37.389290]  iomap_read_reg+0xc/0x30 [m_can_platform]
    [   37.389308]  can_fill_info+0x104/0x520 [can_dev]
    [   37.389336]  rtnl_fill_ifinfo+0x83c/0x11b0
    [   37.389346]  rtnl_getlink+0x238/0x414
    [   37.389352]  rtnetlink_rcv_msg+0x12c/0x390
    [   37.389357]  netlink_rcv_skb+0x5c/0x130
    [   37.389369]  rtnetlink_rcv+0x18/0x24
    [   37.389379]  netlink_unicast+0x2d8/0x330
    [   37.389385]  netlink_sendmsg+0x1ac/0x410
    [   37.389392]  __sys_sendto+0x128/0x164
    [   37.389401]  __arm64_sys_sendto+0x28/0x3c
    [   37.389408]  invoke_syscall+0x48/0x114
    [   37.389419]  el0_svc_common.constprop.0+0xd4/0xfc
    [   37.389426]  do_el0_svc+0x30/0xd0
    [   37.389433]  el0_svc+0x2c/0x84
    [   37.389438]  el0t_64_sync_handler+0xbc/0x140
    [   37.389444]  el0t_64_sync+0x18c/0x190
    [   37.389461] CPU: 1 PID: 176 Comm: systemd-udevd Tainted: G           O       6.1.38-6.4.0-devel+git.725e74990ab5 #1
    [   37.389468] Hardware name: Toradex Verdin AM62 on Verdin Development Board (DT)
    [   37.389471] pstate: 00000005 (nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
    [   37.389478] pc : el1_abort+0x30/0x6c
    [   37.389483] lr : el1_abort+0x24/0x6c
    [   37.389487] sp : ffff8000096cb460
    [   37.389489] x29: ffff8000096cb460 x28: ffff00000217b900 x27: ffff800000cf41b8
    [   37.389499] x26: ffff000003607800 x25: ffff000003607a40 x24: 0000000000000000
    [   37.389509] x23: 0000000060000005 x22: ffff800000d0a00c x21: ffff8000097c7040
    [   37.389518] x20: 0000000096000010 x19: ffff8000096cb4a0 x18: 0000000000000000
    [   37.389527] x17: ffff800036e55000 x16: ffff800008008000 x15: 0000b44b547200cc
    [   37.389536] x14: 0000000000000002 x13: 0000000000000002 x12: 0000000000000001
    [   37.389545] x11: 0000000000000001 x10: 00000000000009b0 x9 : ffff8000096cb1e0
    [   37.389554] x8 : ffff00003fda3180 x7 : 0000040001000000 x6 : ffff000000c06190
    [   37.389562] x5 : ffff8000096cb4a0 x4 : 0000002000000000 x3 : 0000000000000025
    [   37.389571] x2 : 0000002200000000 x1 : 0000000096000010 x0 : 0000000000000000
    [   37.389580] Call trace:
    [   37.389582]  el1_abort+0x30/0x6c
    [   37.389587]  el1h_64_sync_handler+0xd8/0xe4
    [   37.389593]  el1h_64_sync+0x64/0x68
    [   37.389598]  iomap_read_reg+0xc/0x30 [m_can_platform]
    [   37.389609]  can_fill_info+0x104/0x520 [can_dev]
    [   37.389630]  rtnl_fill_ifinfo+0x83c/0x11b0
    [   37.389636]  rtnl_getlink+0x238/0x414
    [   37.389641]  rtnetlink_rcv_msg+0x12c/0x390
    [   37.389646]  netlink_rcv_skb+0x5c/0x130
    [   37.389652]  rtnetlink_rcv+0x18/0x24
    [   37.389660]  netlink_unicast+0x2d8/0x330
    [   37.389667]  netlink_sendmsg+0x1ac/0x410
    [   37.389673]  __sys_sendto+0x128/0x164
    [   37.389679]  __arm64_sys_sendto+0x28/0x3c
    [   37.389685]  invoke_syscall+0x48/0x114
    [   37.389692]  el0_svc_common.constprop.0+0xd4/0xfc
    [   37.389699]  do_el0_svc+0x30/0xd0
    [   37.389705]  el0_svc+0x2c/0x84
    [   37.389711]  el0t_64_sync_handler+0xbc/0x140
    [   37.389716]  el0t_64_sync+0x18c/0x190
    [   37.421668] remoteproc remoteproc2: 30074000.pru is available
    [   37.488283] Internal error: synchronous external abort: 0000000096000010 [#1] PREEMPT SMP
    [   37.828368] Modules linked in: pru_rproc(+) irq_pruss_intc crct10dif_ce snd_soc_simple_card snd_soc_simple_card_utils pvrsrvkm(O) display_connector ti_k3_r5_remoteproc dwc3_am62 virtio_rpmsg_bus rpmsg_ns rtc_ti_k3 ti_k3_m4_remoteproc ti_k3_common snd_soc_davinci_mcasp snd_soc_ti_udma sa2ul tidss mcrc pruss drm_dma_helper snd_soc_ti_edma snd_soc_ti_sdma pwm_tiehrpwm m_can_platform m_can can_dev spi_omap2_mcspi snd_soc_nau8822 ina2xx lontium_lt8912b tc358768 drm_kms_helper cfbfillrect syscopyarea lm75 cfbimgblt sysfillrect sysimgblt fb_sys_fops cfbcopyarea libcomposite fuse drm drm_panel_orientation_quirks ipv6
    [   37.828492] CPU: 1 PID: 176 Comm: systemd-udevd Tainted: G           O       6.1.38-6.4.0-devel+git.725e74990ab5 #1
    [   37.828501] Hardware name: Toradex Verdin AM62 on Verdin Development Board (DT)
    [   37.828507] pstate: 60000005 (nZCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
    [   37.828514] pc : iomap_read_reg+0xc/0x30 [m_can_platform]
    [   37.828539] lr : m_can_get_berr_counter+0x3c/0x10c [m_can]
    [   37.828556] sp : ffff8000096cb5f0
    [   37.828559] x29: ffff8000096cb5f0 x28: 0000000000000240 x27: ffff800000cf41b8
    [   37.828569] x26: ffff000003607800 x25: ffff000003607a40 x24: 0000000000000000
    [   37.828578] x23: 0000000000000000 x22: ffff000000c06010 x21: ffff0000027d8000
    [   37.828587] x20: ffff0000027d8980 x19: ffff8000096cb67c x18: 0000000000000000
    [   37.828596] x17: ffff800036e55000 x16: ffff800008008000 x15: 0000b44b547200cc
    [   37.828605] x14: 0000000000000002 x13: 0000000000000002 x12: 0000000000000001
    [   37.828613] x11: 0000000000000001 x10: 00000000000009b0 x9 : ffff8000096cb1e0
    [   37.828622] x8 : ffff00003fda3180 x7 : 0000040001000000 x6 : ffff000000c06190
    [   37.828631] x5 : 0000000000000000 x4 : 0000000000000000 x3 : 0000000000000000
    [   37.828639] x2 : ffff800000d0a000 x1 : 0000000000000040 x0 : ffff8000097c7040
    [   37.828649] Call trace:
    [   37.828654]  iomap_read_reg+0xc/0x30 [m_can_platform]
    [   37.828666]  can_fill_info+0x104/0x520 [can_dev]
    [   37.828695]  rtnl_fill_ifinfo+0x83c/0x11b0
    [   37.828710]  rtnl_getlink+0x238/0x414
    [   37.828716]  rtnetlink_rcv_msg+0x12c/0x390
    [   37.828722]  netlink_rcv_skb+0x5c/0x130
    [   37.828734]  rtnetlink_rcv+0x18/0x24
    [   37.828744]  netlink_unicast+0x2d8/0x330
    [   37.828750]  netlink_sendmsg+0x1ac/0x410
    [   37.828757]  __sys_sendto+0x128/0x164
    [   37.828767]  __arm64_sys_sendto+0x28/0x3c
    [   37.828773]  invoke_syscall+0x48/0x114
    [   37.828785]  el0_svc_common.constprop.0+0xd4/0xfc
    [   37.828793]  do_el0_svc+0x30/0xd0
    [   37.828799]  el0_svc+0x2c/0x84
    [   37.828808]  el0t_64_sync_handler+0xbc/0x140
    [   37.828814]  el0t_64_sync+0x18c/0x190
    [   37.828832] Code: bad PC value
    [   37.828839] ---[ end trace 0000000000000000 ]---
    [   37.899567] omap_rng 40910000.rng: Random Number Generator ver. 241b34c
    [   37.951131] remoteproc remoteproc3: 30078000.pru is available
    [   38.039060] xhci-hcd xhci-hcd.6.auto: xHCI Host Controller
    

    and again, as I wrote before, sometime the board just hang forever during boot without any significant message on the console.

  • : any additional hint on this comment of yours "This issue has previously been related to DDR timing issues" ? Timing wise everything seems fine, while I would love some guidance on IO configurations (Drive strength, Termination, ODT, ...).

  • Hey fd,

    Sorry about the delay. I'm looking into some things on my side and will get back to you before the end of this week.

    Regards,

    Randolph

  • I was given your DDR configuration files via email and the changes look ok, so let's start with that configuration:

    -create a DDR configuration for a slower frequency (eg 667MHz) to see if the problems go away at cold temp

    -did you perform any DDR board simulations?  These will help provide the appropriate drive strength and terminations settings for your board.  The ones you are using are optimized for the AM62 LP EVM, so they may not be optimal for your board.  

    -have you run memtester to see if there are any errors at cold temp?  Can you boot the board at nominal temp, run memtester, and start dialing down the temp until fail? Send error logs if you have them

    -do you have JTAG access?   If so, when you start seeing errors at cold temps, you connect via JTAG to see if the memtester errors are read or write errors.  This may help narrow down which termination settings to adjust.

    Regards,

    James

  • -create a DDR configuration for a slower frequency (eg 667MHz) 

    We'll test this and let you know the results.

    -did you perform any DDR board simulations? 

    No. Do you have any additional suggestion on this topic, maybe an application note? How would you suggest to proceed?

    have you run memtester to see if there are any errors at cold temp?

    > Can you boot the board at nominal temp, run memtester, and start dialing down the temp until fail?

    From our tests the specific modules that fails boot below -20 degrees C, memtester never fails.

    do you have JTAG access?

    This is something not obvious to do for us when running tests in the climate chamber. If required we can figure out a way.

  • -did you perform any DDR board simulations? 

    No. Do you have any additional suggestion on this topic, maybe an application note? How would you suggest to proceed?

    The application note for a follow on device has applicable information about DDR board simulations.  Please see section 3 of www.ti.com/.../sprad66 

    > Can you boot the board at nominal temp, run memtester, and start dialing down the temp until fail?

    From our tests the specific modules that fails boot below -20 degrees C, memtester never fails.

    This is interesting, as it indicates there isn't a problem with DDR at low temps, something else is failing

    do you have JTAG access?

    This is something not obvious to do for us when running tests in the climate chamber. If required we can figure out a way.

    yes, i agree this can be difficult at times.  

    Since it doesn't appear to be DDR related, i will have to pass this on to a colleague to help interpret the linux logs.  Ensure you have performed exhaustive memtester tests (ie, across a few boards at low temps), to ensure you aren't chasing DDR issues.

    Regards,

    James

     

  • : I assume you got the email forwarded from . We are experiencing 2 different issues, one is described here and not obvious if this is memory or not, while the other one seems more likely to be memory related (memtester failing, SPL R5 not able to correctly init the memory and therefore boot failing). 

    We'll proceed never the less to do the test with 667MHz memory controller configuration.

  • create a DDR configuration for a slower frequency (eg 667MHz) 

    we tested this and we did not have any improvement. From what we can see the situation is even worst, however we do have limited amount of data to be confident.

  • Hey Fd,

    Looks like I'm back on the case. Still working on critical SGX stuff at the moment so please give me a week to respond to this.

    Regards,

    Randolph

  • Hi fd, 

    i think we will need some more details on each of the failures.  Based on what i read above you have two separate failures

    1. Kernel boot fail, mostly at low temp.  No memtester fails

    -you said about 5% of the boots fail.  Is the 5% of the boots on one board, or 5% of the boards.  Do all boards eventually fail?

    -is there any consistency in the fail point, or is it failing at different points in the kernel boot?  From the log you sent a while ago, they seem pretty different, but not sure if there was any progress in some of Randoph's suggestions on blacklisting remoteproc  

    2. SPL boot fail, memtester failing.

    -do you have logs of this fail?  

    -How are you running memtester if SPL fails?  

    -is this fail also happening mostly at cold temps?

    Regards,

    James

  • First, none of the issues are systematic.

    > 1. Kernel boot fail, mostly at low temp.  No memtester fails

    Failing in difference places. Either RCU stall detected or a complete freeze without logs.

    We had one board that was not failing in one run, but the occurency rate is as low as 2% and we are currently testing 7 boards in parallel. Not sure how statistically relevant is this information.

    2. SPL boot fail, memtester failing.

    This is happening all over the working temperature range. 

    The boot failure is something like this:

    ```

    U-Boot SPL 2023.04-6.4.0-devel+git.96179e4a5bb0 (Sep 06 2023 - 06:13:04 +0000)
    SYSFW ABI: 3.1 (firmware rev 0x0009 '9.0.7--v09.00.07 (Kool Koala)')
    ## WARNING: Less than 64MB RAM detected
    SPL initial stack usage: 13376 bytes

    ```

    and after that nothing happens. The `##WARNING`` is because U-Boot `get_ram_size()` fails. This is a very simple memory test using all the data/address lines.

    The issue is not systematic, sometime the module boots fine and we get error running memtester from Linux.

  • Ok, i'd like to focus on the boards that are experiencing the failure in #2.  Do you have JTAG access on your board and/or have used Code Composer?  I'd like to get u-boot out of the picture and focus on just the DDR configuration.  We need to get that robust otherwise everything else will be suspect.

    If you have JTAG access and CCS, i will give you further instructions...

    Forgot to mention, can you also send info on the DDR you are using (part number and/or datasheet) and the register configuration file .dtsi you are using in u-boot

    Regards,

    James

  • : can we use Code Composer with a USB FDTI based JTAG solution (this we have easily available)? What are the supported JTAG HW solutions?

  • yes, this is possible.  We use an XDS110 on our EVMs which is USB FDTI based.  I am also familiar with XDS200 and XDS560, both of which would require a JTAG header on the board.

    Regards,

    James