[PATCH] i2c-algo-bit: Fix spurious SCL timeouts under heavy load

[PATCH] i2c-algo-bit: Fix spurious SCL timeouts under heavy load

[Ville Syrjälä]

When the system is under heavy load, there can be a significant delay
between the getscl() and time_after() calls inside sclhi(). That delay
may cause the time_after() check to trigger after SCL has gone high,
causing sclhi() to return -ETIMEDOUT.

To fix the problem, double check that SCL is still low after the
timeout has been reached, before deciding to return -ETIMEDOUT.

Signed-off-by: Ville Syrjälä <syrjala-ORSVBvAovxo@public.gmane.org>
---
I can easily reproduce these spurious timeouts on my HP-compaq nc6000
laptop with the radeon kms driver. It's enough to have a -j2 kernel
build running, and simultaneosly issue xrandr commands in a
terminal. Calling xrandr will cause the driver to re-read the EDID
from the display. A significant number of the EDID reads will fail.
With this fix I have yet to see any failed EDID reads.

 drivers/i2c/algos/i2c-algo-bit.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

diff --git a/drivers/i2c/algos/i2c-algo-bit.c b/drivers/i2c/algos/i2c-algo-bit.c
index 525c734..d25112e 100644
--- a/drivers/i2c/algos/i2c-algo-bit.c
+++ b/drivers/i2c/algos/i2c-algo-bit.c
@@ -104,9 +104,11 @@ static int sclhi(struct i2c_algo_bit_data *adap)
 		 * are processing data internally.
 		 */
 		if (time_after(jiffies, start + adap->timeout))
-			return -ETIMEDOUT;
+			break;
 		cond_resched();
 	}
+	if (!getscl(adap))
+		return -ETIMEDOUT;
 #ifdef DEBUG
 	if (jiffies != start && i2c_debug >= 3)
 		pr_debug("i2c-algo-bit: needed %ld jiffies for SCL to go "
-- 
1.7.3.4

[DEBUG PATCH] Print a message when a spurious i2c SCL timeout occurs.

[Ville Syrjälä]

A quick hack to verify that the fix works as intended...

Do not apply.

---
 drivers/i2c/algos/i2c-algo-bit.c |    6 ++++++
 1 files changed, 6 insertions(+), 0 deletions(-)

diff --git a/drivers/i2c/algos/i2c-algo-bit.c b/drivers/i2c/algos/i2c-algo-bit.c
index d25112e..3f547b5 100644
--- a/drivers/i2c/algos/i2c-algo-bit.c
+++ b/drivers/i2c/algos/i2c-algo-bit.c
@@ -89,6 +89,7 @@ static inline void scllo(struct i2c_algo_bit_data *adap)
 static int sclhi(struct i2c_algo_bit_data *adap)
 {
 	unsigned long start;
+	bool timeout = false;
 
 	setscl(adap, 1);
 
@@ -104,11 +105,16 @@ static int sclhi(struct i2c_algo_bit_data *adap)
 		 * are processing data internally.
 		 */
 		if (time_after(jiffies, start + adap->timeout))
+		{
+			timeout = true;
 			break;
+		}
 		cond_resched();
 	}
 	if (!getscl(adap))
 		return -ETIMEDOUT;
+	if (timeout)
+		printk(KERN_CRIT "spurious i2c scl timeout\n");
 #ifdef DEBUG
 	if (jiffies != start && i2c_debug >= 3)
 		pr_debug("i2c-algo-bit: needed %ld jiffies for SCL to go "
-- 
1.7.3.4

Re: [PATCH] i2c-algo-bit: Fix spurious SCL timeouts under heavy load

[Jean Delvare]

Hi Ville,

On Wed, 14 Mar 2012 10:32:52 +0200, Ville Syrjälä wrote:
> When the system is under heavy load, there can be a significant delay
> between the getscl() and time_after() calls inside sclhi(). That delay
> may cause the time_after() check to trigger after SCL has gone high,
> causing sclhi() to return -ETIMEDOUT.
> 
> To fix the problem, double check that SCL is still low after the
> timeout has been reached, before deciding to return -ETIMEDOUT.
> 
> Signed-off-by: Ville Syrjälä <syrjala-ORSVBvAovxo@public.gmane.org>
> ---
> I can easily reproduce these spurious timeouts on my HP-compaq nc6000
> laptop with the radeon kms driver. It's enough to have a -j2 kernel
> build running, and simultaneosly issue xrandr commands in a
> terminal. Calling xrandr will cause the driver to re-read the EDID
> from the display. A significant number of the EDID reads will fail.
> With this fix I have yet to see any failed EDID reads.

Thanks for describing a test case, I was able to reproduce the problem
easily by following your instructions. The problem is real, even with
the pending fixes I have to radeon's I2C implementation.

I only have one concern about your implementation:

> 
>  drivers/i2c/algos/i2c-algo-bit.c |    4 +++-
>  1 files changed, 3 insertions(+), 1 deletions(-)
> 
> diff --git a/drivers/i2c/algos/i2c-algo-bit.c b/drivers/i2c/algos/i2c-algo-bit.c
> index 525c734..d25112e 100644
> --- a/drivers/i2c/algos/i2c-algo-bit.c
> +++ b/drivers/i2c/algos/i2c-algo-bit.c
> @@ -104,9 +104,11 @@ static int sclhi(struct i2c_algo_bit_data *adap)
>  		 * are processing data internally.
>  		 */
>  		if (time_after(jiffies, start + adap->timeout))
> -			return -ETIMEDOUT;
> +			break;
>  		cond_resched();
>  	}
> +	if (!getscl(adap))
> +		return -ETIMEDOUT;

This means double-check even in the most common case where time_after()
didn't cause the loop break. From a performance perspective, this seems
undesirable. What would you think of the alternative fix below?

--- linux-3.3-rc7.orig/drivers/i2c/algos/i2c-algo-bit.c	2012-03-15 09:33:10.232176790 +0100
+++ linux-3.3-rc7/drivers/i2c/algos/i2c-algo-bit.c	2012-03-15 14:52:48.127778459 +0100
@@ -103,8 +103,14 @@ static int sclhi(struct i2c_algo_bit_dat
 		 * chips may hold it low ("clock stretching") while they
 		 * are processing data internally.
 		 */
-		if (time_after(jiffies, start + adap->timeout))
+		if (time_after(jiffies, start + adap->timeout)) {
+			/* Test one last time, as we may have been preempted
+			 * between last check and timeout test.
+			 */
+			if (getscl(adap))
+				break;
 			return -ETIMEDOUT;
+		}
 		cond_resched();
 	}
 #ifdef DEBUG

Functionally it should be equivalent to your proposal, but faster. I'll
apply that (and send for stable inclusion.)

Thanks,
-- 
Jean Delvare

Re: [PATCH] i2c-algo-bit: Fix spurious SCL timeouts under heavy load

[Ville Syrjälä]

On Thu, Mar 15, 2012 at 03:32:40PM +0100, Jean Delvare wrote:
> Hi Ville,
> 
> On Wed, 14 Mar 2012 10:32:52 +0200, Ville Syrjälä wrote:
> > When the system is under heavy load, there can be a significant delay
> > between the getscl() and time_after() calls inside sclhi(). That delay
> > may cause the time_after() check to trigger after SCL has gone high,
> > causing sclhi() to return -ETIMEDOUT.
> > 
> > To fix the problem, double check that SCL is still low after the
> > timeout has been reached, before deciding to return -ETIMEDOUT.
> > 
> > Signed-off-by: Ville Syrjälä <syrjala-ORSVBvAovxo@public.gmane.org>
> > ---
> > I can easily reproduce these spurious timeouts on my HP-compaq nc6000
> > laptop with the radeon kms driver. It's enough to have a -j2 kernel
> > build running, and simultaneosly issue xrandr commands in a
> > terminal. Calling xrandr will cause the driver to re-read the EDID
> > from the display. A significant number of the EDID reads will fail.
> > With this fix I have yet to see any failed EDID reads.
> 
> Thanks for describing a test case, I was able to reproduce the problem
> easily by following your instructions. The problem is real, even with
> the pending fixes I have to radeon's I2C implementation.
> 
> I only have one concern about your implementation:
> 
> > 
> >  drivers/i2c/algos/i2c-algo-bit.c |    4 +++-
> >  1 files changed, 3 insertions(+), 1 deletions(-)
> > 
> > diff --git a/drivers/i2c/algos/i2c-algo-bit.c b/drivers/i2c/algos/i2c-algo-bit.c
> > index 525c734..d25112e 100644
> > --- a/drivers/i2c/algos/i2c-algo-bit.c
> > +++ b/drivers/i2c/algos/i2c-algo-bit.c
> > @@ -104,9 +104,11 @@ static int sclhi(struct i2c_algo_bit_data *adap)
> >  		 * are processing data internally.
> >  		 */
> >  		if (time_after(jiffies, start + adap->timeout))
> > -			return -ETIMEDOUT;
> > +			break;
> >  		cond_resched();
> >  	}
> > +	if (!getscl(adap))
> > +		return -ETIMEDOUT;
> 
> This means double-check even in the most common case where time_after()
> didn't cause the loop break. From a performance perspective, this seems
> undesirable. What would you think of the alternative fix below?

Yeah that fact also occured to today. IIRC I did post an another version
of the patch to some bugzilla quite a while ago that didn't suffer from
this issue. Ah here [1] it is. By that time I no longer had access to the
machine (a Thinkpad T400) where I initially saw the problem, so I didn't
pursue it further.

[1] https://bugs.freedesktop.org/show_bug.cgi?id=29787

> --- linux-3.3-rc7.orig/drivers/i2c/algos/i2c-algo-bit.c	2012-03-15 09:33:10.232176790 +0100
> +++ linux-3.3-rc7/drivers/i2c/algos/i2c-algo-bit.c	2012-03-15 14:52:48.127778459 +0100
> @@ -103,8 +103,14 @@ static int sclhi(struct i2c_algo_bit_dat
>  		 * chips may hold it low ("clock stretching") while they
>  		 * are processing data internally.
>  		 */
> -		if (time_after(jiffies, start + adap->timeout))
> +		if (time_after(jiffies, start + adap->timeout)) {
> +			/* Test one last time, as we may have been preempted
> +			 * between last check and timeout test.
> +			 */
> +			if (getscl(adap))
> +				break;
>  			return -ETIMEDOUT;
> +		}
>  		cond_resched();
>  	}
>  #ifdef DEBUG
>
> Functionally it should be equivalent to your proposal, but faster. I'll
> apply that (and send for stable inclusion.)

Looks good. Thanks for taking care of it.

-- 
Ville Syrjälä
Intel OTC