i2c: bcm2835: Add debug support

This adds a debug module parameter to aid in debugging transfer issues
by printing info to the kernel log. When enabled, status values are
collected in the interrupt routine and msg info in
bcm2835_i2c_start_transfer(). This is done in a way that tries to avoid
affecting timing. Having printk in the isr can mask issues.

debug values (additive):
1: Print info on error
2: Print info on all transfers
3: Print messages before transfer is started

The value can be changed at runtime:
/sys/module/i2c_bcm2835/parameters/debug

Example output, debug=3:
[  747.114448] bcm2835_i2c_xfer: msg(1/2) write addr=0x54, len=2 flags= [i2c1]
[  747.114463] bcm2835_i2c_xfer: msg(2/2) read addr=0x54, len=32 flags= [i2c1]
[  747.117809] start_transfer: msg(1/2) write addr=0x54, len=2 flags= [i2c1]
[  747.117825] isr: remain=2, status=0x30000055 : TA TXW TXD TXE  [i2c1]
[  747.117839] start_transfer: msg(2/2) read addr=0x54, len=32 flags= [i2c1]
[  747.117849] isr: remain=32, status=0xd0000039 : TA RXR TXD RXD  [i2c1]
[  747.117861] isr: remain=20, status=0xd0000039 : TA RXR TXD RXD  [i2c1]
[  747.117870] isr: remain=8, status=0x32 : DONE TXD RXD  [i2c1]

Signed-off-by: Noralf Trønnes <noralf@tronnes.org>

drivers/i2c/busses/i2c-bcm2835.c

@@ -51,6 +51,18 @@
 #define BCM2835_I2C_CDIV_MIN	0x0002
 #define BCM2835_I2C_CDIV_MAX	0xFFFE
 
+static unsigned int debug;
+module_param(debug, uint, 0644);
+MODULE_PARM_DESC(debug, "1=err, 2=isr, 3=xfer");
+
+#define BCM2835_DEBUG_MAX	512
+struct bcm2835_debug {
+	struct i2c_msg *msg;
+	int msg_idx;
+	size_t remain;
+	u32 status;
+};
+
 struct bcm2835_i2c_dev {
 	struct device *dev;
 	void __iomem *regs;
@@ -63,8 +75,78 @@ struct bcm2835_i2c_dev {
 	u32 msg_err;
 	u8 *msg_buf;
 	size_t msg_buf_remaining;
+	struct bcm2835_debug debug[BCM2835_DEBUG_MAX];
+	unsigned int debug_num;
+	unsigned int debug_num_msgs;
 };
 
+static inline void bcm2835_debug_add(struct bcm2835_i2c_dev *i2c_dev, u32 s)
+{
+	if (!i2c_dev->debug_num_msgs || i2c_dev->debug_num >= BCM2835_DEBUG_MAX)
+		return;
+
+	i2c_dev->debug[i2c_dev->debug_num].msg = i2c_dev->curr_msg;
+	i2c_dev->debug[i2c_dev->debug_num].msg_idx =
+				i2c_dev->debug_num_msgs - i2c_dev->num_msgs;
+	i2c_dev->debug[i2c_dev->debug_num].remain = i2c_dev->msg_buf_remaining;
+	i2c_dev->debug[i2c_dev->debug_num].status = s;
+	i2c_dev->debug_num++;
+}
+
+static void bcm2835_debug_print_status(struct bcm2835_i2c_dev *i2c_dev,
+				       struct bcm2835_debug *d)
+{
+	u32 s = d->status;
+
+	pr_info("isr: remain=%zu, status=0x%x : %s%s%s%s%s%s%s%s%s%s [i2c%d]\n",
+		d->remain, s,
+		s & BCM2835_I2C_S_TA ? "TA " : "",
+		s & BCM2835_I2C_S_DONE ? "DONE " : "",
+		s & BCM2835_I2C_S_TXW ? "TXW " : "",
+		s & BCM2835_I2C_S_RXR ? "RXR " : "",
+		s & BCM2835_I2C_S_TXD ? "TXD " : "",
+		s & BCM2835_I2C_S_RXD ? "RXD " : "",
+		s & BCM2835_I2C_S_TXE ? "TXE " : "",
+		s & BCM2835_I2C_S_RXF ? "RXF " : "",
+		s & BCM2835_I2C_S_ERR ? "ERR " : "",
+		s & BCM2835_I2C_S_CLKT ? "CLKT " : "",
+		i2c_dev->adapter.nr);
+}
+
+static void bcm2835_debug_print_msg(struct bcm2835_i2c_dev *i2c_dev,
+				    struct i2c_msg *msg, int i, int total,
+				    const char *fname)
+{
+	pr_info("%s: msg(%d/%d) %s addr=0x%02x, len=%u flags=%s%s%s%s%s%s%s [i2c%d]\n",
+		fname, i, total,
+		msg->flags & I2C_M_RD ? "read" : "write", msg->addr, msg->len,
+		msg->flags & I2C_M_TEN ? "TEN" : "",
+		msg->flags & I2C_M_RECV_LEN ? "RECV_LEN" : "",
+		msg->flags & I2C_M_NO_RD_ACK ? "NO_RD_ACK" : "",
+		msg->flags & I2C_M_IGNORE_NAK ? "IGNORE_NAK" : "",
+		msg->flags & I2C_M_REV_DIR_ADDR ? "REV_DIR_ADDR" : "",
+		msg->flags & I2C_M_NOSTART ? "NOSTART" : "",
+		msg->flags & I2C_M_STOP ? "STOP" : "",
+		i2c_dev->adapter.nr);
+}
+
+static void bcm2835_debug_print(struct bcm2835_i2c_dev *i2c_dev)
+{
+	struct bcm2835_debug *d;
+	unsigned int i;
+
+	for (i = 0; i < i2c_dev->debug_num; i++) {
+		d = &i2c_dev->debug[i];
+		if (d->status == ~0)
+			bcm2835_debug_print_msg(i2c_dev, d->msg, d->msg_idx,
+				i2c_dev->debug_num_msgs, "start_transfer");
+		else
+			bcm2835_debug_print_status(i2c_dev, d);
+	}
+	if (i2c_dev->debug_num >= BCM2835_DEBUG_MAX)
+		pr_info("BCM2835_DEBUG_MAX reached\n");
+}
+
 static inline void bcm2835_i2c_writel(struct bcm2835_i2c_dev *i2c_dev,
 				      u32 reg, u32 val)
 {
@@ -252,6 +334,7 @@ static void bcm2835_i2c_start_transfer(struct bcm2835_i2c_dev *i2c_dev)
 	bcm2835_i2c_writel(i2c_dev, BCM2835_I2C_A, msg->addr);
 	bcm2835_i2c_writel(i2c_dev, BCM2835_I2C_DLEN, msg->len);
 	bcm2835_i2c_writel(i2c_dev, BCM2835_I2C_C, c);
+	bcm2835_debug_add(i2c_dev, ~0);
 }
 
 static void bcm2835_i2c_finish_transfer(struct bcm2835_i2c_dev *i2c_dev)
@@ -278,6 +361,7 @@ static irqreturn_t bcm2835_i2c_isr(int this_irq, void *data)
 	u32 val, err;
 
 	val = bcm2835_i2c_readl(i2c_dev, BCM2835_I2C_S);
+	bcm2835_debug_add(i2c_dev, val);
 
 	err = val & (BCM2835_I2C_S_CLKT | BCM2835_I2C_S_ERR);
 	if (err) {
@@ -344,6 +428,13 @@ static int bcm2835_i2c_xfer(struct i2c_adapter *adap, struct i2c_msg msgs[],
 	unsigned long time_left;
 	int i;
 
+	if (debug)
+		i2c_dev->debug_num_msgs = num;
+
+	if (debug > 2)
+		for (i = 0; i < num; i++)
+			bcm2835_debug_print_msg(i2c_dev, &msgs[i], i + 1, num, __func__);
+
 	for (i = 0; i < (num - 1); i++)
 		if (msgs[i].flags & I2C_M_RD) {
 			dev_warn_once(i2c_dev->dev,
@@ -362,6 +453,10 @@ static int bcm2835_i2c_xfer(struct i2c_adapter *adap, struct i2c_msg msgs[],
 
 	bcm2835_i2c_finish_transfer(i2c_dev);
 
+	if (debug > 1 || (debug && (!time_left || i2c_dev->msg_err)))
+		bcm2835_debug_print(i2c_dev);
+	i2c_dev->debug_num_msgs = 0;
+	i2c_dev->debug_num = 0;
 	if (!time_left) {
 		bcm2835_i2c_writel(i2c_dev, BCM2835_I2C_C,
 				   BCM2835_I2C_C_CLEAR);
@@ -372,7 +467,9 @@ static int bcm2835_i2c_xfer(struct i2c_adapter *adap, struct i2c_msg msgs[],
 	if (!i2c_dev->msg_err)
 		return num;
 
-	dev_dbg(i2c_dev->dev, "i2c transfer failed: %x\n", i2c_dev->msg_err);
+	if (debug)
+		dev_err(i2c_dev->dev, "i2c transfer failed: %x\n",
+			i2c_dev->msg_err);
 
 	if (i2c_dev->msg_err & BCM2835_I2C_S_ERR)
 		return -EREMOTEIO;