Hikey960 i2c0/7 problem

Hi, Sir:

I’m using hikey960 kernel4.9 to write the i2c device driver.
Now I only use one gpio to trigger i2c read chip status (16 byte) by i2c_smbus_read_i2c_block_data.
But the function return time is too long, I use I2C0/I2C7 400KHz to do the experiment.
The result is different between I2C0/I2C7.
Below is my gpio isr code.
[ISR]
start = ktime_get();
/* pm_runtime_get_sync(chip->dev); /
ret = i2c_smbus_read_i2c_block_data(chip->i2c, 0xc0, 16, irq_data);
if (ret < 0)
return ret;
/
pm_runtime_put(chip->dev); */
end = ktime_get();
use_us = ktime_to_ns(ktime_sub(end, start));
dev_info(chip->dev, “ns = %lld\n”, use_us)
[I2C0 400KHz]
0-0034: ns = 68640625 → 68.640ms…
[I2C7 400KHz]
2-0034: ns = 1185416 → 1.185ms… still too long

After that, I try to check i2c-designware-core.c, and add the ktime check
I attached the my modified i2c-designware-core.h/i2c-designware-core.c
Please find the below link:
i2c-designware-core.h
i2c-designware-core.c

Label is listed below:
start1 → master xfer start
start2 → after wait IP ready and init function
isr1 → first INTR_ACTIVIVY, and put i2c xfer msgs.
isr2 → IP xfer done
stop → receive the complete notification and master xfer stop

Note:
each time is the offset. only final xfer time is “start1 stop,ns”
For I2C7 400K, 16 byte read, I think IP xfer time make sense for 400~500us.
[I2C0 400KHz]
[ 503.693059] i2c_designware ffd71000.i2c: start1 2, ns = 8194791
[ 503.699103] i2c_designware ffd71000.i2c: start2 isr1, ns = 11527604
[ 503.705490] i2c_designware ffd71000.i2c: isr1 isr2, ns = 31314584
[ 503.711679] i2c_designware ffd71000.i2c: isr2 stop, ns = 246354
[ 503.717700] i2c_designware ffd71000.i2c: start1 stop, ns = 51283333

[I2C7 400KHz]
[ 563.976657] i2c_designware fdf0b000.i2c: start1 2, ns = 69271
[ 563.982714] i2c_designware fdf0b000.i2c: start2 isr1, ns = 16666
[ 563.988953] i2c_designware fdf0b000.i2c: isr1 isr2, ns = 475521
[ 563.995074] i2c_designware fdf0b000.i2c: isr2 stop, ns = 344792
[ 564.001268] i2c_designware fdf0b000.i2c: start1 stop, ns = 906250

Please help to check this bug. The timing doesn’t make sense.

Is it something which is reproducible over your tries. If I understand well, you want to highlight that i2c0 takes ~30ms to transfer the 16 bytes vs ~500us for I2C7. Did you try to probe I2C bus to see if everything looks good at hw bus level?

Hi, Loic:
For HW signal, I have already measured it.
Please see the below picture.
I2C7 400Kbps setting
I2C0 400Kbps setting

At my measurement, even though I2C7 400K works well.
Sometimes, the function return time is still around 500us ~ 2ms.

With I2C0 400K bus, you can check the picture. Every byte will have a long delay. That’s why the i2c xfer function take long time to return back.

From the ideal I2C xfer (write then read 16byte) is about 400us.

I just want to clarify it’s Synopsys I2C IP problem or I2C bus driver problem.

Can you help to check this issue???

Hi:

Does anyone try to check this item?

Hi @u0084500,

I applied your patch at my side, I found if statically enabling dev_dbg in i2c-designware-core.c, then all debugging info also will be enabled in the source code. And if output the debugging log in UART, this introduce big latency.

So at my side, I enable dev_dbg() sentence by adding “#define DEBUG” at the beginning of file i2c-designware-core.c, and I can use below command to “echo 0 > /proc/sys/kernel/printk” to only print debugging log into log buffer but not UART console.

Below are the testing result for I2C0 / I2C1 / I2C7; from below log I cannot see the same big latency with yours. Could you confirm now you are using UEFI/ARM-TF booting images or Hisilicon legacy booting images? And could you paste the booting log.

And could you do one more testing by using commands “echo 0 > /proc/sys/kernel/printk” and “dmesg -c” so can avoid console latency?

console:/data # ./i2cdetect -y -r 0 0x3f 0x3f
console:/data # dmesg -c
[ 4356.423539] i2c_designware ffd71000.i2c: i2c_dw_xfer: msgs: 1
[ 4356.423616] i2c_designware ffd71000.i2c: Standard-mode HCNT:LCNT = 135:159
[ 4356.423641] i2c_designware ffd71000.i2c: Fast-mode HCNT:LCNT = 26:50
[ 4356.423695] i2c_designware ffd71000.i2c: i2c_dw_isr: enabled=0x1 stat=0x10
[ 4356.423794] i2c_designware ffd71000.i2c: i2c_dw_isr: enabled=0x1 stat=0x750
[ 4356.423863] i2c_designware ffd71000.i2c: i2c_dw_handle_tx_abort: slave address not acknowledged (7bit mode)
[ 4356.423899] i2c_designware ffd71000.i2c: start1 2, ns = 7292
[ 4356.423920] i2c_designware ffd71000.i2c: start2 isr1, ns = 29166
[ 4356.423939] i2c_designware ffd71000.i2c: isr1 isr2, ns = 98959
[ 4356.423960] i2c_designware ffd71000.i2c: isr2 stop, ns = 46875
[ 4356.423980] i2c_designware ffd71000.i2c: start1 stop, ns = 182292

console:/data # ./i2cdetect -y -r 1 0x3f 0x3f
console:/data # dmesg -c
[ 4283.248078] i2c_designware ffd72000.i2c: i2c_dw_xfer: msgs: 1
[ 4283.248130] i2c_designware ffd72000.i2c: Standard-mode HCNT:LCNT = 135:159
[ 4283.248145] i2c_designware ffd72000.i2c: Fast-mode HCNT:LCNT = 26:50
[ 4283.248184] i2c_designware ffd72000.i2c: i2c_dw_isr: enabled=0x1 stat=0x10
[ 4283.248255] i2c_designware ffd72000.i2c: i2c_dw_isr: enabled=0x1 stat=0x714
[ 4283.248310] i2c_designware ffd72000.i2c: start1 2, ns = 6771
[ 4283.248322] i2c_designware ffd72000.i2c: start2 isr1, ns = 23437
[ 4283.248333] i2c_designware ffd72000.i2c: isr1 isr2, ns = 71355
[ 4283.248345] i2c_designware ffd72000.i2c: isr2 stop, ns = 31250
[ 4283.248355] i2c_designware ffd72000.i2c: start1 stop, ns = 132813

console:/data # ./i2cdetect -y -r 2 0x3f 0x3f
console:/data # dmesg -c
[ 4379.983612] i2c_designware fdf0b000.i2c: i2c_dw_xfer: msgs: 1
[ 4379.983689] i2c_designware fdf0b000.i2c: Standard-mode HCNT:LCNT = 456:532
[ 4379.983714] i2c_designware fdf0b000.i2c: Fast-mode HCNT:LCNT = 93:170
[ 4379.983765] i2c_designware fdf0b000.i2c: i2c_dw_isr: enabled=0x1 stat=0x10
[ 4379.983871] i2c_designware fdf0b000.i2c: i2c_dw_isr: enabled=0x1 stat=0x750
[ 4379.983941] i2c_designware fdf0b000.i2c: i2c_dw_handle_tx_abort: slave address not acknowledged (7bit mode)
[ 4379.983977] i2c_designware fdf0b000.i2c: start1 2, ns = 5208
[ 4379.983997] i2c_designware fdf0b000.i2c: start2 isr1, ns = 29167
[ 4379.984018] i2c_designware fdf0b000.i2c: isr1 isr2, ns = 106250
[ 4379.984038] i2c_designware fdf0b000.i2c: isr2 stop, ns = 50520
[ 4379.984058] i2c_designware fdf0b000.i2c: start1 stop, ns = 191145

1 Like

Hi, Leo:

Sorry for the late reply

First of all, you can not turn on all uart log.
Only one that you can turn is to count before/after i2c transaction by using the below command.
echo -n “file i2c-designware-core.c line 782 +p” > /sys/kernel/debug/dynamic_debug/control

I have updated the loader image. It seems I2C0 looks normal.
But I also did some experiments to also read 16 bytes data for I2C0/I2C7 400K/1M/3.4M.
Below’s the experiment result.

I2C0 400KHz
Oscilloscope screenshot
total time

clock output from I2C IP

[ 59.296153] i2c_designware ffd71000.i2c: start1 stop, ns = 541667
[ 65.127056] i2c_designware ffd71000.i2c: start1 stop, ns = 538021
[ 67.055718] i2c_designware ffd71000.i2c: start1 stop, ns = 547396
[ 68.976881] i2c_designware ffd71000.i2c: start1 stop, ns = 642187
[ 70.599755] i2c_designware ffd71000.i2c: start1 stop, ns = 547917
[ 72.071762] i2c_designware ffd71000.i2c: start1 stop, ns = 538021
[ 73.727720] i2c_designware ffd71000.i2c: start1 stop, ns = 556771
[ 76.954226] i2c_designware ffd71000.i2c: start1 stop, ns = 7531770
[ 78.641764] i2c_designware ffd71000.i2c: start1 stop, ns = 565104
[ 80.183837] i2c_designware ffd71000.i2c: start1 stop, ns = 542708
[ 81.711164] i2c_designware ffd71000.i2c: start1 stop, ns = 520312
[ 83.312073] i2c_designware ffd71000.i2c: start1 stop, ns = 554166
[ 102.181712] i2c_designware ffd71000.i2c: start1 stop, ns = 653645
[ 107.318715] i2c_designware ffd71000.i2c: start1 stop, ns = 538021
[ 109.154961] i2c_designware ffd71000.i2c: start1 stop, ns = 540625
[ 110.439505] i2c_designware ffd71000.i2c: start1 stop, ns = 520834
[ 111.631998] i2c_designware ffd71000.i2c: start1 stop, ns = 518750

I2C0 1MHz
total time

I2C clock output from I2C IP

[ 51.588048] i2c_designware ffd71000.i2c: start1 stop, ns = 585937
[ 56.562133] i2c_designware ffd71000.i2c: start1 stop, ns = 544271
[ 58.130765] i2c_designware ffd71000.i2c: start1 stop, ns = 536458
[ 59.378611] i2c_designware ffd71000.i2c: start1 stop, ns = 526042
[ 61.066562] i2c_designware ffd71000.i2c: start1 stop, ns = 542709
[ 63.818838] i2c_designware ffd71000.i2c: start1 stop, ns = 575000
[ 66.684354] i2c_designware ffd71000.i2c: start1 stop, ns = 814062
[ 84.233830] i2c_designware ffd71000.i2c: start1 stop, ns = 574479
[ 86.665826] i2c_designware ffd71000.i2c: start1 stop, ns = 538021
[ 88.010006] i2c_designware ffd71000.i2c: start1 stop, ns = 542188
[ 89.681807] i2c_designware ffd71000.i2c: start1 stop, ns = 543750
[ 91.218290] i2c_designware ffd71000.i2c: start1 stop, ns = 779167

I2C0 3.4MHz
total time

i2c clock high speed code

i2c clock after high speed code

[ 51.686775] i2c_designware ffd71000.i2c: start1 stop, ns = 254166
[ 56.039020] i2c_designware ffd71000.i2c: start1 stop, ns = 246875
[ 57.918927] i2c_designware ffd71000.i2c: start1 stop, ns = 463021
[ 59.158680] i2c_designware ffd71000.i2c: start1 stop, ns = 247917
[ 60.326094] i2c_designware ffd71000.i2c: start1 stop, ns = 7567708
[ 61.662052] i2c_designware ffd71000.i2c: start1 stop, ns = 231771
[ 63.950131] i2c_designware ffd71000.i2c: start1 stop, ns = 245833
[ 65.494423] i2c_designware ffd71000.i2c: start1 stop, ns = 247396
[ 67.198170] i2c_designware ffd71000.i2c: start1 stop, ns = 246354
[ 68.816386] i2c_designware ffd71000.i2c: start1 stop, ns = 228125
[ 70.326513] i2c_designware ffd71000.i2c: start1 stop, ns = 275000
[ 71.678380] i2c_designware ffd71000.i2c: start1 stop, ns = 231771
[ 73.238112] i2c_designware ffd71000.i2c: start1 stop, ns = 266146
[ 74.709552] i2c_designware ffd71000.i2c: start1 stop, ns = 7543229
[ 76.239050] i2c_designware ffd71000.i2c: start1 stop, ns = 252083
[ 77.679114] i2c_designware ffd71000.i2c: start1 stop, ns = 237500
[ 79.646043] i2c_designware ffd71000.i2c: start1 stop, ns = 247917
[ 81.790254] i2c_designware ffd71000.i2c: start1 stop, ns = 251042
[ 83.407348] i2c_designware ffd71000.i2c: start1 stop, ns = 252084

I2C7 400KHz
total time

i2c clock

[ 44.523221] i2c_designware fdf0b000.i2c: start1 stop, ns = 497395
[ 50.323538] i2c_designware fdf0b000.i2c: start1 stop, ns = 497916
[ 52.339826] i2c_designware fdf0b000.i2c: start1 stop, ns = 533854
[ 53.906877] i2c_designware fdf0b000.i2c: start1 stop, ns = 500521
[ 67.225191] i2c_designware fdf0b000.i2c: start1 stop, ns = 511459
[ 70.417515] i2c_designware fdf0b000.i2c: start1 stop, ns = 529167
[ 71.641763] i2c_designware fdf0b000.i2c: start1 stop, ns = 506250
[ 72.684754] i2c_designware fdf0b000.i2c: start1 stop, ns = 527084
[ 73.929443] i2c_designware fdf0b000.i2c: start1 stop, ns = 501041
[ 74.980119] i2c_designware fdf0b000.i2c: start1 stop, ns = 523438
[ 77.494751] i2c_designware fdf0b000.i2c: start1 stop, ns = 535938
[ 78.757946] i2c_designware fdf0b000.i2c: start1 stop, ns = 511458
[ 79.992585] i2c_designware fdf0b000.i2c: start1 stop, ns = 522396
[ 81.257584] i2c_designware fdf0b000.i2c: start1 stop, ns = 508854
[ 82.417831] i2c_designware fdf0b000.i2c: start1 stop, ns = 639062
[ 83.429781] i2c_designware fdf0b000.i2c: start1 stop, ns = 479688

I2C7 1MHz
total time

i2c clock

[ 49.510011] i2c_designware fdf0b000.i2c: start1 stop, ns = 504167
[ 52.704952] i2c_designware fdf0b000.i2c: start1 stop, ns = 500000
[ 54.443930] i2c_designware fdf0b000.i2c: start1 stop, ns = 513021
[ 54.944797] i2c_designware fdf0b000.i2c: start1 stop, ns = 485938
[ 55.408585] i2c_designware fdf0b000.i2c: start1 stop, ns = 507292
[ 55.829922] i2c_designware fdf0b000.i2c: start1 stop, ns = 530208
[ 56.253792] i2c_designware fdf0b000.i2c: start1 stop, ns = 479688
[ 56.677975] i2c_designware fdf0b000.i2c: start1 stop, ns = 505729
[ 57.077421] i2c_designware fdf0b000.i2c: start1 stop, ns = 498438
[ 57.495315] i2c_designware fdf0b000.i2c: start1 stop, ns = 489583
[ 57.908306] i2c_designware fdf0b000.i2c: start1 stop, ns = 496875
[ 58.284071] i2c_designware fdf0b000.i2c: start1 stop, ns = 492188
[ 58.655032] i2c_designware fdf0b000.i2c: start1 stop, ns = 507812
[ 59.045591] i2c_designware fdf0b000.i2c: start1 stop, ns = 495313
[ 59.462766] i2c_designware fdf0b000.i2c: start1 stop, ns = 482813
[ 59.853630] i2c_designware fdf0b000.i2c: start1 stop, ns = 619792
[ 60.227959] i2c_designware fdf0b000.i2c: start1 stop, ns = 493229
[ 60.611995] i2c_designware fdf0b000.i2c: start1 stop, ns = 483854
[ 60.974365] i2c_designware fdf0b000.i2c: start1 stop, ns = 510938
[ 61.361875] i2c_designware fdf0b000.i2c: start1 stop, ns = 485416
[ 61.751419] i2c_designware fdf0b000.i2c: start1 stop, ns = 502083
[ 62.117700] i2c_designware fdf0b000.i2c: start1 stop, ns = 482813
[ 62.481843] i2c_designware fdf0b000.i2c: start1 stop, ns = 483333
[ 62.828989] i2c_designware fdf0b000.i2c: start1 stop, ns = 481250
[ 63.659298] i2c_designware fdf0b000.i2c: start1 stop, ns = 504167
[ 64.433775] i2c_designware fdf0b000.i2c: start1 stop, ns = 588542
[ 64.781809] i2c_designware fdf0b000.i2c: start1 stop, ns = 481771
[ 65.177401] i2c_designware fdf0b000.i2c: start1 stop, ns = 498959
[ 65.631850] i2c_designware fdf0b000.i2c: start1 stop, ns = 508334
[ 66.376915] i2c_designware fdf0b000.i2c: start1 stop, ns = 482292
[ 66.865511] i2c_designware fdf0b000.i2c: start1 stop, ns = 497917
[ 67.233225] i2c_designware fdf0b000.i2c: start1 stop, ns = 502605
[ 68.136095] i2c_designware fdf0b000.i2c: start1 stop, ns = 494270
[ 68.670543] i2c_designware fdf0b000.i2c: start1 stop, ns = 584375
[ 69.565803] i2c_designware fdf0b000.i2c: start1 stop, ns = 498437
[ 70.115527] i2c_designware fdf0b000.i2c: start1 stop, ns = 523958
[ 70.605061] i2c_designware fdf0b000.i2c: start1 stop, ns = 647917
[ 70.976543] i2c_designware fdf0b000.i2c: start1 stop, ns = 482291
[ 71.697409] i2c_designware fdf0b000.i2c: start1 stop, ns = 481770

I2C7 3.4MHz
total time

i2c clock high speed code

i2c clock after high speed code

[ 127.597756] i2c_designware fdf0b000.i2c: start1 stop, ns = 156771
[ 128.229081] i2c_designware fdf0b000.i2c: start1 stop, ns = 143229
[ 128.913613] i2c_designware fdf0b000.i2c: start1 stop, ns = 134896
[ 129.544570] i2c_designware fdf0b000.i2c: start1 stop, ns = 121354
[ 130.200572] i2c_designware fdf0b000.i2c: start1 stop, ns = 108334
[ 130.829496] i2c_designware fdf0b000.i2c: start1 stop, ns = 131250
[ 132.123481] i2c_designware fdf0b000.i2c: start1 stop, ns = 150521
[ 132.869800] i2c_designware fdf0b000.i2c: start1 stop, ns = 112500
[ 133.532167] i2c_designware fdf0b000.i2c: start1 stop, ns = 121354
[ 134.160844] i2c_designware fdf0b000.i2c: start1 stop, ns = 127083
[ 134.792397] i2c_designware fdf0b000.i2c: start1 stop, ns = 170313
[ 135.387614] i2c_designware fdf0b000.i2c: start1 stop, ns = 112500
[ 136.015207] i2c_designware fdf0b000.i2c: start1 stop, ns = 113542
[ 136.589023] i2c_designware fdf0b000.i2c: start1 stop, ns = 107813
[ 137.285048] i2c_designware fdf0b000.i2c: start1 stop, ns = 109375
[ 137.854421] i2c_designware fdf0b000.i2c: start1 stop, ns = 112500
[ 138.305443] i2c_designware fdf0b000.i2c: start1 stop, ns = 123438
[ 150.636947] i2c_designware fdf0b000.i2c: start1 stop, ns = 137500
[ 151.612569] i2c_designware fdf0b000.i2c: start1 stop, ns = 141666
[ 152.355146] i2c_designware fdf0b000.i2c: start1 stop, ns = 116666
[ 152.949107] i2c_designware fdf0b000.i2c: start1 stop, ns = 110937
[ 153.458803] i2c_designware fdf0b000.i2c: start1 stop, ns = 110937
[ 153.992739] i2c_designware fdf0b000.i2c: start1 stop, ns = 131250
[ 154.454351] i2c_designware fdf0b000.i2c: start1 stop, ns = 111458
[ 154.868485] i2c_designware fdf0b000.i2c: start1 stop, ns = 118750
[ 155.291879] i2c_designware fdf0b000.i2c: start1 stop, ns = 111458
[ 156.136523] i2c_designware fdf0b000.i2c: start1 stop, ns = 113020
[ 156.496287] i2c_designware fdf0b000.i2c: start1 stop, ns = 125000

From the above experiments, I found 1MHz seems abnormal, the speed is 400KHz
And also I2C0 for 3.4Mhz, after the high speed code, the clock is just 1MHz???
I change the I2C clock-frequency by change dtsi setting like as the below sample dtsi config.

&i2c0 {
/* On Low speed expansion */
label = “LS-I2C0”;
clock-frequency = <1000000>;
status = “okay”;

Is it possible to check it more about the clock setting??

PS: sorry for the picture links. It’s because of the forum limit for the newbie only can upload one picture.

35 /* crgctrl */
36 static const struct hisi_fixed_factor_clock hi3660_crg_fixed_factor_clks[] = {
37 { HI3660_FACTOR_UART3, “clk_factor_uart3”, “iomcu_peri0”, 1, 16, 0, },
38 { HI3660_CLK_FACTOR_MMC, “clk_factor_mmc”, “clkin_sys”, 1, 6, 0, },
39 { HI3660_CLK_GATE_I2C0, “clk_gate_i2c0”, “clk_i2c0_iomcu”, 1, 4, 0, },
40 { HI3660_CLK_GATE_I2C1, “clk_gate_i2c1”, “clk_i2c1_iomcu”, 1, 4, 0, },
41 { HI3660_CLK_GATE_I2C2, “clk_gate_i2c2”, “clk_i2c2_iomcu”, 1, 4, 0, },
42 { HI3660_CLK_GATE_I2C6, “clk_gate_i2c6”, “clk_i2c6_iomcu”, 1, 4, 0, },

I found the clock driver uses “fixed_factor_clock” for I2C clocks, so suspect the clock driver cannot support dynamically change clock… Will check for this furthermore.

There is indeed some issues with fast-mode+ and high speed mode, requesting some driver tuning for now, I suggest you to read this thread: Unable to use 1MHz or 3.4MHz in i2c0 with linaro kernel 4.4

1 Like

Hi, Leo/Loic:

Based on the source code, I t find two functions that are used to calculate the hcnt:lcnt.

i2c_dw_scl_hcnt/i2c_dw_scl_lcnt

I cannot understand the equations, But I see the function also take the I2C Ip clock to to the calculation.
Does it mean I need to rewrite this function?

Or do you have any suggestion?