Snow: Increase timeout for i2c stop bit sending

On snow, there are reports of the following warning in the i2c master
reciever code:

	Stop event deadline passed: CR1=0000001000000001

I've been running this torture test, and even with the timeout feature
completely removed, it never hangs.  The stop bit is always sent
eventually, even through thousands and thousands of transactions (of which
a couple take too long for the current timeout).

I timed a lot of these and it looks like the vast majority are fine but
just a few are really really slow.  To this end, I'm increasing the
timeout.  It seems that the wait loop is getting preempted for a while
before it can go back and check, causing these timeout messages.  So every
now and then the process get pre-empted for a long time causing what
looks like a long timeout.  The thing is, the  stop bit is always getting
sent, we're just not noticing for a while.  So even in the really slow
cases, everything should be fine.

Since the bit's getting sent either way, it seems like increasing the
timeout all but fixes the problem where the EC thinks it didn't send.
However, since the timeout is quite high now, I added a sleep
in the busy loop so that if a message is messed up and the stop bit doesn't
send, the task won't steal the cpu for the entire time.

Note: This also fixes a bug in the i2c error handler where it was trying
to print ints and strings and ads a little more information to the
timeout warning in case it starts showing up again.

BUG=chrome-os-partner:12742
TEST=From the EC console run "battery 100000" while running
"while true; do /usr/local/sbin/i2cdump -f -y 4 0x48; done" to seriously
stress test the i2c bus.  Then reboot the machine several times.  There
should be no Stop bit warnings, or failed i2c transfers
BRANCH=snow

Change-Id: I590a9458783d16e57987102b1ec1299d5ddb0fa2
Signed-off-by: Charlie Mooney <charliemooney@chromium.org>
Reviewed-on: https://gerrit.chromium.org/gerrit/31024
Reviewed-by: David Hendricks <dhendrix@chromium.org>

1 files changed, 31 insertions, 7 deletions

diff --git a/chip/stm32/i2c.c b/chip/stm32/i2c.c
index 2d98d37e1e..42b6da1be4 100644
--- a/chip/stm32/i2c.c
+++ b/chip/stm32/i2c.c
@@ -57,8 +57,16 @@
 #define I2C2      STM32_I2C2_PORT
 
 enum {
-	/* A stop condition should take 2 clocks, so allow 8 */
-	TIMEOUT_STOP_SENT_US	= I2C_PERIOD_US * 8,
+	/*
+	 * A stop condition should take 2 clocks, but the process may need more
+	 * time to notice if it is preempted, so we poll repeatedly for 8
+	 * clocks, before backing off and only check once every
+	 * STOP_SENT_RETRY_US for up to TIMEOUT_STOP_SENT clocks before
+	 * giving up.
+	 */
+	SLOW_STOP_SENT_US	= I2C_PERIOD_US * 8,
+	TIMEOUT_STOP_SENT_US	= I2C_PERIOD_US * 200,
+	STOP_SENT_RETRY_US	= 150,
 };
 
 static uint16_t i2c_sr1[NUM_PORTS];
@@ -333,9 +341,9 @@ static void i2c_error_handler(int port)
 		/* ACK failed (NACK); expected when AP reads final byte.
 		 * Software must clear AF bit. */
 	} else {
-		CPRINTF("%s: I2C_SR1(%s): 0x%04x\n",
+		CPRINTF("%s: I2C_SR1(%d): 0x%04x\n",
 			__func__, port, i2c_sr1[port]);
-		CPRINTF("%s: I2C_SR2(%s): 0x%04x\n",
+		CPRINTF("%s: I2C_SR2(%d): 0x%04x\n",
 			__func__, port, STM32_I2C_SR2(port));
 	}
 
@@ -573,16 +581,32 @@ static void master_stop(int port)
 static int wait_until_stop_sent(int port)
 {
 	timestamp_t deadline;
+	timestamp_t slow_cutoff;
+	uint8_t is_slow;
 
-	deadline = get_time();
+	deadline = slow_cutoff = get_time();
 	deadline.val += TIMEOUT_STOP_SENT_US;
+	slow_cutoff.val += SLOW_STOP_SENT_US;
 
 	while (STM32_I2C_CR1(port) & (1 << 9)) {
 		if (timestamp_expired(deadline, NULL)) {
-			ccprintf("Stop event deadline passed: CR1=%016b\n",
-				 STM32_I2C_CR1(port));
+			ccprintf("Stop event deadline passed:\ttask=%d"
+							"\tCR1=%016b\n",
+				(int)task_get_current(), STM32_I2C_CR1(port));
 			return EC_ERROR_TIMEOUT;
 		}
+
+		if (is_slow) {
+			/* If we haven't gotten a fast response, sleep */
+			usleep(STOP_SENT_RETRY_US);
+		} else {
+			/* Check to see if this request is taking a while */
+			if (timestamp_expired(slow_cutoff, NULL)) {
+				ccprintf("Stop event taking a while: task=%d",
+					(int)task_get_current());
+				is_slow = 1;
+			}
+		}
 	}
 
 	return EC_SUCCESS;