[Letux-kernel] jz4730-i2c - clocksource
H. Nikolaus Schaller
hns at goldelico.com
Sun Feb 28 19:16:16 CET 2021
> Am 28.02.2021 um 18:27 schrieb H. Nikolaus Schaller <hns at goldelico.com>:
>
> and here we are back to the clocksource issue. We know that the
> clocksource=jiffies works but only has a very coarse resolution while
> the ingenic-timer fails.
>
> So I am not sure if I can really fix the i2c before we have found
> the clocksource problem. This had been the idea to make i2c work and
> then POST and ask others for help for the ingenic-timer.
>
> But this dependency means we have to repair the timer first...
>
> Still I have no idea how to debug this. I think the register values
> are correct (we have checked multiple times), having 16 bits or 32
> bit OST1 makes no difference.
>
> So it can either be a timer readout problem (async read may return
> wrong bits while the timer change ripples through the counter) or
> similar. We had tried before but maybe not hard enough...
Here is a commented boot log:
NAND SPL
Starting U-Boot ...
U-Boot 1.1.6 (Jun 24 2008 - 18:57:34)
Board: Ingenic PMP Ver 1.x (CPU Speed 335 MHz)
DRAM: 64 MB
Flash: 0 kB
NAND:1024 MiB
*** Warning - bad CRC or NAND, using default environment
In: serial
Out: serial
Err: serial
Net: JZ ETHERNET
### main_loop: bootcmd="mmcinit;fatload mmc 0 0x80600000 uimage;bootm"
Hit any key to stop autoboot: 0
MMC card found
MMC card is ready
I'm sorry wo only surport fat16 and fat32
I'm sorry wo only surport fat16 and fat32
reading uimage
filesize: 234810, got: 234810
234810 bytes read
## Booting image at 80600000 ...
Image Name: intermediate-u-boot
Image Type: MIPS U-Boot Kernel Image (gzip compressed)
Data Size: 234746 Bytes = 229.2 kB
Load Address: 80100000
Entry Point: 80100000
Verifying Checksum ... OK
Uncompressing Kernel Image ... OK
Starting kernel ...
U-Boot 2021.01-rc2-00029-g3453b36750 (Dec 06 2020 - 12:30:52 +0100)
Board: Skytone Alpha 400
DRAM: 128 MiB
WDT: Started with servicing (0s timeout)
NAND: 2048 MiB
MMC: MSC: 0
In: serial at 10030000
Out: serial at 10030000
Err: serial at 10030000
Net: eth0: ethernet at 13100000
Hit any key to stop autoboot: 0
switch to partitions #0, OK
mmc0 is current device
Scanning mmc 0:1...
Found U-Boot script /boot.scr
2156 bytes read in 14 ms (150.4 KiB/s)
## Executing script at 81000000
try mmc 0:1 for kernel + DT
5236335 bytes read in 540 ms (9.2 MiB/s)
found kernel /Image on mmc 0:1
12106 bytes read in 27 ms (437.5 KiB/s)
bootargs 1: mem=128M console=ttyS0,115200n8 root=/dev/ssfdca1 rw noatime
2108 bytes read in 15 ms (136.7 KiB/s)
## Executing script at 81010000
running bootargs.scr
bootargs.scr done...
bootargs 2: console=ttyS0,115200n8 mtdoops.mtddev=omap2.nand ubi.mtd= root=/dev/mmcblk1p2 rw rootfstype=ext4,ext3 rootwait
bootargs 3: mem=128M earlycon=jz4740_uart,mmio32,0x10030000,115200n8 console=tty0 ignore_loglevel clocksource=jiffies clk_ignore_unused console=ttyS0,115200n8 mtdoops.mtddev=omap2.nand ubi.mtd=
although we have clocksource=jiffies here it is overwritten in this kernel build in boot_override_clocksource()
root=/dev/mmcblk1p2 rw rootfstype=ext4,ext3 rootwait
## Booting kernel from Legacy Image at 84000000 ...
Image Name: Linux-5.11.0-letux-l400+
Image Type: MIPS Linux Kernel Image (gzip compressed)
Data Size: 5236271 Bytes = 5 MiB
Load Address: 80100000
Entry Point: 808cf24c
Verifying Checksum ... OK
## Flattened Device Tree blob at 81100000
Booting using the fdt blob at 0x81100000
Uncompressing Kernel Image
[ 0.000000] Linux version 5.11.0-letux-l400+ (hns at iMac.fritz.box) (mipsel-linux-gnu-gcc (GCC) 4.9.2, GNU ld (GNU Binutils) 2.25) #5128 PREEMPT Sun Feb 28 18:42:45 CET 2021
[ 0.000000] CPU0 revision is: 02d0024f (Ingenic XBurst)
[ 0.000000] MIPS: machine is Skytone Alpha 400
[ 0.000000] earlycon: jz4740_uart0 at MMIO32 0x10030000 (options '115200n8')
[ 0.000000] printk: bootconsole [jz4740_uart0] enabled
[ 0.000000] printk: debug: ignoring loglevel setting.
[ 0.000000] User-defined physical RAM map overwrite
[ 0.000000] Initrd not found or empty - disabling initrd
[ 0.000000] cma: Reserved 32 MiB at 0x01800000
[ 0.000000] Primary instruction cache 16kB, VIPT, 4-way, linesize 32 bytes.
[ 0.000000] Primary data cache 16kB, 4-way, VIPT, no aliases, linesize 32 bytes
[ 0.000000] Zone ranges:
[ 0.000000] Normal [mem 0x0000000000000000-0x0000000007ffffff]
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000000000000-0x0000000007ffffff]
[ 0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x0000000007ffffff]
[ 0.000000] On node 0 totalpages: 32768
[ 0.000000] Normal zone: 288 pages used for memmap
[ 0.000000] Normal zone: 0 pages reserved
[ 0.000000] Normal zone: 32768 pages, LIFO batch:7
[ 0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[ 0.000000] pcpu-alloc: [0] 0
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 32480
[ 0.000000] Kernel command line: mem=128M earlycon=jz4740_uart,mmio32,0x10030000,115200n8 ignore_loglevel clocksource=jiffies clk_ignore_unused console=tty0 console=ttyS0,115200n8 root=/dev/mmcblk0p2 rw rootfstype=ext4,ext3 rootwait
although we have clocksource=jiffies here it is overwritten in this kernel build in boot_override_clocksource()
[ 0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes, linear)
[ 0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes, linear)
[ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[ 0.000000] Memory: 84912K/131072K available (8023K kernel code, 809K rwdata, 2740K rodata, 324K init, 137K bss, 13392K reserved, 32768K cma-reserved)
[ 0.000000] rcu: Preemptible hierarchical RCU implementation.
[ 0.000000] Trampoline variant of Tasks RCU enabled.
[ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[ 0.000000] NR_IRQS: 256
[ 0.000000] random: get_random_bytes called from start_kernel+0x720/0x960 with crng_init=0
[ 0.000000] clocksource: ingenic-timer: mask: 0xffff max_cycles: 0xffff, max_idle_ns: 7910990 ns
Now, the ingenic-timer is initialized
[ 0.012152] sched_clock: 16 bits at 3686kHz, resolution 271ns, wraps every 8888753ns
Here it initialized some scheduler clock
These both come from drivers/clocksource/ingenic-timer.c
[ 0.012163] Console: colour dummy device 80x25
[ 0.004522] printk: console [tty0] enabled
Oops - printk time runs backwards!
[ 0.017993] Calibrating delay loop... 334.23 BogoMIPS (lpj=1671168)
[ 0.050788] pid_max: default: 32768 minimum: 301
[ 0.062225] LSM: Security Framework initializing
[ 0.063110] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
[ 0.076252] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
[ 0.077315] rcu: Hierarchical SRCU implementation.
[ 0.085358] devtmpfs: initialized
[ 0.109684] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
here the jiffies clocksource is initialized
[ 0.103216] futex hash table entries: 256 (order: -1, 3072 bytes, linear)
[ 0.114804] pinctrl core: initialized pinctrl subsystem
[ 0.108509] regulator-dummy: no parameters, enabled
and again printk time runs backwards!
[ 0.110477] NET: Registered protocol family 16
[ 0.126631] thermal_sys: Registered thermal governor 'fair_share'
[ 0.126631] thermal_sys: Registered thermal governor 'step_wise'
[ 0.148380] thermal_sys: Registered thermal governor 'user_space'
[ 0.687663] jz4780-dma 13020000.dma: JZ4780 DMA controller initialised
[ 0.728152] vcc: 3300 mV, enabled
[ 0.736963] reg-fixed-voltage regulator at 0: vcc supplying 3300000uV
[ 0.746892] vmmc: 3300 mV, disabled
[ 0.752478] reg-fixed-voltage regulator at 1: vmmc supplying 3300000uV
[ 0.766219] SCSI subsystem initialized
[ 0.779683] libata version 3.00 loaded.
[ 0.791646] usbcore: registered new interface driver usbfs
[ 0.806129] usbcore: registered new interface driver hub
[ 0.814380] usbcore: registered new device driver usb
[ 0.826003] Advanced Linux Sound Architecture Driver Initialized.
[ 0.869030] clocksource: Switched to clocksource ingenic-timer
Hm. This comes quite late - we are already running (from) the ingenic-timer clocksource?
[ 0.897969] random: fast init done
[ 0.912253] VFS: Disk quotas dquot_6.6.0
[ 0.900560] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
printk time again runs backwards
[ 0.902218] NET: Registered protocol family 2
[ 0.911962] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes, linear)
[ 0.903365] TCP established hash table entries: 1024 (order: 0, 4096 bytes, linear)
[ 0.903573] TCP bind hash table entries: 1024 (order: 0, 4096 bytes, linear)
[ 0.901315] TCP: Hash tables configured (established 1024 bind 1024)
[ 0.908743] UDP hash table entries: 256 (order: 0, 4096 bytes, linear)
[ 0.908743] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes, linear)
[ 0.898025] NET: Registered protocol family 1
[ 0.896086] RPC: Registered named UNIX socket transport module.
[ 0.902674] RPC: Registered udp transport module.
[ 0.902745] RPC: Registered tcp transport module.
[ 0.907663] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.901491] Initialise system trusted keyrings
[ 0.896605] workingset: timestamp_bits=14 max_order=15 bucket_order=1
[ 0.903683] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[ 0.900302] Key type asymmetric registered
[ 0.903541] Asymmetric key parser 'x509' registered
[ 0.895387] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[ 0.903298] io scheduler mq-deadline registered
[ 0.903376] io scheduler kyber registered
[ 0.900689] Serial: 8250/16550 driver, 5 ports, IRQ sharing disabled
[ 0.899882] printk: console [ttyS0] disabled
[ 0.899882] 10030000.serial: ttyS0 at MMIO 0x10030000 (irq = 10, base_baud = 230400) is a 16550A
[ 0.896221] printk: console [ttyS0] enabled
[ 0.896221] printk: console [ttyS0] enabled
[ 0.904889] printk: bootconsole [jz4740_uart0] disabled
[ 0.904889] printk: bootconsole [jz4740_uart0] disabled
[ 0.901611] 10031000.serial: ttyS1 at MMIO 0x10031000 (irq = 11, base_baud = 230400) is a 16550A
[ 0.896944] 10032000.serial: ttyS2 at MMIO 0x10032000 (irq = 12, base_baud = 230400) is a 16550A
[ 0.910286] 10033000.serial: ttyS3 at MMIO 0x10033000 (irq = 13, base_baud = 230400) is a 16550A
[ 0.909385] brd: module loaded
[ 0.895173] loop: module loaded
[ 0.899819] mtdoops: mtd device (mtddev=name/number) must be supplied
[ 0.902180] libphy: Fixed MDIO Bus: probed
[ 0.900463] usbcore: registered new interface driver usb-storage
[ 0.909507] mousedev: PS/2 mouse device common for all mice
[ 0.898347] input: keyboard as /devices/platform/keyboard/input/input0
[ 0.899324] i2c /dev entries driver
[ 0.900234] jz4730-i2c 10042000.i2c: Bus frequency is 100 kHz
[ 0.898026] IR NEC protocol handler initialized
[ 0.898583] IR RC5(x/sz) protocol handler initialized
[ 0.908618] IR RC6 protocol handler initialized
[ 0.908618] IR JVC protocol handler initialized
[ 0.900361] IR Sony protocol handler initialized
[ 0.900439] IR SANYO protocol handler initialized
[ 0.905280] IR Sharp protocol handler initialized
[ 0.910186] IR MCE Keyboard/mouse protocol handler initialized
[ 0.903395] IR XMP protocol handler initialized
[ 0.903470] Driver for 1-wire Dallas network protocol.
[ 0.908217] jz4740-wdt: probe of 10004000.watchdog failed with error -22
[ 0.904139] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.899979] usbcore: registered new interface driver usbhid
[ 0.903300] usbhid: USB HID core driver
[ 0.898018] Initializing XFRM netlink socket
[ 0.901042] NET: Registered protocol family 17
[ 0.905681] NET: Registered protocol family 15
[ 0.910457] 9pnet: Installing 9P2000 support
[ 0.902179] Key type dns_resolver registered
[ 0.902363] oprofile: using timer interrupt.
[ 0.906873] Loading compiled-in X.509 certificates
[ 0.908512] clk: Not disabling unused clocks
[ 0.908547] ALSA device list:
[ 0.898592] No soundcards found.
[ 0.910472] jz4740-mmc 10021000.mmc: Got CD GPIO
[ 0.897779] jz4740-mmc 10021000.mmc: Got WP GPIO
[ 0.902682] jz4740-mmc 10021000.mmc: Looking up vmmc-supply from device tree
[ 0.902913] jz4740-mmc 10021000.mmc: Looking up vqmmc-supply from device tree
Here the kernel hangs - likely in some iopoll or some similarly locked timeout loop
related to MMC.
And after some minutes I see (with backwards running printk time):
[ 0.898184] random: crng init done
But nothing else happens.
So what does this mean?
The interesting part is that sched_clock AND ingenic-timer share the same timer
register.
And enabling ingenic-timer makes the sched_clock readout go wrong.
IMHO both do the same: just read the timer counter register.
So we have:
ingenic_tcu_timer_cs_read() https://elixir.bootlin.com/linux/latest/source/drivers/clocksource/ingenic-timer.c#L62
as the read function passed to clocksource_register_hz()
and
ingenic_tcu_timer_read() https://elixir.bootlin.com/linux/latest/source/drivers/clocksource/ingenic-timer.c#L52
passed to sched_clock_register().
Now since ingenic_tcu_timer_cs_read() is just a wrapper for ingenic_tcu_timer_read()
they should not influence each other!
What I (again) suspect is that it is not a good idea to read the timer register through regmap.
That may not be reentrant or have locks!
I have tried to trace how the ingenic-timer initialized the regmap. It goes through
some subsystems and seems to end up in __regmap_init() which is capable of handling
config options locking, cansleep etc.
So it might really be a not properly set up regmap or the idea of reading through
a regmap which is the source of the problems.
A cure would be to directly read the counter register and bypass the regmap completely.
I'll give it a try (although I think I already did)...
BR,
Nikolaus
More information about the Letux-kernel
mailing list