Improve mmc driver verbose logging.

Make requests logging controllable by hw.mmc.debug sysctl.

1 files changed, 78 insertions, 12 deletions

diff --git a/sys/dev/mmc/mmc.c b/sys/dev/mmc/mmc.c
index 582bdff..0981d93 100644
--- a/sys/dev/mmc/mmc.c
+++ b/sys/dev/mmc/mmc.c
@@ -62,6 +62,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/mutex.h>
 #include <sys/bus.h>
 #include <sys/endian.h>
+#include <sys/sysctl.h>
 
 #include <dev/mmc/mmcreg.h>
 #include <dev/mmc/mmcbrvar.h>
@@ -104,6 +105,11 @@ struct mmc_ivars {
 
 #define CMD_RETRIES	3
 
+SYSCTL_NODE(_hw, OID_AUTO, mmc, CTLFLAG_RD, 0, "mmc driver");
+
+int	mmc_debug;
+SYSCTL_INT(_hw_mmc, OID_AUTO, debug, CTLFLAG_RW, &mmc_debug, 0, "Debug level");
+
 /* bus entry points */
 static int mmc_probe(device_t dev);
 static int mmc_attach(device_t dev);
@@ -233,7 +239,7 @@ mmc_acquire_bus(device_t busdev, device_t dev)
 			sc->last_rca = rca;
 			/* Prepare bus width for the new card. */
 			ivar = device_get_ivars(dev);
-			if (bootverbose) {
+			if (bootverbose || mmc_debug) {
 				device_printf(busdev,
 				    "setting bus width to %d bits\n",
 				    (ivar->bus_width == bus_width_4) ? 4 :
@@ -315,11 +321,21 @@ mmc_wait_for_req(struct mmc_softc *sc, struct mmc_request *req)
 
 	req->done = mmc_wakeup;
 	req->done_data = sc;
+	if (mmc_debug) {
+		device_printf(sc->dev, "REQUEST: CMD%d arg %#x flags %#x",
+		    req->cmd->opcode, req->cmd->arg, req->cmd->flags);
+		if (req->cmd->data) {
+			printf(" data %d\n", (int)req->cmd->data->len);
+		} else
+			printf("\n");
+	}
 	MMCBR_REQUEST(device_get_parent(sc->dev), sc->dev, req);
 	MMC_LOCK(sc);
 	while ((req->flags & MMC_REQ_DONE) == 0)
 		msleep(req, &sc->sc_mtx, 0, "mmcreq", 0);
 	MMC_UNLOCK(sc);
+	if (mmc_debug > 1 || (mmc_debug && req->cmd->error))
+		device_printf(sc->dev, "RESULT: %d\n", req->cmd->error);
 	return (0);
 }
 
@@ -340,9 +356,6 @@ mmc_wait_for_cmd(struct mmc_softc *sc, struct mmc_command *cmd, int retries)
 	memset(cmd->resp, 0, sizeof(cmd->resp));
 	cmd->retries = retries;
 	mreq.cmd = cmd;
-	if (bootverbose)
-		device_printf(sc->dev, "CMD: %#x ARG %#x\n", cmd->opcode,
-		    cmd->arg);
 	mmc_wait_for_req(sc, &mreq);
 	return (cmd->error);
 }
@@ -748,9 +761,10 @@ mmc_decode_cid_sd(uint32_t *raw_cid, struct mmc_cid *cid)
 	cid->oid = mmc_get_bits(raw_cid, 128, 104, 16);
 	for (i = 0; i < 5; i++)
 		cid->pnm[i] = mmc_get_bits(raw_cid, 128, 96 - i * 8, 8);
+	cid->pnm[5] = 0;
 	cid->prv = mmc_get_bits(raw_cid, 128, 56, 8);
 	cid->psn = mmc_get_bits(raw_cid, 128, 24, 32);
-	cid->mdt_year = mmc_get_bits(raw_cid, 128, 12, 8) + 2001;
+	cid->mdt_year = mmc_get_bits(raw_cid, 128, 12, 8) + 2000;
 	cid->mdt_month = mmc_get_bits(raw_cid, 128, 8, 4);
 }
 
@@ -765,6 +779,7 @@ mmc_decode_cid_mmc(uint32_t *raw_cid, struct mmc_cid *cid)
 	cid->oid = mmc_get_bits(raw_cid, 128, 104, 8);
 	for (i = 0; i < 6; i++)
 		cid->pnm[i] = mmc_get_bits(raw_cid, 128, 96 - i * 8, 8);
+	cid->pnm[6] = 0;
 	cid->prv = mmc_get_bits(raw_cid, 128, 48, 8);
 	cid->psn = mmc_get_bits(raw_cid, 128, 16, 32);
 	cid->mdt_month = mmc_get_bits(raw_cid, 128, 12, 4);
@@ -1059,6 +1074,29 @@ mmc_send_relative_addr(struct mmc_softc *sc, uint32_t *resp)
 }
 
 static void
+mmc_log_card(device_t dev, struct mmc_ivars *ivar, int newcard)
+{
+	device_printf(dev, "Card at relative address %d%s:\n",
+	    ivar->rca, newcard ? " added" : "");
+	device_printf(dev, " card: %s%s (0x%x/0x%x/\"%s\" rev %d.%d "
+	    "m/d %02d.%04d s/n %08x)\n",
+	    ivar->mode == mode_sd ? "SD" : "MMC",
+	    ivar->high_cap ? " High Capacity" : "", 
+	    ivar->cid.mid, ivar->cid.oid,
+	    ivar->cid.pnm, ivar->cid.prv >> 4, ivar->cid.prv & 0x0f,
+	    ivar->cid.mdt_month, ivar->cid.mdt_year, ivar->cid.psn);
+	device_printf(dev, " bus: %ubit, %uMHz%s\n",
+	    (ivar->bus_width == bus_width_1 ? 1 :
+	    (ivar->bus_width == bus_width_4 ? 4 : 8)),
+	    (ivar->timing == bus_timing_hs ?
+		ivar->hs_tran_speed : ivar->tran_speed) / 1000000,
+	    ivar->timing == bus_timing_hs ? ", high speed timing" : "");
+	device_printf(dev, " memory: %u blocks, erase sector %u blocks%s\n",
+	    ivar->sec_count, ivar->erase_sector,
+	    ivar->read_only ? ", read-only" : "");
+}
+
+static void
 mmc_discover_cards(struct mmc_softc *sc)
 {
 	struct mmc_ivars *ivar = NULL;
@@ -1070,6 +1108,8 @@ mmc_discover_cards(struct mmc_softc *sc)
 	uint16_t rca = 2;
 	u_char switch_res[64];
 
+	if (bootverbose || mmc_debug)
+		device_printf(sc->dev, "Probing cards\n");
 	while (1) {
 		err = mmc_all_send_cid(sc, raw_cid);
 		if (err == MMC_ERR_TIMEOUT)
@@ -1089,6 +1129,11 @@ mmc_discover_cards(struct mmc_softc *sc)
 			}
 		}
 		free(devlist, M_TEMP);
+		if (bootverbose || mmc_debug) {
+			device_printf(sc->dev, "%sard detected (CID %08x%08x%08x%08x)\n",
+			    newcard ? "New c" : "C",
+			    raw_cid[0], raw_cid[1], raw_cid[2], raw_cid[3]);
+		}
 		if (newcard) {
 			ivar = malloc(sizeof(struct mmc_ivars), M_DEVBUF,
 			    M_WAITOK | M_ZERO);
@@ -1139,6 +1184,8 @@ mmc_discover_cards(struct mmc_softc *sc)
 			if ((mmcbr_get_caps(sc->dev) & MMC_CAP_4_BIT_DATA) &&
 			    (ivar->scr.bus_widths & SD_SCR_BUS_WIDTH_4))
 				ivar->bus_width = bus_width_4;
+			if (bootverbose || mmc_debug)
+				mmc_log_card(sc->dev, ivar, newcard);
 			if (newcard) {
 				/* Add device. */
 				child = device_add_child(sc->dev, NULL, -1);
@@ -1194,6 +1241,8 @@ mmc_discover_cards(struct mmc_softc *sc)
 			ivar->bus_width = bus_width_1;
 			ivar->timing = bus_timing_normal;
 		}
+		if (bootverbose || mmc_debug)
+			mmc_log_card(sc->dev, ivar, newcard);
 		if (newcard) {
 			/* Add device. */
 			child = device_add_child(sc->dev, NULL, -1);
@@ -1214,6 +1263,9 @@ mmc_rescan_cards(struct mmc_softc *sc)
 	for (i = 0; i < devcount; i++) {
 		ivar = device_get_ivars(devlist[i]);
 		if (mmc_select_card(sc, ivar->rca)) {
+			if (bootverbose || mmc_debug)
+				device_printf(sc->dev, "Card at relative address %d lost.\n",
+				    ivar->rca);
 			device_delete_child(sc->dev, devlist[i]);
 			free(ivar, M_DEVBUF);
 		}
@@ -1233,6 +1285,9 @@ mmc_delete_cards(struct mmc_softc *sc)
 		return (err);
 	for (i = 0; i < devcount; i++) {
 		ivar = device_get_ivars(devlist[i]);
+		if (bootverbose || mmc_debug)
+			device_printf(sc->dev, "Card at relative address %d deleted.\n",
+			    ivar->rca);
 		device_delete_child(sc->dev, devlist[i]);
 		free(ivar, M_DEVBUF);
 	}
@@ -1255,21 +1310,30 @@ mmc_go_discovery(struct mmc_softc *sc)
 		mmcbr_set_mode(dev, mode_sd);
 		mmc_power_up(sc);
 		mmcbr_set_bus_mode(dev, pushpull);
-		if (bootverbose)
-			device_printf(sc->dev, "Idle cards for SD probe\n");
+		if (bootverbose || mmc_debug)
+			device_printf(sc->dev, "Probing bus\n");
 		mmc_idle_cards(sc);
 		err = mmc_send_if_cond(sc, 1);
-		if (bootverbose)
-			device_printf(sc->dev, "SD: SEND_IF_CONF %d\n", err);
+		if ((bootverbose || mmc_debug) && err == 0)
+			device_printf(sc->dev, "SD 2.0 interface conditions: OK\n");
 		if (mmc_send_app_op_cond(sc, err ? 0 : MMC_OCR_CCS, &ocr) !=
 		    MMC_ERR_NONE) {
+			if (bootverbose || mmc_debug)
+				device_printf(sc->dev, "SD probe: failed\n");
 			/*
 			 * Failed, try MMC
 			 */
 			mmcbr_set_mode(dev, mode_mmc);
-			if (mmc_send_op_cond(sc, 0, &ocr) != MMC_ERR_NONE)
+			if (mmc_send_op_cond(sc, 0, &ocr) != MMC_ERR_NONE) {
+				if (bootverbose || mmc_debug)
+					device_printf(sc->dev, "MMC probe: failed\n");
 				ocr = 0; /* Failed both, powerdown. */
-		}
+			} else if (bootverbose || mmc_debug)
+				device_printf(sc->dev,
+				    "MMC probe: OK (OCR: 0x%08x)\n", ocr);
+		} else if (bootverbose || mmc_debug)
+			device_printf(sc->dev, "SD probe: OK (OCR: 0x%08x)\n", ocr);
+
 		mmcbr_set_ocr(dev, mmc_select_vdd(sc, ocr));
 		if (mmcbr_get_ocr(dev) != 0)
 			mmc_idle_cards(sc);
@@ -1283,6 +1347,8 @@ mmc_go_discovery(struct mmc_softc *sc)
 	 * Make sure that we have a mutually agreeable voltage to at least
 	 * one card on the bus.
 	 */
+	if (bootverbose || mmc_debug)
+		device_printf(sc->dev, "Current OCR: 0x%08x\n", mmcbr_get_ocr(dev));
 	if (mmcbr_get_ocr(dev) == 0) {
 		mmc_delete_cards(sc);
 		mmc_power_down(sc);
@@ -1344,7 +1410,7 @@ mmc_calculate_clock(struct mmc_softc *sc)
 	free(kids, M_TEMP);
 	if (max_timing == bus_timing_hs)
 		max_dtr = max_hs_dtr;
-	if (bootverbose) {
+	if (bootverbose || mmc_debug) {
 		device_printf(sc->dev,
 		    "setting transfer rate to %d.%03dMHz%s\n",
 		    max_dtr / 1000000, (max_dtr / 1000) % 1000,