[PATCH v2 0/4] Add trace events for SD registers.

[PATCH v2 0/4] Add trace events for SD registers.

[Raul E Rangel]

I am not able to make a single event class for all these registers. They
all have different struct sizes and different printf formats.

Thanks for the reviews!

Changes in v2:
- Made trace_sd_scr print out flags.
- Add BUILD_BUG_ON to make sure tracing stays in sync with structs.
- memcpy using sizeof(__entry->raw)

Raul E Rangel (4):
  mmc: core: Add trace event for SD SCR response
  mmc: core: Add trace event for SD SSR response
  mmc: core: Add trace event for SD OCR response
  mmc: core: Add trace event for CSD response

 drivers/mmc/core/mmc.c     |   4 +
 drivers/mmc/core/sd.c      |  10 ++
 drivers/mmc/core/sd_ops.c  |   6 ++
 include/trace/events/mmc.h | 204 +++++++++++++++++++++++++++++++++++++
 4 files changed, 224 insertions(+)

-- 
2.21.0.392.gf8f6787159e-goog

[PATCH v2 1/4] mmc: core: Add trace event for SD SCR response

[Raul E Rangel]

Example:
sd_scr: mmc0: version: 2, spec3: 1, width: [1-BIT | 4-BIT], cmds: [], raw: {0x2b58000,0x0} */

Signed-off-by: Raul E Rangel <rrangel@chromium.org>
---

 drivers/mmc/core/sd.c      |  6 +++++
 include/trace/events/mmc.h | 51 ++++++++++++++++++++++++++++++++++++++
 2 files changed, 57 insertions(+)

diff --git a/drivers/mmc/core/sd.c b/drivers/mmc/core/sd.c
index 265e1aeeb9d8..f1772972d6a3 100644
--- a/drivers/mmc/core/sd.c
+++ b/drivers/mmc/core/sd.c
@@ -21,6 +21,8 @@
 #include <linux/mmc/mmc.h>
 #include <linux/mmc/sd.h>
 
+#include <trace/events/mmc.h>
+
 #include "core.h"
 #include "card.h"
 #include "host.h"
@@ -200,6 +202,7 @@ static int mmc_decode_scr(struct mmc_card *card)
 	if (scr_struct != 0) {
 		pr_err("%s: unrecognised SCR structure version %d\n",
 			mmc_hostname(card->host), scr_struct);
+		trace_sd_scr(card, NULL);
 		return -EINVAL;
 	}
 
@@ -221,6 +224,9 @@ static int mmc_decode_scr(struct mmc_card *card)
 
 	if (scr->sda_spec3)
 		scr->cmds = UNSTUFF_BITS(resp, 32, 2);
+
+	trace_sd_scr(card, scr);
+
 	return 0;
 }
 
diff --git a/include/trace/events/mmc.h b/include/trace/events/mmc.h
index 7b706ff21335..9761d3db16db 100644
--- a/include/trace/events/mmc.h
+++ b/include/trace/events/mmc.h
@@ -10,6 +10,57 @@
 #include <linux/mmc/host.h>
 #include <linux/tracepoint.h>
 
+#define SD_SCR_WIDTH_FLAGS		\
+	{SD_SCR_BUS_WIDTH_1, "1-BIT"},	\
+	{SD_SCR_BUS_WIDTH_4, "4-BIT"}
+
+#define SD_SCR_CMD_FLAGS		\
+	{SD_SCR_CMD20_SUPPORT, "CMD20"},\
+	{SD_SCR_CMD23_SUPPORT, "CMD23"}
+
+TRACE_EVENT(sd_scr,
+
+	TP_PROTO(struct mmc_card *card, struct sd_scr *scr),
+
+	TP_ARGS(card, scr),
+
+	TP_STRUCT__entry(
+		__array(u32,			raw,	2)
+		__field(unsigned char,		sda_vsn)
+		__field(unsigned char,		sda_spec3)
+		__field(unsigned char,		bus_widths)
+		__field(unsigned char,		cmds)
+		__string(name,			mmc_hostname(card->host))
+	),
+
+	TP_fast_assign(
+		BUILD_BUG_ON(sizeof(card->raw_scr) != sizeof(__entry->raw));
+		memcpy(__entry->raw, card->raw_scr, sizeof(__entry->raw));
+		if (scr) {
+			__entry->sda_vsn = scr->sda_vsn;
+			__entry->sda_spec3 = scr->sda_spec3;
+			__entry->bus_widths = scr->bus_widths;
+			__entry->cmds = scr->cmds;
+		} else {
+			__entry->sda_vsn = 0;
+			__entry->sda_spec3 = 0;
+			__entry->bus_widths = 0;
+			__entry->cmds = 0;
+		}
+		__assign_str(name, mmc_hostname(card->host));
+	),
+
+	TP_printk("%s: version: %d, spec3: %d, width: [%s], cmds: [%s], "
+		  "raw: %s",
+		  __get_str(name),
+		  __entry->sda_vsn,
+		  __entry->sda_spec3,
+		  __print_flags(__entry->bus_widths, " | ", SD_SCR_WIDTH_FLAGS),
+		  __print_flags(__entry->cmds, " | ", SD_SCR_CMD_FLAGS),
+		  __print_array(__entry->raw, 2, sizeof(u32))
+	)
+);
+
 TRACE_EVENT(mmc_request_start,
 
 	TP_PROTO(struct mmc_host *host, struct mmc_request *mrq),
-- 
2.21.0.392.gf8f6787159e-goog

[PATCH v2 2/4] mmc: core: Add trace event for SD SSR response

[Raul E Rangel]

Example:
sd_ssr: mmc0: au: 8192, erase time: 0, erase offset: 0x0, raw: {0x0,0x3000000,0x1019000,0x10000,0x0,0x0,0x0,0x0,0x0,0x0,0x0,0x0,0x0,0x0,0x0,0x0}

Signed-off-by: Raul E Rangel <rrangel@chromium.org>
---

 drivers/mmc/core/sd.c      |  2 ++
 include/trace/events/mmc.h | 32 ++++++++++++++++++++++++++++++++
 2 files changed, 34 insertions(+)

diff --git a/drivers/mmc/core/sd.c b/drivers/mmc/core/sd.c
index f1772972d6a3..908c3087cdcd 100644
--- a/drivers/mmc/core/sd.c
+++ b/drivers/mmc/core/sd.c
@@ -292,6 +292,8 @@ static int mmc_read_ssr(struct mmc_card *card)
 	card->erase_arg = (card->scr.sda_specx && discard_support) ?
 			    SD_DISCARD_ARG : SD_ERASE_ARG;
 
+	trace_sd_ssr(card);
+
 	return 0;
 }
 
diff --git a/include/trace/events/mmc.h b/include/trace/events/mmc.h
index 9761d3db16db..463cf318d762 100644
--- a/include/trace/events/mmc.h
+++ b/include/trace/events/mmc.h
@@ -61,6 +61,38 @@ TRACE_EVENT(sd_scr,
 	)
 );
 
+TRACE_EVENT(sd_ssr,
+
+	TP_PROTO(struct mmc_card *card),
+
+	TP_ARGS(card),
+
+	TP_STRUCT__entry(
+		__array(u32,			raw,	16)
+		__field(unsigned int,		au)
+		__field(unsigned int,		erase_timeout)
+		__field(unsigned int,		erase_offset)
+		__string(name,			mmc_hostname(card->host))
+	),
+
+	TP_fast_assign(
+		BUILD_BUG_ON(sizeof(card->raw_ssr) != sizeof(__entry->raw));
+		memcpy(__entry->raw, card->raw_ssr, sizeof(__entry->raw));
+		__entry->au = card->ssr.au;
+		__entry->erase_timeout = card->ssr.erase_timeout;
+		__entry->erase_offset = card->ssr.erase_offset;
+		__assign_str(name, mmc_hostname(card->host));
+	),
+
+	TP_printk("%s: au: %d, erase time: %d, erase offset: %#x, raw: %s",
+		  __get_str(name),
+		  __entry->au,
+		  __entry->erase_timeout,
+		  __entry->erase_offset,
+		  __print_array(__entry->raw, 16, sizeof(u32))
+	)
+);
+
 TRACE_EVENT(mmc_request_start,
 
 	TP_PROTO(struct mmc_host *host, struct mmc_request *mrq),
-- 
2.21.0.392.gf8f6787159e-goog

[PATCH v2 3/4] mmc: core: Add trace event for SD OCR response

[Raul E Rangel]

Example:
sd_ocr_request: mmc0: 0x0 []
sd_ocr_request: mmc0: 0x51200000 [SDHC or SDXC Supported (HCS) | Maximum Performance (XPC) | Switch to 1.8V (S18R) | 3.3 ~ 3.4]
sd_ocr_response: mmc0: 0xff8000 [2.7 ~ 2.8 | 2.8 ~ 2.9 | 2.9 ~ 3.0 | 3.0 ~ 3.1 | 3.1 ~ 3.2 | 3.2 ~ 3.3 | 3.3 ~ 3.4 | 3.4 ~ 3.5 | 3.5 ~ 3.6]

Signed-off-by: Raul E Rangel <rrangel@chromium.org>
---

 drivers/mmc/core/sd_ops.c  |  6 +++
 include/trace/events/mmc.h | 92 ++++++++++++++++++++++++++++++++++++++
 2 files changed, 98 insertions(+)

diff --git a/drivers/mmc/core/sd_ops.c b/drivers/mmc/core/sd_ops.c
index 0bb0b8419016..4cf0f040f896 100644
--- a/drivers/mmc/core/sd_ops.c
+++ b/drivers/mmc/core/sd_ops.c
@@ -19,6 +19,8 @@
 #include <linux/mmc/mmc.h>
 #include <linux/mmc/sd.h>
 
+#include <trace/events/mmc.h>
+
 #include "core.h"
 #include "sd_ops.h"
 
@@ -130,11 +132,15 @@ int mmc_send_app_op_cond(struct mmc_host *host, u32 ocr, u32 *rocr)
 		cmd.arg = ocr;
 	cmd.flags = MMC_RSP_SPI_R1 | MMC_RSP_R3 | MMC_CMD_BCR;
 
+	trace_sd_ocr_request(host, ocr);
+
 	for (i = 100; i; i--) {
 		err = mmc_wait_for_app_cmd(host, NULL, &cmd);
 		if (err)
 			break;
 
+		trace_sd_ocr_response(host, cmd.resp[0]);
+
 		/* if we're just probing, do a single pass */
 		if (ocr == 0)
 			break;
diff --git a/include/trace/events/mmc.h b/include/trace/events/mmc.h
index 463cf318d762..8d97810221cd 100644
--- a/include/trace/events/mmc.h
+++ b/include/trace/events/mmc.h
@@ -10,6 +10,98 @@
 #include <linux/mmc/host.h>
 #include <linux/tracepoint.h>
 
+
+#define SD_OCR_REQUEST \
+	{SD_OCR_CCS, "SDHC or SDXC Supported (HCS)"}, \
+	{SD_OCR_XPC, "Maximum Performance (XPC)"}, \
+	{SD_ROCR_S18A, "Switch to 1.8V (S18R)"}, \
+	{MMC_VDD_165_195, "1.65 - 1.95"}, \
+	{MMC_VDD_20_21, "2.0 ~ 2.1"}, \
+	{MMC_VDD_21_22, "2.1 ~ 2.2"}, \
+	{MMC_VDD_22_23, "2.2 ~ 2.3"}, \
+	{MMC_VDD_23_24, "2.3 ~ 2.4"}, \
+	{MMC_VDD_24_25, "2.4 ~ 2.5"}, \
+	{MMC_VDD_25_26, "2.5 ~ 2.6"}, \
+	{MMC_VDD_26_27, "2.6 ~ 2.7"}, \
+	{MMC_VDD_27_28, "2.7 ~ 2.8"}, \
+	{MMC_VDD_28_29, "2.8 ~ 2.9"}, \
+	{MMC_VDD_29_30, "2.9 ~ 3.0"}, \
+	{MMC_VDD_30_31, "3.0 ~ 3.1"}, \
+	{MMC_VDD_31_32, "3.1 ~ 3.2"}, \
+	{MMC_VDD_32_33, "3.2 ~ 3.3"}, \
+	{MMC_VDD_33_34, "3.3 ~ 3.4"}, \
+	{MMC_VDD_34_35, "3.4 ~ 3.5"}, \
+	{MMC_VDD_35_36, "3.5 ~ 3.6"} \
+
+TRACE_EVENT(sd_ocr_request,
+
+	TP_PROTO(struct mmc_host *host, u32 ocr),
+
+	TP_ARGS(host, ocr),
+
+	TP_STRUCT__entry(
+		__field(u32,			ocr)
+		__string(name,			mmc_hostname(host))
+	),
+
+	TP_fast_assign(
+		__entry->ocr = ocr;
+		__assign_str(name, mmc_hostname(host));
+	),
+
+	TP_printk("%s: %#x [%s]",
+		  __get_str(name),
+		  __entry->ocr,
+		  __print_flags(__entry->ocr, " | ", SD_OCR_REQUEST)
+	)
+);
+
+#define SD_OCR_RESPONSE \
+	{MMC_CARD_BUSY, "Ready"}, \
+	{SD_OCR_CCS, "SDHC or SDXC (CCS)"}, \
+	{(1<<29), "UHS-II Card"}, \
+	{SD_ROCR_S18A, "1.8V Accepted (S18A)"}, \
+	{MMC_VDD_165_195, "1.65 - 1.95"}, \
+	{MMC_VDD_20_21, "2.0 ~ 2.1"}, \
+	{MMC_VDD_21_22, "2.1 ~ 2.2"}, \
+	{MMC_VDD_22_23, "2.2 ~ 2.3"}, \
+	{MMC_VDD_23_24, "2.3 ~ 2.4"}, \
+	{MMC_VDD_24_25, "2.4 ~ 2.5"}, \
+	{MMC_VDD_25_26, "2.5 ~ 2.6"}, \
+	{MMC_VDD_26_27, "2.6 ~ 2.7"}, \
+	{MMC_VDD_27_28, "2.7 ~ 2.8"}, \
+	{MMC_VDD_28_29, "2.8 ~ 2.9"}, \
+	{MMC_VDD_29_30, "2.9 ~ 3.0"}, \
+	{MMC_VDD_30_31, "3.0 ~ 3.1"}, \
+	{MMC_VDD_31_32, "3.1 ~ 3.2"}, \
+	{MMC_VDD_32_33, "3.2 ~ 3.3"}, \
+	{MMC_VDD_33_34, "3.3 ~ 3.4"}, \
+	{MMC_VDD_34_35, "3.4 ~ 3.5"}, \
+	{MMC_VDD_35_36, "3.5 ~ 3.6"}
+
+TRACE_EVENT(sd_ocr_response,
+
+	TP_PROTO(struct mmc_host *host, u32 ocr),
+
+	TP_ARGS(host, ocr),
+
+	TP_STRUCT__entry(
+		__field(u32,			ocr)
+		__string(name,			mmc_hostname(host))
+	),
+
+	TP_fast_assign(
+		__entry->ocr = ocr;
+		__assign_str(name, mmc_hostname(host));
+	),
+
+	TP_printk("%s: %#x [%s]",
+		  __get_str(name),
+		  __entry->ocr,
+		  __print_flags(__entry->ocr, " | ", SD_OCR_RESPONSE)
+	)
+);
+
 #define SD_SCR_WIDTH_FLAGS		\
 	{SD_SCR_BUS_WIDTH_1, "1-BIT"},	\
 	{SD_SCR_BUS_WIDTH_4, "4-BIT"}
-- 
2.21.0.392.gf8f6787159e-goog

[PATCH v2 4/4] mmc: core: Add trace event for CSD response

[Raul E Rangel]

Example:
mmc_csd: mmc0: struct: 0, cmdclass: 0x5b5, raw: {0x400e0032,0x5b590000,0x3b4b7f80,0xa404000}

Signed-off-by: Raul E Rangel <rrangel@chromium.org>
---

 drivers/mmc/core/mmc.c     |  4 ++++
 drivers/mmc/core/sd.c      |  2 ++
 include/trace/events/mmc.h | 29 +++++++++++++++++++++++++++++
 3 files changed, 35 insertions(+)

diff --git a/drivers/mmc/core/mmc.c b/drivers/mmc/core/mmc.c
index 3e786ba204c3..46ce894f7c03 100644
--- a/drivers/mmc/core/mmc.c
+++ b/drivers/mmc/core/mmc.c
@@ -20,6 +20,8 @@
 #include <linux/mmc/card.h>
 #include <linux/mmc/mmc.h>
 
+#include <trace/events/mmc.h>
+
 #include "core.h"
 #include "card.h"
 #include "host.h"
@@ -182,6 +184,8 @@ static int mmc_decode_csd(struct mmc_card *card)
 		csd->erase_size <<= csd->write_blkbits - 9;
 	}
 
+	trace_mmc_csd(card);
+
 	return 0;
 }
 
diff --git a/drivers/mmc/core/sd.c b/drivers/mmc/core/sd.c
index 908c3087cdcd..3b2e09fa72c5 100644
--- a/drivers/mmc/core/sd.c
+++ b/drivers/mmc/core/sd.c
@@ -183,6 +183,8 @@ static int mmc_decode_csd(struct mmc_card *card)
 
 	card->erase_size = csd->erase_size;
 
+	trace_mmc_csd(card);
+
 	return 0;
 }
 
diff --git a/include/trace/events/mmc.h b/include/trace/events/mmc.h
index 8d97810221cd..46fd918bcae3 100644
--- a/include/trace/events/mmc.h
+++ b/include/trace/events/mmc.h
@@ -185,6 +185,35 @@ TRACE_EVENT(sd_ssr,
 	)
 );
 
+TRACE_EVENT(mmc_csd,
+
+	TP_PROTO(struct mmc_card *card),
+
+	TP_ARGS(card),
+
+	TP_STRUCT__entry(
+		__array(u32,			raw,	4)
+		__field(unsigned char,		structure)
+		__field(unsigned short,		cmdclass)
+		__string(name,			mmc_hostname(card->host))
+	),
+
+	TP_fast_assign(
+		BUILD_BUG_ON(sizeof(card->raw_csd) != sizeof(__entry->raw));
+		memcpy(__entry->raw, card->raw_csd, sizeof(__entry->raw));
+		__entry->structure = card->csd.structure;
+		__entry->cmdclass = card->csd.cmdclass;
+		__assign_str(name, mmc_hostname(card->host));
+	),
+
+	TP_printk("%s: struct: %d, cmdclass: %#x, raw: %s",
+		  __get_str(name),
+		  __entry->structure,
+		  __entry->cmdclass,
+		  __print_array(__entry->raw, 4, sizeof(u32))
+	)
+);
+
 TRACE_EVENT(mmc_request_start,
 
 	TP_PROTO(struct mmc_host *host, struct mmc_request *mrq),
-- 
2.21.0.392.gf8f6787159e-goog

Re: [PATCH v2 0/4] Add trace events for SD registers.

[Ulf Hansson]

On Tue, 16 Apr 2019 at 20:33, Raul E Rangel <rrangel@chromium.org> wrote:
>
> I am not able to make a single event class for all these registers. They
> all have different struct sizes and different printf formats.
>
> Thanks for the reviews!
>
> Changes in v2:
> - Made trace_sd_scr print out flags.
> - Add BUILD_BUG_ON to make sure tracing stays in sync with structs.
> - memcpy using sizeof(__entry->raw)
>
> Raul E Rangel (4):
>   mmc: core: Add trace event for SD SCR response
>   mmc: core: Add trace event for SD SSR response
>   mmc: core: Add trace event for SD OCR response
>   mmc: core: Add trace event for CSD response
>
>  drivers/mmc/core/mmc.c     |   4 +
>  drivers/mmc/core/sd.c      |  10 ++
>  drivers/mmc/core/sd_ops.c  |   6 ++
>  include/trace/events/mmc.h | 204 +++++++++++++++++++++++++++++++++++++
>  4 files changed, 224 insertions(+)
>
> --
> 2.21.0.392.gf8f6787159e-goog
>

Why do you need this? We already have these card registers reflected
though sysfs files, isn't that sufficient?

Kind regards
Uffe

Re: [PATCH v2 0/4] Add trace events for SD registers.

[Raul Rangel]

On Tue, Apr 23, 2019 at 08:29:15AM +0200, Ulf Hansson wrote:
> On Tue, 16 Apr 2019 at 20:33, Raul E Rangel <rrangel@chromium.org> wrote:
> >
> > I am not able to make a single event class for all these registers. They
> > all have different struct sizes and different printf formats.
> >
> > Thanks for the reviews!
> >
> > Changes in v2:
> > - Made trace_sd_scr print out flags.
> > - Add BUILD_BUG_ON to make sure tracing stays in sync with structs.
> > - memcpy using sizeof(__entry->raw)
> >
> > Raul E Rangel (4):
> >   mmc: core: Add trace event for SD SCR response
> >   mmc: core: Add trace event for SD SSR response
> >   mmc: core: Add trace event for SD OCR response
> >   mmc: core: Add trace event for CSD response
> >
> >  drivers/mmc/core/mmc.c     |   4 +
> >  drivers/mmc/core/sd.c      |  10 ++
> >  drivers/mmc/core/sd_ops.c  |   6 ++
> >  include/trace/events/mmc.h | 204 +++++++++++++++++++++++++++++++++++++
> >  4 files changed, 224 insertions(+)
> >
> > --
> > 2.21.0.392.gf8f6787159e-goog
> >
> 
> Why do you need this? We already have these card registers reflected
> though sysfs files, isn't that sufficient?
> 
I was not actually aware that the registers were exposed via sysfs. I
was debugging a problem where the host controller was returning all
zeros when reading from the card. I wasn't aware that it was returning
all zeros until I added tracing. It made it quite easy to diagnose the
problem by just diffing the two traces.

Also if the card fails to mount because the data is invalid, the
registers would not be exposed via sysfs. So tracing makes gives us an
easy way to debug these types of failures.

Thanks,
Raul
> Kind regards
> Uffe

Re: [PATCH v2 0/4] Add trace events for SD registers.

[Ulf Hansson]

On Wed, 24 Apr 2019 at 17:31, Raul Rangel <rrangel@chromium.org> wrote:
>
> On Tue, Apr 23, 2019 at 08:29:15AM +0200, Ulf Hansson wrote:
> > On Tue, 16 Apr 2019 at 20:33, Raul E Rangel <rrangel@chromium.org> wrote:
> > >
> > > I am not able to make a single event class for all these registers. They
> > > all have different struct sizes and different printf formats.
> > >
> > > Thanks for the reviews!
> > >
> > > Changes in v2:
> > > - Made trace_sd_scr print out flags.
> > > - Add BUILD_BUG_ON to make sure tracing stays in sync with structs.
> > > - memcpy using sizeof(__entry->raw)
> > >
> > > Raul E Rangel (4):
> > >   mmc: core: Add trace event for SD SCR response
> > >   mmc: core: Add trace event for SD SSR response
> > >   mmc: core: Add trace event for SD OCR response
> > >   mmc: core: Add trace event for CSD response
> > >
> > >  drivers/mmc/core/mmc.c     |   4 +
> > >  drivers/mmc/core/sd.c      |  10 ++
> > >  drivers/mmc/core/sd_ops.c  |   6 ++
> > >  include/trace/events/mmc.h | 204 +++++++++++++++++++++++++++++++++++++
> > >  4 files changed, 224 insertions(+)
> > >
> > > --
> > > 2.21.0.392.gf8f6787159e-goog
> > >
> >
> > Why do you need this? We already have these card registers reflected
> > though sysfs files, isn't that sufficient?
> >
> I was not actually aware that the registers were exposed via sysfs. I
> was debugging a problem where the host controller was returning all
> zeros when reading from the card. I wasn't aware that it was returning
> all zeros until I added tracing. It made it quite easy to diagnose the
> problem by just diffing the two traces.

This sounds like a quite an unusual problem, and I don't think having
the buffers printed via tracing is worth it.

Moreover, we already have tracing per command/request (but don't print
the buffers), that should cover most of error cases during init, don't
you think?

[...]

Kind regards
Uffe