RE: [RESEND RFC PATCH v4 2/3] ufs: exynos: introduce command history

["Kiwoong Kim" <kwmad.kim@samsung.com>]

> > This includes functions to record contexts of incoming commands in a
> > circular queue. ufshcd.c has already some function tracer calls to get
> > command history but ftrace would be gone when system dies before you
> > get the information, such as panic cases.
> Maybe add one more line explaining how you are handling dump_on_oops
> differently

Even dump_on_oops eventually run by software, that means there is a possibility
to access system memory. I don’t assume only conditions where memory accesses
work. In abnormal cases, methods in kernel doesn't work and you just need to dump
memory in another software after resetting system with keeping data in system memory.
Dump_on_oops doesn't guarantee those situations.

> 
> >
> > This patch also implements callbacks compl_xfer_req to store IO
> > contexts at completion times.
> >
> > When you turn on CONFIG_SCSI_UFS_EXYNOS_CMD_LOG, the driver collects
> > the information from incoming commands in the circular queue.
> >
> > Signed-off-by: Kiwoong Kim <kwmad.kim@samsung.com>
> > ---
> >  drivers/scsi/ufs/Kconfig          |  14 +++
> >  drivers/scsi/ufs/Makefile         |   2 +-
> >  drivers/scsi/ufs/ufs-exynos-dbg.c | 201
> > ++++++++++++++++++++++++++++++++++++++
> >  drivers/scsi/ufs/ufs-exynos-if.h  |  17 ++++
> >  drivers/scsi/ufs/ufs-exynos.c     |  37 +++++++
> >  drivers/scsi/ufs/ufs-exynos.h     |  12 +++
> >  6 files changed, 282 insertions(+), 1 deletion(-)  create mode 100644
> > drivers/scsi/ufs/ufs-exynos-dbg.c  create mode 100644
> > drivers/scsi/ufs/ufs-exynos-if.h
> >
> > diff --git a/drivers/scsi/ufs/Kconfig b/drivers/scsi/ufs/Kconfig index
> > 8cd9026..ebab446 100644
> > --- a/drivers/scsi/ufs/Kconfig
> > +++ b/drivers/scsi/ufs/Kconfig
> > @@ -172,3 +172,17 @@ config SCSI_UFS_EXYNOS
> >
> >           Select this if you have UFS host controller on EXYNOS chipset.
> >           If unsure, say N.
> > +
> > +config SCSI_UFS_EXYNOS_CMD_LOG
> > +       bool "EXYNOS specific command log"
> > +       default n
> > +       depends on SCSI_UFS_EXYNOS
> > +       help
> > +         This selects EXYNOS specific functions to get and even print
> > +         some information to see what's happening at both command
> > +         issue time completion time.
> > +         The information may contain gerernal things as well as
> Typo: gerernal -> general
Got it

> 
> > +         EXYNOS specific, such as vendor specific hardware contexts.
> > +
> > +         Select this if you want to get and print the information.
> > +         If unsure, say N.
> > diff --git a/drivers/scsi/ufs/Makefile b/drivers/scsi/ufs/Makefile
> > index f0c5b95..d9e4da7 100644
> > --- a/drivers/scsi/ufs/Makefile
> > +++ b/drivers/scsi/ufs/Makefile
> > @@ -4,7 +4,7 @@ obj-$(CONFIG_SCSI_UFS_DWC_TC_PCI) += tc-dwc-g210-pci.o
> > ufshcd-dwc.o tc-dwc-g210.
> >  obj-$(CONFIG_SCSI_UFS_DWC_TC_PLATFORM) += tc-dwc-g210-pltfrm.o
> > ufshcd-dwc.o tc-dwc-g210.o
> >  obj-$(CONFIG_SCSI_UFS_CDNS_PLATFORM) += cdns-pltfrm.o
> >  obj-$(CONFIG_SCSI_UFS_QCOM) += ufs-qcom.o
> > -obj-$(CONFIG_SCSI_UFS_EXYNOS) += ufs-exynos.o
> > +obj-$(CONFIG_SCSI_UFS_EXYNOS) += ufs-exynos.o ufs-exynos-dbg.o
> If the key functionality depends on SCSI_UFS_EXYNOS_CMD_LOG, Why not use
> it for make as well, and in your header as well?
> 
> >  obj-$(CONFIG_SCSI_UFSHCD) += ufshcd-core.o
> >  ufshcd-core-y                          += ufshcd.o ufs-sysfs.o
> >  ufshcd-core-$(CONFIG_SCSI_UFS_BSG)     += ufs_bsg.o
> > diff --git a/drivers/scsi/ufs/ufs-exynos-dbg.c
> > b/drivers/scsi/ufs/ufs-exynos- dbg.c new file mode 100644 index
> > 0000000..0663026
> > --- /dev/null
> > +++ b/drivers/scsi/ufs/ufs-exynos-dbg.c
> > @@ -0,0 +1,201 @@
> > +// SPDX-License-Identifier: GPL-2.0-only
> > +/*
> > + * UFS Exynos debugging functions
> > + *
> > + * Copyright (C) 2020 Samsung Electronics Co., Ltd.
> > + * Author: Kiwoong Kim <kwmad.kim@samsung.com>
> > + *
> > + */
> > +#include <linux/platform_device.h>
> > +#include <linux/module.h>
> > +#include "ufshcd.h"
> > +#include "ufs-exynos-if.h"
> > +
> > +#define MAX_CMD_LOGS    32
> > +
> > +struct cmd_data {
> > +       unsigned int tag;
> > +       unsigned int sct;
> > +       u64 lba;
> > +       u64 start_time;
> > +       u64 end_time;
> > +       u64 outstanding_reqs;
> > +       int retries;
> > +       u8 op;
> > +};
> > +
> > +struct ufs_cmd_info {
> > +       u32 total;
> > +       u32 last;
> > +       struct cmd_data data[MAX_CMD_LOGS];
> > +       struct cmd_data *pdata[MAX_CMD_LOGS]; };
> > +
> > +/*
> > + * This structure points out several contexts on debugging
> > + * per one host instant.
> > + * Now command history exists in here but later handle may
> > + * contains some mmio base addresses including vendor specific
> > + * regions to get hardware contexts.
> > + */
> > +struct ufs_s_dbg_mgr {
> > +       struct ufs_exynos_handle *handle;
> > +       int active;
> > +       u64 first_time;
> > +       u64 time;
> > +
> > +       /* cmd log */
> > +       struct ufs_cmd_info cmd_info;
> > +       struct cmd_data cmd_log;                /* temp buffer to put */
> > +       spinlock_t cmd_lock;
> > +};
> > +
> > +static void ufs_s_print_cmd_log(struct ufs_s_dbg_mgr *mgr, struct
> > +device
> > *dev)
> > +{
> > +       struct ufs_cmd_info *cmd_info = &mgr->cmd_info;
> > +       struct cmd_data *data = cmd_info->data;
> > +       u32 i;
> > +       u32 last;
> > +       u32 max = MAX_CMD_LOGS;
> > +       unsigned long flags;
> > +       u32 total;
> > +
> > +       spin_lock_irqsave(&mgr->cmd_lock, flags);
> > +       total = cmd_info->total;
> > +       if (cmd_info->total < max)
> > +               max = cmd_info->total;
> > +       last = (cmd_info->last + MAX_CMD_LOGS - 1) % MAX_CMD_LOGS;
> > +       spin_unlock_irqrestore(&mgr->cmd_lock, flags);
> > +
> > +       dev_err(dev, ":--------------------------------------------------
> -\n");
> > +       dev_err(dev, ":\t\tSCSI CMD(%u)\n", total - 1);
> > +       dev_err(dev, ":--------------------------------------------------
> -\n");
> > +       dev_err(dev, ":OP, TAG, LBA, SCT, RETRIES, STIME, ETIME,
> > + REQS\n\n");
> > +
> > +       for (i = 0 ; i < max ; i++, data++) {
> > +               dev_err(dev, ": 0x%02x, %02d, 0x%08llx, 0x%04x, %d,
> > + %llu, %llu,
> > 0x%llx %s",
> > +                       data->op, data->tag, data->lba, data->sct, data-
> >retries,
> > +                       data->start_time, data->end_time, data-
> >outstanding_reqs,
> > +                       ((last == i) ? "<--" : " "));
> > +               if (last == i)
> > +                       dev_err(dev, "\n");
> > +       }
> > +}
> Since you cache last, why not printing from first to last instead of
> marking it?
Got it and this looks that because it's easy to make.

> 
> 
> > +
> > +static void ufs_s_put_cmd_log(struct ufs_s_dbg_mgr *mgr,
> > +                             struct cmd_data *cmd_data) {
> > +       struct ufs_cmd_info *cmd_info = &mgr->cmd_info;
> > +       unsigned long flags;
> > +       struct cmd_data *pdata;
> > +
> > +       spin_lock_irqsave(&mgr->cmd_lock, flags);
> > +       pdata = &cmd_info->data[cmd_info->last];
> > +       ++cmd_info->total;
> > +       ++cmd_info->last;
> > +       cmd_info->last = cmd_info->last % MAX_CMD_LOGS;
> > +       spin_unlock_irqrestore(&mgr->cmd_lock, flags);
> > +
> > +       pdata->op = cmd_data->op;
> > +       pdata->tag = cmd_data->tag;
> > +       pdata->lba = cmd_data->lba;
> > +       pdata->sct = cmd_data->sct;
> > +       pdata->retries = cmd_data->retries;
> > +       pdata->start_time = cmd_data->start_time;
> > +       pdata->end_time = 0;
> > +       pdata->outstanding_reqs = cmd_data->outstanding_reqs;
> > +       cmd_info->pdata[cmd_data->tag] = pdata; }
> > +
> > +/*
> > + * EXTERNAL FUNCTIONS
> > + *
> > + * There are two classes that are to initialize data structures for
> > +debug
> > + * and to define actual behavior.
> > + */
> > +void exynos_ufs_dump_info(struct ufs_exynos_handle *handle, struct
> > +device
> > *dev)
> > +{
> > +       struct ufs_s_dbg_mgr *mgr = (struct ufs_s_dbg_mgr
> > +*)handle->private;
> > +
> > +       if (mgr->active == 0)
> > +               goto out;
> > +
> > +       mgr->time = cpu_clock(raw_smp_processor_id());
> > +
> > +#ifdef CONFIG_SCSI_UFS_EXYNOS_CMD_LOG
> > +       ufs_s_print_cmd_log(mgr, dev); #endif
> > +
> > +       if (mgr->first_time == 0ULL)
> > +               mgr->first_time = mgr->time;
> > +out:
> > +       return;
> > +}
> > +
> > +void exynos_ufs_cmd_log_start(struct ufs_exynos_handle *handle,
> > +                             struct ufs_hba *hba, struct scsi_cmnd
> > +*cmd) {
> > +       struct ufs_s_dbg_mgr *mgr = (struct ufs_s_dbg_mgr *)handle-
> >private;
> > +       int cpu = raw_smp_processor_id();
> > +       struct cmd_data *cmd_log = &mgr->cmd_log;       /* temp buffer to
> put
> > */
> > +       u64 lba = (cmd->cmnd[2] << 24) |
> > +                                       (cmd->cmnd[3] << 16) |
> > +                                       (cmd->cmnd[4] << 8) |
> > +                                       (cmd->cmnd[5] << 0);
> Use put_unaligned?
> 
> > +       unsigned int sct = (cmd->cmnd[7] << 8) |
> > +                                       (cmd->cmnd[8] << 0);
> ditto
> 
Got it.

> > +
> > +       if (mgr->active == 0)
> > +               return;
> > +
> > +       cmd_log->start_time = cpu_clock(cpu);
> > +       cmd_log->op = cmd->cmnd[0];
> > +       cmd_log->tag = cmd->request->tag;
> > +
> > +       /* This function runtime is protected by spinlock from outside */
> > +       cmd_log->outstanding_reqs = hba->outstanding_reqs;
> > +
> > +       /* unmap */
> > +       if (cmd->cmnd[0] != UNMAP)
> > +               cmd_log->lba = lba;
> > +
> > +       cmd_log->sct = sct;
> > +       cmd_log->retries = cmd->allowed;
> > +
> > +       ufs_s_put_cmd_log(mgr, cmd_log); }
> > +
> > +void exynos_ufs_cmd_log_end(struct ufs_exynos_handle *handle,
> > +                           struct ufs_hba *hba, struct scsi_cmnd
> > +*cmd) {
> > +       struct ufs_s_dbg_mgr *mgr = (struct ufs_s_dbg_mgr *)handle-
> >private;
> > +       struct ufs_cmd_info *cmd_info = &mgr->cmd_info;
> > +       int cpu = raw_smp_processor_id();
> > +       int tag = cmd->request->tag;
> > +
> > +       if (mgr->active == 0)
> > +               return;
> > +
> > +       cmd_info->pdata[tag]->end_time = cpu_clock(cpu); }
> > +
> > +int exynos_ufs_init_dbg(struct ufs_exynos_handle *handle, struct
> > +device
> > *dev)
> > +{
> > +       struct ufs_s_dbg_mgr *mgr;
> > +
> > +       mgr = devm_kzalloc(dev, sizeof(struct ufs_s_dbg_mgr), GFP_KERNEL);
> > +       if (!mgr)
> > +               return -ENOMEM;
> > +       handle->private = (void *)mgr;
> > +       mgr->handle = handle;
> > +       mgr->active = 1;
> > +
> > +       /* cmd log */
> > +       spin_lock_init(&mgr->cmd_lock);
> > +
> > +       return 0;
> > +}
> > +MODULE_AUTHOR("Kiwoong Kim <kwmad.kim@samsung.com>");
> > +MODULE_DESCRIPTION("Exynos UFS debug information");
> > +MODULE_LICENSE("GPL"); MODULE_VERSION("0.1");
> > diff --git a/drivers/scsi/ufs/ufs-exynos-if.h
> > b/drivers/scsi/ufs/ufs-exynos-if.h
> > new file mode 100644
> > index 0000000..c746f59
> > --- /dev/null
> > +++ b/drivers/scsi/ufs/ufs-exynos-if.h
> > @@ -0,0 +1,17 @@
> > +/* SPDX-License-Identifier: GPL-2.0-only */
> > +/*
> > + * UFS Exynos debugging functions
> > + *
> > + * Copyright (C) 2020 Samsung Electronics Co., Ltd.
> > + * Author: Kiwoong Kim <kwmad.kim@samsung.com>
> > + *
> > + */
> > +#ifndef _UFS_EXYNOS_IF_H_
> > +#define _UFS_EXYNOS_IF_H_
> > +
> > +/* more members would be added in the future */ struct
> > +ufs_exynos_handle {
> > +       void *private;
> > +};
> > +
> > +#endif /* _UFS_EXYNOS_IF_H_ */
> > diff --git a/drivers/scsi/ufs/ufs-exynos.c
> > b/drivers/scsi/ufs/ufs-exynos.c index 440f2af..8c60f7d 100644
> > --- a/drivers/scsi/ufs/ufs-exynos.c
> > +++ b/drivers/scsi/ufs/ufs-exynos.c
> > @@ -700,11 +700,31 @@ static int exynos_ufs_post_pwr_mode(struct
> > ufs_hba *hba,
> >         return 0;
> >  }
> >
> > +#ifdef CONFIG_SCSI_UFS_EXYNOS_CMD_LOG static void
> > +exynos_ufs_cmd_log(struct ufs_hba *hba,
> > +                              struct scsi_cmnd *cmd, int enter)
> Maybe make it static inline in you header, e.g. ufs-exynos-if.h, And make
> it empty if CONFIG_SCSI_UFS_EXYNOS_CMD_LOG is not defined?
> 
> > +{
> > +       struct exynos_ufs *ufs = ufshcd_get_variant(hba);
> > +       struct ufs_exynos_handle *handle = &ufs->handle;
> > +
> > +       if (enter == 1)
> Maybe use "start" instead of "enter"
> If (start)
>    ....
> else
>    ....
Got it.

> 
> > +               exynos_ufs_cmd_log_start(handle, hba, cmd);
> > +       else if (enter == 2)
> > +               exynos_ufs_cmd_log_end(handle, hba, cmd); } #endif
> > +
> >  static void exynos_ufs_specify_nexus_t_xfer_req(struct ufs_hba *hba,
> >                                                 int tag, bool op)  {
> >         struct exynos_ufs *ufs = ufshcd_get_variant(hba);
> >         u32 type;
> > +#ifdef CONFIG_SCSI_UFS_EXYNOS_CMD_LOG
> > +       struct scsi_cmnd *cmd = hba->lrb[tag].cmd;
> > +
> > +       if (op)
> > +               exynos_ufs_cmd_log(hba, cmd, 1); #endif
> >
> >         type =  hci_readl(ufs, HCI_UTRL_NEXUS_TYPE);
> >
> > @@ -714,6 +734,16 @@ static void
> > exynos_ufs_specify_nexus_t_xfer_req(struct ufs_hba *hba,
> >                 hci_writel(ufs, type & ~(1 << tag),
> > HCI_UTRL_NEXUS_TYPE);  }
> >
> > +static void exynos_ufs_compl_xfer_req(struct ufs_hba *hba, int tag,
> > +bool op) { #ifdef CONFIG_SCSI_UFS_EXYNOS_CMD_LOG
> > +       struct scsi_cmnd *cmd = hba->lrb[tag].cmd;
> > +
> > +       if (op)
> > +               exynos_ufs_cmd_log(hba, cmd, 2); #endif }
> > +
> >  static void exynos_ufs_specify_nexus_t_tm_req(struct ufs_hba *hba,
> >                                                 int tag, u8 func)  {
> > @@ -1008,6 +1038,12 @@ static int exynos_ufs_init(struct ufs_hba *hba)
> >                 goto out;
> >         exynos_ufs_specify_phy_time_attr(ufs);
> >         exynos_ufs_config_smu(ufs);
> > +
> > +       /* init dbg */
> > +       ret = exynos_ufs_init_dbg(&ufs->handle, dev);
> > +       if (ret)
> > +               return ret;
> > +       spin_lock_init(&ufs->dbg_lock);
> >         return 0;
> >
> >  phy_off:
> > @@ -1217,6 +1253,7 @@ static struct ufs_hba_variant_ops
> > ufs_hba_exynos_ops = {
> >         .link_startup_notify            = exynos_ufs_link_startup_notify,
> >         .pwr_change_notify              = exynos_ufs_pwr_change_notify,
> >         .setup_xfer_req                 = exynos_ufs_specify_nexus_t_xfer_req,
> > +       .compl_xfer_req                 = exynos_ufs_compl_xfer_req,
> >         .setup_task_mgmt                = exynos_ufs_specify_nexus_t_tm_req,
> >         .hibern8_notify                 = exynos_ufs_hibern8_notify,
> >         .suspend                        = exynos_ufs_suspend,
> > diff --git a/drivers/scsi/ufs/ufs-exynos.h
> > b/drivers/scsi/ufs/ufs-exynos.h index 76d6e39..c947fd8 100644
> > --- a/drivers/scsi/ufs/ufs-exynos.h
> > +++ b/drivers/scsi/ufs/ufs-exynos.h
> > @@ -8,6 +8,7 @@
> >
> >  #ifndef _UFS_EXYNOS_H_
> >  #define _UFS_EXYNOS_H_
> > +#include "ufs-exynos-if.h"
> >
> >  /*
> >   * UNIPRO registers
> > @@ -212,6 +213,10 @@ struct exynos_ufs {
> >  #define EXYNOS_UFS_OPT_BROKEN_AUTO_CLK_CTRL    BIT(2)
> >  #define EXYNOS_UFS_OPT_BROKEN_RX_SEL_IDX       BIT(3)
> >  #define EXYNOS_UFS_OPT_USE_SW_HIBERN8_TIMER    BIT(4)
> > +
> > +       struct ufs_exynos_handle handle;
> > +       spinlock_t dbg_lock;
> > +       int under_dump;
> >  };
> >
> >  #define for_each_ufs_rx_lane(ufs, i) \ @@ -284,4 +289,11 @@ struct
> > exynos_ufs_uic_attr exynos7_uic_attr = {
> >         .rx_hs_g3_prep_sync_len_cap     = PREP_LEN(0xf),
> >         .pa_dbg_option_suite            = 0x30103,
> >  };
> > +
> > +/* public function declarations */
> > +void exynos_ufs_cmd_log_start(struct ufs_exynos_handle *handle,
> > +                             struct ufs_hba *hba, struct scsi_cmnd
> > +*cmd); void exynos_ufs_cmd_log_end(struct ufs_exynos_handle *handle,
> > +                           struct ufs_hba *hba, struct scsi_cmnd
> > +*cmd); int exynos_ufs_init_dbg(struct ufs_exynos_handle *handle,
> > +struct device
> > *dev);
> >  #endif /* _UFS_EXYNOS_H_ */
> > --
> > 2.7.4



Thanks.
Kiwoong Kim