RE: [PATCH v3] ufs: core: ufshcd: use local_clock() for debugging timestamps

[Avri Altman <Avri.Altman@wdc.com>]

> CLOCK_MONOTONIC is not advanced when the system is in suspend. This
> becomes problematic when debugging issues related to suspend-resume:
> the timestamps printed by ufshcd_print_trs can not be correlated with dmesg
> entries, which are timestamped with local_clock().
> 
> This CL changes the used clock to local_clock() for the informational timestamp
> variables and adds mirroring *_local_clock instances for variables used in
> subsequent derevations (to not change the semantics of those derevations).
I agree with this approach because the words of cautious while using sched_clock()
Happens to be true for various ufs platforms, specifically of a required stabilization period.

Acked-by: Avri Altman <avri.altman@wdc.com> 

> 
> Signed-off-by: Daniil Lunev <dlunev@chromium.org>
> 
> ---
> 
> Changes in v3:
> - Add missing header
> 
> Changes in v2:
> - Use local clock to better align with dmesg
> - Correct commit message
> 
>  drivers/ufs/core/ufshcd.c | 20 ++++++++++++--------
>  include/ufs/ufshcd.h      | 14 +++++++++-----
>  2 files changed, 21 insertions(+), 13 deletions(-)
> 
> diff --git a/drivers/ufs/core/ufshcd.c b/drivers/ufs/core/ufshcd.c index
> ce86d1b790c05..e61dafb93986f 100644
> --- a/drivers/ufs/core/ufshcd.c
> +++ b/drivers/ufs/core/ufshcd.c
> @@ -21,6 +21,7 @@
>  #include <linux/interrupt.h>
>  #include <linux/module.h>
>  #include <linux/regulator/consumer.h>
> +#include <linux/sched/clock.h>
>  #include <scsi/scsi_cmnd.h>
>  #include <scsi/scsi_dbg.h>
>  #include <scsi/scsi_driver.h>
> @@ -460,7 +461,7 @@ static void ufshcd_print_evt(struct ufs_hba *hba, u32 id,
>                 if (e->tstamp[p] == 0)
>                         continue;
>                 dev_err(hba->dev, "%s[%d] = 0x%x at %lld us\n", err_name, p,
> -                       e->val[p], ktime_to_us(e->tstamp[p]));
> +                       e->val[p], e->tstamp[p] / 1000);
>                 found = true;
>         }
> 
> @@ -505,9 +506,9 @@ void ufshcd_print_trs(struct ufs_hba *hba, unsigned
> long bitmap, bool pr_prdt)
>                 lrbp = &hba->lrb[tag];
> 
>                 dev_err(hba->dev, "UPIU[%d] - issue time %lld us\n",
> -                               tag, ktime_to_us(lrbp->issue_time_stamp));
> +                               tag, lrbp->issue_time_stamp_local_clock
> + / 1000);
>                 dev_err(hba->dev, "UPIU[%d] - complete time %lld us\n",
> -                               tag, ktime_to_us(lrbp->compl_time_stamp));
> +                               tag, lrbp->compl_time_stamp_local_clock
> + / 1000);
>                 dev_err(hba->dev,
>                         "UPIU[%d] - Transfer Request Descriptor phys@0x%llx\n",
>                         tag, (u64)lrbp->utrd_dma_addr); @@ -569,10 +570,10 @@ static
> void ufshcd_print_host_state(struct ufs_hba *hba)
>         dev_err(hba->dev, "Clk gate=%d\n", hba->clk_gating.state);
>         dev_err(hba->dev,
>                 "last_hibern8_exit_tstamp at %lld us, hibern8_exit_cnt=%d\n",
> -               ktime_to_us(hba->ufs_stats.last_hibern8_exit_tstamp),
> +               hba->ufs_stats.last_hibern8_exit_tstamp / 1000,
>                 hba->ufs_stats.hibern8_exit_cnt);
>         dev_err(hba->dev, "last intr at %lld us, last intr status=0x%x\n",
> -               ktime_to_us(hba->ufs_stats.last_intr_ts),
> +               hba->ufs_stats.last_intr_ts / 1000,
>                 hba->ufs_stats.last_intr_status);
>         dev_err(hba->dev, "error handling flags=0x%x, req. abort count=%d\n",
>                 hba->eh_flags, hba->req_abort_count); @@ -2142,7 +2143,9 @@ void
> ufshcd_send_command(struct ufs_hba *hba, unsigned int task_tag)
>         unsigned long flags;
> 
>         lrbp->issue_time_stamp = ktime_get();
> +       lrbp->issue_time_stamp_local_clock = local_clock();
>         lrbp->compl_time_stamp = ktime_set(0, 0);
> +       lrbp->compl_time_stamp_local_clock = 0;
>         ufshcd_add_command_trace(hba, task_tag, UFS_CMD_SEND);
>         ufshcd_clk_scaling_start_busy(hba);
>         if (unlikely(ufshcd_should_inform_monitor(hba, lrbp))) @@ -4199,7 +4202,7
> @@ int ufshcd_uic_hibern8_exit(struct ufs_hba *hba)
>         } else {
>                 ufshcd_vops_hibern8_notify(hba, UIC_CMD_DME_HIBER_EXIT,
>                                                                 POST_CHANGE);
> -               hba->ufs_stats.last_hibern8_exit_tstamp = ktime_get();
> +               hba->ufs_stats.last_hibern8_exit_tstamp = local_clock();
>                 hba->ufs_stats.hibern8_exit_cnt++;
>         }
> 
> @@ -4696,7 +4699,7 @@ void ufshcd_update_evt_hist(struct ufs_hba *hba,
> u32 id, u32 val)
> 
>         e = &hba->ufs_stats.event[id];
>         e->val[e->pos] = val;
> -       e->tstamp[e->pos] = ktime_get();
> +       e->tstamp[e->pos] = local_clock();
>         e->cnt += 1;
>         e->pos = (e->pos + 1) % UFS_EVENT_HIST_LENGTH;
> 
> @@ -5329,6 +5332,7 @@ static void __ufshcd_transfer_req_compl(struct
> ufs_hba *hba,
>         for_each_set_bit(index, &completed_reqs, hba->nutrs) {
>                 lrbp = &hba->lrb[index];
>                 lrbp->compl_time_stamp = ktime_get();
> +               lrbp->compl_time_stamp_local_clock = local_clock();
>                 cmd = lrbp->cmd;
>                 if (cmd) {
>                         if (unlikely(ufshcd_should_inform_monitor(hba, lrbp))) @@ -6617,7
> +6621,7 @@ static irqreturn_t ufshcd_intr(int irq, void *__hba)
> 
>         intr_status = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
>         hba->ufs_stats.last_intr_status = intr_status;
> -       hba->ufs_stats.last_intr_ts = ktime_get();
> +       hba->ufs_stats.last_intr_ts = local_clock();
> 
>         /*
>          * There could be max of hba->nutrs reqs in flight and in worst case diff --git
> a/include/ufs/ufshcd.h b/include/ufs/ufshcd.h index
> a92271421718e..2de73196bb779 100644
> --- a/include/ufs/ufshcd.h
> +++ b/include/ufs/ufshcd.h
> @@ -160,8 +160,10 @@ struct ufs_pm_lvl_states {
>   * @task_tag: Task tag of the command
>   * @lun: LUN of the command
>   * @intr_cmd: Interrupt command (doesn't participate in interrupt aggregation)
> - * @issue_time_stamp: time stamp for debug purposes
> - * @compl_time_stamp: time stamp for statistics
> + * @issue_time_stamp: time stamp for debug purposes (CLOCK_MONOTONIC)
> + * @issue_time_stamp_local_clock: time stamp for debug purposes
> + (local_clock)
> + * @compl_time_stamp: time stamp for statistics (CLOCK_MONOTONIC)
> + * @compl_time_stamp_local_clock: time stamp for debug purposes
> + (local_clock)
>   * @crypto_key_slot: the key slot to use for inline crypto (-1 if none)
>   * @data_unit_num: the data unit number for the first block for inline crypto
>   * @req_abort_skip: skip request abort task flag @@ -185,7 +187,9 @@ struct
> ufshcd_lrb {
>         u8 lun; /* UPIU LUN id field is only 8-bit wide */
>         bool intr_cmd;
>         ktime_t issue_time_stamp;
> +       u64 issue_time_stamp_local_clock;
>         ktime_t compl_time_stamp;
> +       u64 compl_time_stamp_local_clock;
>  #ifdef CONFIG_SCSI_UFS_CRYPTO
>         int crypto_key_slot;
>         u64 data_unit_num;
> @@ -430,7 +434,7 @@ struct ufs_clk_scaling {  struct ufs_event_hist {
>         int pos;
>         u32 val[UFS_EVENT_HIST_LENGTH];
> -       ktime_t tstamp[UFS_EVENT_HIST_LENGTH];
> +       u64 tstamp[UFS_EVENT_HIST_LENGTH];
>         unsigned long long cnt;
>  };
> 
> @@ -446,10 +450,10 @@ struct ufs_event_hist {
>   */
>  struct ufs_stats {
>         u32 last_intr_status;
> -       ktime_t last_intr_ts;
> +       u64 last_intr_ts;
> 
>         u32 hibern8_exit_cnt;
> -       ktime_t last_hibern8_exit_tstamp;
> +       u64 last_hibern8_exit_tstamp;
>         struct ufs_event_hist event[UFS_EVT_CNT];  };
> 
> --
> 2.31.0