enable_uart=1 NOT fixing core_freq to 250MHz

[pb66]

Is this the right place for my bug report?
I hope so, apologies if that's not the case.
I've also posted on the RPi forum (See https://www.raspberrypi.org/forums/viewtopic.php?f=28&t=302771)

Describe the bug

Mini UART baud unstable or incorrect when enable_uart=1 is set without also setting core_freq=250, so I suspect setting enable_uart=1 does NOT currently fix the clock speed.

To reproduce
With vanilla raspiOS, set enable_uart=1 in config.txt, edit cmdline.txt to remove console=serial0,115200 and reboot.

Use serial terminal (eg minicom) to attempt to use Mini UART and primary UART with address /dev/serial0 at the correct baud for test signal device connected to the GPIO (signal needs to be easily readable or at least easly distinguised from serial garbage).

If garbage output is all you get, set core_freq=250 in config.txt and reboot.

Try test with minicom again, this time should be successful.

Expected behaviour

core_freq should be fixed to 250MHz when enable_uart=1 set and therefore the Mini UART baud should be constant/correct, there shouldn't be a need to explicitly set core_freq according to documentation and previous experience.
(see https://www.raspberrypi.org/documentation/configuration/uart.md)

Actual behaviour
Mini UART baud unstable unless core_freq=250 explicitly set.

System

raspinfo output

pi@RedPi:~ $ raspinfo System Information ------------------

Raspberry Pi 3 Model B Rev 1.2
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"

Raspberry Pi reference 2020-12-02
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, cce27bd6f44a3b2e83855645986b3e21f771e852, stage4

Linux RedPi 5.10.11-v7+ #1399 SMP Thu Jan 28 12:06:05 GMT 2021 armv7l GNU/Linux
Revision : a02082
Serial : 00000000aa5fd460
Model : Raspberry Pi 3 Model B Rev 1.2
Throttled flag : throttled=0x50000
Camera : supported=0 detected=0

Videocore information

Jan 27 2021 22:26:53
Copyright (c) 2012 Broadcom
version 99d9a48302e4553cff3688692bb7e9ac760a03fa (clean) (release) (start)

alloc failures: 0
compactions: 0
legacy block fails: 0

Filesystem information

Filesystem 1K-blocks Used Available Use% Mounted on
/dev/root 7312680 3432020 3530624 50% /
devtmpfs 439916 0 439916 0% /dev
tmpfs 473196 0 473196 0% /dev/shm
tmpfs 473196 6404 466792 2% /run
tmpfs 5120 4 5116 1% /run/lock
tmpfs 473196 0 473196 0% /sys/fs/cgroup
/dev/mmcblk0p1 258095 48682 209413 19% /boot
log2ram 102400 51480 50920 51% /var/log
tmpfs 94636 4 94632 1% /run/user/1000

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

Package version information

raspberrypi-ui-mods:
Installed: 1.20201210+nmu1
raspberrypi-sys-mods:
Installed: 20210125
openbox:
Installed: 3.6.1-8+rpt5
lxpanel:
Installed: 0.10.0-2+rpt14
pcmanfm:
Installed: 1.3.1-1+rpt25
rpd-plym-splash:
Installed: 0.26

Networking Information

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

lo: flags=73<UP,LOOPBACK,RUNNING> mtu 65536
inet x.x.x.x netmask x.x.x.x
inet6 ::1 prefixlen 128 scopeid 0x10
loop txqueuelen 1000 (Local Loopback)
RX packets 6 bytes 528 (528.0 B)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 6 bytes 528 (528.0 B)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

wlan0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet x.x.x.x netmask x.x.x.x broadcast x.x.x.x
inet6 y::y.y.y.y prefixlen 64 scopeid 0x20
ether m.m.m.m txqueuelen 1000 (Ethernet)
RX packets 225 bytes 100726 (98.3 KiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 374 bytes 67257 (65.6 KiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

USB Information

/: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=dwc_otg/1p, 480M
|__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/5p, 480M
|__ Port 1: Dev 3, If 0, Class=Vendor Specific Class, Driver=smsc95xx, 480M

config.txt

aphy_params_current=819
arm_freq=1200
arm_freq_min=600
audio_pwm_mode=514
config_hdmi_boost=5
core_freq=250
desired_osc_freq=0x387520
disable_commandline_tags=2
disable_l2cache=1
display_hdmi_rotate=-1
display_lcd_rotate=-1
dphy_params_current=547
dvfs=2
enable_tvout=1
enable_uart=1
force_eeprom_read=1
force_pwm_open=1
framebuffer_ignore_alpha=1
framebuffer_swap=1
gpu_freq=300
init_uart_clock=0x2dc6c00
lcd_framerate=60
max_framebuffers=-1
over_voltage_avs=0x10c8e
pause_burst_frames=1
program_serial_random=1
sdram_freq=450
total_mem=1024
hdmi_force_cec_address:0=65535
hdmi_force_cec_address:1=65535
hdmi_pixel_freq_limit:0=0x9a7ec80
device_tree=-
overlay_prefix=overlays/
hdmi_cvt:0=
hdmi_cvt:1=
hdmi_edid_filename:0=
hdmi_edid_filename:1=
hdmi_timings:0=
hdmi_timings:1=

cmdline.txt

coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 console=tty1 root=PARTUUID=5afeb470-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait quiet splash plymouth.ignore-serial-consoles

raspi-gpio settings

BANK0 (GPIO 0 to 27):
GPIO 0: level=1 fsel=0 func=INPUT
GPIO 1: level=1 fsel=0 func=INPUT
GPIO 2: level=1 fsel=0 func=INPUT
GPIO 3: level=1 fsel=0 func=INPUT
GPIO 4: level=1 fsel=0 func=INPUT
GPIO 5: level=1 fsel=0 func=INPUT
GPIO 6: level=1 fsel=0 func=INPUT
GPIO 7: level=1 fsel=0 func=INPUT
GPIO 8: level=1 fsel=0 func=INPUT
GPIO 9: level=0 fsel=0 func=INPUT
GPIO 10: level=0 fsel=0 func=INPUT
GPIO 11: level=0 fsel=0 func=INPUT
GPIO 12: level=0 fsel=0 func=INPUT
GPIO 13: level=0 fsel=0 func=INPUT
GPIO 14: level=1 fsel=2 alt=5 func=TXD1
GPIO 15: level=1 fsel=2 alt=5 func=RXD1
GPIO 16: level=0 fsel=0 func=INPUT
GPIO 17: level=0 fsel=0 func=INPUT
GPIO 18: level=0 fsel=0 func=INPUT
GPIO 19: level=0 fsel=0 func=INPUT
GPIO 20: level=0 fsel=0 func=INPUT
GPIO 21: level=0 fsel=0 func=INPUT
GPIO 22: level=0 fsel=0 func=INPUT
GPIO 23: level=0 fsel=0 func=INPUT
GPIO 24: level=0 fsel=0 func=INPUT
GPIO 25: level=0 fsel=0 func=INPUT
GPIO 26: level=0 fsel=0 func=INPUT
GPIO 27: level=0 fsel=0 func=INPUT
BANK1 (GPIO 28 to 45):
GPIO 28: level=0 fsel=0 func=INPUT
GPIO 29: level=1 fsel=0 func=INPUT
GPIO 30: level=0 fsel=0 func=INPUT
GPIO 31: level=0 fsel=0 func=INPUT
GPIO 32: level=1 fsel=7 alt=3 func=TXD0
GPIO 33: level=1 fsel=7 alt=3 func=RXD0
GPIO 34: level=1 fsel=7 alt=3 func=SD1_CLK
GPIO 35: level=1 fsel=7 alt=3 func=SD1_CMD
GPIO 36: level=1 fsel=7 alt=3 func=SD1_DAT0
GPIO 37: level=1 fsel=7 alt=3 func=SD1_DAT1
GPIO 38: level=1 fsel=7 alt=3 func=SD1_DAT2
GPIO 39: level=1 fsel=7 alt=3 func=SD1_DAT3
GPIO 40: level=1 fsel=4 alt=0 func=PWM0
GPIO 41: level=0 fsel=4 alt=0 func=PWM1
GPIO 42: level=0 fsel=4 alt=0 func=GPCLK1
GPIO 43: level=1 fsel=4 alt=0 func=GPCLK2
GPIO 44: level=1 fsel=0 func=INPUT
GPIO 45: level=1 fsel=0 func=INPUT
BANK2 (GPIO 46 to 53):
GPIO 46: level=1 fsel=0 func=INPUT
GPIO 47: level=1 fsel=1 func=OUTPUT
GPIO 48: level=0 fsel=4 alt=0 func=SD0_CLK
GPIO 49: level=1 fsel=4 alt=0 func=SD0_CMD
GPIO 50: level=1 fsel=4 alt=0 func=SD0_DAT0
GPIO 51: level=1 fsel=4 alt=0 func=SD0_DAT1
GPIO 52: level=1 fsel=4 alt=0 func=SD0_DAT2
GPIO 53: level=1 fsel=4 alt=0 func=SD0_DAT3

vcdbg log messages

001328.415: brfs: File read: /mfs/sd/config.txt
001329.544: brfs: File read: 1914 bytes
001382.256: HDMI0:EDID error reading EDID block 0 attempt 0
001383.522: HDMI0:EDID error reading EDID block 0 attempt 1
001384.788: HDMI0:EDID error reading EDID block 0 attempt 2
001386.052: HDMI0:EDID error reading EDID block 0 attempt 3
001387.318: HDMI0:EDID error reading EDID block 0 attempt 4
001388.583: HDMI0:EDID error reading EDID block 0 attempt 5
001389.849: HDMI0:EDID error reading EDID block 0 attempt 6
001391.113: HDMI0:EDID error reading EDID block 0 attempt 7
001392.379: HDMI0:EDID error reading EDID block 0 attempt 8
001393.644: HDMI0:EDID error reading EDID block 0 attempt 9
001394.668: HDMI0:EDID giving up on reading EDID block 0
001397.253: brfs: File read: /mfs/sd/config.txt
001398.284: gpioman: gpioman_get_pin_num: pin LEDS_PWR_OK not defined
001418.036: brfs: File read: 1914 bytes
001609.125: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
001610.454: gpioman: gpioman_get_pin_num: pin LEDS_PWR_OK not defined
001610.518: *** Restart logging
001611.697: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
001612.968: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
001614.236: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
001615.505: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
001616.772: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
001618.041: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
001619.309: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
001620.579: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
001621.846: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
001623.115: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
001624.141: hdmi: HDMI0:EDID giving up on reading EDID block 0
001624.475: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
001625.745: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
001627.013: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
001628.283: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
001629.550: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
001630.820: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
001632.088: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
001633.358: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
001634.625: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
001635.895: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
001636.921: hdmi: HDMI0:EDID giving up on reading EDID block 0
001637.222: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
001637.245: HDMI0: hdmi_pixel_encoding: 162000000
001637.492: vec: vec_middleware_power_on: vec_base: 0x7e806000 rev-id 0x00002708 @ vec: 0x7e806100 @ 0x00000420 enc: 0x7e806060 @ 0x00000220 cgmsae: 0x7e80605c @ 0x00000000
001643.017: dtb_file 'bcm2710-rpi-3-b.dtb'
001647.471: brfs: File read: /mfs/sd/bcm2710-rpi-3-b.dtb
001647.495: Loading 'bcm2710-rpi-3-b.dtb' to 0x100 size 0x6e14
001660.891: brfs: File read: 28180 bytes
001672.386: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
001738.020: brfs: File read: 1523 bytes
001741.221: brfs: File read: /mfs/sd/config.txt
001741.832: dtparam: audio=on
001752.787: brfs: File read: 1914 bytes
001765.818: brfs: File read: /mfs/sd/overlays/w1-gpio.dtbo
001771.595: Loaded overlay 'w1-gpio'
001771.612: dtparam: gpiopin=5
001772.919: dtparam: pullup=0
001801.026: brfs: File read: 1036 bytes
001802.717: brfs: File read: /mfs/sd/cmdline.txt
001802.771: Read command line from file 'cmdline.txt':
001802.791: 'console=tty1 root=PARTUUID=5afeb470-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait quiet splash plymouth.ignore-serial-consoles'
001818.911: gpioman: gpioman_get_pin_num: pin EMMC_ENABLE not defined
003397.208: brfs: File read: 143 bytes
003829.806: brfs: File read: /mfs/sd/kernel7.img
003829.830: Loading 'kernel7.img' to 0x8000 size 0x6034a8
003829.862: Device tree loaded to 0x2eff8c00 (size 0x734c)
003832.159: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
007396.112: vchiq_core: vchiq_init_state: slot_zero = 0xf7580000, is_master = 1

dmesg log

[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 5.10.11-v7+ (dom@buildbot) (arm-linux-gnueabihf-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1399 SMP Thu Jan 28 12:06:05 GMT 2021
[ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[ 0.000000] CPU: div instructions available: patching division code
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] Reserved memory: created CMA memory pool at 0x37400000, size 64 MiB
[ 0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[ 0.000000] Zone ranges:
[ 0.000000] DMA [mem 0x0000000000000000-0x000000003b3fffff]
[ 0.000000] Normal empty
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000000000000-0x000000003b3fffff]
[ 0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x000000003b3fffff]
[ 0.000000] On node 0 totalpages: 242688
[ 0.000000] DMA zone: 2133 pages used for memmap
[ 0.000000] DMA zone: 0 pages reserved
[ 0.000000] DMA zone: 242688 pages, LIFO batch:63
[ 0.000000] percpu: Embedded 20 pages/cpu s50636 r8192 d23092 u81920
[ 0.000000] pcpu-alloc: s50636 r8192 d23092 u81920 alloc=20*4096
[ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 240555
[ 0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 console=tty1 root=PARTUUID=5afeb470-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait quiet splash plymouth.ignore-serial-consoles
[ 0.000000] Kernel parameter elevator= does not have any effect anymore.
Please use sysfs to set IO scheduler for individual devices.
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[ 0.000000] Memory: 879832K/970752K available (9216K kernel code, 1311K rwdata, 2936K rodata, 1024K init, 860K bss, 25384K reserved, 65536K cma-reserved)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] ftrace: allocating 31819 entries in 63 pages
[ 0.000000] ftrace: allocated 63 pages with 6 groups
[ 0.000000] rcu: Hierarchical RCU implementation.
[ 0.000000] Rude variant of Tasks RCU enabled.
[ 0.000000] Tracing variant of Tasks RCU enabled.
[ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[ 0.000000] random: get_random_bytes called from start_kernel+0x3ac/0x580 with crng_init=0
[ 0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[ 0.000008] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[ 0.000021] Switching to timer-based delay loop, resolution 52ns
[ 0.000306] Console: colour dummy device 80x30
[ 0.000379] printk: console [tty1] enabled
[ 0.000437] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[ 0.000466] pid_max: default: 32768 minimum: 301
[ 0.000677] LSM: Security Framework initializing
[ 0.000918] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[ 0.000942] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[ 0.002530] Disabling memory control group subsystem
[ 0.002648] CPU: Testing write buffer coherency: ok
[ 0.003146] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.004388] Setting up static identity map for 0x100000 - 0x10003c
[ 0.004573] rcu: Hierarchical SRCU implementation.
[ 0.005493] smp: Bringing up secondary CPUs ...
[ 0.006658] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.007945] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[ 0.009161] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[ 0.009319] smp: Brought up 1 node, 4 CPUs
[ 0.009342] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[ 0.009354] CPU: All CPU(s) started in HYP mode.
[ 0.009365] CPU: Virtualization extensions available.
[ 0.010468] devtmpfs: initialized
[ 0.028308] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[ 0.028562] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.028592] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[ 0.031833] pinctrl core: initialized pinctrl subsystem
[ 0.033003] NET: Registered protocol family 16
[ 0.037392] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[ 0.043095] audit: initializing netlink subsys (disabled)
[ 0.043414] audit: type=2000 audit(0.040:1): state=initialized audit_enabled=0 res=1
[ 0.043997] thermal_sys: Registered thermal governor 'step_wise'
[ 0.045107] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.045123] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.045401] Serial: AMBA PL011 UART driver
[ 0.064401] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[ 0.080125] raspberrypi-firmware soc:firmware: Attached to firmware from 2021-01-27T22:26:53, variant start
[ 0.090134] raspberrypi-firmware soc:firmware: Firmware hash is 99d9a48302e4553cff3688692bb7e9ac760a03fa
[ 0.139488] bcm2835-dma 3f007000.dma: DMA legacy API manager, dmachans=0x1
[ 0.142008] SCSI subsystem initialized
[ 0.142270] usbcore: registered new interface driver usbfs
[ 0.142336] usbcore: registered new interface driver hub
[ 0.142406] usbcore: registered new device driver usb
[ 0.144520] clocksource: Switched to clocksource arch_sys_counter
[ 1.870649] VFS: Disk quotas dquot_6.6.0
[ 1.870764] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 1.870969] FS-Cache: Loaded
[ 1.871250] CacheFiles: Loaded
[ 1.881991] NET: Registered protocol family 2
[ 1.883101] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[ 1.883247] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[ 1.883366] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[ 1.883559] TCP: Hash tables configured (established 8192 bind 8192)
[ 1.883735] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[ 1.883792] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[ 1.884120] NET: Registered protocol family 1
[ 1.885001] RPC: Registered named UNIX socket transport module.
[ 1.885015] RPC: Registered udp transport module.
[ 1.885027] RPC: Registered tcp transport module.
[ 1.885039] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 1.886851] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[ 1.890546] Initialise system trusted keyrings
[ 1.890841] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[ 1.900386] zbud: loaded
[ 1.902458] FS-Cache: Netfs 'nfs' registered for caching
[ 1.903304] NFS: Registering the id_resolver key type
[ 1.903359] Key type id_resolver registered
[ 1.903372] Key type id_legacy registered
[ 1.903537] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[ 1.904809] Key type asymmetric registered
[ 1.904824] Asymmetric key parser 'x509' registered
[ 1.904878] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[ 1.904893] io scheduler mq-deadline registered
[ 1.904906] io scheduler kyber registered
[ 1.909813] bcm2708_fb soc:fb: FB found 1 display(s)
[ 1.916557] Console: switching to colour frame buffer device 82x26
[ 1.921441] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
[ 1.925334] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[ 1.926091] bcm2835-aux-uart 3f215040.serial: there is not valid maps for state default
[ 1.927870] bcm2835-rng 3f104000.rng: hwrng registered
[ 1.928335] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[ 1.929148] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[ 1.942200] brd: module loaded
[ 1.954277] loop: module loaded
[ 1.955947] Loading iSCSI transport class v2.0-870.
[ 1.957568] libphy: Fixed MDIO Bus: probed
[ 1.957891] usbcore: registered new interface driver lan78xx
[ 1.957958] usbcore: registered new interface driver smsc95xx
[ 1.957984] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 2.686252] Core Release: 2.80a
[ 2.686269] Setting default values for core params
[ 2.686302] Finished setting default values for core params
[ 2.886686] Using Buffer DMA mode
[ 2.886700] Periodic Transfer Interrupt Enhancement - disabled
[ 2.886712] Multiprocessor Interrupt Enhancement - disabled
[ 2.886726] OTG VER PARAM: 0, OTG VER FLAG: 0
[ 2.886753] Dedicated Tx FIFOs mode

[ 2.887322] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = b7504000 dma = 0xf7504000 len=9024
[ 2.887355] FIQ FSM acceleration enabled for :
Non-periodic Split Transactions
Periodic Split Transactions
High-Speed Isochronous Endpoints
Interrupt/Control Split Transaction hack enabled
[ 2.887370] dwc_otg: Microframe scheduler enabled

[ 2.887439] WARN::hcd_init_fiq:457: FIQ on core 1

[ 2.887455] WARN::hcd_init_fiq:458: FIQ ASM at 807bae50 length 36

[ 2.887472] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
[ 2.887495] dwc_otg 3f980000.usb: DWC OTG Controller
[ 2.887533] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[ 2.887584] dwc_otg 3f980000.usb: irq 89, io mem 0x00000000
[ 2.887640] Init: Port Power? op_state=1
[ 2.887652] Init: Power Port (0)
[ 2.888030] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.10
[ 2.888048] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 2.888064] usb usb1: Product: DWC OTG Controller
[ 2.888079] usb usb1: Manufacturer: Linux 5.10.11-v7+ dwc_otg_hcd
[ 2.888093] usb usb1: SerialNumber: 3f980000.usb
[ 2.888840] hub 1-0:1.0: USB hub found
[ 2.888909] hub 1-0:1.0: 1 port detected
[ 2.890000] dwc_otg: FIQ enabled
[ 2.890013] dwc_otg: NAK holdoff enabled
[ 2.890025] dwc_otg: FIQ split-transaction FSM enabled
[ 2.890042] Module dwc_common_port init
[ 2.890368] usbcore: registered new interface driver usb-storage
[ 2.890571] mousedev: PS/2 mouse device common for all mice
[ 2.891788] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[ 2.894480] sdhci: Secure Digital Host Controller Interface driver
[ 2.894556] sdhci: Copyright(c) Pierre Ossman
[ 2.895185] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
[ 2.895894] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[ 2.896131] sdhci-pltfm: SDHCI platform and OF driver helper
[ 2.897975] ledtrig-cpu: registered to indicate activity on CPUs
[ 2.898391] hid: raw HID events driver (C) Jiri Kosina
[ 2.898552] usbcore: registered new interface driver usbhid
[ 2.898564] usbhid: USB HID core driver
[ 2.903616] Initializing XFRM netlink socket
[ 2.903665] NET: Registered protocol family 17
[ 2.903815] Key type dns_resolver registered
[ 2.904724] Registering SWP/SWPB emulation handler
[ 2.904905] registered taskstats version 1
[ 2.904937] Loading compiled-in X.509 certificates
[ 2.905770] Key type ._fscrypt registered
[ 2.905784] Key type .fscrypt registered
[ 2.905797] Key type fscrypt-provisioning registered
[ 2.917096] uart-pl011 3f201000.serial: cts_event_workaround enabled
[ 2.917213] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 114, base_baud = 0) is a PL011 rev2
[ 2.919440] bcm2835-aux-uart 3f215040.serial: there is not valid maps for state default
[ 2.920204] 3f215040.serial: ttyS0 at MMIO 0x3f215040 (irq = 86, base_baud = 31250000) is a 16550
[ 2.921171] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[ 2.922836] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
[ 2.922852] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
[ 2.948781] sdhost: log_buf @ (ptrval) (f7507000)
[ 2.985704] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 2.987335] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 2.988965] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 2.991885] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 2.998128] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 3.001090] of_cfs_init
[ 3.001392] of_cfs_init: OK
[ 3.002554] Waiting for root device PARTUUID=5afeb470-02...
[ 3.057235] random: fast init done
[ 3.086303] mmc0: host does not support reading read-only switch, assuming write-enable
[ 3.091254] mmc0: new high speed SDHC card at address aaaa
[ 3.092373] mmcblk0: mmc0:aaaa SL08G 7.40 GiB
[ 3.095287] mmcblk0: p1 p2
[ 3.104767] Indeed it is in host mode hprt0 = 00021501
[ 3.127670] EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
[ 3.127687] EXT4-fs (mmcblk0p2): write access will be enabled during recovery
[ 3.171366] mmc1: new high speed SDIO card at address 0001
[ 3.314567] usb 1-1: new high-speed USB device number 2 using dwc_otg
[ 3.314732] Indeed it is in host mode hprt0 = 00001101
[ 3.554884] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00
[ 3.554905] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 3.555747] hub 1-1:1.0: USB hub found
[ 3.555866] hub 1-1:1.0: 5 ports detected
[ 3.874565] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[ 4.005011] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
[ 4.005037] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 4.007955] smsc95xx v2.0.0
[ 4.070694] libphy: smsc95xx-mdiobus: probed
[ 4.071744] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, m.m.m.m
[ 4.182992] EXT4-fs (mmcblk0p2): recovery complete
[ 4.191115] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 4.191209] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[ 4.192148] devtmpfs: mounted
[ 4.199079] Freeing unused kernel memory: 1024K
[ 4.199542] Run /sbin/init as init process
[ 4.199554] with arguments:
[ 4.199565] /sbin/init
[ 4.199576] splash
[ 4.199587] with environment:
[ 4.199598] HOME=/
[ 4.199609] TERM=linux
[ 4.822481] systemd[1]: System time before build time, advancing clock.
[ 4.972757] NET: Registered protocol family 10
[ 4.974416] Segment Routing with IPv6
[ 5.043706] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[ 5.044767] systemd[1]: Detected architecture arm.
[ 5.132103] systemd[1]: Set hostname to .
[ 6.223326] random: systemd: uninitialized urandom read (16 bytes read)
[ 6.239207] random: systemd: uninitialized urandom read (16 bytes read)
[ 6.240247] systemd[1]: Listening on fsck to fsckd communication Socket.
[ 6.240603] random: systemd: uninitialized urandom read (16 bytes read)
[ 6.241237] systemd[1]: Listening on Syslog Socket.
[ 6.244754] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[ 6.245039] systemd[1]: Reached target Swap.
[ 6.246397] systemd[1]: Created slice system-getty.slice.
[ 6.246829] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 6.255292] systemd[1]: Listening on Journal Audit Socket.
[ 6.381234] i2c /dev entries driver
[ 6.929168] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 7.692264] Driver for 1-wire Dallas network protocol.
[ 7.695759] gpio-5 (onewire@5): enforced open drain please flag it properly in DT/ACPI DSDT/board file
[ 7.723627] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[ 7.726686] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[ 7.726715] [vc_sm_connected_init]: start
[ 7.727620] [vc_sm_connected_init]: installed successfully
[ 7.734071] mc: Linux media interface: v0.10
[ 7.790896] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[ 7.792007] videodev: Linux video capture interface: v2.00
[ 7.796897] bcm2835_audio bcm2835_audio: card created with 8 channels
[ 7.831931] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[ 7.850524] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[ 7.899592] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[ 7.921513] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[ 7.922854] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[ 7.923348] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[ 7.923799] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[ 7.923844] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[ 7.923870] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[ 7.923891] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[ 7.923913] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[ 7.930120] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[ 7.936361] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[ 7.940731] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[ 7.940792] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[ 7.949401] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[ 7.949452] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[ 7.953489] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[ 7.953541] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[ 8.227921] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[ 8.361702] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[ 8.465103] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
[ 8.473436] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[ 8.473772] usbcore: registered new interface driver brcmfmac
[ 8.495952] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43430-sdio.raspberrypi,3-model-b.txt failed with error -2
[ 8.723981] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[ 8.724156] brcmfmac: brcmf_c_process_clm_blob: no clm_blob available (err=-2), device may have limited channels available
[ 8.725153] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/1 wl0: Oct 22 2019 01:59:28 version 7.45.98.94 (r723000 CY) FWID 01-3b33decd
[ 10.074717] Under-voltage detected! (0x00050000)
[ 10.443724] systemd[1]: Started File System Check on /dev/disk/by-partuuid/5afeb470-01.
[ 10.454400] systemd[1]: Mounting /boot...
[ 10.538893] systemd[1]: Mounted /boot.
[ 10.542463] systemd[1]: Reached target Local File Systems.
[ 10.548401] systemd[1]: Starting Set console font and keymap...
[ 10.555435] systemd[1]: Starting Raise network interfaces...
[ 10.562502] systemd[1]: Starting Preprocess NFS configuration...
[ 10.570388] systemd[1]: Starting Log2Ram...
[ 10.577596] systemd[1]: Starting Tell Plymouth To Write Out Runtime Data...
[ 10.578365] systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.
[ 12.154750] Voltage normalised (0x00000000)
[ 13.718644] systemd-journald[362]: Received request to flush runtime journal from PID 1
[ 14.814329] uart-pl011 3f201000.serial: no DMA platform data
[ 14.887609] random: crng init done
[ 14.887639] random: 7 urandom warning(s) missed due to ratelimiting
[ 15.132905] 8021q: 802.1Q VLAN Support v1.8
[ 15.748742] Adding 102396k swap on /var/swap. Priority:-2 extents:1 across:102396k SSFS
[ 16.007613] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[ 16.314729] Under-voltage detected! (0x00050005)
[ 16.747585] SMSC LAN8700 usb-001:003:01: attached PHY driver [SMSC LAN8700] (mii_bus:phy_addr=usb-001:003:01, irq=POLL)
[ 16.748130] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 16.769074] smsc95xx 1-1.1:1.0 eth0: Link is Down
[ 19.306266] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 19.432069] Bluetooth: Core ver 2.22
[ 19.432223] NET: Registered protocol family 31
[ 19.432236] Bluetooth: HCI device and connection manager initialized
[ 19.432272] Bluetooth: HCI socket layer initialized
[ 19.432296] Bluetooth: L2CAP socket layer initialized
[ 19.432333] Bluetooth: SCO socket layer initialized
[ 19.445947] Bluetooth: HCI UART driver ver 2.3
[ 19.445975] Bluetooth: HCI UART protocol H4 registered
[ 19.446132] Bluetooth: HCI UART protocol Three-wire (H5) registered
[ 19.446431] Bluetooth: HCI UART protocol Broadcom registered
[ 20.060308] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[ 20.060335] Bluetooth: BNEP filters: protocol multicast
[ 20.060372] Bluetooth: BNEP socket layer initialized
[ 22.700288] fuse: init (API version 7.32)
[ 24.534877] Bluetooth: RFCOMM TTY layer initialized
[ 24.534931] Bluetooth: RFCOMM socket layer initialized
[ 24.534996] Bluetooth: RFCOMM ver 1.11
[ 35.034706] Voltage normalised (0x00000000)
[ 47.514784] Under-voltage detected! (0x00050005)
[ 53.754674] Voltage normalised (0x00000000)
[ 106.169615] w1_master_driver w1_bus_master1: Attaching one wire slave 20.010000000000 crc b1
[ 106.184274] w1_master_driver w1_bus_master1: Family 20 for 20.010000000000.b1 is not registered.
pi@RedPi:~ $

Additional context

I have a simple ("rfm2pi") device mounted on the first 2x5 GPIO pins that periodically transmits a data frame out to the primary UART at a baud of 38400.

Appologies if this is a planned change and just a (delayed) documentation issue.

Having now seen issue raspberrypi/documentation#1614 I will (when I get a chance) try this again from scratch as, perhaps coincidentally, this particular sd card image was initially booted on a RPI 4 before being moved to a RPI 3, but that could well be of no consequence, but I will try to eliminate/confirm that if anyone thinks it may have impacted some config. I understood raspiOS images to be interchangable across models, but with the new (to me) revelation of an alternative fixed 500MHz core_freq on a Pi 4, I wonder . .

Thanks in advance.

[pelwell]

Your expectation is correct - if the mini-UART (UART1) is enabled in Device Tree, e.g. with enable_uart=1 then the core clock should be at a fixed frequency in order to guarantee a stable baud rate.

Aside from a regression in clock management (not demonstrated, but not ruled out), another possibility is that the CPU frequency is being capped due to over-temperature or under-voltage. Can you try the following?:

1. Report the output of vcgencnd get_throttled after the corruption has been seen.
2. Run vcgencmd measure_clock core repeatedly (with sleeps if in a loop) when the Pi is busy (while true; do true; done & should be enough) and when idle, and report your observations.

[pelwell]

Looking back at the email notification which included your kernel log I see:

[ 47.514784] Under-voltage detected! (0x00050005)

Perhaps this is a factor in the problem.

[pb66]

Thanks for the speedy reply. I will try these tests later and report back.

A little more info on this application, this Pi is monitoring a few things and never breaks a sweat, it just ticks over 24/7 with a pretty steady load, the only real exception to that is when i ssh in for a bit of tinkering, updating the os or pull in some changes from Github. It doesn't even have a server or database, it just forwards data elsewhere.

I won't entirely rule out PSU (undervoltage) but I do prefer higher quality over sized PSU's although i haven't tested this particular PSU recently, however, the "rfm2pi" board I have on the GPIO has an rfm module on it and these rfm2pi's are known to have issues with the rfm module browning out at the slightest wisp of a low voltage and that's powered from the 3v GPIO, it only receives not transmits so the load it presents on the RPi is pretty negligible and also constant. I have to say I see the under voltage warnings occur on even the most stable of setups, but that doesn't mean they can be ignored of course, I just wasn't surprised or alarmed by their presence. With the rfm module happily working throughout I am pretty confident the supply is fine, but will of course investigate and confirm.

Report the output of vcgencnd get_throttled after the corruption has been seen.

This is a permanent state, it doesn't come and go, the serial is garbage until I set the core_freq and reboot, likewise it works perfectly until I remove that setting again.

when the Pi is busy

It's never busy, are you asking me to artificially load it up for a test or for the test to be done at it's busiest (ie anytime) ?

[pb66]

Ok so I've done some remote tests, I will have to wait til I'm there to do the PSU and alternative sd image tests, maybe this evening or tomorrow.

Firstly, I have to declare I was wrong about the loading, one of the things monitored was offline causing the script to retry and increase the load significantly. I was made aware of this by the fact the clock core is actually increasing to 400MHz rather than being throttled when I remove core_freq=250 and reboot.

Just a few seconds without core_freq=250

pi@RedPi:~ $ while true; do echo $(vcgencmd measure_clock core); sleep 1; done
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=400000000
frequency(1)=400000000
frequency(1)=400000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=400000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=400000000
frequency(1)=400000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=400000000
frequency(1)=400000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=400000000
frequency(1)=400000000
frequency(1)=400000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=399999000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=399999000

that led me to check top to see why it was increasing and found a service hogging all the cpu, due to the endpoint being offline, So whilst this may change the info I've given, I still would expect that core_freq to be fixed at 250MHz due to the enable_uart=1 and I suspect the under-voltage to be less of a concern if it is not throttling, but i will still do some checks as I have confirmed that vcgencnd get_throttled reports 0x5000 immediately after booting, so I will recheck once I check the voltages manually, swap out the PSU and sort/stop the over working service. I also notice the wifi is alittle sketchy today which maybe adding some load perhaps.

With core_freq=250 the same test output is static at frequency(1)=250000000.

[pelwell]

It would be good to confirm which firmware is running - vcgencmd version. One of the not-so-recent changes had the effect of changing the "locked" frequency to the upper limit (cpu_freq) rather than the lower limit (cpu_freq_min). This is good for performance, but does mean that throttling will change the frequency.

[pb66]

pi@RedPi:~ $ vcgencmd version
Jan 27 2021 22:26:53
Copyright (c) 2012 Broadcom
version 99d9a48302e4553cff3688692bb7e9ac760a03fa (clean) (release) (start)

but does mean that throttling will change the frequency.

Surely throttling would mean a downward change? If "fixed" at 250MHz and then gets overruled by throttling that would be lower than 250MHz rather than 400MHz, no? Or are you saying the incorrect "locked freq" from enable_uart=1 when NOT using core_freq=250 is 400MHz and that is then being throttled TO 250MHz?

[pb66]

Just a brief note to say I stopped the service hogging the cpu and rechecked the core freq and with just enable_uart=1 (not core_freq=250) it's a steady(ish) 250MHz

pi@RedPi:~ $ while true; do echo $(vcgencmd measure_clock core); sleep 1; done
frequency(1)=250000000
frequency(1)=249999000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000
frequency(1)=250000000

and the serial comms via the Mini UART seem stable.

So I can no longer be sure this is definitely a new bug as it would appear to have only surfaced due to the abnormally high load put on the cpu by the demanding service.

I have noticed that even in this low load test there are a fair few frequency(1)=249999000 appearances that do not ever seem to appear when core_freq=250 is set, in practice I know this will not bee an issue but it does suggest, even under light loading, the core freq isn't being fixed by enable_uart=1. Typical! Just spotted one.

I will hopefully get to do the physical checks later today.

[pelwell]

Having had a chance to test this I find it to be behaving as I would expect, which is:

1. With only enable_uart=1 in config.txt (no UART-related overlays, no core_freq or core_freq_min settings), which on a Pi 3 implies that ttyS0/UART1 is the primary/console UART, the core frequency at idle is 400MHz. This is because the firmware has detected that UART1 is required and locked the core frequency.
2. The old behaviour was to lock the core to the minimum frequency (core_freq_min), but that is a bit limiting on some systems so for the last year or so it has locked to the maximum (core_freq) instead.
3. The small variation in frequency seen with vcgencmd measure_clock core (e.g. between 250000000 and 249999000) is just a sampling artifact. measure_clock does exactly that, attaching a counter to the specified clock, running it for 1 millisecond and multiplying the result by 1000; changes in the answer of +/-1000 depending on the phase of the chosen clock and the precise time of the count are to be expected.

The change from min to max frequency locking has performance advantages, but with a few potential drawbacks:

• It will use slightly more power, even though for the same compute load the VPUs should spend more time idle.
• In the event of throttling the core will drop back to the minimum, at which point your baud rate changes.

Although I consider throttling to be an error condition - the Pi should have more power or better cooling - and that some data loss is acceptable, it would be better if the UART clock divisor could be adjusted to allow some control.

Having said that, the question in your case is why the frequency is hovering at 250MHz rather than 400MHz. What do the following commands return:

$ grep . /sys/devices/system/cpu/cpufreq/policy0/*
$ grep -v -E "^(#.*)?$" /boot/config.txt
$ vcgencmd measure_temp
$ vcgencmd measure_volts
$ dmesg | grep throttle