From 0f85e74756b5e85a0de6dce7d8c07f0b4e1f7726 Mon Sep 17 00:00:00 2001 From: Daniil Lunev Date: Thu, 4 Aug 2022 06:50:34 +1000 Subject: scsi: ufs: core: Use local_clock() for debugging timestamps 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(). Change 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). Link: https://lore.kernel.org/r/20220804065019.v5.1.I699244ea7efbd326a34a6dfd9b5a31e78400cf68@changeid Acked-by: Stanley Chu Acked-by: Avri Altman Signed-off-by: Daniil Lunev Signed-off-by: Martin K. Petersen --- drivers/ufs/core/ufshcd.c | 20 ++++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) (limited to 'drivers/ufs/core') diff --git a/drivers/ufs/core/ufshcd.c b/drivers/ufs/core/ufshcd.c index 6bc679d22927..0391b66ed632 100644 --- a/drivers/ufs/core/ufshcd.c +++ b/drivers/ufs/core/ufshcd.c @@ -21,6 +21,7 @@ #include #include #include +#include #include #include #include @@ -457,7 +458,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], div_u64(e->tstamp[p], 1000)); found = true; } @@ -502,9 +503,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, div_u64(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, div_u64(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); @@ -566,10 +567,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), + div_u64(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), + div_u64(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); @@ -2140,7 +2141,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))) @@ -4222,7 +4225,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++; } @@ -4724,7 +4727,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; @@ -5357,6 +5360,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))) @@ -6645,7 +6649,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 -- cgit