Acked-by: Avri Altman <avri.altman@xxxxxxx>
>
>
> 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
