Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Date:   Wed, 28 Sep 2022 23:27:34 +0300
From:   Michael Zaidman <michael.zaidman@gmail.com>
To:     David Laight <David.Laight@aculab.com>
Cc:     "jikos@kernel.org" <jikos@kernel.org>,
        "linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>,
        "linux-input@vger.kernel.org" <linux-input@vger.kernel.org>,
        Guillaume Champagne <champagne.guillaume.c@gmail.com>
Subject: Re: [PATCH v2 2/7] HID: ft260: improve i2c write performance
Message-ID: <YzSuNlP5LlvSdYYT@michael-VirtualBox>
References: <20220928144854.5580-1-michael.zaidman@gmail.com>
 <20220928144854.5580-3-michael.zaidman@gmail.com>
 <f9be53a647cd4b698ed820a70b67b7d4@AcuMS.aculab.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <f9be53a647cd4b698ed820a70b67b7d4@AcuMS.aculab.com>
Precedence: bulk

On Wed, Sep 28, 2022 at 03:50:36PM +0000, David Laight wrote:
> From: Michael Zaidman
> > Sent: 28 September 2022 15:49
> > 
> > The patch improves i2c writing performance by about 30 percent by revising
> > the sleep time in the ft260_hid_output_report_check_status() in the
> > following ways:
> 
> Spinning in kernel for several milliseconds isn't friendly at all.
> 
> 	David
> 
We do not sleep if the estimated I2C transfer time is below 2 ms since the
first xfer check frequently takes about 1.5 ms on the real HW (i7-4790K @ 4.0GHz).
That means the condition is usually satisfied already on the first 1-3 checks,
as can be seen in example #1.

On the other hand, sending a large amount of data at a low I2C clock rate
saturates the internal FT260 buffer and causes hiccups in status readiness,
as shown in exemple #2. Aligning the status checking wait time to the worst
case significantly reduces the performance.  

Exemple #1

$ sudo ./i2cperf -f 2 -o 2 -s 16 -r 0-0xff 13 0x51 -S

  Fill block with increment via i2ctransfer by chunks
  -------------------------------------------------------------------
  data rate(bps)  efficiency(%)  data size(B)  total IOs   IO size(B)
  -------------------------------------------------------------------
  49823           73             256           16          16

[Sep28 21:40] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.005031] ft260_xfer_status: bus_status 0x20, clock 100
[  +0.016531] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001710] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000227] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.011805] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.000747] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000189] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.014932] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.000806] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000223] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000178] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.010921] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.000704] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000181] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000228] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000182] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.014243] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001220] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000143] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.011332] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001533] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000183] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.011865] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.000934] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000197] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.014102] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001722] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000181] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.014000] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.000845] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000172] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.013294] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001499] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000190] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.011524] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001238] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000291] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000182] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.013632] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.000967] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000184] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.013505] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001302] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000140] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.012673] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001147] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000140] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000217] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.012426] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001172] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000192] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000192] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000184] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000211] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000193] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000194] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000197] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000175] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000226] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000132] ft260_xfer_status: bus_status 0x20, clock 100


Exemple #2

$ sudo ./i2cperf -f 2 -o 2 -s 128 -r 0-0x1ff 13 0x51 -S

  Fill block with increment via i2ctransfer by chunks
  -------------------------------------------------------------------
  data rate(bps)  efficiency(%)  data size(B)  total IOs   IO size(B)
  -------------------------------------------------------------------
  65553           86             512           4           128

[Sep28 22:04] ft260_i2c_write: rep 0xde addr 0x51 off 0 len 130 wlen 60 flag 0x2 d[0] 0x0
[  +0.005707] ft260_hid_output_report_check_status: wait 4260 usec, len 64
[  +0.000846] ft260_xfer_status: bus_status 0x20, clock 100
[  +0.000002] ft260_i2c_write: rep 0xde addr 0x51 off 60 len 70 wlen 60 flag 0x0 d[0] 0x0
[  +0.005155] ft260_hid_output_report_check_status: wait 4260 usec, len 64
[  +0.000245] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000002] ft260_i2c_write: rep 0xd2 addr 0x51 off 120 len 10 wlen 10 flag 0x4 d[0] 0x0
[  +0.001593] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.016725] ft260_i2c_write: rep 0xde addr 0x51 off 0 len 130 wlen 60 flag 0x2 d[0] 0x0
[  +0.005433] ft260_hid_output_report_check_status: wait 4260 usec, len 64
[  +0.000240] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000193] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000001] ft260_i2c_write: rep 0xde addr 0x51 off 60 len 70 wlen 60 flag 0x0 d[0] 0x0
[  +0.005547] ft260_hid_output_report_check_status: wait 4260 usec, len 64
[  +0.000185] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000002] ft260_i2c_write: rep 0xd2 addr 0x51 off 120 len 10 wlen 10 flag 0x4 d[0] 0x0
[  +0.001575] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000235] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000186] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000195] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000160] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.014875] ft260_i2c_write: rep 0xde addr 0x51 off 0 len 130 wlen 60 flag 0x2 d[0] 0x1
[  +0.005596] ft260_hid_output_report_check_status: wait 4260 usec, len 64
[  +0.000230] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000188] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000002] ft260_i2c_write: rep 0xde addr 0x51 off 60 len 70 wlen 60 flag 0x0 d[0] 0x1
[  +0.005568] ft260_hid_output_report_check_status: wait 4260 usec, len 64
[  +0.000190] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000175] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000172] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000002] ft260_i2c_write: rep 0xd2 addr 0x51 off 120 len 10 wlen 10 flag 0x4 d[0] 0x1
[  +0.001287] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000226] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000176] ft260_xfer_status: bus_status 0x41, clock 100]
[  +0.000234] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000201] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000173] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000223] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000180] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000218] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000195] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000178] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000129] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000128] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000130] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.014159] ft260_i2c_write: rep 0xde addr 0x51 off 0 len 130 wlen 60 flag 0x2 d[0] 0x1
[  +0.005546] ft260_hid_output_report_check_status: wait 4260 usec, len 64
[  +0.000196] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000183] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000251] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000141] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000191] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000181] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000225] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000001] ft260_i2c_write: rep 0xde addr 0x51 off 60 len 70 wlen 60 flag 0x0 d[0] 0x1
[  +0.005693] ft260_hid_output_report_check_status: wait 4260 usec, len 64
[  +0.000180] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000227] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000151] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000002] ft260_i2c_write: rep 0xd2 addr 0x51 off 120 len 10 wlen 10 flag 0x4 d[0] 0x1
[  +0.001321] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000185] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000179] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000234] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000162] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000237] ft260_xfer_status: bus_status 0x40, clock 100


> > 
> > 1. Reduce the sleep time and start to poll earlier:
> > 
> >   Before:
> >     $ sudo ./i2cperf -f 2 -o 2 -s 32 -r 0-0xff 13 0x51 -S
> > 
> >       Fill block with increment via i2ctransfer by chunks
> >       -------------------------------------------------------------------
> >       data rate(bps)  efficiency(%)  data size(B)  total IOs   IO size(B)
> >       -------------------------------------------------------------------
> >       40510           80             256           8           32
> > 
> >   After:
> >     $ sudo ./i2cperf -f 2 -o 2 -s 32 -r 0-0xff 13 0x51 -S
> > 
> >       Fill block with increment via i2ctransfer by chunks
> >       -------------------------------------------------------------------
> >       data rate(bps)  efficiency(%)  data size(B)  total IOs   IO size(B)
> >       -------------------------------------------------------------------
> >       52584           80             256           8           32
> > 
> > 2. Do not sleep when the calculated sleep time is below 2 ms:
> > 
> >   Before:
> >     $ sudo ./i2cperf -f 2 -o 2 -s 16 -r 0-0xff 13 0x51 -S
> > 
> >       Fill block with increment via i2ctransfer by chunks
> >       -------------------------------------------------------------------
> >       data rate(bps)  efficiency(%)  data size(B)  total IOs   IO size(B)
> >       -------------------------------------------------------------------
> >       26707           73             256           16          16
> > 
> >   After:
> >     $ sudo ./i2cperf -f 2 -o 2 -s 16 -r 0-0xff 13 0x51 -S
> > 
> >       Fill block with increment via i2ctransfer by chunks
> >       -------------------------------------------------------------------
> >       data rate(bps)  efficiency(%)  data size(B)  total IOs   IO size(B)
> >       -------------------------------------------------------------------
> >       37034           73             256           16          16
> > 
> > Link to the i2cperf - https://github.com/MichaelZaidman/i2cperf
> > 
> > Signed-off-by: Michael Zaidman <michael.zaidman@gmail.com>
> > Tested-by: Guillaume Champagne <champagne.guillaume.c@gmail.com>
> > ---
> >  drivers/hid/hid-ft260.c | 14 +++++++++-----
> >  1 file changed, 9 insertions(+), 5 deletions(-)
> > 
> > diff --git a/drivers/hid/hid-ft260.c b/drivers/hid/hid-ft260.c
> > index a35201d68b15..44106cadd746 100644
> > --- a/drivers/hid/hid-ft260.c
> > +++ b/drivers/hid/hid-ft260.c
> > @@ -345,7 +345,7 @@ static int ft260_hid_output_report(struct hid_device *hdev, u8 *data,
> >  static int ft260_hid_output_report_check_status(struct ft260_device *dev,
> >  						u8 *data, int len)
> >  {
> > -	int ret, usec, try = 3;
> > +	int ret, usec, try = 100;
> >  	struct hid_device *hdev = dev->hdev;
> > 
> >  	ret = ft260_hid_output_report(hdev, data, len);
> > @@ -356,10 +356,14 @@ static int ft260_hid_output_report_check_status(struct ft260_device *dev,
> >  		return ret;
> >  	}
> > 
> > -	/* transfer time = 1 / clock(KHz) * 10 bits * bytes */
> > -	usec = 10000 / dev->clock * len;
> > -	usleep_range(usec, usec + 100);
> > -	ft260_dbg("wait %d usec, len %d\n", usec, len);
> > +	/* transfer time = 1 / clock(KHz) * 9 bits * bytes */
> > +	usec = len * 9000 / dev->clock;
> > +	if (usec > 2000) {
> > +		usec -= 1500;
> > +		usleep_range(usec, usec + 100);
> > +		ft260_dbg("wait %d usec, len %d\n", usec, len);
> > +	}
> > +
> >  	do {
> >  		ret = ft260_xfer_status(dev);
> >  		if (ret != -EAGAIN)
> > --
> > 2.34.1
> 
> -
> Registered Address Lakeside, Bramley Road, Mount Farm, Milton Keynes, MK1 1PT, UK
> Registration No: 1397386 (Wales)
>