[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