[Letux-kernel] [PATCH 00/20] A bunch of JZ4730 fixups for letux-kernel

[H. Nikolaus Schaller]

Hi Paul,

> Am 26.12.2020 um 22:16 schrieb Paul Boddie <paul at boddie.org.uk>:
> 
> On Saturday, 26 December 2020 21:54:04 CET H. Nikolaus Schaller wrote:
>>> Am 26.12.2020 um 17:38 schrieb Paul Boddie <paul at boddie.org.uk>:
>>> 
>>> I did wonder whether the transmission of the last byte might need to be
>>> accompanied by the stop condition,
>> 
>> Yes, it should or well, the STOP must come after the last byte. There is
>> code in my irq handler.
> 
> Right. The stop condition is immediate, then. I can't remember if the JZ4780 
> couples the stop condition with the final byte or whether it also performs an 
> immediate stop. I just thought that use of the former mechanism might explain 
> any lingering bus activity.
> 
>> But it now works with interrupts always enabled. So it looks as if I have
>> found the right triggers to end an interrupt request...
> 
> I suppose that there is some uncertainty about what will cause interrupt 
> conditions. I would have to look at the manual again, but I don't think it is 
> very thorough about that.

Well, it only mentions to enable interrupts in the flow chart. But has no
explanation and the flow-charts do not use interrupts at all. Besides enabling
them...

> 
>> So I think I will have some more minor changes and then merge it into
>> letux-5.10.3 for more public testing. This will become available on the
>> goldelico git soon.
>> 
>> What is still strange is the system time. First of all, "date" now runs much
>> slower than real time. I think this has changed after I hot the LCD create
>> some /dev/fb0 and X11 running. Needs more time to verify this assumed
>> dependency.
>> 
>> And there are really strange values printed to dmesg. The sequence is
>> correct, but the time jumps back and forth?
>> 
>> Well, it may be as simple as the time_val tv_usec having random and negative
>> values...
> 
> I just thought that this is what happens in Linux logging now, with logging 
> possibly being done in parallel (maybe systemd even gets involved).
> 
> [...]

I think the timestamp is kernel-generated. systemd just reads the kernel
log and copies it into its own logs. And the initial boot log is already
mangled before any systemd can be running.

The code where the kernel adds the time-stamp to log buffer records is
here:

https://elixir.bootlin.com/linux/latest/source/kernel/printk/printk.c#L495

So it either reads the ts_nsec parameter which is 0 by

https://elixir.bootlin.com/linux/latest/source/kernel/printk/printk.c#L1910

or calls local_clock().

So may either have a problem with u64 emulation or our scheduler clock doesn't
work correctly. The latter would also explain why boot and X11 has these hickups.

> 
>> I am not at all sure but it may have started with the latest TCU/CGU update?
> 
> No, it was in your earlier logs, too. I had to sort one of them to make sense 
> of it.


Yes, you are right. It is already jittering in the regs-5.10.txt. I just didn't
notice. Anyways the time scale seems to have changed by a factor between 10 and 16.
In regs-5.10.txt it was

[    0.178323] jz4740-mmc 10021000.mmc: Ingenic SD/MMC card driver registered
[    0.169440] jz4740-mmc 10021000.mmc: Using PIO, 4-bit mode
[    0.175484] reg: cpm
[    0.177888] reg: 10000000: 0d522220
[    0.181572] reg: 10000004: 000000f8
[    0.185254] reg: 10000008: 00000001
[    0.171697] reg: 1000000c: 00000000

Now it is

[    2.588107] jz4740-mmc 10021000.mmc: Ingenic SD/MMC card driver registered
[    2.804999] jz4740-mmc 10021000.mmc: Using PIO, 4-bit mode
[    1.840017] reg: cpm
[    1.912256] reg: 10000000: 0d522220
[    2.024097] reg: 10000004: 000000f8
[    2.168697] reg: 10000008: 00000001
[    2.281562] reg: 1000000c: 00000000

which is closer to real time.

> 
>> PS: I just found that after removing all my printk() the i2c driver starts
>> to fail. I need one printing the state and the status register :(
>> So there is another timing issue to be fixed before publishing it...
> 
> I guess you added spinlock usage back to whichever function it was where you 
> had been relying on interrupts being disabled. In any case, I hope you can 
> figure it out.

Well, I have even removed most spinlocks in further cleanup because there isn't
much to lock any more. Well, interrupts are locked and setting the state machine
state in xfer().

Since almost all jz4730_i2c_updateb are now done inside the locked irq handler
they do not need their own lock. The remaining two calls are not critical.

Basically it looks as if the BUSY flag remains active for a while and it
triggers another (now) unexpected interrupt at the end of a send xfer.

So I am now trying to use the flow-chart in non-irq mode to print and analyse
how the status and control register flags really are doing, i.e. when they
are reset. What I don't know is how to check if they would generate an interrupt
request or release it.

BR,
Nikolaus