* [PATCH v1 0/2] scsi: ufs: Add trace event for UIC commands @ 2020-06-12 15:09 Stanley Chu 2020-06-12 15:09 ` [PATCH v1 1/2] scsi: ufs: Remove unused field in struct uic_command Stanley Chu 2020-06-12 15:10 ` [PATCH v1 2/2] scsi: ufs: Add trace event for UIC commands Stanley Chu 0 siblings, 2 replies; 7+ messages in thread From: Stanley Chu @ 2020-06-12 15:09 UTC (permalink / raw) To: linux-scsi, martin.petersen, avri.altman, alim.akhtar, jejb, asutoshd Cc: beanhuo, cang, matthias.bgg, bvanassche, linux-mediatek, linux-arm-kernel, linux-kernel, kuohong.wang, peter.wang, chun-hung.wu, andy.teng, chaotian.jing, cc.chou, Stanley Chu Hi, This series adds trace event for UIC commands and do a small cleanup in struct uic_command. Stanley Chu (2): scsi: ufs: Remove unused field in struct uic_command scsi: ufs: Add trace event for UIC commands drivers/scsi/ufs/ufshcd.c | 29 +++++++++++++++++++++++++++++ drivers/scsi/ufs/ufshcd.h | 2 -- include/trace/events/ufs.h | 33 +++++++++++++++++++++++++++++++++ 3 files changed, 62 insertions(+), 2 deletions(-) -- 2.18.0 ^ permalink raw reply [flat|nested] 7+ messages in thread
* [PATCH v1 1/2] scsi: ufs: Remove unused field in struct uic_command 2020-06-12 15:09 [PATCH v1 0/2] scsi: ufs: Add trace event for UIC commands Stanley Chu @ 2020-06-12 15:09 ` Stanley Chu 2020-06-12 16:22 ` Alim Akhtar 2020-06-12 15:10 ` [PATCH v1 2/2] scsi: ufs: Add trace event for UIC commands Stanley Chu 1 sibling, 1 reply; 7+ messages in thread From: Stanley Chu @ 2020-06-12 15:09 UTC (permalink / raw) To: linux-scsi, martin.petersen, avri.altman, alim.akhtar, jejb, asutoshd Cc: beanhuo, cang, matthias.bgg, bvanassche, linux-mediatek, linux-arm-kernel, linux-kernel, kuohong.wang, peter.wang, chun-hung.wu, andy.teng, chaotian.jing, cc.chou, Stanley Chu Remove unused field "cmd_active" in struct ufs_command. Signed-off-by: Stanley Chu <stanley.chu@mediatek.com> --- drivers/scsi/ufs/ufshcd.h | 2 -- 1 file changed, 2 deletions(-) diff --git a/drivers/scsi/ufs/ufshcd.h b/drivers/scsi/ufs/ufshcd.h index bf97d616e597..814e44871ff0 100644 --- a/drivers/scsi/ufs/ufshcd.h +++ b/drivers/scsi/ufs/ufshcd.h @@ -88,7 +88,6 @@ enum dev_cmd_type { * @argument1: UIC command argument 1 * @argument2: UIC command argument 2 * @argument3: UIC command argument 3 - * @cmd_active: Indicate if UIC command is outstanding * @result: UIC command result * @done: UIC command completion */ @@ -97,7 +96,6 @@ struct uic_command { u32 argument1; u32 argument2; u32 argument3; - int cmd_active; int result; struct completion done; }; -- 2.18.0 ^ permalink raw reply related [flat|nested] 7+ messages in thread
* RE: [PATCH v1 1/2] scsi: ufs: Remove unused field in struct uic_command 2020-06-12 15:09 ` [PATCH v1 1/2] scsi: ufs: Remove unused field in struct uic_command Stanley Chu @ 2020-06-12 16:22 ` Alim Akhtar 0 siblings, 0 replies; 7+ messages in thread From: Alim Akhtar @ 2020-06-12 16:22 UTC (permalink / raw) To: 'Stanley Chu', linux-scsi, martin.petersen, avri.altman, jejb, asutoshd Cc: beanhuo, cang, matthias.bgg, bvanassche, linux-mediatek, linux-arm-kernel, linux-kernel, kuohong.wang, peter.wang, chun-hung.wu, andy.teng, chaotian.jing, cc.chou Hi Stanley > -----Original Message----- > From: Stanley Chu <stanley.chu@mediatek.com> > Sent: 12 June 2020 20:40 > To: linux-scsi@vger.kernel.org; martin.petersen@oracle.com; > avri.altman@wdc.com; alim.akhtar@samsung.com; jejb@linux.ibm.com; > asutoshd@codeaurora.org > Cc: beanhuo@micron.com; cang@codeaurora.org; matthias.bgg@gmail.com; > bvanassche@acm.org; linux-mediatek@lists.infradead.org; linux-arm- > kernel@lists.infradead.org; linux-kernel@vger.kernel.org; > kuohong.wang@mediatek.com; peter.wang@mediatek.com; chun- > hung.wu@mediatek.com; andy.teng@mediatek.com; > chaotian.jing@mediatek.com; cc.chou@mediatek.com; Stanley Chu > <stanley.chu@mediatek.com> > Subject: [PATCH v1 1/2] scsi: ufs: Remove unused field in struct uic_command > > Remove unused field "cmd_active" in struct ufs_command. > > Signed-off-by: Stanley Chu <stanley.chu@mediatek.com> > --- Reviewed-by: Alim Akhtar <alim.akhtar@samsung.com> > drivers/scsi/ufs/ufshcd.h | 2 -- > 1 file changed, 2 deletions(-) > > diff --git a/drivers/scsi/ufs/ufshcd.h b/drivers/scsi/ufs/ufshcd.h index > bf97d616e597..814e44871ff0 100644 > --- a/drivers/scsi/ufs/ufshcd.h > +++ b/drivers/scsi/ufs/ufshcd.h > @@ -88,7 +88,6 @@ enum dev_cmd_type { > * @argument1: UIC command argument 1 > * @argument2: UIC command argument 2 > * @argument3: UIC command argument 3 > - * @cmd_active: Indicate if UIC command is outstanding > * @result: UIC command result > * @done: UIC command completion > */ > @@ -97,7 +96,6 @@ struct uic_command { > u32 argument1; > u32 argument2; > u32 argument3; > - int cmd_active; > int result; > struct completion done; > }; > -- > 2.18.0 ^ permalink raw reply [flat|nested] 7+ messages in thread
* [PATCH v1 2/2] scsi: ufs: Add trace event for UIC commands 2020-06-12 15:09 [PATCH v1 0/2] scsi: ufs: Add trace event for UIC commands Stanley Chu 2020-06-12 15:09 ` [PATCH v1 1/2] scsi: ufs: Remove unused field in struct uic_command Stanley Chu @ 2020-06-12 15:10 ` Stanley Chu 2020-06-13 10:48 ` Avri Altman 1 sibling, 1 reply; 7+ messages in thread From: Stanley Chu @ 2020-06-12 15:10 UTC (permalink / raw) To: linux-scsi, martin.petersen, avri.altman, alim.akhtar, jejb, asutoshd Cc: beanhuo, cang, matthias.bgg, bvanassche, linux-mediatek, linux-arm-kernel, linux-kernel, kuohong.wang, peter.wang, chun-hung.wu, andy.teng, chaotian.jing, cc.chou, Stanley Chu Use the ftrace infrastructure to conditionally trace UFS UIC command events. New trace event "ufshcd_uic_command" is created, which samples the following UFS UIC command data: - Device name - Optional identification string - UIC command opcode - UIC command argument1 - UIC command argument2 - UIC command argement3 - UIC command execution result Usage: echo 1 > /sys/kernel/debug/tracing/events/ufs/enable cat /sys/kernel/debug/tracing/trace_pipe Signed-off-by: Stanley Chu <stanley.chu@mediatek.com> --- drivers/scsi/ufs/ufshcd.c | 29 +++++++++++++++++++++++++++++ include/trace/events/ufs.h | 33 +++++++++++++++++++++++++++++++++ 2 files changed, 62 insertions(+) diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c index c197a3315d21..181617966658 100644 --- a/drivers/scsi/ufs/ufshcd.c +++ b/drivers/scsi/ufs/ufshcd.c @@ -339,6 +339,27 @@ static void ufshcd_add_tm_upiu_trace(struct ufs_hba *hba, unsigned int tag, &descp->input_param1); } +static void ufshcd_add_uic_command_trace(struct ufs_hba *hba, + struct uic_command *ucmd, + const char *str) +{ + u32 cmd; + + if (!trace_ufshcd_uic_command_enabled()) + return; + + if (!strcmp(str, "uic_send")) + cmd = ucmd->command; + else + cmd = ufshcd_readl(hba, REG_UIC_COMMAND); + + trace_ufshcd_uic_command(dev_name(hba->dev), str, cmd, + ucmd->result, + 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) { @@ -2054,6 +2075,8 @@ ufshcd_dispatch_uic_cmd(struct ufs_hba *hba, struct uic_command *uic_cmd) /* Write UIC Cmd */ ufshcd_writel(hba, uic_cmd->command & COMMAND_OPCODE_MASK, REG_UIC_COMMAND); + + ufshcd_add_uic_command_trace(hba, uic_cmd, "uic_send"); } /** @@ -2080,6 +2103,9 @@ ufshcd_wait_for_uic_cmd(struct ufs_hba *hba, struct uic_command *uic_cmd) hba->active_uic_cmd = NULL; spin_unlock_irqrestore(hba->host->host_lock, flags); + uic_cmd->result = ret; + ufshcd_add_uic_command_trace(hba, uic_cmd, "uic_complete"); + return ret; } @@ -3760,6 +3786,9 @@ static int ufshcd_uic_pwr_ctrl(struct ufs_hba *hba, struct uic_command *cmd) ret = (status != PWR_OK) ? status : -1; } out: + cmd->result = ret; + ufshcd_add_uic_command_trace(hba, cmd, "uic_complete"); + if (ret) { ufshcd_print_host_state(hba); ufshcd_print_pwr_info(hba); diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h index 5f300739240d..cf8d568d5a13 100644 --- a/include/trace/events/ufs.h +++ b/include/trace/events/ufs.h @@ -249,6 +249,39 @@ TRACE_EVENT(ufshcd_command, ) ); +TRACE_EVENT(ufshcd_uic_command, + TP_PROTO(const char *dev_name, const char *str, u32 cmd, int result, + u32 arg1, u32 arg2, u32 arg3), + + TP_ARGS(dev_name, str, cmd, result, arg1, arg2, arg3), + + TP_STRUCT__entry( + __string(dev_name, dev_name) + __string(str, str) + __field(u32, cmd) + __field(int, result) + __field(u32, arg1) + __field(u32, arg2) + __field(u32, arg3) + ), + + TP_fast_assign( + __assign_str(dev_name, dev_name); + __assign_str(str, str); + __entry->cmd = cmd; + __entry->result = result; + __entry->arg1 = arg1; + __entry->arg2 = arg2; + __entry->arg3 = arg3; + ), + + TP_printk( + "%s: %s: cmd: 0x%x, arg1: 0x%x, arg2: 0x%x, arg3: 0x%x, result: %d", + __get_str(str), __get_str(dev_name), __entry->cmd, + __entry->arg1, __entry->arg2, __entry->arg3, __entry->result + ) +); + TRACE_EVENT(ufshcd_upiu, TP_PROTO(const char *dev_name, const char *str, void *hdr, void *tsf), -- 2.18.0 ^ permalink raw reply related [flat|nested] 7+ messages in thread
* RE: [PATCH v1 2/2] scsi: ufs: Add trace event for UIC commands 2020-06-12 15:10 ` [PATCH v1 2/2] scsi: ufs: Add trace event for UIC commands Stanley Chu @ 2020-06-13 10:48 ` Avri Altman 2020-06-13 14:18 ` Stanley Chu 0 siblings, 1 reply; 7+ messages in thread From: Avri Altman @ 2020-06-13 10:48 UTC (permalink / raw) To: Stanley Chu, linux-scsi, martin.petersen, alim.akhtar, jejb, asutoshd Cc: beanhuo, cang, matthias.bgg, bvanassche, linux-mediatek, linux-arm-kernel, linux-kernel, kuohong.wang, peter.wang, chun-hung.wu, andy.teng, chaotian.jing, cc.chou > +static void ufshcd_add_uic_command_trace(struct ufs_hba *hba, > + struct uic_command *ucmd, > + const char *str) > +{ > + u32 cmd; > + > + if (!trace_ufshcd_uic_command_enabled()) > + return; > + > + if (!strcmp(str, "uic_send")) > + cmd = ucmd->command; > + else > + cmd = ufshcd_readl(hba, REG_UIC_COMMAND); Why on complete you can't just use ucmd->command as well? > + > + trace_ufshcd_uic_command(dev_name(hba->dev), str, cmd, > + ucmd->result, > + ufshcd_readl(hba, REG_UIC_COMMAND_ARG_1), > + ufshcd_readl(hba, REG_UIC_COMMAND_ARG_2), > + ufshcd_readl(hba, REG_UIC_COMMAND_ARG_3)); Why can't you just use the ucmd members? Why need to read those? > +} > + > static void ufshcd_add_command_trace(struct ufs_hba *hba, > unsigned int tag, const char *str) > { > @@ -2054,6 +2075,8 @@ ufshcd_dispatch_uic_cmd(struct ufs_hba *hba, > struct uic_command *uic_cmd) > /* Write UIC Cmd */ > ufshcd_writel(hba, uic_cmd->command & COMMAND_OPCODE_MASK, > REG_UIC_COMMAND); > + > + ufshcd_add_uic_command_trace(hba, uic_cmd, "uic_send"); > } > > /** > @@ -2080,6 +2103,9 @@ ufshcd_wait_for_uic_cmd(struct ufs_hba *hba, > struct uic_command *uic_cmd) > hba->active_uic_cmd = NULL; > spin_unlock_irqrestore(hba->host->host_lock, flags); > > + uic_cmd->result = ret; > + ufshcd_add_uic_command_trace(hba, uic_cmd, "uic_complete"); > + > return ret; > } Can't you just call the "send" and "complete" from ufshcd_send_uic_cmd? > > @@ -3760,6 +3786,9 @@ static int ufshcd_uic_pwr_ctrl(struct ufs_hba *hba, > struct uic_command *cmd) > ret = (status != PWR_OK) ? status : -1; > } > out: > + cmd->result = ret; > + ufshcd_add_uic_command_trace(hba, cmd, "uic_complete"); > + > if (ret) { > ufshcd_print_host_state(hba); > ufshcd_print_pwr_info(hba); > diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h > index 5f300739240d..cf8d568d5a13 100644 > --- a/include/trace/events/ufs.h > +++ b/include/trace/events/ufs.h > @@ -249,6 +249,39 @@ TRACE_EVENT(ufshcd_command, > ) > ); > > +TRACE_EVENT(ufshcd_uic_command, > + TP_PROTO(const char *dev_name, const char *str, u32 cmd, int result, > + u32 arg1, u32 arg2, u32 arg3), > + > + TP_ARGS(dev_name, str, cmd, result, arg1, arg2, arg3), > + > + TP_STRUCT__entry( > + __string(dev_name, dev_name) > + __string(str, str) > + __field(u32, cmd) > + __field(int, result) > + __field(u32, arg1) > + __field(u32, arg2) > + __field(u32, arg3) > + ), > + > + TP_fast_assign( > + __assign_str(dev_name, dev_name); > + __assign_str(str, str); > + __entry->cmd = cmd; > + __entry->result = result; > + __entry->arg1 = arg1; > + __entry->arg2 = arg2; > + __entry->arg3 = arg3; > + ), > + > + TP_printk( > + "%s: %s: cmd: 0x%x, arg1: 0x%x, arg2: 0x%x, arg3: 0x%x, result: %d", > + __get_str(str), __get_str(dev_name), __entry->cmd, > + __entry->arg1, __entry->arg2, __entry->arg3, __entry->result > + ) Personally, as those trace events aren't very human readable anyway, I would just dump the uic command, And let the parsers do their job. And if this is the case, result is redundant as it is part of arg2 Thanks, Avri > +); > + > TRACE_EVENT(ufshcd_upiu, > TP_PROTO(const char *dev_name, const char *str, void *hdr, void *tsf), > > -- > 2.18.0 ^ permalink raw reply [flat|nested] 7+ messages in thread
* RE: [PATCH v1 2/2] scsi: ufs: Add trace event for UIC commands 2020-06-13 10:48 ` Avri Altman @ 2020-06-13 14:18 ` Stanley Chu 2020-06-14 9:27 ` Avri Altman 0 siblings, 1 reply; 7+ messages in thread From: Stanley Chu @ 2020-06-13 14:18 UTC (permalink / raw) To: Avri Altman Cc: linux-scsi, martin.petersen, alim.akhtar, jejb, asutoshd, beanhuo, cang, matthias.bgg, bvanassche, linux-mediatek, linux-arm-kernel, linux-kernel, kuohong.wang, peter.wang, chun-hung.wu, andy.teng, chaotian.jing, cc.chou Hi Avri, On Sat, 2020-06-13 at 10:48 +0000, Avri Altman wrote: > > +static void ufshcd_add_uic_command_trace(struct ufs_hba *hba, > > + struct uic_command *ucmd, > > + const char *str) > > +{ > > + u32 cmd; > > + > > + if (!trace_ufshcd_uic_command_enabled()) > > + return; > > + > > + if (!strcmp(str, "uic_send")) > > + cmd = ucmd->command; > > + else > > + cmd = ufshcd_readl(hba, REG_UIC_COMMAND); > Why on complete you can't just use ucmd->command as well? Reading registers is really helpful for debugging to check if host UIC command register really received the command before. But the original requesting UIC command shall be logged in trace so ucmd->command is logged during "send", and the command in register is read and logged during "completed". Then we could simply check them to know if something wrong while sending the command. This concept is similar as current UTP command trace events that doorbell register is read and dumped in the trace. > > > + > > + trace_ufshcd_uic_command(dev_name(hba->dev), str, cmd, > > + ucmd->result, > > + ufshcd_readl(hba, REG_UIC_COMMAND_ARG_1), > > + ufshcd_readl(hba, REG_UIC_COMMAND_ARG_2), > > + ufshcd_readl(hba, REG_UIC_COMMAND_ARG_3)); > Why can't you just use the ucmd members? > Why need to read those? As above same reason, reading registers can know which arguments are exactly sent to the device. This is very helpful for fast issue breakdown if UIC command is not responded under expectation. Here, we also really want to keep the original requesting arguments from "ucmd", just like UIC command. However, arguments in register will be changed after UIC command is done so we can not do the same way as UIC command. So a compromise is here that we logged the arguments which host register exactly received in trace. > > > +} > > > > + > > static void ufshcd_add_command_trace(struct ufs_hba *hba, > > unsigned int tag, const char *str) > > { > > @@ -2054,6 +2075,8 @@ ufshcd_dispatch_uic_cmd(struct ufs_hba *hba, > > struct uic_command *uic_cmd) > > /* Write UIC Cmd */ > > ufshcd_writel(hba, uic_cmd->command & COMMAND_OPCODE_MASK, > > REG_UIC_COMMAND); > > + > > + ufshcd_add_uic_command_trace(hba, uic_cmd, "uic_send"); > > } > > > > /** > > @@ -2080,6 +2103,9 @@ ufshcd_wait_for_uic_cmd(struct ufs_hba *hba, > > struct uic_command *uic_cmd) > > hba->active_uic_cmd = NULL; > > spin_unlock_irqrestore(hba->host->host_lock, flags); > > > > + uic_cmd->result = ret; > > + ufshcd_add_uic_command_trace(hba, uic_cmd, "uic_complete"); > > + > > return ret; > > } > Can't you just call the "send" and "complete" from ufshcd_send_uic_cmd? For "send", we would like to log the time as precise as possible so "send" event is logged while UIC command is sent. Thanks so much! Your question reminds me that "send" trace shall be moved before UIC command is sent otherwise register value may be changed before logging "send" trace. I will fix this in next version. For "completed", to make logging time as closed to UIC command completion as possible, maybe I need to change the logging timing to ufshcd_uic_cmd_compl(), just like UTP command completion trace which is logged in __ufshcd_transfer_reg_compl(). If you have no objection, I will try to fix this in next version. > > > > > > @@ -3760,6 +3786,9 @@ static int ufshcd_uic_pwr_ctrl(struct ufs_hba *hba, > > struct uic_command *cmd) > > ret = (status != PWR_OK) ? status : -1; > > } > > out: > > + cmd->result = ret; > > + ufshcd_add_uic_command_trace(hba, cmd, "uic_complete"); > > + > > if (ret) { > > ufshcd_print_host_state(hba); > > ufshcd_print_pwr_info(hba); > > diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h > > index 5f300739240d..cf8d568d5a13 100644 > > --- a/include/trace/events/ufs.h > > +++ b/include/trace/events/ufs.h > > @@ -249,6 +249,39 @@ TRACE_EVENT(ufshcd_command, > > ) > > ); > > > > +TRACE_EVENT(ufshcd_uic_command, > > + TP_PROTO(const char *dev_name, const char *str, u32 cmd, int result, > > + u32 arg1, u32 arg2, u32 arg3), > > + > > + TP_ARGS(dev_name, str, cmd, result, arg1, arg2, arg3), > > + > > + TP_STRUCT__entry( > > + __string(dev_name, dev_name) > > + __string(str, str) > > + __field(u32, cmd) > > + __field(int, result) > > + __field(u32, arg1) > > + __field(u32, arg2) > > + __field(u32, arg3) > > + ), > > + > > + TP_fast_assign( > > + __assign_str(dev_name, dev_name); > > + __assign_str(str, str); > > + __entry->cmd = cmd; > > + __entry->result = result; > > + __entry->arg1 = arg1; > > + __entry->arg2 = arg2; > > + __entry->arg3 = arg3; > > + ), > > + > > + TP_printk( > > + "%s: %s: cmd: 0x%x, arg1: 0x%x, arg2: 0x%x, arg3: 0x%x, result: %d", > > + __get_str(str), __get_str(dev_name), __entry->cmd, > > + __entry->arg1, __entry->arg2, __entry->arg3, __entry->result > > + ) > Personally, as those trace events aren't very human readable anyway, I would just dump the uic command, > And let the parsers do their job. > And if this is the case, result is redundant as it is part of arg2 My original thought is to log some exceptions, like "-ETIMEDOUT" in "result". But if I changed "completion" trace handling to interrupt handler, there will be no chance to log those exceptions. This is OK because UTP trace is exactly behave this way: No completion event in trace if request is not back. And if this way is implemented, "result" is definitely redundant and shall be removed. Thanks, Stanley Chu ^ permalink raw reply [flat|nested] 7+ messages in thread
* RE: [PATCH v1 2/2] scsi: ufs: Add trace event for UIC commands 2020-06-13 14:18 ` Stanley Chu @ 2020-06-14 9:27 ` Avri Altman 0 siblings, 0 replies; 7+ messages in thread From: Avri Altman @ 2020-06-14 9:27 UTC (permalink / raw) To: Stanley Chu Cc: linux-scsi, martin.petersen, alim.akhtar, jejb, asutoshd, beanhuo, cang, matthias.bgg, bvanassche, linux-mediatek, linux-arm-kernel, linux-kernel, kuohong.wang, peter.wang, chun-hung.wu, andy.teng, chaotian.jing, cc.chou Acked-by: Avri Altman <avri.altman@wdc.com> > > > Hi Avri, > > On Sat, 2020-06-13 at 10:48 +0000, Avri Altman wrote: > > > +static void ufshcd_add_uic_command_trace(struct ufs_hba *hba, > > > + struct uic_command *ucmd, > > > + const char *str) > > > +{ > > > + u32 cmd; > > > + > > > + if (!trace_ufshcd_uic_command_enabled()) > > > + return; > > > + > > > + if (!strcmp(str, "uic_send")) > > > + cmd = ucmd->command; > > > + else > > > + cmd = ufshcd_readl(hba, REG_UIC_COMMAND); > > Why on complete you can't just use ucmd->command as well? > > Reading registers is really helpful for debugging to check if host UIC > command register really received the command before. > > But the original requesting UIC command shall be logged in trace so > ucmd->command is logged during "send", and the command in register is > read and logged during "completed". Then we could simply check them to > know if something wrong while sending the command. > > This concept is similar as current UTP command trace events that > doorbell register is read and dumped in the trace. > > > > > > + > > > + trace_ufshcd_uic_command(dev_name(hba->dev), str, cmd, > > > + ucmd->result, > > > + ufshcd_readl(hba, REG_UIC_COMMAND_ARG_1), > > > + ufshcd_readl(hba, REG_UIC_COMMAND_ARG_2), > > > + ufshcd_readl(hba, REG_UIC_COMMAND_ARG_3)); > > Why can't you just use the ucmd members? > > Why need to read those? > > As above same reason, reading registers can know which arguments are > exactly sent to the device. > > This is very helpful for fast issue breakdown if UIC command is not > responded under expectation. > > Here, we also really want to keep the original requesting arguments from > "ucmd", just like UIC command. However, arguments in register will be > changed after UIC command is done so we can not do the same way as UIC > command. So a compromise is here that we logged the arguments which host > register exactly received in trace. > > > > > > +} > > > > > > > + > > > static void ufshcd_add_command_trace(struct ufs_hba *hba, > > > unsigned int tag, const char *str) > > > { > > > @@ -2054,6 +2075,8 @@ ufshcd_dispatch_uic_cmd(struct ufs_hba *hba, > > > struct uic_command *uic_cmd) > > > /* Write UIC Cmd */ > > > ufshcd_writel(hba, uic_cmd->command & > COMMAND_OPCODE_MASK, > > > REG_UIC_COMMAND); > > > + > > > + ufshcd_add_uic_command_trace(hba, uic_cmd, "uic_send"); > > > } > > > > > > /** > > > @@ -2080,6 +2103,9 @@ ufshcd_wait_for_uic_cmd(struct ufs_hba *hba, > > > struct uic_command *uic_cmd) > > > hba->active_uic_cmd = NULL; > > > spin_unlock_irqrestore(hba->host->host_lock, flags); > > > > > > + uic_cmd->result = ret; > > > + ufshcd_add_uic_command_trace(hba, uic_cmd, "uic_complete"); > > > + > > > return ret; > > > } > > Can't you just call the "send" and "complete" from ufshcd_send_uic_cmd? > > For "send", we would like to log the time as precise as possible so > "send" event is logged while UIC command is sent. > > Thanks so much! Your question reminds me that "send" trace shall be > moved before UIC command is sent otherwise register value may be changed > before logging "send" trace. I will fix this in next version. > > For "completed", to make logging time as closed to UIC command > completion as possible, maybe I need to change the logging timing to > ufshcd_uic_cmd_compl(), just like UTP command completion trace which is > logged in __ufshcd_transfer_reg_compl(). > > If you have no objection, I will try to fix this in next version. > > > > > > > > > > > @@ -3760,6 +3786,9 @@ static int ufshcd_uic_pwr_ctrl(struct ufs_hba > *hba, > > > struct uic_command *cmd) > > > ret = (status != PWR_OK) ? status : -1; > > > } > > > out: > > > + cmd->result = ret; > > > + ufshcd_add_uic_command_trace(hba, cmd, "uic_complete"); > > > + > > > if (ret) { > > > ufshcd_print_host_state(hba); > > > ufshcd_print_pwr_info(hba); > > > diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h > > > index 5f300739240d..cf8d568d5a13 100644 > > > --- a/include/trace/events/ufs.h > > > +++ b/include/trace/events/ufs.h > > > @@ -249,6 +249,39 @@ TRACE_EVENT(ufshcd_command, > > > ) > > > ); > > > > > > +TRACE_EVENT(ufshcd_uic_command, > > > + TP_PROTO(const char *dev_name, const char *str, u32 cmd, int > result, > > > + u32 arg1, u32 arg2, u32 arg3), > > > + > > > + TP_ARGS(dev_name, str, cmd, result, arg1, arg2, arg3), > > > + > > > + TP_STRUCT__entry( > > > + __string(dev_name, dev_name) > > > + __string(str, str) > > > + __field(u32, cmd) > > > + __field(int, result) > > > + __field(u32, arg1) > > > + __field(u32, arg2) > > > + __field(u32, arg3) > > > + ), > > > + > > > + TP_fast_assign( > > > + __assign_str(dev_name, dev_name); > > > + __assign_str(str, str); > > > + __entry->cmd = cmd; > > > + __entry->result = result; > > > + __entry->arg1 = arg1; > > > + __entry->arg2 = arg2; > > > + __entry->arg3 = arg3; > > > + ), > > > + > > > + TP_printk( > > > + "%s: %s: cmd: 0x%x, arg1: 0x%x, arg2: 0x%x, arg3: 0x%x, result: > %d", > > > + __get_str(str), __get_str(dev_name), __entry->cmd, > > > + __entry->arg1, __entry->arg2, __entry->arg3, __entry->result > > > + ) > > Personally, as those trace events aren't very human readable anyway, I > would just dump the uic command, > > And let the parsers do their job. > > And if this is the case, result is redundant as it is part of arg2 > > My original thought is to log some exceptions, like "-ETIMEDOUT" in > "result". But if I changed "completion" trace handling to interrupt > handler, there will be no chance to log those exceptions. This is OK > because UTP trace is exactly behave this way: No completion event in > trace if request is not back. And if this way is implemented, "result" > is definitely redundant and shall be removed. > > Thanks, > Stanley Chu ^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2020-06-14 9:28 UTC | newest] Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2020-06-12 15:09 [PATCH v1 0/2] scsi: ufs: Add trace event for UIC commands Stanley Chu 2020-06-12 15:09 ` [PATCH v1 1/2] scsi: ufs: Remove unused field in struct uic_command Stanley Chu 2020-06-12 16:22 ` Alim Akhtar 2020-06-12 15:10 ` [PATCH v1 2/2] scsi: ufs: Add trace event for UIC commands Stanley Chu 2020-06-13 10:48 ` Avri Altman 2020-06-13 14:18 ` Stanley Chu 2020-06-14 9:27 ` Avri Altman
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).