twsi: compile in support for debug messages, disabled by default

Debug messages can now be enabled per driver instance via a new sysctl.
Also, debug messages in TWSI_READ and TWSI_WRITE require debug level
greater than 1 as they are mostly redundant because callers of those
functions already log most interesting results.

NB: the twsi drivers call their device iichb, so the new sysctl will
appear under dev.iichb.N.

MFC after:	1 week

2 files changed, 75 insertions, 62 deletions

diff --git a/sys/dev/iicbus/twsi/twsi.c b/sys/dev/iicbus/twsi/twsi.c
index 84bf0223fba7..49fe608473b2 100644
--- a/sys/dev/iicbus/twsi/twsi.c
+++ b/sys/dev/iicbus/twsi/twsi.c
@@ -49,6 +49,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/module.h>
 #include <sys/resource.h>
 #include <sys/rman.h>
+#include <sys/sysctl.h>
 
 #include <machine/_inttypes.h>
 #include <machine/bus.h>
@@ -85,11 +86,8 @@ __FBSDID("$FreeBSD$");
 #define	TWSI_DEBUG
 #undef TWSI_DEBUG
 
-#ifdef TWSI_DEBUG
-#define	debugf(dev, fmt, args...) device_printf(dev, "%s: " fmt, __func__, ##args)
-#else
-#define	debugf(dev, fmt, args...)
-#endif
+#define	debugf(sc, fmt, args...)	if ((sc)->debug)	\
+    device_printf((sc)->dev, "%s: " fmt, __func__, ##args)
 
 static struct resource_spec res_spec[] = {
 	{ SYS_RES_MEMORY, 0, RF_ACTIVE },
@@ -103,7 +101,8 @@ TWSI_READ(struct twsi_softc *sc, bus_size_t off)
 	uint32_t val;
 
 	val = bus_read_4(sc->res[0], off);
-	debugf(sc->dev, "read %x from %lx\n", val, off);
+	if (sc->debug > 1)
+		debugf(sc, "read %x from %lx\n", val, off);
 	return (val);
 }
 
@@ -111,7 +110,8 @@ static __inline void
 TWSI_WRITE(struct twsi_softc *sc, bus_size_t off, uint32_t val)
 {
 
-	debugf(sc->dev, "Writing %x to %lx\n", val, off);
+	if (sc->debug > 1)
+		debugf(sc, "Writing %x to %lx\n", val, off);
 	bus_write_4(sc->res[0], off, val);
 }
 
@@ -121,10 +121,10 @@ twsi_control_clear(struct twsi_softc *sc, uint32_t mask)
 	uint32_t val;
 
 	val = TWSI_READ(sc, sc->reg_control);
-	debugf(sc->dev, "read val=%x\n", val);
+	debugf(sc, "read val=%x\n", val);
 	val &= ~(TWSI_CONTROL_STOP | TWSI_CONTROL_START);
 	val &= ~mask;
-	debugf(sc->dev, "write val=%x\n", val);
+	debugf(sc, "write val=%x\n", val);
 	TWSI_WRITE(sc, sc->reg_control, val);
 }
 
@@ -134,10 +134,10 @@ twsi_control_set(struct twsi_softc *sc, uint32_t mask)
 	uint32_t val;
 
 	val = TWSI_READ(sc, sc->reg_control);
-	debugf(sc->dev, "read val=%x\n", val);
+	debugf(sc, "read val=%x\n", val);
 	val &= ~(TWSI_CONTROL_STOP | TWSI_CONTROL_START);
 	val |= mask;
-	debugf(sc->dev, "write val=%x\n", val);
+	debugf(sc, "write val=%x\n", val);
 	TWSI_WRITE(sc, sc->reg_control, val);
 }
 
@@ -166,13 +166,13 @@ twsi_poll_ctrl(struct twsi_softc *sc, int timeout, uint32_t mask)
 {
 
 	timeout /= 10;
-	debugf(sc->dev, "Waiting for ctrl reg to match mask %x\n", mask);
+	debugf(sc, "Waiting for ctrl reg to match mask %x\n", mask);
 	while (!(TWSI_READ(sc, sc->reg_control) & mask)) {
 		DELAY(10);
 		if (--timeout < 0)
 			return (timeout);
 	}
-	debugf(sc->dev, "done\n");
+	debugf(sc, "done\n");
 	return (0);
 }
 
@@ -196,11 +196,11 @@ twsi_locked_start(device_t dev, struct twsi_softc *sc, int32_t mask,
 		/* read IFLG to know if it should be cleared later; from NBSD */
 		iflg_set = TWSI_READ(sc, sc->reg_control) & TWSI_CONTROL_IFLG;
 
-	debugf(dev, "send start\n");
+	debugf(sc, "send start\n");
 	twsi_control_set(sc, TWSI_CONTROL_START);
 
 	if (mask == TWSI_STATUS_RPTD_START && iflg_set) {
-		debugf(dev, "IFLG set, clearing (mask=%x)\n", mask);
+		debugf(sc, "IFLG set, clearing (mask=%x)\n", mask);
 		twsi_clear_iflg(sc);
 	}
 
@@ -211,16 +211,16 @@ twsi_locked_start(device_t dev, struct twsi_softc *sc, int32_t mask,
 	DELAY(1000);
 
 	if (twsi_poll_ctrl(sc, timeout, TWSI_CONTROL_IFLG)) {
-		debugf(dev, "timeout sending %sSTART condition\n",
+		debugf(sc, "timeout sending %sSTART condition\n",
 		    mask == TWSI_STATUS_START ? "" : "repeated ");
 		return (IIC_ETIMEOUT);
 	}
 
 	status = TWSI_READ(sc, sc->reg_status);
-	debugf(dev, "status=%x\n", status);
+	debugf(sc, "status=%x\n", status);
 
 	if (status != mask) {
-		debugf(dev, "wrong status (%02x) after sending %sSTART condition\n",
+		debugf(sc, "wrong status (%02x) after sending %sSTART condition\n",
 		    status, mask == TWSI_STATUS_START ? "" : "repeated ");
 		return (IIC_ESTATUS);
 	}
@@ -230,7 +230,7 @@ twsi_locked_start(device_t dev, struct twsi_softc *sc, int32_t mask,
 	DELAY(1000);
 
 	if (twsi_poll_ctrl(sc, timeout, TWSI_CONTROL_IFLG)) {
-		debugf(dev, "timeout sending slave address (timeout=%d)\n", timeout);
+		debugf(sc, "timeout sending slave address (timeout=%d)\n", timeout);
 		return (IIC_ETIMEOUT);
 	}
 
@@ -238,7 +238,7 @@ twsi_locked_start(device_t dev, struct twsi_softc *sc, int32_t mask,
 	status = TWSI_READ(sc, sc->reg_status);
 	if (status != (read_access ?
 	    TWSI_STATUS_ADDR_R_ACK : TWSI_STATUS_ADDR_W_ACK)) {
-		debugf(dev, "no ACK (status: %02x) after sending slave address\n",
+		debugf(sc, "no ACK (status: %02x) after sending slave address\n",
 		    status);
 		return (IIC_ENOACK);
 	}
@@ -264,7 +264,7 @@ twsi_calc_baud_rate(struct twsi_softc *sc, const u_int target,
 	if (clk_get_freq(sc->clk_core, &clk) < 0)
 		return (-1);
 
-	debugf(sc->dev, "Bus clock is at %ju\n", clk);
+	debugf(sc, "Bus clock is at %ju\n", clk);
 
 	for (n = 0; n < 8; n++) {
 		for (m = 0; m < 16; m++) {
@@ -306,23 +306,23 @@ twsi_reset(device_t dev, u_char speed, u_char addr, u_char *oldaddr)
 		case IIC_SLOW:
 		case IIC_FAST:
 			param = sc->baud_rate[speed].param;
-			debugf(dev, "Using IIC_FAST mode with speed param=%x\n", param);
+			debugf(sc, "Using IIC_FAST mode with speed param=%x\n", param);
 			break;
 		case IIC_FASTEST:
 		case IIC_UNKNOWN:
 		default:
 			param = sc->baud_rate[IIC_FAST].param;
-			debugf(dev, "Using IIC_FASTEST/UNKNOWN mode with speed param=%x\n", param);
+			debugf(sc, "Using IIC_FASTEST/UNKNOWN mode with speed param=%x\n", param);
 			break;
 		}
 #ifdef EXT_RESOURCES
 	}
 #endif
 
-	debugf(dev, "Using clock param=%x\n", param);
+	debugf(sc, "Using clock param=%x\n", param);
 
 	mtx_lock(&sc->mutex);
-	TWSI_WRITE(sc, sc->reg_soft_reset, 0x0);
+	TWSI_WRITE(sc, sc->reg_soft_reset, 0x1);
 	TWSI_WRITE(sc, sc->reg_baud_rate, param);
 	TWSI_WRITE(sc, sc->reg_control, TWSI_CONTROL_TWSIEN);
 	DELAY(1000);
@@ -338,7 +338,7 @@ twsi_stop(device_t dev)
 
 	sc = device_get_softc(dev);
 
-	debugf(dev, "%s\n", __func__);
+	debugf(sc, "%s\n", __func__);
 	mtx_lock(&sc->mutex);
 	twsi_control_clear(sc, TWSI_CONTROL_ACK);
 	twsi_control_set(sc, TWSI_CONTROL_STOP);
@@ -360,7 +360,7 @@ twsi_repeated_start(device_t dev, u_char slave, int timeout)
 
 	sc = device_get_softc(dev);
 
-	debugf(dev, "%s: slave=%x\n", __func__, slave);
+	debugf(sc, "%s: slave=%x\n", __func__, slave);
 	mtx_lock(&sc->mutex);
 	rv = twsi_locked_start(dev, sc, TWSI_STATUS_RPTD_START, slave,
 	    timeout);
@@ -384,7 +384,7 @@ twsi_start(device_t dev, u_char slave, int timeout)
 
 	sc = device_get_softc(dev);
 
-	debugf(dev, "%s: slave=%x\n", __func__, slave);
+	debugf(sc, "%s: slave=%x\n", __func__, slave);
 	mtx_lock(&sc->mutex);
 	rv = twsi_locked_start(dev, sc, TWSI_STATUS_START, slave, timeout);
 	mtx_unlock(&sc->mutex);
@@ -422,7 +422,7 @@ twsi_read(device_t dev, char *buf, int len, int *read, int last, int delay)
 		DELAY(1000);
 
 		if (twsi_poll_ctrl(sc, delay, TWSI_CONTROL_IFLG)) {
-			debugf(dev, "timeout reading data (delay=%d)\n", delay);
+			debugf(sc, "timeout reading data (delay=%d)\n", delay);
 			rv = IIC_ETIMEOUT;
 			goto out;
 		}
@@ -430,7 +430,7 @@ twsi_read(device_t dev, char *buf, int len, int *read, int last, int delay)
 		status = TWSI_READ(sc, sc->reg_status);
 		if (status != (last_byte ?
 		    TWSI_STATUS_DATA_RD_NOACK : TWSI_STATUS_DATA_RD_ACK)) {
-			debugf(dev, "wrong status (%02x) while reading\n", status);
+			debugf(sc, "wrong status (%02x) while reading\n", status);
 			rv = IIC_ESTATUS;
 			goto out;
 		}
@@ -461,14 +461,14 @@ twsi_write(device_t dev, const char *buf, int len, int *sent, int timeout)
 		twsi_clear_iflg(sc);
 		DELAY(1000);
 		if (twsi_poll_ctrl(sc, timeout, TWSI_CONTROL_IFLG)) {
-			debugf(dev, "timeout writing data (timeout=%d)\n", timeout);
+			debugf(sc, "timeout writing data (timeout=%d)\n", timeout);
 			rv = IIC_ETIMEOUT;
 			goto out;
 		}
 
 		status = TWSI_READ(sc, sc->reg_status);
 		if (status != TWSI_STATUS_DATA_WR_ACK) {
-			debugf(dev, "wrong status (%02x) while writing\n", status);
+			debugf(sc, "wrong status (%02x) while writing\n", status);
 			rv = IIC_ESTATUS;
 			goto out;
 		}
@@ -495,8 +495,8 @@ twsi_transfer(device_t dev, struct iic_msg *msgs, uint32_t nmsgs)
 	sc->control_val = TWSI_CONTROL_TWSIEN |
 		TWSI_CONTROL_INTEN | TWSI_CONTROL_ACK;
 	TWSI_WRITE(sc, sc->reg_control, sc->control_val);
-	debugf(dev, "transmitting %d messages\n", nmsgs);
-	debugf(sc->dev, "status=%x\n", TWSI_READ(sc, sc->reg_status));
+	debugf(sc, "transmitting %d messages\n", nmsgs);
+	debugf(sc, "status=%x\n", TWSI_READ(sc, sc->reg_status));
 	sc->nmsgs = nmsgs;
 	sc->msgs = msgs;
 	sc->msg_idx = 0;
@@ -504,7 +504,7 @@ twsi_transfer(device_t dev, struct iic_msg *msgs, uint32_t nmsgs)
 
 #ifdef TWSI_DEBUG
 	for (int i = 0; i < nmsgs; i++)
-		debugf(sc->dev, "msg %d is %d bytes long\n", i, msgs[i].len);
+		debugf(sc, "msg %d is %d bytes long\n", i, msgs[i].len);
 #endif
 	/* Send start and re-enable interrupts */
 	sc->control_val = TWSI_CONTROL_TWSIEN |
@@ -515,17 +515,17 @@ twsi_transfer(device_t dev, struct iic_msg *msgs, uint32_t nmsgs)
 	while (sc->error == 0 && sc->transfer != 0) {
 		tsleep_sbt(sc, 0, "twsi", SBT_1MS * 30, SBT_1MS, 0);
 	}
-	debugf(sc->dev, "pause finish\n");
+	debugf(sc, "pause finish\n");
 
 	if (sc->error) {
-		debugf(sc->dev, "Error, aborting (%d)\n", sc->error);
+		debugf(sc, "Error, aborting (%d)\n", sc->error);
 		TWSI_WRITE(sc, sc->reg_control, 0);
 	}
 
 	/* Disable module and interrupts */
-	debugf(sc->dev, "status=%x\n", TWSI_READ(sc, sc->reg_status));
+	debugf(sc, "status=%x\n", TWSI_READ(sc, sc->reg_status));
 	TWSI_WRITE(sc, sc->reg_control, 0);
-	debugf(sc->dev, "status=%x\n", TWSI_READ(sc, sc->reg_status));
+	debugf(sc, "status=%x\n", TWSI_READ(sc, sc->reg_status));
 
 	return (sc->error);
 }
@@ -539,16 +539,16 @@ twsi_intr(void *arg)
 
 	sc = arg;
 
-	debugf(sc->dev, "Got interrupt Current msg=%x\n", sc->msg_idx);
+	debugf(sc, "Got interrupt Current msg=%x\n", sc->msg_idx);
 
 	status = TWSI_READ(sc, sc->reg_status);
-	debugf(sc->dev, "reg control=%x\n", TWSI_READ(sc, sc->reg_control));
+	debugf(sc, "reg control=%x\n", TWSI_READ(sc, sc->reg_control));
 
 	switch (status) {
 	case TWSI_STATUS_START:
 	case TWSI_STATUS_RPTD_START:
 		/* Transmit the address */
-		debugf(sc->dev, "Send the address (%x)", sc->msgs[sc->msg_idx].slave);
+		debugf(sc, "Send the address (%x)", sc->msgs[sc->msg_idx].slave);
 
 		if (sc->msgs[sc->msg_idx].flags & IIC_M_RD)
 			TWSI_WRITE(sc, sc->reg_data,
@@ -560,10 +560,10 @@ twsi_intr(void *arg)
 		break;
 
 	case TWSI_STATUS_ADDR_W_ACK:
-		debugf(sc->dev, "Ack received after transmitting the address (write)\n");
+		debugf(sc, "Ack received after transmitting the address (write)\n");
 		/* Directly send the first byte */
 		sc->sent_bytes = 1;
-		debugf(sc->dev, "Sending byte 0 (of %d) = %x\n",
+		debugf(sc, "Sending byte 0 (of %d) = %x\n",
 		    sc->msgs[sc->msg_idx].len,
 		    sc->msgs[sc->msg_idx].buf[0]);
 		TWSI_WRITE(sc, sc->reg_data, sc->msgs[sc->msg_idx].buf[0]);
@@ -572,7 +572,7 @@ twsi_intr(void *arg)
 		break;
 
 	case TWSI_STATUS_ADDR_R_ACK:
-		debugf(sc->dev, "Ack received after transmitting the address (read)\n");
+		debugf(sc, "Ack received after transmitting the address (read)\n");
 		sc->recv_bytes = 0;
 
 		TWSI_WRITE(sc, sc->reg_control, sc->control_val);
@@ -580,7 +580,7 @@ twsi_intr(void *arg)
 
 	case TWSI_STATUS_ADDR_W_NACK:
 	case TWSI_STATUS_ADDR_R_NACK:
-		debugf(sc->dev, "No ack received after transmitting the address\n");
+		debugf(sc, "No ack received after transmitting the address\n");
 		sc->transfer = 0;
 		sc->error = IIC_ENOACK;
 		sc->control_val = 0;
@@ -588,29 +588,29 @@ twsi_intr(void *arg)
 		break;
 
 	case TWSI_STATUS_DATA_WR_ACK:
-		debugf(sc->dev, "Ack received after transmitting data\n");
+		debugf(sc, "Ack received after transmitting data\n");
 		if (sc->sent_bytes == sc->msgs[sc->msg_idx].len) {
-			debugf(sc->dev, "Done sending all the bytes for msg %d\n", sc->msg_idx);
+			debugf(sc, "Done sending all the bytes for msg %d\n", sc->msg_idx);
 			/* Send stop, no interrupts on stop */
 			if (!(sc->msgs[sc->msg_idx].flags & IIC_M_NOSTOP)) {
-				debugf(sc->dev, "Done TX data, send stop\n");
+				debugf(sc, "Done TX data, send stop\n");
 				TWSI_WRITE(sc, sc->reg_control,
 				    sc->control_val | TWSI_CONTROL_STOP);
 			} else {
-				debugf(sc->dev, "Done TX data with NO_STOP\n");
+				debugf(sc, "Done TX data with NO_STOP\n");
 				TWSI_WRITE(sc, sc->reg_control, sc->control_val | TWSI_CONTROL_START);
 			}
 			sc->msg_idx++;
 			if (sc->msg_idx == sc->nmsgs) {
-				debugf(sc->dev, "transfer_done=1\n");
+				debugf(sc, "transfer_done=1\n");
 				transfer_done = 1;
 				sc->error = 0;
 			} else {
-				debugf(sc->dev, "Send repeated start\n");
+				debugf(sc, "Send repeated start\n");
 				TWSI_WRITE(sc, sc->reg_control, sc->control_val | TWSI_CONTROL_START);
 			}
 		} else {
-			debugf(sc->dev, "Sending byte %d (of %d) = %x\n",
+			debugf(sc, "Sending byte %d (of %d) = %x\n",
 			    sc->sent_bytes,
 			    sc->msgs[sc->msg_idx].len,
 			    sc->msgs[sc->msg_idx].buf[sc->sent_bytes]);
@@ -623,18 +623,18 @@ twsi_intr(void *arg)
 		break;
 
 	case TWSI_STATUS_DATA_RD_ACK:
-		debugf(sc->dev, "Ack received after receiving data\n");
+		debugf(sc, "Ack received after receiving data\n");
 		sc->msgs[sc->msg_idx].buf[sc->recv_bytes++] = TWSI_READ(sc, sc->reg_data);
-		debugf(sc->dev, "msg_len=%d recv_bytes=%d\n", sc->msgs[sc->msg_idx].len, sc->recv_bytes);
+		debugf(sc, "msg_len=%d recv_bytes=%d\n", sc->msgs[sc->msg_idx].len, sc->recv_bytes);
 
 		/* If we only have one byte left, disable ACK */
 		if (sc->msgs[sc->msg_idx].len - sc->recv_bytes == 1)
 			sc->control_val &= ~TWSI_CONTROL_ACK;
 		if (sc->msgs[sc->msg_idx].len == sc->recv_bytes) {
-			debugf(sc->dev, "Done with msg %d\n", sc->msg_idx);
+			debugf(sc, "Done with msg %d\n", sc->msg_idx);
 			sc->msg_idx++;
 			if (sc->msg_idx == sc->nmsgs - 1) {
-				debugf(sc->dev, "No more msgs\n");
+				debugf(sc, "No more msgs\n");
 				transfer_done = 1;
 				sc->error = 0;
 			}
@@ -645,12 +645,12 @@ twsi_intr(void *arg)
 	case TWSI_STATUS_DATA_RD_NOACK:
 		if (sc->msgs[sc->msg_idx].len - sc->recv_bytes == 1) {
 			sc->msgs[sc->msg_idx].buf[sc->recv_bytes++] = TWSI_READ(sc, sc->reg_data);
-			debugf(sc->dev, "Done RX data, send stop (2)\n");
+			debugf(sc, "Done RX data, send stop (2)\n");
 			if (!(sc->msgs[sc->msg_idx].flags & IIC_M_NOSTOP))
 				TWSI_WRITE(sc, sc->reg_control,
 				    sc->control_val | TWSI_CONTROL_STOP);
 		} else {
-			debugf(sc->dev, "No ack when receiving data, sending stop anyway\n");
+			debugf(sc, "No ack when receiving data, sending stop anyway\n");
 			if (!(sc->msgs[sc->msg_idx].flags & IIC_M_NOSTOP))
 				TWSI_WRITE(sc, sc->reg_control,
 				    sc->control_val | TWSI_CONTROL_STOP);
@@ -661,14 +661,14 @@ twsi_intr(void *arg)
 		break;
 
 	default:
-		debugf(sc->dev, "status=%x hot handled\n", status);
+		debugf(sc, "status=%x hot handled\n", status);
 		sc->transfer = 0;
 		sc->error = IIC_EBUSERR;
 		sc->control_val = 0;
 		wakeup(sc);
 		break;
 	}
-	debugf(sc->dev, "Refresh reg_control\n");
+	debugf(sc, "Refresh reg_control\n");
 
 	/*
 	 * Newer Allwinner chips clear IFLG after writing 1 to it.
@@ -676,7 +676,7 @@ twsi_intr(void *arg)
 	TWSI_WRITE(sc, sc->reg_control, sc->control_val |
 	    (sc->iflag_w1c ? TWSI_CONTROL_IFLG : 0));
 
-	debugf(sc->dev, "Done with interrupts\n\n");
+	debugf(sc, "Done with interrupts\n\n");
 	if (transfer_done == 1) {
 		sc->transfer = 0;
 		wakeup(sc);
@@ -701,6 +701,9 @@ int
 twsi_attach(device_t dev)
 {
 	struct twsi_softc *sc;
+	struct sysctl_ctx_list *ctx;
+	struct sysctl_oid *tree_node;
+	struct sysctl_oid_list *tree;
 
 	sc = device_get_softc(dev);
 	sc->dev = dev;
@@ -713,6 +716,15 @@ twsi_attach(device_t dev)
 		return (ENXIO);
 	}
 
+#ifdef TWSI_DEBUG
+	sc->debug = 1;
+#endif
+	ctx = device_get_sysctl_ctx(dev);
+	tree_node = device_get_sysctl_tree(dev);
+	tree = SYSCTL_CHILDREN(tree_node);
+	SYSCTL_ADD_INT(ctx, tree, OID_AUTO, "debug", CTLFLAG_RWTUN,
+	    &sc->debug, 0, "Set debug level (zero to disable)");
+
 	/* Attach the iicbus. */
 	if ((sc->iicbus = device_add_child(dev, "iicbus", -1)) == NULL) {
 		device_printf(dev, "could not allocate iicbus instance\n");
diff --git a/sys/dev/iicbus/twsi/twsi.h b/sys/dev/iicbus/twsi/twsi.h
index b10ce45be6f4..ed0ea72ab819 100644
--- a/sys/dev/iicbus/twsi/twsi.h
+++ b/sys/dev/iicbus/twsi/twsi.h
@@ -64,6 +64,7 @@ struct twsi_softc {
 	uint16_t		recv_bytes;
 	int			transfer;
 	int			error;
+	int			debug;
 	uint32_t		control_val;
 	bool			iflag_w1c;