RE: [PATCH v1 2/2] scsi: ufs: Add trace event for UIC commands

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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





[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[Index of Archives]     [SCSI Target Devel]     [Linux SCSI Target Infrastructure]     [Kernel Newbies]     [IDE]     [Security]     [Git]     [Netfilter]     [Bugtraq]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Linux ATA RAID]     [Linux IIO]     [Samba]     [Device Mapper]

  Powered by Linux