[PATCH v4 0/6] Several changes for the UPIU trace

[PATCH v4 0/6] Several changes for the UPIU trace

[Bean Huo]

From: Bean Huo <beanhuo@micron.com>

Changelog:

V3--v4:
 1. Rebase patch onto 5.12/scsi-queue
 2. Incorporate Avri's suggestion in patch 2/6

V2--V3:
  1. Fix a typo in patch 1/6 (Reported-by: Joe Perches <joe@perches.com>)

V1--V2:
  1. Convert __get_str(str) to __print_symbolic()
  2. Add new patches 1/6, 2/6,3/6
  3. Use __print_symbolic() in patch 6/6

Bean Huo (6):
  scsi: ufs: Remove stringize operator '#' restriction
  scsi: ufs: Use __print_symbolic() for UFS trace string print
  scsi: ufs: Don't call trace_ufshcd_upiu() in case trace poit is
    disabled
  scsi: ufs: Distinguish between query REQ and query RSP in query trace
  scsi: ufs: Distinguish between TM request UPIU and response UPIU in TM
    UPIU trace
  scsi: ufs: Make UPIU trace easier differentiate among CDB, OSF, and TM

 drivers/scsi/ufs/ufs.h     |  17 ++++++
 drivers/scsi/ufs/ufshcd.c  |  72 ++++++++++++++++---------
 include/trace/events/ufs.h | 108 +++++++++++++++++++++++--------------
 3 files changed, 131 insertions(+), 66 deletions(-)

-- 
2.17.1

[PATCH v4 1/6] scsi: ufs: Remove stringize operator '#' restriction

[Bean Huo]

From: Bean Huo <beanhuo@micron.com>

Current EM macro definition, we use stringize operator '#', which turns
the argument it precedes into a quoted string. Thus requires the symbol
of __print_symbolic() should be the string corresponding to the name of
the enum.

However, we have other cases, the symbol and enum name are not the same,
we can redefine EM/EMe, but there will introduce some redundant codes.
This patch is to remove this restriction, let others reuse the current
EM/EMe definition.

Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Bean Huo <beanhuo@micron.com>
---
 include/trace/events/ufs.h | 40 +++++++++++++++++++-------------------
 1 file changed, 20 insertions(+), 20 deletions(-)

diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h
index 0bd54a184391..fa755394bc0f 100644
--- a/include/trace/events/ufs.h
+++ b/include/trace/events/ufs.h
@@ -20,28 +20,28 @@
 		{ SYNCHRONIZE_CACHE,	"SYNC" },			\
 		{ UNMAP,		"UNMAP" })
 
-#define UFS_LINK_STATES			\
-	EM(UIC_LINK_OFF_STATE)		\
-	EM(UIC_LINK_ACTIVE_STATE)	\
-	EMe(UIC_LINK_HIBERN8_STATE)
-
-#define UFS_PWR_MODES			\
-	EM(UFS_ACTIVE_PWR_MODE)		\
-	EM(UFS_SLEEP_PWR_MODE)		\
-	EM(UFS_POWERDOWN_PWR_MODE)	\
-	EMe(UFS_DEEPSLEEP_PWR_MODE)
-
-#define UFSCHD_CLK_GATING_STATES	\
-	EM(CLKS_OFF)			\
-	EM(CLKS_ON)			\
-	EM(REQ_CLKS_OFF)		\
-	EMe(REQ_CLKS_ON)
+#define UFS_LINK_STATES						\
+	EM(UIC_LINK_OFF_STATE,		"UIC_LINK_OFF_STATE")		\
+	EM(UIC_LINK_ACTIVE_STATE,	"UIC_LINK_ACTIVE_STATE")	\
+	EMe(UIC_LINK_HIBERN8_STATE,	"UIC_LINK_HIBERN8_STATE")
+
+#define UFS_PWR_MODES							\
+	EM(UFS_ACTIVE_PWR_MODE,		"UFS_ACTIVE_PWR_MODE")		\
+	EM(UFS_SLEEP_PWR_MODE,		"UFS_SLEEP_PWR_MODE")		\
+	EM(UFS_POWERDOWN_PWR_MODE,	"UFS_POWERDOWN_PWR_MODE")	\
+	EMe(UFS_DEEPSLEEP_PWR_MODE,	"UFS_DEEPSLEEP_PWR_MODE")
+
+#define UFSCHD_CLK_GATING_STATES				\
+	EM(CLKS_OFF,			"CLKS_OFF")		\
+	EM(CLKS_ON,			"CLKS_ON")		\
+	EM(REQ_CLKS_OFF,		"REQ_CLKS_OFF")		\
+	EMe(REQ_CLKS_ON,		"REQ_CLKS_ON")
 
 /* Enums require being exported to userspace, for user tool parsing */
 #undef EM
 #undef EMe
-#define EM(a)	TRACE_DEFINE_ENUM(a);
-#define EMe(a)	TRACE_DEFINE_ENUM(a);
+#define EM(a, b)	TRACE_DEFINE_ENUM(a);
+#define EMe(a, b)	TRACE_DEFINE_ENUM(a);
 
 UFS_LINK_STATES;
 UFS_PWR_MODES;
@@ -53,8 +53,8 @@ UFSCHD_CLK_GATING_STATES;
  */
 #undef EM
 #undef EMe
-#define EM(a)	{ a, #a },
-#define EMe(a)	{ a, #a }
+#define EM(a, b)	{a, b},
+#define EMe(a, b)	{a, b}
 
 TRACE_EVENT(ufshcd_clk_gating,
 
-- 
2.17.1

[PATCH v4 2/6] scsi: ufs: Use __print_symbolic() for UFS trace string print

[Bean Huo]

From: Bean Huo <beanhuo@micron.com>

__print_symbolic() is designed for exporting the print formatting table
to userspace and allows parsing tool, such as trace-cmd and perf, to analyze
trace log according to this print formatting table, meanwhile, by using
__print_symbolic()s, save space in the trace ring buffer.

original print format:

print fmt: "%s: %s: HDR:%s, CDB:%s", __get_str(str), __get_str(dev_name),
            __print_hex(REC->hdr, sizeof(REC->hdr)),
            __print_hex(REC->tsf, sizeof(REC->tsf))

after this change:

print fmt: "%s: %s: HDR:%s, CDB:%s",
      print_symbolic(REC->str_t, {0, "send"},
                                 {1, "complete"},
                                 {2, "dev_complete"},
                                 {3, "query_send"},
                                 {4, "query_complete"},
                                 {5, "query_complete_err"},
                                 {6, "tm_send"},
                                 {7, "tm_complete"},
                                 {8, "tm_complete_err"}),
      __get_str(dev_name), __print_hex(REC->hdr, sizeof(REC->hdr)),
      __print_hex(REC->tsf, sizeof(REC->tsf))

Note: This patch just converts current __get_str(str) to __print_symbolic(),
      the original tracing log will not be affected by this change, so it
      doesn't break what current parsers expect.

Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Bean Huo <beanhuo@micron.com>
---
 drivers/scsi/ufs/ufs.h     | 10 +++++++
 drivers/scsi/ufs/ufshcd.c  | 48 ++++++++++++++++-----------------
 include/trace/events/ufs.h | 54 ++++++++++++++++++++++++--------------
 3 files changed, 69 insertions(+), 43 deletions(-)

diff --git a/drivers/scsi/ufs/ufs.h b/drivers/scsi/ufs/ufs.h
index 14dfda735adf..ba24b504f85a 100644
--- a/drivers/scsi/ufs/ufs.h
+++ b/drivers/scsi/ufs/ufs.h
@@ -545,6 +545,16 @@ struct ufs_dev_info {
 	u8 b_presrv_uspc_en;
 };
 
+/*
+ * This enum is used in string mapping in include/trace/events/ufs.h.
+ */
+enum ufs_trace_str_t {
+	UFS_CMD_SEND, UFS_CMD_COMP, UFS_DEV_COMP,
+	UFS_QUERY_SEND, UFS_QUERY_COMP, UFS_QUERY_ERR,
+	UFS_TM_SEND, UFS_TM_COMP, UFS_TM_ERR
+};
+
+
 /**
  * ufs_is_valid_unit_desc_lun - checks if the given LUN has a unit descriptor
  * @dev_info: pointer of instance of struct ufs_dev_info
diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index 82ad31781bc9..c68afd356abb 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -305,53 +305,53 @@ static void ufshcd_scsi_block_requests(struct ufs_hba *hba)
 }
 
 static void ufshcd_add_cmd_upiu_trace(struct ufs_hba *hba, unsigned int tag,
-		const char *str)
+				      enum ufs_trace_str_t str_t)
 {
 	struct utp_upiu_req *rq = hba->lrb[tag].ucd_req_ptr;
 
-	trace_ufshcd_upiu(dev_name(hba->dev), str, &rq->header, &rq->sc.cdb);
+	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &rq->header, &rq->sc.cdb);
 }
 
 static void ufshcd_add_query_upiu_trace(struct ufs_hba *hba, unsigned int tag,
-		const char *str)
+					enum ufs_trace_str_t str_t)
 {
 	struct utp_upiu_req *rq = hba->lrb[tag].ucd_req_ptr;
 
-	trace_ufshcd_upiu(dev_name(hba->dev), str, &rq->header, &rq->qr);
+	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &rq->header, &rq->qr);
 }
 
 static void ufshcd_add_tm_upiu_trace(struct ufs_hba *hba, unsigned int tag,
-		const char *str)
+				     enum ufs_trace_str_t str_t)
 {
 	int off = (int)tag - hba->nutrs;
 	struct utp_task_req_desc *descp = &hba->utmrdl_base_addr[off];
 
-	trace_ufshcd_upiu(dev_name(hba->dev), str, &descp->req_header,
+	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &descp->req_header,
 			&descp->input_param1);
 }
 
 static void ufshcd_add_uic_command_trace(struct ufs_hba *hba,
 					 struct uic_command *ucmd,
-					 const char *str)
+					 enum ufs_trace_str_t str_t)
 {
 	u32 cmd;
 
 	if (!trace_ufshcd_uic_command_enabled())
 		return;
 
-	if (!strcmp(str, "send"))
+	if (str_t == UFS_CMD_SEND)
 		cmd = ucmd->command;
 	else
 		cmd = ufshcd_readl(hba, REG_UIC_COMMAND);
 
-	trace_ufshcd_uic_command(dev_name(hba->dev), str, cmd,
+	trace_ufshcd_uic_command(dev_name(hba->dev), str_t, cmd,
 				 ufshcd_readl(hba, REG_UIC_COMMAND_ARG_1),
 				 ufshcd_readl(hba, REG_UIC_COMMAND_ARG_2),
 				 ufshcd_readl(hba, REG_UIC_COMMAND_ARG_3));
 }
 
-static void ufshcd_add_command_trace(struct ufs_hba *hba,
-		unsigned int tag, const char *str)
+static void ufshcd_add_command_trace(struct ufs_hba *hba, unsigned int tag,
+				     enum ufs_trace_str_t str_t)
 {
 	sector_t lba = -1;
 	u8 opcode = 0, group_id = 0;
@@ -363,13 +363,13 @@ static void ufshcd_add_command_trace(struct ufs_hba *hba,
 	if (!trace_ufshcd_command_enabled()) {
 		/* trace UPIU W/O tracing command */
 		if (cmd)
-			ufshcd_add_cmd_upiu_trace(hba, tag, str);
+			ufshcd_add_cmd_upiu_trace(hba, tag, str_t);
 		return;
 	}
 
 	if (cmd) { /* data phase exists */
 		/* trace UPIU also */
-		ufshcd_add_cmd_upiu_trace(hba, tag, str);
+		ufshcd_add_cmd_upiu_trace(hba, tag, str_t);
 		opcode = cmd->cmnd[0];
 		if ((opcode == READ_10) || (opcode == WRITE_10)) {
 			/*
@@ -392,7 +392,7 @@ static void ufshcd_add_command_trace(struct ufs_hba *hba,
 
 	intr = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
 	doorbell = ufshcd_readl(hba, REG_UTP_TRANSFER_REQ_DOOR_BELL);
-	trace_ufshcd_command(dev_name(hba->dev), str, tag,
+	trace_ufshcd_command(dev_name(hba->dev), str_t, tag,
 			doorbell, transfer_len, intr, lba, opcode, group_id);
 }
 
@@ -2001,7 +2001,7 @@ void ufshcd_send_command(struct ufs_hba *hba, unsigned int task_tag)
 	lrbp->issue_time_stamp = ktime_get();
 	lrbp->compl_time_stamp = ktime_set(0, 0);
 	ufshcd_vops_setup_xfer_req(hba, task_tag, (lrbp->cmd ? true : false));
-	ufshcd_add_command_trace(hba, task_tag, "send");
+	ufshcd_add_command_trace(hba, task_tag, UFS_CMD_SEND);
 	ufshcd_clk_scaling_start_busy(hba);
 	__set_bit(task_tag, &hba->outstanding_reqs);
 	ufshcd_writel(hba, 1 << task_tag, REG_UTP_TRANSFER_REQ_DOOR_BELL);
@@ -2137,7 +2137,7 @@ ufshcd_dispatch_uic_cmd(struct ufs_hba *hba, struct uic_command *uic_cmd)
 	ufshcd_writel(hba, uic_cmd->argument2, REG_UIC_COMMAND_ARG_2);
 	ufshcd_writel(hba, uic_cmd->argument3, REG_UIC_COMMAND_ARG_3);
 
-	ufshcd_add_uic_command_trace(hba, uic_cmd, "send");
+	ufshcd_add_uic_command_trace(hba, uic_cmd, UFS_CMD_SEND);
 
 	/* Write UIC Cmd */
 	ufshcd_writel(hba, uic_cmd->command & COMMAND_OPCODE_MASK,
@@ -2856,7 +2856,7 @@ static int ufshcd_exec_dev_cmd(struct ufs_hba *hba,
 
 	hba->dev_cmd.complete = &wait;
 
-	ufshcd_add_query_upiu_trace(hba, tag, "query_send");
+	ufshcd_add_query_upiu_trace(hba, tag, UFS_QUERY_SEND);
 	/* Make sure descriptors are ready before ringing the doorbell */
 	wmb();
 	spin_lock_irqsave(hba->host->host_lock, flags);
@@ -2867,7 +2867,7 @@ static int ufshcd_exec_dev_cmd(struct ufs_hba *hba,
 
 out:
 	ufshcd_add_query_upiu_trace(hba, tag,
-			err ? "query_complete_err" : "query_complete");
+			err ? UFS_QUERY_ERR : UFS_QUERY_COMP);
 
 out_put_tag:
 	blk_put_request(req);
@@ -5028,7 +5028,7 @@ static irqreturn_t ufshcd_uic_cmd_compl(struct ufs_hba *hba, u32 intr_status)
 
 	if (retval == IRQ_HANDLED)
 		ufshcd_add_uic_command_trace(hba, hba->active_uic_cmd,
-					     "complete");
+					     UFS_CMD_COMP);
 	return retval;
 }
 
@@ -5052,7 +5052,7 @@ static void __ufshcd_transfer_req_compl(struct ufs_hba *hba,
 		lrbp->compl_time_stamp = ktime_get();
 		cmd = lrbp->cmd;
 		if (cmd) {
-			ufshcd_add_command_trace(hba, index, "complete");
+			ufshcd_add_command_trace(hba, index, UFS_CMD_COMP);
 			result = ufshcd_transfer_rsp_status(hba, lrbp);
 			scsi_dma_unmap(cmd);
 			cmd->result = result;
@@ -5066,7 +5066,7 @@ static void __ufshcd_transfer_req_compl(struct ufs_hba *hba,
 			lrbp->command_type == UTP_CMD_TYPE_UFS_STORAGE) {
 			if (hba->dev_cmd.complete) {
 				ufshcd_add_command_trace(hba, index,
-						"dev_complete");
+							 UFS_DEV_COMP);
 				complete(hba->dev_cmd.complete);
 				update_scaling = true;
 			}
@@ -6369,7 +6369,7 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba *hba,
 
 	spin_unlock_irqrestore(host->host_lock, flags);
 
-	ufshcd_add_tm_upiu_trace(hba, task_tag, "tm_send");
+	ufshcd_add_tm_upiu_trace(hba, task_tag, UFS_TM_SEND);
 
 	/* wait until the task management command is completed */
 	err = wait_for_completion_io_timeout(&wait,
@@ -6380,7 +6380,7 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba *hba,
 		 * use-after-free.
 		 */
 		req->end_io_data = NULL;
-		ufshcd_add_tm_upiu_trace(hba, task_tag, "tm_complete_err");
+		ufshcd_add_tm_upiu_trace(hba, task_tag, UFS_TM_ERR);
 		dev_err(hba->dev, "%s: task management cmd 0x%.2x timed-out\n",
 				__func__, tm_function);
 		if (ufshcd_clear_tm_cmd(hba, free_slot))
@@ -6391,7 +6391,7 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba *hba,
 		err = 0;
 		memcpy(treq, hba->utmrdl_base_addr + free_slot, sizeof(*treq));
 
-		ufshcd_add_tm_upiu_trace(hba, task_tag, "tm_complete");
+		ufshcd_add_tm_upiu_trace(hba, task_tag, UFS_TM_COMP);
 	}
 
 	spin_lock_irqsave(hba->host->host_lock, flags);
diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h
index fa755394bc0f..7613a5cd14de 100644
--- a/include/trace/events/ufs.h
+++ b/include/trace/events/ufs.h
@@ -37,6 +37,17 @@
 	EM(REQ_CLKS_OFF,		"REQ_CLKS_OFF")		\
 	EMe(REQ_CLKS_ON,		"REQ_CLKS_ON")
 
+#define UFS_CMD_TRACE_STRINGS					\
+	EM(UFS_CMD_SEND,	"send_req")			\
+	EM(UFS_CMD_COMP,	"complete_rsp")			\
+	EM(UFS_DEV_COMP,	"dev_complete")			\
+	EM(UFS_QUERY_SEND,	"query_send")			\
+	EM(UFS_QUERY_COMP,	"query_complete")		\
+	EM(UFS_QUERY_ERR,	"query_complete_err")		\
+	EM(UFS_TM_SEND,		"tm_send")			\
+	EM(UFS_TM_COMP,		"tm_complete")			\
+	EMe(UFS_TM_ERR,		"tm_complete_err")
+
 /* Enums require being exported to userspace, for user tool parsing */
 #undef EM
 #undef EMe
@@ -46,6 +57,7 @@
 UFS_LINK_STATES;
 UFS_PWR_MODES;
 UFSCHD_CLK_GATING_STATES;
+UFS_CMD_TRACE_STRINGS
 
 /*
  * Now redefine the EM() and EMe() macros to map the enums to the strings
@@ -56,6 +68,9 @@ UFSCHD_CLK_GATING_STATES;
 #define EM(a, b)	{a, b},
 #define EMe(a, b)	{a, b}
 
+#define show_ufs_cmd_trace_str(str_t)	\
+				__print_symbolic(str_t, UFS_CMD_TRACE_STRINGS)
+
 TRACE_EVENT(ufshcd_clk_gating,
 
 	TP_PROTO(const char *dev_name, int state),
@@ -223,16 +238,16 @@ DEFINE_EVENT(ufshcd_template, ufshcd_init,
 	     TP_ARGS(dev_name, err, usecs, dev_state, link_state));
 
 TRACE_EVENT(ufshcd_command,
-	TP_PROTO(const char *dev_name, const char *str, unsigned int tag,
-			u32 doorbell, int transfer_len, u32 intr, u64 lba,
-			u8 opcode, u8 group_id),
+	TP_PROTO(const char *dev_name, enum ufs_trace_str_t str_t,
+		 unsigned int tag, u32 doorbell, int transfer_len, u32 intr,
+		 u64 lba, u8 opcode, u8 group_id),
 
-	TP_ARGS(dev_name, str, tag, doorbell, transfer_len,
+	TP_ARGS(dev_name, str_t, tag, doorbell, transfer_len,
 				intr, lba, opcode, group_id),
 
 	TP_STRUCT__entry(
 		__string(dev_name, dev_name)
-		__string(str, str)
+		__field(enum ufs_trace_str_t, str_t)
 		__field(unsigned int, tag)
 		__field(u32, doorbell)
 		__field(int, transfer_len)
@@ -244,7 +259,7 @@ TRACE_EVENT(ufshcd_command,
 
 	TP_fast_assign(
 		__assign_str(dev_name, dev_name);
-		__assign_str(str, str);
+		__entry->str_t = str_t;
 		__entry->tag = tag;
 		__entry->doorbell = doorbell;
 		__entry->transfer_len = transfer_len;
@@ -256,22 +271,22 @@ TRACE_EVENT(ufshcd_command,
 
 	TP_printk(
 		"%s: %s: tag: %u, DB: 0x%x, size: %d, IS: %u, LBA: %llu, opcode: 0x%x (%s), group_id: 0x%x",
-		__get_str(str), __get_str(dev_name), __entry->tag,
-		__entry->doorbell, __entry->transfer_len,
+		show_ufs_cmd_trace_str(__entry->str_t), __get_str(dev_name),
+		__entry->tag, __entry->doorbell, __entry->transfer_len,
 		__entry->intr, __entry->lba, (u32)__entry->opcode,
 		str_opcode(__entry->opcode), (u32)__entry->group_id
 	)
 );
 
 TRACE_EVENT(ufshcd_uic_command,
-	TP_PROTO(const char *dev_name, const char *str, u32 cmd,
+	TP_PROTO(const char *dev_name, enum ufs_trace_str_t str_t, u32 cmd,
 		 u32 arg1, u32 arg2, u32 arg3),
 
-	TP_ARGS(dev_name, str, cmd, arg1, arg2, arg3),
+	TP_ARGS(dev_name, str_t, cmd, arg1, arg2, arg3),
 
 	TP_STRUCT__entry(
 		__string(dev_name, dev_name)
-		__string(str, str)
+		__field(enum ufs_trace_str_t, str_t)
 		__field(u32, cmd)
 		__field(u32, arg1)
 		__field(u32, arg2)
@@ -280,7 +295,7 @@ TRACE_EVENT(ufshcd_uic_command,
 
 	TP_fast_assign(
 		__assign_str(dev_name, dev_name);
-		__assign_str(str, str);
+		__entry->str_t = str_t;
 		__entry->cmd = cmd;
 		__entry->arg1 = arg1;
 		__entry->arg2 = arg2;
@@ -289,33 +304,34 @@ TRACE_EVENT(ufshcd_uic_command,
 
 	TP_printk(
 		"%s: %s: cmd: 0x%x, arg1: 0x%x, arg2: 0x%x, arg3: 0x%x",
-		__get_str(str), __get_str(dev_name), __entry->cmd,
-		__entry->arg1, __entry->arg2, __entry->arg3
+		show_ufs_cmd_trace_str(__entry->str_t), __get_str(dev_name),
+		__entry->cmd, __entry->arg1, __entry->arg2, __entry->arg3
 	)
 );
 
 TRACE_EVENT(ufshcd_upiu,
-	TP_PROTO(const char *dev_name, const char *str, void *hdr, void *tsf),
+	TP_PROTO(const char *dev_name, enum ufs_trace_str_t str_t, void *hdr,
+		 void *tsf),
 
-	TP_ARGS(dev_name, str, hdr, tsf),
+	TP_ARGS(dev_name, str_t, hdr, tsf),
 
 	TP_STRUCT__entry(
 		__string(dev_name, dev_name)
-		__string(str, str)
+		__field(enum ufs_trace_str_t, str_t)
 		__array(unsigned char, hdr, 12)
 		__array(unsigned char, tsf, 16)
 	),
 
 	TP_fast_assign(
 		__assign_str(dev_name, dev_name);
-		__assign_str(str, str);
+		__entry->str_t = str_t;
 		memcpy(__entry->hdr, hdr, sizeof(__entry->hdr));
 		memcpy(__entry->tsf, tsf, sizeof(__entry->tsf));
 	),
 
 	TP_printk(
 		"%s: %s: HDR:%s, CDB:%s",
-		__get_str(str), __get_str(dev_name),
+		show_ufs_cmd_trace_str(__entry->str_t), __get_str(dev_name),
 		__print_hex(__entry->hdr, sizeof(__entry->hdr)),
 		__print_hex(__entry->tsf, sizeof(__entry->tsf))
 	)
-- 
2.17.1

[PATCH v4 3/6] scsi: ufs: Don't call trace_ufshcd_upiu() in case trace poit is disabled

[Bean Huo]

From: Bean Huo <beanhuo@micron.com>

Don't call trace_ufshcd_upiu() in case ufshba_upiu trace poit is not enabled.

Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Bean Huo <beanhuo@micron.com>
---
 drivers/scsi/ufs/ufshcd.c | 9 +++++++++
 1 file changed, 9 insertions(+)

diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index c68afd356abb..9c8fc46183c4 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -309,6 +309,9 @@ static void ufshcd_add_cmd_upiu_trace(struct ufs_hba *hba, unsigned int tag,
 {
 	struct utp_upiu_req *rq = hba->lrb[tag].ucd_req_ptr;
 
+	if (!trace_ufshcd_upiu_enabled())
+		return;
+
 	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &rq->header, &rq->sc.cdb);
 }
 
@@ -317,6 +320,9 @@ static void ufshcd_add_query_upiu_trace(struct ufs_hba *hba, unsigned int tag,
 {
 	struct utp_upiu_req *rq = hba->lrb[tag].ucd_req_ptr;
 
+	if (!trace_ufshcd_upiu_enabled())
+		return;
+
 	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &rq->header, &rq->qr);
 }
 
@@ -326,6 +332,9 @@ static void ufshcd_add_tm_upiu_trace(struct ufs_hba *hba, unsigned int tag,
 	int off = (int)tag - hba->nutrs;
 	struct utp_task_req_desc *descp = &hba->utmrdl_base_addr[off];
 
+	if (!trace_ufshcd_upiu_enabled())
+		return;
+
 	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &descp->req_header,
 			&descp->input_param1);
 }
-- 
2.17.1

[PATCH v4 4/6] scsi: ufs: Distinguish between query REQ and query RSP in query trace

[Bean Huo]

From: Bean Huo <beanhuo@micron.com>

Currently, in the query completion trace print,  since we use
hba->lrb[tag].ucd_req_ptr and didn't differentiate UPIU between
request and response, thus header and transaction-specific field
in UPIU printed by query trace are identical. This is not very
practical. As below:

query_send: HDR:16 00 00 0e 00 81 00 00 00 00 00 00, CDB:06 0e 03 00 00 00 00 00 00 00 00 00 00 00 00 00
query_complete: HDR:16 00 00 0e 00 81 00 00 00 00 00 00, CDB:06 0e 03 00 00 00 00 00 00 00 00 00 00 00 00 00

For the failure analysis, we want to understand the real response
reported by the UFS device, however, the current query trace tells
us nothing. After this patch, the query trace on the query_send, and
the above a pair of query_send and query_complete will be:

query_send: HDR:16 00 00 0e 00 81 00 00 00 00 00 00, CDB:06 0e 03 00 00 00 00 00 00 00 00 00 00 00 00 00
ufshcd_upiu: HDR:36 00 00 0e 00 81 00 00 00 00 00 00, CDB:06 0e 03 00 00 00 00 00 00 00 00 01 00 00 00 00

Acked-by: Avri Altman <avri.altman@wdc.com>
Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Bean Huo <beanhuo@micron.com>
---
 drivers/scsi/ufs/ufshcd.c | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index 9c8fc46183c4..6ccf71ab3b9c 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -318,12 +318,18 @@ static void ufshcd_add_cmd_upiu_trace(struct ufs_hba *hba, unsigned int tag,
 static void ufshcd_add_query_upiu_trace(struct ufs_hba *hba, unsigned int tag,
 					enum ufs_trace_str_t str_t)
 {
-	struct utp_upiu_req *rq = hba->lrb[tag].ucd_req_ptr;
+	struct utp_upiu_req *rq_rsp;
 
 	if (!trace_ufshcd_upiu_enabled())
 		return;
 
-	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &rq->header, &rq->qr);
+	if (str_t == UFS_QUERY_SEND)
+		rq_rsp = hba->lrb[tag].ucd_req_ptr;
+	else
+		rq_rsp = (struct utp_upiu_req *)hba->lrb[tag].ucd_rsp_ptr;
+
+	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &rq_rsp->header,
+			  &rq_rsp->qr);
 }
 
 static void ufshcd_add_tm_upiu_trace(struct ufs_hba *hba, unsigned int tag,
-- 
2.17.1

[PATCH v4 5/6] scsi: ufs: Distinguish between TM request UPIU and response UPIU in TM UPIU trace

[Bean Huo]

From: Bean Huo <beanhuo@micron.com>

Distinguish between TM request UPIU and response UPIU in TM UPIU trace,
for the TM response, let TM UPIU trace print its TM response UPIU.

Acked-by: Avri Altman <avri.altman@wdc.com>
Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Bean Huo <beanhuo@micron.com>
---
 drivers/scsi/ufs/ufshcd.c | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index 6ccf71ab3b9c..4df17005e398 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -341,8 +341,12 @@ static void ufshcd_add_tm_upiu_trace(struct ufs_hba *hba, unsigned int tag,
 	if (!trace_ufshcd_upiu_enabled())
 		return;
 
-	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &descp->req_header,
-			&descp->input_param1);
+	if (str_t == UFS_TM_SEND)
+		trace_ufshcd_upiu(dev_name(hba->dev), str_t, &descp->req_header,
+				  &descp->input_param1);
+	else
+		trace_ufshcd_upiu(dev_name(hba->dev), str_t, &descp->rsp_header,
+				  &descp->output_param1);
 }
 
 static void ufshcd_add_uic_command_trace(struct ufs_hba *hba,
-- 
2.17.1

[PATCH v4 6/6] scsi: ufs: Make UPIU trace easier differentiate among CDB, OSF, and TM

[Bean Huo]

From: Bean Huo <beanhuo@micron.com>

Transaction Specific Fields (TSF) in the UPIU package could be CDB
(SCSI/UFS Command Descriptor Block), OSF (Opcode Specific Field), and
TM I/O parameter (Task Management Input/Output Parameter). But, currently,
we take all of these as CDB  in the UPIU trace. Thus makes user confuse
among CDB, OSF, and TM message. So fix it with this patch.

Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Bean Huo <beanhuo@micron.com>
---
 drivers/scsi/ufs/ufs.h     |  7 +++++++
 drivers/scsi/ufs/ufshcd.c  |  9 +++++----
 include/trace/events/ufs.h | 18 +++++++++++++++---
 3 files changed, 27 insertions(+), 7 deletions(-)

diff --git a/drivers/scsi/ufs/ufs.h b/drivers/scsi/ufs/ufs.h
index ba24b504f85a..50f46f3bc8a2 100644
--- a/drivers/scsi/ufs/ufs.h
+++ b/drivers/scsi/ufs/ufs.h
@@ -554,6 +554,13 @@ enum ufs_trace_str_t {
 	UFS_TM_SEND, UFS_TM_COMP, UFS_TM_ERR
 };
 
+/*
+ * Transaction Specific Fields (TSF) type in the UPIU package, this enum is
+ * used in include/trace/events/ufs.h for UFS command trace.
+ */
+enum ufs_trace_tsf_t {
+	UFS_TSF_CDB, UFS_TSF_OSF, UFS_TSF_TM_INPUT, UFS_TSF_TM_OUTPUT
+};
 
 /**
  * ufs_is_valid_unit_desc_lun - checks if the given LUN has a unit descriptor
diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index 4df17005e398..3be555e5410f 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -312,7 +312,8 @@ static void ufshcd_add_cmd_upiu_trace(struct ufs_hba *hba, unsigned int tag,
 	if (!trace_ufshcd_upiu_enabled())
 		return;
 
-	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &rq->header, &rq->sc.cdb);
+	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &rq->header, &rq->sc.cdb,
+			  UFS_TSF_CDB);
 }
 
 static void ufshcd_add_query_upiu_trace(struct ufs_hba *hba, unsigned int tag,
@@ -329,7 +330,7 @@ static void ufshcd_add_query_upiu_trace(struct ufs_hba *hba, unsigned int tag,
 		rq_rsp = (struct utp_upiu_req *)hba->lrb[tag].ucd_rsp_ptr;
 
 	trace_ufshcd_upiu(dev_name(hba->dev), str_t, &rq_rsp->header,
-			  &rq_rsp->qr);
+			  &rq_rsp->qr, UFS_TSF_OSF);
 }
 
 static void ufshcd_add_tm_upiu_trace(struct ufs_hba *hba, unsigned int tag,
@@ -343,10 +344,10 @@ static void ufshcd_add_tm_upiu_trace(struct ufs_hba *hba, unsigned int tag,
 
 	if (str_t == UFS_TM_SEND)
 		trace_ufshcd_upiu(dev_name(hba->dev), str_t, &descp->req_header,
-				  &descp->input_param1);
+				  &descp->input_param1, UFS_TSF_TM_INPUT);
 	else
 		trace_ufshcd_upiu(dev_name(hba->dev), str_t, &descp->rsp_header,
-				  &descp->output_param1);
+				  &descp->output_param1, UFS_TSF_TM_OUTPUT);
 }
 
 static void ufshcd_add_uic_command_trace(struct ufs_hba *hba,
diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h
index 7613a5cd14de..e151477d645c 100644
--- a/include/trace/events/ufs.h
+++ b/include/trace/events/ufs.h
@@ -48,6 +48,12 @@
 	EM(UFS_TM_COMP,		"tm_complete")			\
 	EMe(UFS_TM_ERR,		"tm_complete_err")
 
+#define UFS_CMD_TRACE_TSF_TYPES					\
+	EM(UFS_TSF_CDB,		"CDB")		                \
+	EM(UFS_TSF_OSF,		"OSF")		                \
+	EM(UFS_TSF_TM_INPUT,	"TM_INPUT")                     \
+	EMe(UFS_TSF_TM_OUTPUT,	"TM_OUTPUT")
+
 /* Enums require being exported to userspace, for user tool parsing */
 #undef EM
 #undef EMe
@@ -58,6 +64,7 @@ UFS_LINK_STATES;
 UFS_PWR_MODES;
 UFSCHD_CLK_GATING_STATES;
 UFS_CMD_TRACE_STRINGS
+UFS_CMD_TRACE_TSF_TYPES
 
 /*
  * Now redefine the EM() and EMe() macros to map the enums to the strings
@@ -70,6 +77,8 @@ UFS_CMD_TRACE_STRINGS
 
 #define show_ufs_cmd_trace_str(str_t)	\
 				__print_symbolic(str_t, UFS_CMD_TRACE_STRINGS)
+#define show_ufs_cmd_trace_tsf(tsf)	\
+				__print_symbolic(tsf, UFS_CMD_TRACE_TSF_TYPES)
 
 TRACE_EVENT(ufshcd_clk_gating,
 
@@ -311,15 +320,16 @@ TRACE_EVENT(ufshcd_uic_command,
 
 TRACE_EVENT(ufshcd_upiu,
 	TP_PROTO(const char *dev_name, enum ufs_trace_str_t str_t, void *hdr,
-		 void *tsf),
+		 void *tsf, enum ufs_trace_tsf_t tsf_t),
 
-	TP_ARGS(dev_name, str_t, hdr, tsf),
+	TP_ARGS(dev_name, str_t, hdr, tsf, tsf_t),
 
 	TP_STRUCT__entry(
 		__string(dev_name, dev_name)
 		__field(enum ufs_trace_str_t, str_t)
 		__array(unsigned char, hdr, 12)
 		__array(unsigned char, tsf, 16)
+		__field(enum ufs_trace_tsf_t, tsf_t)
 	),
 
 	TP_fast_assign(
@@ -327,12 +337,14 @@ TRACE_EVENT(ufshcd_upiu,
 		__entry->str_t = str_t;
 		memcpy(__entry->hdr, hdr, sizeof(__entry->hdr));
 		memcpy(__entry->tsf, tsf, sizeof(__entry->tsf));
+		__entry->tsf_t = tsf_t;
 	),
 
 	TP_printk(
-		"%s: %s: HDR:%s, CDB:%s",
+		"%s: %s: HDR:%s, %s:%s",
 		show_ufs_cmd_trace_str(__entry->str_t), __get_str(dev_name),
 		__print_hex(__entry->hdr, sizeof(__entry->hdr)),
+		show_ufs_cmd_trace_tsf(__entry->tsf_t),
 		__print_hex(__entry->tsf, sizeof(__entry->tsf))
 	)
 );
-- 
2.17.1

Re: [PATCH v4 0/6] Several changes for the UPIU trace

[Martin K. Petersen]

Bean,

> Bean Huo (6):
>   scsi: ufs: Remove stringize operator '#' restriction
>   scsi: ufs: Use __print_symbolic() for UFS trace string print
>   scsi: ufs: Don't call trace_ufshcd_upiu() in case trace poit is
>     disabled
>   scsi: ufs: Distinguish between query REQ and query RSP in query trace
>   scsi: ufs: Distinguish between TM request UPIU and response UPIU in TM
>     UPIU trace
>   scsi: ufs: Make UPIU trace easier differentiate among CDB, OSF, and TM

Applied to 5.12/scsi-staging, thanks!

-- 
Martin K. Petersen	Oracle Linux Engineering

Re: [PATCH v4 0/6] Several changes for the UPIU trace

[Martin K. Petersen]

On Tue, 5 Jan 2021 12:34:40 +0100, Bean Huo wrote:

> Changelog:
> 
> V3--v4:
>  1. Rebase patch onto 5.12/scsi-queue
>  2. Incorporate Avri's suggestion in patch 2/6
> 
> V2--V3:
>   1. Fix a typo in patch 1/6 (Reported-by: Joe Perches <joe@perches.com>)
> 
> [...]

Applied to 5.12/scsi-queue, thanks!

[1/6] scsi: ufs: Remove stringize operator '#' restriction
      https://git.kernel.org/mkp/scsi/c/c7c730ac6a88
[2/6] scsi: ufs: Use __print_symbolic() for UFS trace string print
      https://git.kernel.org/mkp/scsi/c/28fa68fc557a
[3/6] scsi: ufs: Don't call trace_ufshcd_upiu() in case trace poit is disabled
      https://git.kernel.org/mkp/scsi/c/9d5095e74c83
[4/6] scsi: ufs: Distinguish between query REQ and query RSP in query trace
      https://git.kernel.org/mkp/scsi/c/be20b51cfd85
[5/6] scsi: ufs: Distinguish between TM request UPIU and response UPIU in TM UPIU trace
      https://git.kernel.org/mkp/scsi/c/0ed083e91662
[6/6] scsi: ufs: Make UPIU trace easier differentiate among CDB, OSF, and TM
      https://git.kernel.org/mkp/scsi/c/867fdc2d6e34

-- 
Martin K. Petersen	Oracle Linux Engineering