Commit 0f85e747 authored by Daniil Lunev's avatar Daniil Lunev Committed by Martin K. Petersen
Browse files

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: default avatarStanley Chu <stanley.chu@mediatek.com>
Acked-by: default avatarAvri Altman <avri.altman@wdc.com>
Signed-off-by: default avatarDaniil Lunev <dlunev@chromium.org>
Signed-off-by: default avatarMartin K. Petersen <martin.petersen@oracle.com>
parent b7dbc686

drivers/ufs/core/ufshcd.c

+12 −8
Original line number Diff line number Diff line
@@ -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>
@@ -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

include/ufs/ufshcd.h

+9 −5
Original line number Diff line number Diff line
@@ -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];

};