Edit:
Unnecessary snark aside, I found that there was a commit referencing this exact issue in the kernel two days ago.
As of now I'm compiling from source, and while I had it available, I also disabled the following settings in the kernel menuconfig:
-> Device Drivers -> Character Devices -> TTY_PRINTK
(TTY driver to output user messages via printk)
and
-> Kernel hacking -> Early printk
(Write kernel log output directly into the VGA buffer or serial port.)
I'll update when finished building and tested.
================================================
Original:
I'm working with a compute module 3, in an embedded system with the official 7 inch display. Latest raspbian, all updates.
I have tried relentlessly to get this error to quit appearing. I had a completely silent boot, with only my (plymouth) splash image displaying, and then my UI starting up (a fullscreen Qt app started directly with startx). It works great, and my UI is up and usable ~9 seconds after powerup.
Then I moved the console to the mini uart, as I needed the beefier PL011 for an RS485 driver, but still wanted debugging access. Afterwards this little guy started popping up on both my display, and the serial console:
[ 0.178940] bcm2835-aux-uart 3f215040.serial: could not get clk: -517
What's bugging me is that I have loglevel set to zero, so this should never display. The mini uart console works fine, it just looks really unprofessional with an error on bootup.
It looks like it's something to due with the clock on it? (As I'm pretty sure the mini uart is the auxiliary.) I know that's dependent on the VPU core frequency, but I thought force_turbo=1 kept that stable.
I would greatly appreciate any ideas/suggestions.
/boot/cmdline.txt
dwc_otg.lpm_enable=0 console=serial1,115200 console=tty1 loglevel=0 vt.global_cursor_default=0 root=PARTUUID=60d03c1a-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait consoleblank=0 quiet splash logo.nologo plymouth.ignore-serial-consoles fastboot noswap
/boot/config.txt
[... defaults above ...]
# Screen Settings
disable_splash=1
display_rotate=1
force_turbo=1
# Overlays
dtoverlay=enc28j60
dtoverlay=spi1-3cs
dtoverlay=uart0,txd0_pin=36,rxd0_pin=37
dtoverlay=uart1,txd1_pin=32,rxd1_pin=33
dmesg
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 4.9.76-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611) ) #1076 SMP Wed Jan 10 17:34:49 GMT 2018
[ 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 Compute Module 3 Rev 1.0
[ 0.000000] cma: Reserved 8 MiB at 0x3ac00000
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] On node 0 totalpages: 242688
[ 0.000000] free_area_init_node: node 0, pgdat 80c6f440, node_mem_map ba3a1000
[ 0.000000] Normal zone: 2133 pages used for memmap
[ 0.000000] Normal zone: 0 pages reserved
[ 0.000000] Normal zone: 242688 pages, LIFO batch:31
[ 0.000000] percpu: Embedded 14 pages/cpu @ba35a000 s25600 r8192 d23552 u57344
[ 0.000000] pcpu-alloc: s25600 r8192 d23552 u57344 alloc=14*4096
[ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 240555
[ 0.000000] Kernel command line: 8250.nr_uarts=1 bcm2708_fb.fbwidth=480 bcm2708_fb.fbheight=800 bcm2708_fb.fbswap=1 smsc95xx.macaddr=B8:27:EB:03:6B:BD vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 loglevel=0 vt.global_cursor_default=0 root=PARTUUID=60d03c1a-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait consoleblank=0 quiet splash logo.nologo plymouth.ignore-serial-consoles fastboot noswap
[ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Memory: 940360K/970752K available (7168K kernel code, 486K rwdata, 2012K rodata, 1024K init, 770K bss, 22200K reserved, 8192K cma-reserved)
[ 0.000000] Virtual kernel memory layout:
vector : 0xffff0000 - 0xffff1000 ( 4 kB)
fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
vmalloc : 0xbb800000 - 0xff800000 (1088 MB)
lowmem : 0x80000000 - 0xbb400000 ( 948 MB)
modules : 0x7f000000 - 0x80000000 ( 16 MB)
.text : 0x80008000 - 0x80800000 (8160 kB)
.init : 0x80b00000 - 0x80c00000 (1024 kB)
.data : 0x80c00000 - 0x80c798fc ( 487 kB)
.bss : 0x80c7b000 - 0x80d3b9a4 ( 771 kB)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] Build-time adjustment of leaf fanout to 32.
[ 0.000000] NR_IRQS:16 nr_irqs:16 16
[ 0.000000] arm_arch_timer: Architected 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.000003] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[ 0.000010] Switching to timer-based delay loop, resolution 52ns
[ 0.000155] Console: colour dummy device 80x30
[ 0.000166] console [tty1] enabled
[ 0.000180] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[ 0.000188] pid_max: default: 32768 minimum: 301
[ 0.000351] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.000357] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.000924] Disabling memory control group subsystem
[ 0.000964] CPU: Testing write buffer coherency: ok
[ 0.000985] ftrace: allocating 22402 entries in 66 pages
[ 0.025284] CPU0: update cpu_capacity 1024
[ 0.025294] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.025319] Setting up static identity map for 0x100000 - 0x100034
[ 0.026354] CPU1: update cpu_capacity 1024
[ 0.026358] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.026714] CPU2: update cpu_capacity 1024
[ 0.026717] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[ 0.027055] CPU3: update cpu_capacity 1024
[ 0.027058] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[ 0.027103] Brought up 4 CPUs
[ 0.027109] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[ 0.027111] CPU: All CPU(s) started in HYP mode.
[ 0.027113] CPU: Virtualization extensions available.
[ 0.027580] devtmpfs: initialized
[ 0.033646] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[ 0.033796] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.033806] futex hash table entries: 1024 (order: 4, 65536 bytes)
[ 0.034109] pinctrl core: initialized pinctrl subsystem
[ 0.034610] NET: Registered protocol family 16
[ 0.036001] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[ 0.040602] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.040606] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.040693] Serial: AMBA PL011 UART driver
[ 0.041796] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[ 0.042343] irq: no irq domain found for /soc/aux@0x7e215000 !
[ 0.042452] irq: no irq domain found for /soc/aux@0x7e215000 !
[ 0.095679] bcm2835-dma 3f007000.dma: DMA legacy API manager at bb80f000, dmachans=0x1
[ 0.096634] SCSI subsystem initialized
[ 0.096714] usbcore: registered new interface driver usbfs
[ 0.096753] usbcore: registered new interface driver hub
[ 0.096799] usbcore: registered new device driver usb
[ 0.105092] raspberrypi-firmware soc:firmware: Attached to firmware from 2018-01-11 19:20
[ 0.105944] clocksource: Switched to clocksource arch_sys_counter
[ 0.130350] VFS: Disk quotas dquot_6.6.0
[ 0.130394] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.130505] FS-Cache: Loaded
[ 0.130653] CacheFiles: Loaded
[ 0.136829] NET: Registered protocol family 2
[ 0.137322] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.137377] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.137469] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.137523] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.137544] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.137653] NET: Registered protocol family 1
[ 0.137886] RPC: Registered named UNIX socket transport module.
[ 0.137889] RPC: Registered udp transport module.
[ 0.137891] RPC: Registered tcp transport module.
[ 0.137893] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.138563] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[ 0.139765] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[ 0.147882] FS-Cache: Netfs 'nfs' registered for caching
[ 0.148387] NFS: Registering the id_resolver key type
[ 0.148408] Key type id_resolver registered
[ 0.148410] Key type id_legacy registered
[ 0.149623] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[ 0.149680] io scheduler noop registered
[ 0.149683] io scheduler deadline registered (default)
[ 0.149818] io scheduler cfq registered
[ 0.152822] BCM2708FB: allocated DMA memory fad10000
[ 0.152835] BCM2708FB: allocated DMA channel 0 @ bb80f000
[ 0.164597] Console: switching to colour frame buffer device 60x50
[ 0.169919] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[ 0.170868] bcm2835-aux-uart 3f215040.serial: could not get clk: -517
[ 0.171513] bcm2835-rng 3f104000.rng: hwrng registered
[ 0.171575] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[ 0.171842] vc-sm: Videocore shared memory driver
[ 0.179664] brd: module loaded
[ 0.184215] loop: module loaded
[ 0.184222] Loading iSCSI transport class v2.0-870.
[ 0.184510] usbcore: registered new interface driver smsc95xx
[ 0.184519] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 0.412336] Core Release: 2.80a
[ 0.412341] Setting default values for core params
[ 0.412360] Finished setting default values for core params
[ 0.612576] Using Buffer DMA mode
[ 0.612579] Periodic Transfer Interrupt Enhancement - disabled
[ 0.612581] Multiprocessor Interrupt Enhancement - disabled
[ 0.612584] OTG VER PARAM: 0, OTG VER FLAG: 0
[ 0.612594] Dedicated Tx FIFOs mode
[ 0.612788] WARN::dwc_otg_hcd_init:1032: FIQ DMA bounce buffers: virt = 0xbad04000 dma = 0xfad04000 len=9024
[ 0.612802] FIQ FSM acceleration enabled for :
Non-periodic Split Transactions
Periodic Split Transactions
High-Speed Isochronous Endpoints
Interrupt/Control Split Transaction hack enabled
[ 0.612805] dwc_otg: Microframe scheduler enabled
[ 0.612830] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x80590ad0
[ 0.612835] WARN::hcd_init_fiq:460: FIQ ASM at 0x80590e40 length 36
[ 0.612841] WARN::hcd_init_fiq:486: MPHI regs_base at 0xbb87a000
[ 0.612873] dwc_otg 3f980000.usb: DWC OTG Controller
[ 0.612892] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[ 0.612909] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[ 0.612945] Init: Port Power? op_state=1
[ 0.612948] Init: Power Port (0)
[ 0.613057] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 0.613062] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.613067] usb usb1: Product: DWC OTG Controller
[ 0.613071] usb usb1: Manufacturer: Linux 4.9.76-v7+ dwc_otg_hcd
[ 0.613074] usb usb1: SerialNumber: 3f980000.usb
[ 0.613500] hub 1-0:1.0: USB hub found
[ 0.613521] hub 1-0:1.0: 1 port detected
[ 0.613855] dwc_otg: FIQ enabled
[ 0.613858] dwc_otg: NAK holdoff enabled
[ 0.613860] dwc_otg: FIQ split-transaction FSM enabled
[ 0.613867] Module dwc_common_port init
[ 0.613984] usbcore: registered new interface driver usb-storage
[ 0.614094] mousedev: PS/2 mouse device common for all mice
[ 0.614617] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[ 0.614774] bcm2835-cpufreq: min=1200000 max=1200000
[ 0.614994] sdhci: Secure Digital Host Controller Interface driver
[ 0.614996] sdhci: Copyright(c) Pierre Ossman
[ 0.616995] sdhost-bcm2835 3f202000.sdhost: could not get clk, deferring probe
[ 0.617107] sdhci-pltfm: SDHCI platform and OF driver helper
[ 0.617336] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.617388] hidraw: raw HID events driver (C) Jiri Kosina
[ 0.617491] usbcore: registered new interface driver usbhid
[ 0.617493] usbhid: USB HID core driver
[ 0.617931] vchiq: vchiq_init_state: slot_zero = 0xbad80000, is_master = 0
[ 0.618849] [vc_sm_connected_init]: start
[ 0.625680] [vc_sm_connected_init]: end - returning 0
[ 0.625889] Initializing XFRM netlink socket
[ 0.625902] NET: Registered protocol family 17
[ 0.626022] Key type dns_resolver registered
[ 0.626368] Registering SWP/SWPB emulation handler
[ 0.626769] registered taskstats version 1
[ 0.629842] uart-pl011 3f201000.serial: cts_event_workaround enabled
[ 0.629878] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[ 0.631380] console [ttyS0] disabled
[ 0.631396] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 220, base_baud = 50000000) is a 16550
[ 0.637967] console [ttyS0] enabled
[ 0.640226] sdhost: log_buf @ bad07000 (fad07000)
[ 0.715960] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 0.716008] of_cfs_init
[ 0.716057] of_cfs_init: OK
[ 0.716333] Waiting for root device PARTUUID=60d03c1a-02...
[ 0.907238] mmc0: new high speed MMC card at address 0001
[ 0.907617] mmcblk0: mmc0:0001 4FPD3R 3.64 GiB
[ 0.907754] mmcblk0boot0: mmc0:0001 4FPD3R partition 1 4.00 MiB
[ 0.907888] mmcblk0boot1: mmc0:0001 4FPD3R partition 2 4.00 MiB
[ 0.908025] mmcblk0rpmb: mmc0:0001 4FPD3R partition 3 512 KiB
[ 0.908947] mmcblk0: p1 p2
[ 0.964442] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 0.964473] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[ 0.971293] devtmpfs: mounted
[ 0.972267] Freeing unused kernel memory: 1024K
[ 1.351299] systemd[1]: System time before build time, advancing clock.
[ 1.366565] random: fast init done
[ 1.451748] NET: Registered protocol family 10
[ 1.459244] ip_tables: (C) 2000-2006 Netfilter Core Team
[ 1.475810] systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[ 1.476169] systemd[1]: Detected architecture arm.
[ 1.476854] systemd[1]: Set hostname to beta-001
[ 1.791590] systemd[1]: Listening on udev Kernel Socket.
[ 1.791802] systemd[1]: Reached target Swap.
[ 1.791936] systemd[1]: Listening on udev Control Socket.
[ 1.792053] systemd[1]: Listening on Syslog Socket.
[ 1.792199] systemd[1]: Listening on Journal Socket.
[ 1.792610] systemd[1]: Created slice System Slice.
[ 1.794199] systemd[1]: Mounting Debug File System...
[ 1.852542] i2c /dev entries driver
[ 2.090169] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 2.152165] systemd-journald[129]: Received request to flush runtime journal from PID 1
[ 2.289378] rpi-ft5406 rpi_ft5406: Probing device
[ 2.290636] input: FT5406 memory based driver as /devices/virtual/input/input0
[ 2.308560] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[ 2.688483] enc28j60 spi0.0: enc28j60 Ethernet driver 1.02 loaded
[ 2.691959] net eth0: enc28j60 driver registered
[ 3.149824] net eth0: link down
[ 3.149851] net eth0: multicast mode
[ 3.149980] net eth0: multicast mode
[ 3.149994] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 3.207240] net eth0: multicast mode
[ 3.251836] net eth0: multicast mode
[ 3.263467] net eth0: multicast mode
[ 3.263954] net eth0: multicast mode
[ 5.018815] net eth0: link up - Half duplex
[ 5.018947] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 5.026217] net eth0: multicast mode
[ 6.396181] net eth0: multicast mode
raspi-gpio get
GPIO 0: level=1 fsel=4 alt=0 func=SDA0
GPIO 1: level=1 fsel=4 alt=0 func=SCL0
GPIO 2: level=1 fsel=4 alt=0 func=SDA1
GPIO 3: level=1 fsel=4 alt=0 func=SCL1
GPIO 4: level=1 fsel=0 func=INPUT
GPIO 5: level=1 fsel=1 func=OUTPUT
GPIO 6: level=0 fsel=1 func=OUTPUT
GPIO 7: level=1 fsel=1 func=OUTPUT
GPIO 8: level=1 fsel=1 func=OUTPUT
GPIO 9: level=0 fsel=4 alt=0 func=SPI0_MISO
GPIO 10: level=0 fsel=4 alt=0 func=SPI0_MOSI
GPIO 11: level=0 fsel=4 alt=0 func=SPI0_SCLK
GPIO 12: level=0 fsel=0 func=INPUT
GPIO 13: level=0 fsel=0 func=INPUT
GPIO 14: level=1 fsel=4 alt=0 func=TXD0
GPIO 15: level=1 fsel=4 alt=0 func=RXD0
GPIO 16: level=0 fsel=1 func=OUTPUT
GPIO 17: level=0 fsel=0 func=INPUT
GPIO 18: level=1 fsel=1 func=OUTPUT
GPIO 19: level=0 fsel=3 alt=4 func=SPI1_MISO
GPIO 20: level=0 fsel=3 alt=4 func=SPI1_MOSI
GPIO 21: level=0 fsel=3 alt=4 func=SPI1_SCLK
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=1 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=0 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=2 alt=5 func=TXD1
GPIO 33: level=1 fsel=2 alt=5 func=RXD1
GPIO 34: level=1 fsel=0 func=INPUT
GPIO 35: level=1 fsel=0 func=INPUT
GPIO 36: level=1 fsel=0 func=INPUT
GPIO 37: level=0 fsel=0 func=INPUT
GPIO 38: level=0 fsel=0 func=INPUT
GPIO 39: level=0 fsel=0 func=INPUT
GPIO 40: level=0 fsel=0 func=INPUT
GPIO 41: level=0 fsel=0 func=INPUT
GPIO 42: level=0 fsel=0 func=INPUT
GPIO 43: level=0 fsel=0 func=INPUT
GPIO 44: level=0 fsel=0 func=INPUT
GPIO 45: level=0 fsel=0 func=INPUT
BANK2 (GPIO 46 to 53):
GPIO 46: level=1 fsel=0 func=INPUT
GPIO 47: level=1 fsel=0 func=INPUT
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