[PATCH v1 0/4] Add tracing for SDHCI register access

[PATCH v1 0/4] Add tracing for SDHCI register access

[Raul E Rangel]

I was debugging a SDHC hardware bug and got tired of having to
translate the register values by hand. This patch set makes it so all
SDHC register read and write operations can be traced and easily read by
a human.

An example trace can be seen here: https://pastebin.com/x73d5cvL

I ended up defining a new tracing function `trace_print_register`. This
method takes a register definition and pretty prints it. It's a hybrid
of `trace_print_flags_seq` and `trace_print_symbols_seq`. It supports
printing bit fields, enum fields, and numeric fields. See the
documentation for usage.

I hope this makes someone else's life easier when debugging SDHC
hardware problems.

Raul E Rangel (4):
  trace_events: Add trace_print_register to print register fields
  mmc/sdhci: Rename sdhci.c to sdhci-core.c
  mmc/host/sdhci: Add register read and write trace events
  mmc/host/sdhci: Make sdhci_read/sdhci_write call trace functions

 drivers/mmc/host/Makefile                  |   4 +
 drivers/mmc/host/{sdhci.c => sdhci-core.c} | 136 +++++++++
 drivers/mmc/host/sdhci-trace.c             | 319 +++++++++++++++++++++
 drivers/mmc/host/sdhci-trace.h             |  93 ++++++
 drivers/mmc/host/sdhci.h                   |  89 +-----
 include/linux/trace_events.h               |   4 +
 include/linux/tracepoint-defs.h            |   6 +
 include/trace/trace_events.h               |   9 +
 kernel/trace/trace_output.c                | 121 ++++++++
 9 files changed, 698 insertions(+), 83 deletions(-)
 rename drivers/mmc/host/{sdhci.c => sdhci-core.c} (97%)
 create mode 100644 drivers/mmc/host/sdhci-trace.c
 create mode 100644 drivers/mmc/host/sdhci-trace.h

-- 
2.21.0.392.gf8f6787159e-goog

[PATCH v1 1/4] trace_events: Add trace_print_register to print register fields

[Raul E Rangel]

This is a hybrid method that combines the functionality of
trace_print_flags_seq and trace_print_symbols_seq. It supports printing
bit fields, enum fields, and numeric fields.

Given the following register definition:
  * 0   - Enabled
  * 1   - Width, 0 = 1-bits, 1 = 4-bits
  * 2:3 - DMA, 0 = None, 1 = SDMA, 2 = ADMA, 3 = ADMA2
  * 4:7 - Timeout Counter

The register fields could be defined as follows:

  const struct trace_print_field reg[] = {
    {1<<0, "ENABLED"},
    {
      .mask = 1<<1,
      .name = "WIDTH",
      .symbols = (const struct trace_print_flags[]) {
        {0, "1-BIT"},
        {1, "4-BIT"},
        {}
      }
    }, {
      .mask = 3<<2,
      .symbols = (const struct trace_print_flags[]) {
        {0, "NONE"},
        {1, "SDMA"},
        {2, "ADMA"},
        {3, "ADMA2"},
        {}
      }
    },
    {0xF<<4, "TIMEOUT"}
  }

This would print out the following given value 0xAB:

ENABLED: 1 | WIDTH: 4-BIT | ADMA | TIMEOUT: 0xA

See https://pastebin.com/x73d5cvL for this in action.

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

 include/linux/trace_events.h    |   4 ++
 include/linux/tracepoint-defs.h |   6 ++
 include/trace/trace_events.h    |   9 +++
 kernel/trace/trace_output.c     | 121 ++++++++++++++++++++++++++++++++
 4 files changed, 140 insertions(+)

diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index 8a62731673f7..3c44909ce8b3 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -23,6 +23,10 @@ const char *trace_print_flags_seq(struct trace_seq *p, const char *delim,
 const char *trace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 				    const struct trace_print_flags *symbol_array);
 
+const char *trace_print_register(struct trace_seq *p,
+				 const struct trace_print_field fields[],
+				 unsigned long val, unsigned long mask);
+
 #if BITS_PER_LONG == 32
 const char *trace_print_flags_seq_u64(struct trace_seq *p, const char *delim,
 		      unsigned long long flags,
diff --git a/include/linux/tracepoint-defs.h b/include/linux/tracepoint-defs.h
index 49ba9cde7e4b..c3dc27c192f4 100644
--- a/include/linux/tracepoint-defs.h
+++ b/include/linux/tracepoint-defs.h
@@ -16,6 +16,12 @@ struct trace_print_flags {
 	const char		*name;
 };
 
+struct trace_print_field {
+	unsigned long			mask;
+	const char			*name;
+	const struct trace_print_flags	*symbols;
+};
+
 struct trace_print_flags_u64 {
 	unsigned long long	mask;
 	const char		*name;
diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
index 4ecdfe2e3580..6adc32fcb1c3 100644
--- a/include/trace/trace_events.h
+++ b/include/trace/trace_events.h
@@ -300,6 +300,14 @@ TRACE_MAKE_SYSTEM_STR();
 		trace_print_symbols_seq(p, value, symbols);		\
 	})
 
+#undef __print_register
+#define __print_register(value, mask, field_array...)			\
+	({								\
+		static const struct trace_print_field fields[] =	\
+			{ field_array, {} };			\
+		trace_print_register(p, value, mask, fields);		\
+	})
+
 #undef __print_flags_u64
 #undef __print_symbolic_u64
 #if BITS_PER_LONG == 32
@@ -744,6 +752,7 @@ static inline void ftrace_test_probe_##call(void)			\
 
 #undef __print_flags
 #undef __print_symbolic
+#undef __print_register
 #undef __print_hex
 #undef __print_hex_str
 #undef __get_dynamic_array
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 54373d93e251..cd5727ad54c3 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -124,6 +124,127 @@ trace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 }
 EXPORT_SYMBOL(trace_print_symbols_seq);
 
+/**
+ * trace_print_register - Prints all the fields of a register.
+ *
+ * This is a hybrid method that combines the functionality of
+ * trace_print_flags_seq and trace_print_symbols_seq. It supports printing
+ * bit fields, enum fields, and numeric fields.
+ *
+ * Given the following register definition:
+ *   * 0   - Enabled
+ *   * 1   - Width, 0 = 1-bits, 1 = 4-bits
+ *   * 2:3 - DMA, 0 = None, 1 = SDMA, 2 = ADMA, 3 = ADMA2
+ *   * 4:7 - Timeout Counter
+ *
+ * The register fields could be defined as follows:
+ *
+ *   const struct trace_print_field reg[] = {
+ *     {1<<0, "ENABLED"},
+ *     {
+ *       .mask = 1<<1,
+ *       .name = "WIDTH",
+ *       .symbols = (const struct trace_print_flags[]) {
+ *         {0, "1-BIT"},
+ *         {1, "4-BIT"},
+ *         {}
+ *       }
+ *     }, {
+ *       .mask = 3<<2,
+ *       .symbols = (const struct trace_print_flags[]) {
+ *         {0, "NONE"},
+ *         {1, "SDMA"},
+ *         {2, "ADMA"},
+ *         {3, "ADMA2"},
+ *         {}
+ *       }
+ *     },
+ *     {0xF<<4, "TIMEOUT"}
+ *   }
+ *
+ * This would print out the following given value 0xAB:
+ *
+ * ENABLED: 1 | WIDTH: 4-BIT | ADMA | TIMEOUT: 0xA
+ *
+ * @p: trace buffer
+ * @fields: Array of fields that describe the register. Must be terminated with
+ *          an empty value.
+ * @val: register value
+ * @mask: Mask that defines the bits present in @val. Useful if only a subset
+ *        of the register was read. Any fields that fall outside of the mask
+ *        will not be printed.
+ */
+const char *trace_print_register(struct trace_seq *p,
+				 const struct trace_print_field fields[],
+				 unsigned long val, unsigned long mask)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+	char *tail;
+	unsigned long fval;
+	int first = 1, symbol_found;
+	const struct trace_print_field *field;
+	const struct trace_print_flags *symbol;
+
+	for (field = fields; field->mask; field++) {
+		/* Make sure the field mask is within the accessed bits */
+		if ((mask & field->mask) != field->mask)
+			continue;
+
+		if (!first)
+			trace_seq_puts(p, " | ");
+
+		first = 0;
+
+		if (field->name) {
+			trace_seq_puts(p, field->name);
+			trace_seq_puts(p, ": ");
+		}
+
+		fval = val & field->mask;
+		fval >>= ffs(field->mask) - 1;
+
+		val &= ~field->mask;
+
+		symbol_found = 0;
+		for (symbol = field->symbols; symbol && symbol->name;
+		     symbol++) {
+			if (symbol->mask != fval)
+				continue;
+			trace_seq_puts(p, symbol->name);
+			symbol_found = 1;
+			break;
+		}
+
+		if (!symbol_found) {
+			if (fval == 0) {
+				trace_seq_puts(p, "0");
+			} else if (fval == 1) {
+				trace_seq_puts(p, "1");
+			} else {
+				trace_seq_printf(p, "%#x", fval);
+
+				/* Strip off the null terminator */
+				for (tail = trace_seq_buffer_ptr(p) - 1;
+				     tail > ret && !*tail; tail--) {
+					p->seq.len--;
+				}
+			}
+		}
+	}
+
+	/* Print any left over bits */
+	if (val) {
+		if (!first)
+			trace_seq_puts(p, " | ");
+		trace_seq_printf(p, "%#x", val);
+	}
+
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
+EXPORT_SYMBOL(trace_print_register);
+
 #if BITS_PER_LONG == 32
 const char *
 trace_print_flags_seq_u64(struct trace_seq *p, const char *delim,
-- 
2.21.0.392.gf8f6787159e-goog

[PATCH v1 2/4] mmc/sdhci: Rename sdhci.c to sdhci-core.c

[Raul E Rangel]

Preparing to add an sdhci-trace.o to the sdhci module.

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

 drivers/mmc/host/Makefile                  | 1 +
 drivers/mmc/host/{sdhci.c => sdhci-core.c} | 0
 2 files changed, 1 insertion(+)
 rename drivers/mmc/host/{sdhci.c => sdhci-core.c} (100%)

diff --git a/drivers/mmc/host/Makefile b/drivers/mmc/host/Makefile
index 73578718f119..11174945c116 100644
--- a/drivers/mmc/host/Makefile
+++ b/drivers/mmc/host/Makefile
@@ -11,6 +11,7 @@ obj-$(CONFIG_MMC_PXA)		+= pxamci.o
 obj-$(CONFIG_MMC_MXC)		+= mxcmmc.o
 obj-$(CONFIG_MMC_MXS)		+= mxs-mmc.o
 obj-$(CONFIG_MMC_SDHCI)		+= sdhci.o
+sdhci-objs			+= sdhci-core.o
 obj-$(CONFIG_MMC_SDHCI_PCI)	+= sdhci-pci.o
 sdhci-pci-y			+= sdhci-pci-core.o sdhci-pci-o2micro.o sdhci-pci-arasan.o \
 				   sdhci-pci-dwc-mshc.o
diff --git a/drivers/mmc/host/sdhci.c b/drivers/mmc/host/sdhci-core.c
similarity index 100%
rename from drivers/mmc/host/sdhci.c
rename to drivers/mmc/host/sdhci-core.c
-- 
2.21.0.392.gf8f6787159e-goog

[PATCH v1 3/4] mmc/host/sdhci: Add register read and write trace events

[Raul E Rangel]

Adds an sdhci-trace object file that is linked with the sdhci module.
This will allow sdhci-core to call the trace functions.

There weren't constants defined for some of the fields, so I just used
the raw values.

See the next change for usage.

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

 drivers/mmc/host/Makefile      |   5 +-
 drivers/mmc/host/sdhci-trace.c | 319 +++++++++++++++++++++++++++++++++
 drivers/mmc/host/sdhci-trace.h |  93 ++++++++++
 3 files changed, 416 insertions(+), 1 deletion(-)
 create mode 100644 drivers/mmc/host/sdhci-trace.c
 create mode 100644 drivers/mmc/host/sdhci-trace.h

diff --git a/drivers/mmc/host/Makefile b/drivers/mmc/host/Makefile
index 11174945c116..1cb695a3b359 100644
--- a/drivers/mmc/host/Makefile
+++ b/drivers/mmc/host/Makefile
@@ -3,6 +3,9 @@
 # Makefile for MMC/SD host controller drivers
 #
 
+# tell define_trace.h where to find the sdhci trace header
+CFLAGS_sdhci-trace.o := -I$(src)
+
 obj-$(CONFIG_MMC_ARMMMCI) += armmmci.o
 armmmci-y := mmci.o
 armmmci-$(CONFIG_MMC_QCOM_DML) += mmci_qcom_dml.o
@@ -11,7 +14,7 @@ obj-$(CONFIG_MMC_PXA)		+= pxamci.o
 obj-$(CONFIG_MMC_MXC)		+= mxcmmc.o
 obj-$(CONFIG_MMC_MXS)		+= mxs-mmc.o
 obj-$(CONFIG_MMC_SDHCI)		+= sdhci.o
-sdhci-objs			+= sdhci-core.o
+sdhci-objs			+= sdhci-core.o sdhci-trace.o
 obj-$(CONFIG_MMC_SDHCI_PCI)	+= sdhci-pci.o
 sdhci-pci-y			+= sdhci-pci-core.o sdhci-pci-o2micro.o sdhci-pci-arasan.o \
 				   sdhci-pci-dwc-mshc.o
diff --git a/drivers/mmc/host/sdhci-trace.c b/drivers/mmc/host/sdhci-trace.c
new file mode 100644
index 000000000000..a7d803470664
--- /dev/null
+++ b/drivers/mmc/host/sdhci-trace.c
@@ -0,0 +1,319 @@
+// SPDX-License-Identifier: GPL-2.0
+// Copyright 2019 Google LLC.
+
+#include <linux/trace_events.h>
+#include "sdhci.h"
+
+#define SDHCI_REGS \
+	{SDHCI_DMA_ADDRESS, "DMA_ADDRESS"}, \
+	{SDHCI_BLOCK_SIZE, "BLOCK_SIZE"}, \
+	{SDHCI_ARGUMENT, "ARGUMENT"}, \
+	{SDHCI_TRANSFER_MODE, "TRANSFER_MODE"}, \
+	{SDHCI_RESPONSE, "RESP10"}, \
+	{SDHCI_RESPONSE + 4, "RESP32"}, \
+	{SDHCI_RESPONSE + 8, "RESP54"}, \
+	{SDHCI_RESPONSE + 12, "RESP76"}, \
+	{SDHCI_BUFFER, "BUFFER"}, \
+	{SDHCI_PRESENT_STATE, "PRESENT_STATE"}, \
+	{SDHCI_HOST_CONTROL, "HOST_CONTROL"}, \
+	{SDHCI_CLOCK_CONTROL, "CLOCK_CONTROL"}, \
+	{SDHCI_INT_STATUS, "INT_STATUS"}, \
+	{SDHCI_INT_ENABLE, "INT_ENABLE"}, \
+	{SDHCI_SIGNAL_ENABLE, "SIGNAL_ENABLE"}, \
+	{SDHCI_ACMD12_ERR, "ACMD12_ERR"}, \
+	{SDHCI_CAPABILITIES, "CAPABILITIES"}, \
+	{SDHCI_CAPABILITIES_1, "CAPABILITIES_1"}, \
+	{SDHCI_MAX_CURRENT, "MAX_CURRENT"}, \
+	{SDHCI_SET_ACMD12_ERROR, "SET_ACMD12_ERROR"}, \
+	{SDHCI_ADMA_ERROR, "ADMA_ERROR"}, \
+	{SDHCI_ADMA_ADDRESS, "ADMA_ADDRESS"}, \
+	{SDHCI_ADMA_ADDRESS_HI, "ADMA_ADDRESS_HI"}, \
+	{SDHCI_SLOT_INT_STATUS, "SLOT_INT_STATUS"}
+
+static const struct trace_print_flags const int_flags[] = {
+	{SDHCI_INT_RESPONSE, "RESPONSE"},
+	{SDHCI_INT_DATA_END, "DATA_END"},
+	{SDHCI_INT_BLK_GAP, "BLK_GAP"},
+	{SDHCI_INT_DMA_END, "DMA_END"},
+	{SDHCI_INT_SPACE_AVAIL, "SPACE_AVAIL"},
+	{SDHCI_INT_DATA_AVAIL, "DATA_AVAIL"},
+	{SDHCI_INT_CARD_INSERT, "CARD_INSERT"},
+	{SDHCI_INT_CARD_REMOVE, "CARD_REMOVE"},
+	{SDHCI_INT_CARD_INT, "CARD_INT"},
+	{SDHCI_INT_RETUNE, "RETUNE"},
+	{SDHCI_INT_CQE, "CQE"},
+	{SDHCI_INT_ERROR, "ERROR"},
+	{SDHCI_INT_TIMEOUT, "TIMEOUT"},
+	{SDHCI_INT_CRC, "CRC"},
+	{SDHCI_INT_END_BIT, "END_BIT"},
+	{SDHCI_INT_INDEX, "INDEX"},
+	{SDHCI_INT_DATA_TIMEOUT, "DATA_TIMEOUT"},
+	{SDHCI_INT_DATA_CRC, "DATA_CRC"},
+	{SDHCI_INT_DATA_END_BIT, "DATA_END_BIT"},
+	{SDHCI_INT_BUS_POWER, "BUS_POWER"},
+	{SDHCI_INT_ACMD12ERR, "ACMD12ERR"},
+	{SDHCI_INT_ADMA_ERROR, "ADMA_ERROR"},
+	{ -1, NULL }
+};
+
+static const struct trace_print_flags const present_state_flags[] = {
+	{SDHCI_CMD_INHIBIT, "CMD_INHIBIT"},
+	{SDHCI_DATA_INHIBIT, "DATA_INHIBIT"},
+	{1<<2, "DAT_LINE_ACTIVE"},
+	{SDHCI_DOING_WRITE, "DOING_WRITE"},
+	{SDHCI_DOING_READ, "DOING_READ"},
+	{SDHCI_SPACE_AVAILABLE, "SPACE_AVAILABLE"},
+	{SDHCI_DATA_AVAILABLE, "DATA_AVAILABLE"},
+	{SDHCI_CARD_PRESENT, "CARD_PRESENT"},
+	{1<<17, "CARD_STABLE"},
+	{1<<18, "CD_HIGH"},
+	{SDHCI_WRITE_PROTECT, "WRITE_PROTECT"},
+	{1<<20, "DATA0"},
+	{1<<21, "DATA1"},
+	{1<<22, "DATA2"},
+	{1<<23, "DATA3"},
+	{SDHCI_CMD_LVL, "CMD_LVL"},
+	{ -1, NULL }
+};
+
+static const struct trace_print_field block_cnt_reg[] = {
+	{
+		.mask = 0xFFF,
+		.name = "BLOCK_SIZE"
+	},
+	{
+		.mask = 7 << 12,
+		.name = "DMA_BUF_BOUNDARY",
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "4K"},
+			{1, "8K"},
+			{2, "16K"},
+			{3, "32K"},
+			{4, "64K"},
+			{5, "128K"},
+			{6, "256K"},
+			{7, "512K"},
+			{}
+		}
+	},
+	{
+		.mask = 0xFFFF << 16,
+		.name = "BLOCK_CNT"
+	},
+};
+
+static const struct trace_print_field host_control_reg[] = {
+	{
+		.mask = SDHCI_CTRL_LED,
+		.name = "LED",
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "OFF"},
+			{1, "ON"},
+			{}
+		}
+	}, {
+		.mask = SDHCI_CTRL_4BITBUS,
+		.name = "TX_WIDTH",
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "1-BIT"},
+			{1, "4-BIT"},
+			{}
+		}
+	}, {
+		.mask = SDHCI_CTRL_HISPD,
+		.name = "HIGH_SPEED"
+	}, {
+		.mask = SDHCI_CTRL_DMA_MASK,
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "SDMA"},
+			{1, "ADMA-32"},
+			{2, "ADMA2-32"},
+			{3, "ADMA2-64"},
+			{}
+		}
+	}, {
+		.mask = SDHCI_CTRL_8BITBUS,
+		.name = "MMC_WIDTH",
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "DAT_WIDTH"},
+			{1, "8-BIT"},
+			{}
+		}
+	},
+	{SDHCI_CTRL_CDTEST_INS, "CDTEST_INS"},
+	{SDHCI_CTRL_CDTEST_EN, "CDTEST_EN"},
+	{1<<8, "BUS_POWER"},
+	{
+		.mask = 0x7 << 9,
+		.name = "BUS_VOLTAGE",
+		.symbols = (const struct trace_print_flags[]) {
+			{0x00, "0.0V"},
+			{0x05, "1.8V"},
+			{0x06, "3.0V"},
+			{0x07, "3.3V"},
+			{}
+		}
+	},
+	{1<<16, "BLOCK_GAP_STOP"},
+	{1<<17, "CONT_REQ"},
+	{1<<18, "READ_WAIT_EN"},
+	{1<<19, "BLOCK_GAP_INT_EN"},
+	{1<<24, "INT_WAKE_EN"},
+	{1<<25, "INS_WAKE_EN"},
+	{1<<26, "REM_WAKE_EN"},
+	{},
+};
+
+static const struct trace_print_field transfer_mode_reg[] = {
+	{SDHCI_TRNS_DMA, "DMA_EN"},
+	{SDHCI_TRNS_BLK_CNT_EN, "BLK_CNT_EN"},
+	{
+		.mask = 0xC,
+		.name = "AUTO_CMD",
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "DISABLED"},
+			{1, "12"},
+			{2, "23"},
+			{3, "RESERVED"},
+			{}
+		}
+	}, {
+		.mask = SDHCI_TRNS_READ,
+		.name = "DATA_DIR",
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "WRITE"},
+			{1, "READ"},
+			{}
+		}
+	},
+	{SDHCI_TRNS_MULTI, "MULTI_BLK"},
+	{
+		.mask = 0x3 << 16,
+		.name = "RESP_TYPE",
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "NONE"},
+			{1, "136-BITS"},
+			{2, "48-BITS"},
+			{3, "48-BITS W/ BUSY"},
+			{}
+		}
+	},
+	{1<<19, "CRC_CHECK_EN"},
+	{1<<20, "CMD_IDX_CHECK_EN"},
+	{1<<21, "DATA_PRESENT"},
+	{
+		.mask = 0x3 << 22,
+		.name = "CMD_TYPE",
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "NORMAL"},
+			{1, "SUSPEND CMD52"},
+			{2, "RESUME CMD52"},
+			{3, "ABORT"},
+			{}
+		}
+	},
+	{0x3f << 24, "CMD"},
+	{},
+};
+
+static const struct trace_print_field const clk_control_reg[] = {
+	{1<<0, "SYSCLK_EN"},
+	{1<<1, "SYSCLK_STABLE"},
+	{1<<2, "SDCLK_EN"},
+	{1<<5, "PRG_CLK_MODE"},
+	{0xc0, "SD_CLK_DIV[9:8]"},
+	{0xFF00, "SD_CLK_DIV"},
+	{0xF0000, "DATA_TIMEOUT_CNT"},
+	{1<<24, "SOFT_RESET_ALL"},
+	{1<<25, "SOFT_RESET_CMD"},
+	{1<<26, "SOFT_RESET_DAT"},
+	{}
+};
+
+static const struct trace_print_field const acmd_err_flags[] = {
+	{1<<0, "EXEC_ERROR"},
+	{1<<1, "TIMEOUT_ERROR"},
+	{1<<2, "CRC_ERROR"},
+	{1<<3, "END_BIT_ERROR"},
+	{1<<4, "INDEX_ERROR"},
+	{1<<7, "CMD_ERROR"},
+	{
+		.mask = 7 << 16,
+		.name = "UHS_MODE",
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "SDR12"},
+			{1, "SDR25"},
+			{2, "SDR50"},
+			{3, "SDR104"},
+			{4, "DDR50"},
+			{}
+		}
+	},
+	{
+		.mask = 1 << 19,
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "3.3V"},
+			{1, "1.8V"},
+			{}
+		}
+	},
+	{
+		.mask = 3 << 20,
+		.name = "DRIVE_STRENGTH",
+		.symbols = (const struct trace_print_flags[]) {
+			{0, "B"},
+			{1, "A"},
+			{2, "C"},
+			{3, "D"},
+			{}
+		}
+	},
+	{1<<22, "TUNING"},
+	{1<<23, "SAMPLE_CLK"},
+	{1<<30, "ASYNC_INT_EN"},
+	{1<<31, "AUTO_PRESENT_VAL"},
+	{}
+};
+
+/**
+ * sdhci_decode_register() - Decodes a SDHCI register
+ *
+ * @reg: Register offset that was accessed
+ * @val: Value written to the register
+ * @mask: Mask containing the number of bits written to the register. e.g.,
+ *        byte = 0xFF, word = 0xFFFF, long = 0xFFFFFFFF.
+ */
+static const char *sdhci_decode_register(struct trace_seq *p, u32 reg, u32 val,
+					 u32 mask)
+{
+	u32 aligned = reg & ~3UL;
+	int shift = (reg - aligned) * 8;
+
+	val <<= shift;
+	mask <<= shift;
+
+	switch (aligned) {
+	case SDHCI_BLOCK_SIZE:
+		return trace_print_register(p, block_cnt_reg, val, mask);
+	case SDHCI_INT_STATUS:
+	case SDHCI_INT_ENABLE:
+	case SDHCI_SIGNAL_ENABLE:
+		return trace_print_flags_seq(p, " | ", val, int_flags);
+	case SDHCI_PRESENT_STATE:
+		return trace_print_flags_seq(p, " | ", val,
+					     present_state_flags);
+	case SDHCI_HOST_CONTROL:
+		return trace_print_register(p, host_control_reg, val, mask);
+	case SDHCI_TRANSFER_MODE:
+		return trace_print_register(p, transfer_mode_reg, val, mask);
+	case SDHCI_CLOCK_CONTROL:
+		return trace_print_register(p, clk_control_reg, val, mask);
+	case SDHCI_ACMD12_ERR:
+		return trace_print_register(p, acmd_err_flags, val, mask);
+	default:
+		return "";
+	}
+}
+
+#define CREATE_TRACE_POINTS
+#include "sdhci-trace.h"
diff --git a/drivers/mmc/host/sdhci-trace.h b/drivers/mmc/host/sdhci-trace.h
new file mode 100644
index 000000000000..938a032ea38a
--- /dev/null
+++ b/drivers/mmc/host/sdhci-trace.h
@@ -0,0 +1,93 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/* Copyright 2019 Google LLC. */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM sdhci
+
+#if !defined(_TRACE_SDHCI_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_SDHCI_H
+
+#include <linux/mmc/host.h>
+#include <linux/tracepoint.h>
+#include "sdhci.h"
+
+TRACE_EVENT(sdhci_read,
+
+	TP_PROTO(struct sdhci_host *host, u32 reg, u32 val, u32 mask),
+
+	TP_ARGS(host, reg, val, mask),
+
+	TP_STRUCT__entry(
+		__field(u32,	reg)
+		__field(u32,	val)
+		__field(u32,	mask)
+		__string(name,	mmc_hostname(host->mmc))
+	),
+
+	TP_fast_assign(
+		__entry->reg = reg;
+		__entry->val = val;
+		__entry->mask = mask;
+		__assign_str(name, mmc_hostname(host->mmc));
+	),
+
+	TP_printk("%s: %#x [%s] => %#x: %s",
+		  __get_str(name),
+		  __entry->reg,
+		  __print_symbolic(__entry->reg & ~3UL, SDHCI_REGS),
+		  __entry->val,
+		  sdhci_decode_register(
+			p,
+			__entry->reg,
+			__entry->val,
+			__entry->mask
+		  )
+	)
+);
+
+TRACE_EVENT(sdhci_write,
+
+	TP_PROTO(struct sdhci_host *host, u32 reg, u32 val, u32 mask),
+
+	TP_ARGS(host, reg, val, mask),
+
+	TP_STRUCT__entry(
+		__field(u32,	reg)
+		__field(u32,	val)
+		__field(u32,	mask)
+		__string(name,	mmc_hostname(host->mmc))
+	),
+
+	TP_fast_assign(
+		__entry->reg = reg;
+		__entry->val = val;
+		__entry->mask = mask;
+		__assign_str(name, mmc_hostname(host->mmc));
+	),
+
+	TP_printk("%s: %#x [%s] <= %#x: %s",
+		  __get_str(name),
+		  __entry->reg,
+		  __print_symbolic(__entry->reg & ~3UL, SDHCI_REGS),
+		  __entry->val,
+		  sdhci_decode_register(
+			p,
+			__entry->reg,
+			__entry->val,
+			__entry->mask
+		  )
+	)
+);
+
+
+#endif /* _TRACE_SDHCI_H */
+
+/* this part must be outside header guard */
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE sdhci-trace
+
+#include <trace/define_trace.h>
-- 
2.21.0.392.gf8f6787159e-goog

[PATCH v1 4/4] mmc/host/sdhci: Make sdhci_read/sdhci_write call trace functions

[Raul E Rangel]

An example trace can be seen here: https://pastebin.com/x73d5cvL

I was unable to leave sdhci_readX and sdhci_writeX as macros because
they are used in other modules (i.e., sdhci-pci). This means they can't
call the trace_sdhci_XXX functions without explicitly exporting the
private trace function name.

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

 drivers/mmc/host/sdhci-core.c | 136 ++++++++++++++++++++++++++++++++++
 drivers/mmc/host/sdhci.h      |  89 ++--------------------
 2 files changed, 142 insertions(+), 83 deletions(-)

diff --git a/drivers/mmc/host/sdhci-core.c b/drivers/mmc/host/sdhci-core.c
index a8141ff9be03..9e3f114629d9 100644
--- a/drivers/mmc/host/sdhci-core.c
+++ b/drivers/mmc/host/sdhci-core.c
@@ -36,6 +36,7 @@
 #include <linux/mmc/slot-gpio.h>
 
 #include "sdhci.h"
+#include "sdhci-trace.h"
 
 #define DRIVER_NAME "sdhci"
 
@@ -54,6 +55,141 @@ static void sdhci_finish_data(struct sdhci_host *);
 
 static void sdhci_enable_preset_value(struct sdhci_host *host, bool enable);
 
+#ifdef CONFIG_MMC_SDHCI_IO_ACCESSORS
+
+void sdhci_writel(struct sdhci_host *host, u32 val, int reg)
+{
+	trace_sdhci_write(host, reg, val, U32_MAX);
+
+	if (unlikely(host->ops->write_l))
+		host->ops->write_l(host, val, reg);
+	else
+		writel(val, host->ioaddr + reg);
+}
+EXPORT_SYMBOL(sdhci_writel);
+
+void sdhci_writew(struct sdhci_host *host, u16 val, int reg)
+{
+	trace_sdhci_write(host, reg, val, U16_MAX);
+
+	if (unlikely(host->ops->write_w))
+		host->ops->write_w(host, val, reg);
+	else
+		writew(val, host->ioaddr + reg);
+}
+EXPORT_SYMBOL(sdhci_writew);
+
+void sdhci_writeb(struct sdhci_host *host, u8 val, int reg)
+{
+	trace_sdhci_write(host, reg, val, U8_MAX);
+
+	if (unlikely(host->ops->write_b))
+		host->ops->write_b(host, val, reg);
+	else
+		writeb(val, host->ioaddr + reg);
+}
+EXPORT_SYMBOL(sdhci_writeb);
+
+u32 sdhci_readl(struct sdhci_host *host, int reg)
+{
+	u32 val;
+
+	if (unlikely(host->ops->read_l))
+		val = host->ops->read_l(host, reg);
+	else
+		val = readl(host->ioaddr + reg);
+
+	trace_sdhci_read(host, reg, val, U32_MAX);
+
+	return val;
+}
+EXPORT_SYMBOL(sdhci_readl);
+
+u16 sdhci_readw(struct sdhci_host *host, int reg)
+{
+	u16 val;
+
+	if (unlikely(host->ops->read_w))
+		val = host->ops->read_w(host, reg);
+	else
+		val = readw(host->ioaddr + reg);
+
+	trace_sdhci_read(host, reg, val, U16_MAX);
+
+	return val;
+}
+EXPORT_SYMBOL(sdhci_readw);
+
+u8 sdhci_readb(struct sdhci_host *host, int reg)
+{
+	u8 val;
+
+	if (unlikely(host->ops->read_b))
+		val = host->ops->read_b(host, reg);
+	else
+		val = readb(host->ioaddr + reg);
+
+	trace_sdhci_read(host, reg, val, U8_MAX);
+
+	return val;
+}
+EXPORT_SYMBOL(sdhci_readb);
+
+#else
+
+void sdhci_writel(struct sdhci_host *host, u32 val, int reg)
+{
+	trace_sdhci_write(host, reg, val, U32_MAX);
+	writel(val, host->ioaddr + reg);
+}
+EXPORT_SYMBOL(sdhci_writel);
+
+void sdhci_writew(struct sdhci_host *host, u16 val, int reg)
+{
+	trace_sdhci_write(host, reg, val, U16_MAX);
+	writew(val, host->ioaddr + reg);
+}
+EXPORT_SYMBOL(sdhci_writew);
+
+void sdhci_writeb(struct sdhci_host *host, u8 val, int reg)
+{
+	trace_sdhci_write(host, reg, val, U8_MAX);
+	writeb(val, host->ioaddr + reg);
+}
+EXPORT_SYMBOL(sdhci_writeb);
+
+u32 sdhci_readl(struct sdhci_host *host, int reg)
+{
+	u32 val = readl(host->ioaddr + reg);
+
+	trace_sdhci_read(host, reg, val, U32_MAX);
+
+	return val;
+}
+EXPORT_SYMBOL(sdhci_readl);
+
+u16 sdhci_readw(struct sdhci_host *host, int reg)
+{
+	u16 val = readw(host->ioaddr + reg);
+
+	trace_sdhci_read(host, reg, val, U16_MAX);
+
+	return val;
+}
+EXPORT_SYMBOL(sdhci_readw);
+
+u8 sdhci_readb(struct sdhci_host *host, int reg)
+{
+	u8 val = readb(host->ioaddr + reg);
+
+	trace_sdhci_read(host, reg, val, U8_MAX);
+
+	return val;
+}
+EXPORT_SYMBOL(sdhci_readb);
+
+#endif /* CONFIG_MMC_SDHCI_IO_ACCESSORS */
+
 void sdhci_dumpregs(struct sdhci_host *host)
 {
 	SDHCI_DUMP("============ SDHCI REGISTER DUMP ===========\n");
diff --git a/drivers/mmc/host/sdhci.h b/drivers/mmc/host/sdhci.h
index 01002cba1359..052361f27ec0 100644
--- a/drivers/mmc/host/sdhci.h
+++ b/drivers/mmc/host/sdhci.h
@@ -647,89 +647,12 @@ struct sdhci_ops {
 				   dma_addr_t addr, int len, unsigned int cmd);
 };
 
-#ifdef CONFIG_MMC_SDHCI_IO_ACCESSORS
-
-static inline void sdhci_writel(struct sdhci_host *host, u32 val, int reg)
-{
-	if (unlikely(host->ops->write_l))
-		host->ops->write_l(host, val, reg);
-	else
-		writel(val, host->ioaddr + reg);
-}
-
-static inline void sdhci_writew(struct sdhci_host *host, u16 val, int reg)
-{
-	if (unlikely(host->ops->write_w))
-		host->ops->write_w(host, val, reg);
-	else
-		writew(val, host->ioaddr + reg);
-}
-
-static inline void sdhci_writeb(struct sdhci_host *host, u8 val, int reg)
-{
-	if (unlikely(host->ops->write_b))
-		host->ops->write_b(host, val, reg);
-	else
-		writeb(val, host->ioaddr + reg);
-}
-
-static inline u32 sdhci_readl(struct sdhci_host *host, int reg)
-{
-	if (unlikely(host->ops->read_l))
-		return host->ops->read_l(host, reg);
-	else
-		return readl(host->ioaddr + reg);
-}
-
-static inline u16 sdhci_readw(struct sdhci_host *host, int reg)
-{
-	if (unlikely(host->ops->read_w))
-		return host->ops->read_w(host, reg);
-	else
-		return readw(host->ioaddr + reg);
-}
-
-static inline u8 sdhci_readb(struct sdhci_host *host, int reg)
-{
-	if (unlikely(host->ops->read_b))
-		return host->ops->read_b(host, reg);
-	else
-		return readb(host->ioaddr + reg);
-}
-
-#else
-
-static inline void sdhci_writel(struct sdhci_host *host, u32 val, int reg)
-{
-	writel(val, host->ioaddr + reg);
-}
-
-static inline void sdhci_writew(struct sdhci_host *host, u16 val, int reg)
-{
-	writew(val, host->ioaddr + reg);
-}
-
-static inline void sdhci_writeb(struct sdhci_host *host, u8 val, int reg)
-{
-	writeb(val, host->ioaddr + reg);
-}
-
-static inline u32 sdhci_readl(struct sdhci_host *host, int reg)
-{
-	return readl(host->ioaddr + reg);
-}
-
-static inline u16 sdhci_readw(struct sdhci_host *host, int reg)
-{
-	return readw(host->ioaddr + reg);
-}
-
-static inline u8 sdhci_readb(struct sdhci_host *host, int reg)
-{
-	return readb(host->ioaddr + reg);
-}
-
-#endif /* CONFIG_MMC_SDHCI_IO_ACCESSORS */
+void sdhci_writel(struct sdhci_host *host, u32 val, int reg);
+void sdhci_writew(struct sdhci_host *host, u16 val, int reg);
+void sdhci_writeb(struct sdhci_host *host, u8 val, int reg);
+u32 sdhci_readl(struct sdhci_host *host, int reg);
+u16 sdhci_readw(struct sdhci_host *host, int reg);
+u8 sdhci_readb(struct sdhci_host *host, int reg);
 
 struct sdhci_host *sdhci_alloc_host(struct device *dev, size_t priv_size);
 void sdhci_free_host(struct sdhci_host *host);
-- 
2.21.0.392.gf8f6787159e-goog

Re: [PATCH v1 1/4] trace_events: Add trace_print_register to print register fields

[Steven Rostedt]

On Thu, 11 Apr 2019 16:08:19 -0600
Raul E Rangel <rrangel@chromium.org> wrote:

> This is a hybrid method that combines the functionality of
> trace_print_flags_seq and trace_print_symbols_seq. It supports printing
> bit fields, enum fields, and numeric fields.
> 
> Given the following register definition:
>   * 0   - Enabled
>   * 1   - Width, 0 = 1-bits, 1 = 4-bits
>   * 2:3 - DMA, 0 = None, 1 = SDMA, 2 = ADMA, 3 = ADMA2
>   * 4:7 - Timeout Counter
> 
> The register fields could be defined as follows:
> 
>   const struct trace_print_field reg[] = {
>     {1<<0, "ENABLED"},
>     {
>       .mask = 1<<1,
>       .name = "WIDTH",
>       .symbols = (const struct trace_print_flags[]) {
>         {0, "1-BIT"},
>         {1, "4-BIT"},
>         {}
>       }
>     }, {
>       .mask = 3<<2,
>       .symbols = (const struct trace_print_flags[]) {
>         {0, "NONE"},
>         {1, "SDMA"},
>         {2, "ADMA"},
>         {3, "ADMA2"},
>         {}
>       }
>     },
>     {0xF<<4, "TIMEOUT"}
>   }
> 
> This would print out the following given value 0xAB:
> 
> ENABLED: 1 | WIDTH: 4-BIT | ADMA | TIMEOUT: 0xA
> 

Note the rational for the __print_symbolic and __print_flags is that
they show how to translate into something that perf and trace-cmd can
read from userspace.

How does perf or trace-cmd parse this? To add something like this, you
need them to have the same output as what is displayed by the trace
file otherwise NAK.

-- Steve


> See https://pastebin.com/x73d5cvL for this in action.
> 
> Signed-off-by: Raul E Rangel <rrangel@chromium.org>
> ---
> 
>  include/linux/trace_events.h    |   4 ++
>  include/linux/tracepoint-defs.h |   6 ++
>  include/trace/trace_events.h    |   9 +++
>  kernel/trace/trace_output.c     | 121 ++++++++++++++++++++++++++++++++
>  4 files changed, 140 insertions(+)
> 
> diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
> index 8a62731673f7..3c44909ce8b3 100644
> --- a/include/linux/trace_events.h
> +++ b/include/linux/trace_events.h
> @@ -23,6 +23,10 @@ const char *trace_print_flags_seq(struct trace_seq *p, const char *delim,
>  const char *trace_print_symbols_seq(struct trace_seq *p, unsigned long val,
>  				    const struct trace_print_flags *symbol_array);
>  
> +const char *trace_print_register(struct trace_seq *p,
> +				 const struct trace_print_field fields[],
> +				 unsigned long val, unsigned long mask);
> +
>  #if BITS_PER_LONG == 32
>  const char *trace_print_flags_seq_u64(struct trace_seq *p, const char *delim,
>  		      unsigned long long flags,
> diff --git a/include/linux/tracepoint-defs.h b/include/linux/tracepoint-defs.h
> index 49ba9cde7e4b..c3dc27c192f4 100644
> --- a/include/linux/tracepoint-defs.h
> +++ b/include/linux/tracepoint-defs.h
> @@ -16,6 +16,12 @@ struct trace_print_flags {
>  	const char		*name;
>  };
>  
> +struct trace_print_field {
> +	unsigned long			mask;
> +	const char			*name;
> +	const struct trace_print_flags	*symbols;
> +};
> +
>  struct trace_print_flags_u64 {
>  	unsigned long long	mask;
>  	const char		*name;
> diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
> index 4ecdfe2e3580..6adc32fcb1c3 100644
> --- a/include/trace/trace_events.h
> +++ b/include/trace/trace_events.h
> @@ -300,6 +300,14 @@ TRACE_MAKE_SYSTEM_STR();
>  		trace_print_symbols_seq(p, value, symbols);		\
>  	})
>  
> +#undef __print_register
> +#define __print_register(value, mask, field_array...)			\
> +	({								\
> +		static const struct trace_print_field fields[] =	\
> +			{ field_array, {} };			\
> +		trace_print_register(p, value, mask, fields);		\
> +	})
> +
>  #undef __print_flags_u64
>  #undef __print_symbolic_u64
>  #if BITS_PER_LONG == 32
> @@ -744,6 +752,7 @@ static inline void ftrace_test_probe_##call(void)			\
>  
>  #undef __print_flags
>  #undef __print_symbolic
> +#undef __print_register
>  #undef __print_hex
>  #undef __print_hex_str
>  #undef __get_dynamic_array
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index 54373d93e251..cd5727ad54c3 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -124,6 +124,127 @@ trace_print_symbols_seq(struct trace_seq *p, unsigned long val,
>  }
>  EXPORT_SYMBOL(trace_print_symbols_seq);
>  
> +/**
> + * trace_print_register - Prints all the fields of a register.
> + *
> + * This is a hybrid method that combines the functionality of
> + * trace_print_flags_seq and trace_print_symbols_seq. It supports printing
> + * bit fields, enum fields, and numeric fields.
> + *
> + * Given the following register definition:
> + *   * 0   - Enabled
> + *   * 1   - Width, 0 = 1-bits, 1 = 4-bits
> + *   * 2:3 - DMA, 0 = None, 1 = SDMA, 2 = ADMA, 3 = ADMA2
> + *   * 4:7 - Timeout Counter
> + *
> + * The register fields could be defined as follows:
> + *
> + *   const struct trace_print_field reg[] = {
> + *     {1<<0, "ENABLED"},
> + *     {
> + *       .mask = 1<<1,
> + *       .name = "WIDTH",
> + *       .symbols = (const struct trace_print_flags[]) {
> + *         {0, "1-BIT"},
> + *         {1, "4-BIT"},
> + *         {}
> + *       }
> + *     }, {
> + *       .mask = 3<<2,
> + *       .symbols = (const struct trace_print_flags[]) {
> + *         {0, "NONE"},
> + *         {1, "SDMA"},
> + *         {2, "ADMA"},
> + *         {3, "ADMA2"},
> + *         {}
> + *       }
> + *     },
> + *     {0xF<<4, "TIMEOUT"}
> + *   }
> + *
> + * This would print out the following given value 0xAB:
> + *
> + * ENABLED: 1 | WIDTH: 4-BIT | ADMA | TIMEOUT: 0xA
> + *
> + * @p: trace buffer
> + * @fields: Array of fields that describe the register. Must be terminated with
> + *          an empty value.
> + * @val: register value
> + * @mask: Mask that defines the bits present in @val. Useful if only a subset
> + *        of the register was read. Any fields that fall outside of the mask
> + *        will not be printed.
> + */
> +const char *trace_print_register(struct trace_seq *p,
> +				 const struct trace_print_field fields[],
> +				 unsigned long val, unsigned long mask)
> +{
> +	const char *ret = trace_seq_buffer_ptr(p);
> +	char *tail;
> +	unsigned long fval;
> +	int first = 1, symbol_found;
> +	const struct trace_print_field *field;
> +	const struct trace_print_flags *symbol;
> +
> +	for (field = fields; field->mask; field++) {
> +		/* Make sure the field mask is within the accessed bits */
> +		if ((mask & field->mask) != field->mask)
> +			continue;
> +
> +		if (!first)
> +			trace_seq_puts(p, " | ");
> +
> +		first = 0;
> +
> +		if (field->name) {
> +			trace_seq_puts(p, field->name);
> +			trace_seq_puts(p, ": ");
> +		}
> +
> +		fval = val & field->mask;
> +		fval >>= ffs(field->mask) - 1;
> +
> +		val &= ~field->mask;
> +
> +		symbol_found = 0;
> +		for (symbol = field->symbols; symbol && symbol->name;
> +		     symbol++) {
> +			if (symbol->mask != fval)
> +				continue;
> +			trace_seq_puts(p, symbol->name);
> +			symbol_found = 1;
> +			break;
> +		}
> +
> +		if (!symbol_found) {
> +			if (fval == 0) {
> +				trace_seq_puts(p, "0");
> +			} else if (fval == 1) {
> +				trace_seq_puts(p, "1");
> +			} else {
> +				trace_seq_printf(p, "%#x", fval);
> +
> +				/* Strip off the null terminator */
> +				for (tail = trace_seq_buffer_ptr(p) - 1;
> +				     tail > ret && !*tail; tail--) {
> +					p->seq.len--;
> +				}
> +			}
> +		}
> +	}
> +
> +	/* Print any left over bits */
> +	if (val) {
> +		if (!first)
> +			trace_seq_puts(p, " | ");
> +		trace_seq_printf(p, "%#x", val);
> +	}
> +
> +	trace_seq_putc(p, 0);
> +
> +	return ret;
> +}
> +EXPORT_SYMBOL(trace_print_register);
> +
>  #if BITS_PER_LONG == 32
>  const char *
>  trace_print_flags_seq_u64(struct trace_seq *p, const char *delim,

Re: [PATCH v1 0/4] Add tracing for SDHCI register access

[Adrian Hunter]

On 12/04/19 1:08 AM, Raul E Rangel wrote:
> I was debugging a SDHC hardware bug and got tired of having to
> translate the register values by hand. This patch set makes it so all
> SDHC register read and write operations can be traced and easily read by
> a human.

While this might be useful for people unfamiliar with SDHCI, I am not sure
it should be in the upstream kernel.  Also, it doesn't seem ideal for every
driver to add its own plumbing for such a feature.

Re: [PATCH v1 0/4] Add tracing for SDHCI register access

[Raul Rangel]

On Fri, Apr 12, 2019 at 09:26:44AM +0300, Adrian Hunter wrote:
> On 12/04/19 1:08 AM, Raul E Rangel wrote:
> > I was debugging a SDHC hardware bug and got tired of having to
> > translate the register values by hand. This patch set makes it so all
> > SDHC register read and write operations can be traced and easily read by
> > a human.
> 
> While this might be useful for people unfamiliar with SDHCI, I am not sure
> it should be in the upstream kernel.
Can you help me understand your hesitation? Would you prefer removing the
pretty printing? Or would you prefer not having any trace events at all?

The xhci driver has a bunch of pretty print trace events that make it
invaluable when debugging.
https://github.com/torvalds/linux/blob/d7563ca5bfca53398e100eb74345c5d3ef06bf9d/drivers/usb/host/xhci.h#L2160

> Also, it doesn't seem ideal for every
> driver to add its own plumbing for such a feature.
What do you mean by every driver having to add it's own plumbing? Any
driver that uses sdhci_readX or sdhci_writeX get the functionality for
free.

Thanks,
Raul

Re: [PATCH v1 1/4] trace_events: Add trace_print_register to print register fields

[Raul Rangel]

On Thu, Apr 11, 2019 at 06:39:34PM -0400, Steven Rostedt wrote:
> On Thu, 11 Apr 2019 16:08:19 -0600
> Raul E Rangel <rrangel@chromium.org> wrote:
> 
> > This is a hybrid method that combines the functionality of
> > trace_print_flags_seq and trace_print_symbols_seq. It supports printing
> > bit fields, enum fields, and numeric fields.
> > 
> > Given the following register definition:
> >   * 0   - Enabled
> >   * 1   - Width, 0 = 1-bits, 1 = 4-bits
> >   * 2:3 - DMA, 0 = None, 1 = SDMA, 2 = ADMA, 3 = ADMA2
> >   * 4:7 - Timeout Counter
> > 
> > The register fields could be defined as follows:
> > 
> >   const struct trace_print_field reg[] = {
> >     {1<<0, "ENABLED"},
> >     {
> >       .mask = 1<<1,
> >       .name = "WIDTH",
> >       .symbols = (const struct trace_print_flags[]) {
> >         {0, "1-BIT"},
> >         {1, "4-BIT"},
> >         {}
> >       }
> >     }, {
> >       .mask = 3<<2,
> >       .symbols = (const struct trace_print_flags[]) {
> >         {0, "NONE"},
> >         {1, "SDMA"},
> >         {2, "ADMA"},
> >         {3, "ADMA2"},
> >         {}
> >       }
> >     },
> >     {0xF<<4, "TIMEOUT"}
> >   }
> > 
> > This would print out the following given value 0xAB:
> > 
> > ENABLED: 1 | WIDTH: 4-BIT | ADMA | TIMEOUT: 0xA
> > 
> 
> Note the rational for the __print_symbolic and __print_flags is that
> they show how to translate into something that perf and trace-cmd can
> read from userspace.

Ah, I wasn't aware that the format was exposed via sysfs. That makes
sense why the macros are used. I was using xhci-trace as my reference
point which just calls arbitrary functions.

cat /sys/kernel/debug/tracing/events/xhci-hcd/xhci_handle_event/format
print fmt: "%s: %s",
xhci_ring_type_string(REC->type),
xhci_decode_trb(REC->field0, REC->field1, REC->field2, REC->field3)

I'm guessing calling out to a function is not the way the framework was
intended to be used. Does this mean that every TRB type in xhci_decode_trb
should be its own trace event so the printf format isn't hidden inside
the code?

> 
> How does perf or trace-cmd parse this? To add something like this, you
> need them to have the same output as what is displayed by the trace
> file otherwise NAK.

So for the short term I can remove __print_register. The SDHCI tracing
doesn't use it, but instead calls out to a method that calls
trace_print_register directly. Or I could move trace_print_register
into the sdhci-trace module.

cat /sys/kernel/debug/tracing/events/sdhci/sdhci_read/format

print fmt: "%s: %#x [%s] => %#x: %s",
  __get_str(name),
  REC->reg,
  __print_symbolic(REC->reg & ~3UL, {0x00, "DMA_ADDRESS"}, ...),
  REC->val,
  sdhci_decode_register( p, REC->reg, REC->val, REC->mask )

The format prints out the raw value, so using perf or trace-cmd
will still have value, you just won't get the pretty print.

For the long term I could make event-parser handle __print_register. I'm
assuming it just needs to handle the additional case?
https://github.com/torvalds/linux/blob/master/tools/lib/traceevent/event-parse.c#L3040

Thanks for the feedback,
Raul

> 
> -- Steve
> 
> 
> > See https://pastebin.com/x73d5cvL for this in action.
> > 
> > Signed-off-by: Raul E Rangel <rrangel@chromium.org>
> > ---
> > 
> >  include/linux/trace_events.h    |   4 ++
> >  include/linux/tracepoint-defs.h |   6 ++
> >  include/trace/trace_events.h    |   9 +++
> >  kernel/trace/trace_output.c     | 121 ++++++++++++++++++++++++++++++++
> >  4 files changed, 140 insertions(+)
> > 
> > diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
> > index 8a62731673f7..3c44909ce8b3 100644
> > --- a/include/linux/trace_events.h
> > +++ b/include/linux/trace_events.h
> > @@ -23,6 +23,10 @@ const char *trace_print_flags_seq(struct trace_seq *p, const char *delim,
> >  const char *trace_print_symbols_seq(struct trace_seq *p, unsigned long val,
> >  				    const struct trace_print_flags *symbol_array);
> >  
> > +const char *trace_print_register(struct trace_seq *p,
> > +				 const struct trace_print_field fields[],
> > +				 unsigned long val, unsigned long mask);
> > +
> >  #if BITS_PER_LONG == 32
> >  const char *trace_print_flags_seq_u64(struct trace_seq *p, const char *delim,
> >  		      unsigned long long flags,
> > diff --git a/include/linux/tracepoint-defs.h b/include/linux/tracepoint-defs.h
> > index 49ba9cde7e4b..c3dc27c192f4 100644
> > --- a/include/linux/tracepoint-defs.h
> > +++ b/include/linux/tracepoint-defs.h
> > @@ -16,6 +16,12 @@ struct trace_print_flags {
> >  	const char		*name;
> >  };
> >  
> > +struct trace_print_field {
> > +	unsigned long			mask;
> > +	const char			*name;
> > +	const struct trace_print_flags	*symbols;
> > +};
> > +
> >  struct trace_print_flags_u64 {
> >  	unsigned long long	mask;
> >  	const char		*name;
> > diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
> > index 4ecdfe2e3580..6adc32fcb1c3 100644
> > --- a/include/trace/trace_events.h
> > +++ b/include/trace/trace_events.h
> > @@ -300,6 +300,14 @@ TRACE_MAKE_SYSTEM_STR();
> >  		trace_print_symbols_seq(p, value, symbols);		\
> >  	})
> >  
> > +#undef __print_register
> > +#define __print_register(value, mask, field_array...)			\
> > +	({								\
> > +		static const struct trace_print_field fields[] =	\
> > +			{ field_array, {} };			\
> > +		trace_print_register(p, value, mask, fields);		\
> > +	})
> > +
> >  #undef __print_flags_u64
> >  #undef __print_symbolic_u64
> >  #if BITS_PER_LONG == 32
> > @@ -744,6 +752,7 @@ static inline void ftrace_test_probe_##call(void)			\
> >  
> >  #undef __print_flags
> >  #undef __print_symbolic
> > +#undef __print_register
> >  #undef __print_hex
> >  #undef __print_hex_str
> >  #undef __get_dynamic_array
> > diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> > index 54373d93e251..cd5727ad54c3 100644
> > --- a/kernel/trace/trace_output.c
> > +++ b/kernel/trace/trace_output.c
> > @@ -124,6 +124,127 @@ trace_print_symbols_seq(struct trace_seq *p, unsigned long val,
> >  }
> >  EXPORT_SYMBOL(trace_print_symbols_seq);
> >  
> > +/**
> > + * trace_print_register - Prints all the fields of a register.
> > + *
> > + * This is a hybrid method that combines the functionality of
> > + * trace_print_flags_seq and trace_print_symbols_seq. It supports printing
> > + * bit fields, enum fields, and numeric fields.
> > + *
> > + * Given the following register definition:
> > + *   * 0   - Enabled
> > + *   * 1   - Width, 0 = 1-bits, 1 = 4-bits
> > + *   * 2:3 - DMA, 0 = None, 1 = SDMA, 2 = ADMA, 3 = ADMA2
> > + *   * 4:7 - Timeout Counter
> > + *
> > + * The register fields could be defined as follows:
> > + *
> > + *   const struct trace_print_field reg[] = {
> > + *     {1<<0, "ENABLED"},
> > + *     {
> > + *       .mask = 1<<1,
> > + *       .name = "WIDTH",
> > + *       .symbols = (const struct trace_print_flags[]) {
> > + *         {0, "1-BIT"},
> > + *         {1, "4-BIT"},
> > + *         {}
> > + *       }
> > + *     }, {
> > + *       .mask = 3<<2,
> > + *       .symbols = (const struct trace_print_flags[]) {
> > + *         {0, "NONE"},
> > + *         {1, "SDMA"},
> > + *         {2, "ADMA"},
> > + *         {3, "ADMA2"},
> > + *         {}
> > + *       }
> > + *     },
> > + *     {0xF<<4, "TIMEOUT"}
> > + *   }
> > + *
> > + * This would print out the following given value 0xAB:
> > + *
> > + * ENABLED: 1 | WIDTH: 4-BIT | ADMA | TIMEOUT: 0xA
> > + *
> > + * @p: trace buffer
> > + * @fields: Array of fields that describe the register. Must be terminated with
> > + *          an empty value.
> > + * @val: register value
> > + * @mask: Mask that defines the bits present in @val. Useful if only a subset
> > + *        of the register was read. Any fields that fall outside of the mask
> > + *        will not be printed.
> > + */
> > +const char *trace_print_register(struct trace_seq *p,
> > +				 const struct trace_print_field fields[],
> > +				 unsigned long val, unsigned long mask)
> > +{
> > +	const char *ret = trace_seq_buffer_ptr(p);
> > +	char *tail;
> > +	unsigned long fval;
> > +	int first = 1, symbol_found;
> > +	const struct trace_print_field *field;
> > +	const struct trace_print_flags *symbol;
> > +
> > +	for (field = fields; field->mask; field++) {
> > +		/* Make sure the field mask is within the accessed bits */
> > +		if ((mask & field->mask) != field->mask)
> > +			continue;
> > +
> > +		if (!first)
> > +			trace_seq_puts(p, " | ");
> > +
> > +		first = 0;
> > +
> > +		if (field->name) {
> > +			trace_seq_puts(p, field->name);
> > +			trace_seq_puts(p, ": ");
> > +		}
> > +
> > +		fval = val & field->mask;
> > +		fval >>= ffs(field->mask) - 1;
> > +
> > +		val &= ~field->mask;
> > +
> > +		symbol_found = 0;
> > +		for (symbol = field->symbols; symbol && symbol->name;
> > +		     symbol++) {
> > +			if (symbol->mask != fval)
> > +				continue;
> > +			trace_seq_puts(p, symbol->name);
> > +			symbol_found = 1;
> > +			break;
> > +		}
> > +
> > +		if (!symbol_found) {
> > +			if (fval == 0) {
> > +				trace_seq_puts(p, "0");
> > +			} else if (fval == 1) {
> > +				trace_seq_puts(p, "1");
> > +			} else {
> > +				trace_seq_printf(p, "%#x", fval);
> > +
> > +				/* Strip off the null terminator */
> > +				for (tail = trace_seq_buffer_ptr(p) - 1;
> > +				     tail > ret && !*tail; tail--) {
> > +					p->seq.len--;
> > +				}
> > +			}
> > +		}
> > +	}
> > +
> > +	/* Print any left over bits */
> > +	if (val) {
> > +		if (!first)
> > +			trace_seq_puts(p, " | ");
> > +		trace_seq_printf(p, "%#x", val);
> > +	}
> > +
> > +	trace_seq_putc(p, 0);
> > +
> > +	return ret;
> > +}
> > +EXPORT_SYMBOL(trace_print_register);
> > +
> >  #if BITS_PER_LONG == 32
> >  const char *
> >  trace_print_flags_seq_u64(struct trace_seq *p, const char *delim,
> 

Re: [PATCH v1 1/4] trace_events: Add trace_print_register to print register fields

[Steven Rostedt]

On Fri, 12 Apr 2019 09:30:36 -0600
Raul Rangel <rrangel@chromium.org> wrote:

> Ah, I wasn't aware that the format was exposed via sysfs. That makes
> sense why the macros are used. I was using xhci-trace as my reference
> point which just calls arbitrary functions.
> 
> cat /sys/kernel/debug/tracing/events/xhci-hcd/xhci_handle_event/format
> print fmt: "%s: %s",
> xhci_ring_type_string(REC->type),
> xhci_decode_trb(REC->field0, REC->field1, REC->field2, REC->field3)
> 
> I'm guessing calling out to a function is not the way the framework was
> intended to be used. Does this mean that every TRB type in xhci_decode_trb
> should be its own trace event so the printf format isn't hidden inside
> the code?

You can add plugins to handle this. See tools/lib/traceevent/plugin_*.c

> 
> > 
> > How does perf or trace-cmd parse this? To add something like this, you
> > need them to have the same output as what is displayed by the trace
> > file otherwise NAK.  
> 
> So for the short term I can remove __print_register. The SDHCI tracing
> doesn't use it, but instead calls out to a method that calls
> trace_print_register directly. Or I could move trace_print_register
> into the sdhci-trace module.

For the short term yeah. And you can add a plugin to the libtraceevent
to teach trace-cmd and perf how to parse it.
See "tep_register_print_function()"

> 
> cat /sys/kernel/debug/tracing/events/sdhci/sdhci_read/format
> 
> print fmt: "%s: %#x [%s] => %#x: %s",
>   __get_str(name),
>   REC->reg,
>   __print_symbolic(REC->reg & ~3UL, {0x00, "DMA_ADDRESS"}, ...),
>   REC->val,
>   sdhci_decode_register( p, REC->reg, REC->val, REC->mask )
> 
> The format prints out the raw value, so using perf or trace-cmd
> will still have value, you just won't get the pretty print.
> 
> For the long term I could make event-parser handle __print_register. I'm
> assuming it just needs to handle the additional case?
> https://github.com/torvalds/linux/blob/master/tools/lib/traceevent/event-parse.c#L3040
> 

Yes, I'm fine with adding new generic functions that can parse the code
properly to libtraceevent. Anything added to the trace_event code
should have a corresponding routine added to libtraceevent. Just
remember, that those *are* user API, and once made, they can not change.

Thanks!

-- Steve

Re: [PATCH v1 0/4] Add tracing for SDHCI register access

[Adrian Hunter]

On 12/04/19 5:50 PM, Raul Rangel wrote:
> On Fri, Apr 12, 2019 at 09:26:44AM +0300, Adrian Hunter wrote:
>> On 12/04/19 1:08 AM, Raul E Rangel wrote:
>>> I was debugging a SDHC hardware bug and got tired of having to
>>> translate the register values by hand. This patch set makes it so all
>>> SDHC register read and write operations can be traced and easily read by
>>> a human.
>>
>> While this might be useful for people unfamiliar with SDHCI, I am not sure
>> it should be in the upstream kernel.
> Can you help me understand your hesitation? Would you prefer removing the
> pretty printing? Or would you prefer not having any trace events at all?

It is just cost/benefit.  I am not sure the cost of maintaining it is worth
the benefit of having it upstream.

> The xhci driver has a bunch of pretty print trace events that make it
> invaluable when debugging.
> https://github.com/torvalds/linux/blob/d7563ca5bfca53398e100eb74345c5d3ef06bf9d/drivers/usb/host/xhci.h#L2160
> 
>> Also, it doesn't seem ideal for every
>> driver to add its own plumbing for such a feature.
> What do you mean by every driver having to add it's own plumbing? Any
> driver that uses sdhci_readX or sdhci_writeX get the functionality for
> free.

I/O memory mappings are recorded for devices. e.g. /proc/iomem so it could
be possible to add tracing for all I/O memory accesses via readx/writex etc,
configurable / filterable by device id.

Re: [PATCH v1 0/4] Add tracing for SDHCI register access

[Raul Rangel]

On Thu, Apr 18, 2019 at 09:24:16AM +0300, Adrian Hunter wrote:
> On 12/04/19 5:50 PM, Raul Rangel wrote:
> > On Fri, Apr 12, 2019 at 09:26:44AM +0300, Adrian Hunter wrote:
> >> On 12/04/19 1:08 AM, Raul E Rangel wrote:
> >>> I was debugging a SDHC hardware bug and got tired of having to
> >>> translate the register values by hand. This patch set makes it so all
> >>> SDHC register read and write operations can be traced and easily read by
> >>> a human.
> >>
> >> While this might be useful for people unfamiliar with SDHCI, I am not sure
> >> it should be in the upstream kernel.
> > Can you help me understand your hesitation? Would you prefer removing the
> > pretty printing? Or would you prefer not having any trace events at all?
> 
> It is just cost/benefit.  I am not sure the cost of maintaining it is worth
> the benefit of having it upstream.
> 
Steven,
Since it seems this series won't be accepted upstream, would you still be
open to accepting patches for trace_print_register? I can work on adding
support to lib traceevent.

Thanks,
Raul
> > The xhci driver has a bunch of pretty print trace events that make it
> > invaluable when debugging.
> > https://github.com/torvalds/linux/blob/d7563ca5bfca53398e100eb74345c5d3ef06bf9d/drivers/usb/host/xhci.h#L2160
> > 
> >> Also, it doesn't seem ideal for every
> >> driver to add its own plumbing for such a feature.
> > What do you mean by every driver having to add it's own plumbing? Any
> > driver that uses sdhci_readX or sdhci_writeX get the functionality for
> > free.
> 
> I/O memory mappings are recorded for devices. e.g. /proc/iomem so it could
> be possible to add tracing for all I/O memory accesses via readx/writex etc,
> configurable / filterable by device id.

Re: [PATCH v1 0/4] Add tracing for SDHCI register access

[Steven Rostedt]

On Fri, 19 Apr 2019 12:40:13 -0600
Raul Rangel <rrangel@chromium.org> wrote:

> Steven,
> Since it seems this series won't be accepted upstream, would you still be
> open to accepting patches for trace_print_register? I can work on adding
> support to lib traceevent.

It would require having a user in the kernel code.

If you are going to do something out of tree, simply make a helper
function inside your trace event, and then write a plugin for it if you
want to use it for libtraceevent. It allows for custom plugins.

-- Steve