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

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

[Daniil Lunev]

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 patch 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).

Signed-off-by: Daniil Lunev <dlunev@chromium.org>

---

Changes in v2:
- Use local clock to better align with dmesg
- Correct commit message

 drivers/ufs/core/ufshcd.c | 19 +++++++++++--------
 include/ufs/ufshcd.h      | 14 +++++++++-----
 2 files changed, 20 insertions(+), 13 deletions(-)

diff --git a/drivers/ufs/core/ufshcd.c b/drivers/ufs/core/ufshcd.c
index ce86d1b790c05..86875a626ea77 100644
--- a/drivers/ufs/core/ufshcd.c
+++ b/drivers/ufs/core/ufshcd.c
@@ -460,7 +460,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 +505,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 +569,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 +2142,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 +4201,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 +4698,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 +5331,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 +6620,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

Re: [PATCH v2] ufs: core: ufshcd: use local_clock() for debugging timestamps

[Stanley Chu]

Hi,

On Mon, Aug 1, 2022 at 12:30 PM Daniil Lunev <dlunev@chromium.org> wrote:
>
> 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 patch 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).
>
> Signed-off-by: Daniil Lunev <dlunev@chromium.org>
>
I am not sure if it is better to keep only one kind of timestamp in
the UFS driver.

Either way, it looks good to me.

Acked-by: Stanley Chu <stanley.chu@mediatek.com>

Re: [PATCH v2] ufs: core: ufshcd: use local_clock() for debugging timestamps

[kernel test robot]

Hi Daniil,

Thank you for the patch! Yet something to improve:

[auto build test ERROR on jejb-scsi/for-next]
[also build test ERROR on mkp-scsi/for-next linus/master v5.19 next-20220728]
[cannot apply to bvanassche/for-next]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Daniil-Lunev/ufs-core-ufshcd-use-local_clock-for-debugging-timestamps/20220801-123157
base:   https://git.kernel.org/pub/scm/linux/kernel/git/jejb/scsi.git for-next
config: i386-randconfig-a005 (https://download.01.org/0day-ci/archive/20220801/202208011814.gx9OZFDF-lkp@intel.com/config)
compiler: gcc-11 (Debian 11.3.0-3) 11.3.0
reproduce (this is a W=1 build):
        # https://github.com/intel-lab-lkp/linux/commit/45a46347597e5c368c27a9fe01e400af675eb5e9
        git remote add linux-review https://github.com/intel-lab-lkp/linux
        git fetch --no-tags linux-review Daniil-Lunev/ufs-core-ufshcd-use-local_clock-for-debugging-timestamps/20220801-123157
        git checkout 45a46347597e5c368c27a9fe01e400af675eb5e9
        # save the config file
        mkdir build_dir && cp config build_dir/.config
        make W=1 O=build_dir ARCH=i386 SHELL=/bin/bash drivers/ufs/core/

If you fix the issue, kindly add following tag where applicable
Reported-by: kernel test robot <lkp@intel.com>

All errors (new ones prefixed by >>):

   drivers/ufs/core/ufshcd.c: In function 'ufshcd_send_command':
>> drivers/ufs/core/ufshcd.c:2143:46: error: implicit declaration of function 'local_clock'; did you mean 'local_lock'? [-Werror=implicit-function-declaration]
    2143 |         lrbp->issue_time_stamp_local_clock = local_clock();
         |                                              ^~~~~~~~~~~
         |                                              local_lock
   cc1: some warnings being treated as errors


vim +2143 drivers/ufs/core/ufshcd.c

  2130	
  2131	/**
  2132	 * ufshcd_send_command - Send SCSI or device management commands
  2133	 * @hba: per adapter instance
  2134	 * @task_tag: Task tag of the command
  2135	 */
  2136	static inline
  2137	void ufshcd_send_command(struct ufs_hba *hba, unsigned int task_tag)
  2138	{
  2139		struct ufshcd_lrb *lrbp = &hba->lrb[task_tag];
  2140		unsigned long flags;
  2141	
  2142		lrbp->issue_time_stamp = ktime_get();
> 2143		lrbp->issue_time_stamp_local_clock = local_clock();
  2144		lrbp->compl_time_stamp = ktime_set(0, 0);
  2145		lrbp->compl_time_stamp_local_clock = 0;
  2146		ufshcd_add_command_trace(hba, task_tag, UFS_CMD_SEND);
  2147		ufshcd_clk_scaling_start_busy(hba);
  2148		if (unlikely(ufshcd_should_inform_monitor(hba, lrbp)))
  2149			ufshcd_start_monitor(hba, lrbp);
  2150	
  2151		spin_lock_irqsave(&hba->outstanding_lock, flags);
  2152		if (hba->vops && hba->vops->setup_xfer_req)
  2153			hba->vops->setup_xfer_req(hba, task_tag, !!lrbp->cmd);
  2154		__set_bit(task_tag, &hba->outstanding_reqs);
  2155		ufshcd_writel(hba, 1 << task_tag, REG_UTP_TRANSFER_REQ_DOOR_BELL);
  2156		spin_unlock_irqrestore(&hba->outstanding_lock, flags);
  2157	}
  2158	

-- 
0-DAY CI Kernel Test Service
https://01.org/lkp

Re: [PATCH v2] ufs: core: ufshcd: use local_clock() for debugging timestamps

[kernel test robot]

Hi Daniil,

Thank you for the patch! Yet something to improve:

[auto build test ERROR on jejb-scsi/for-next]
[also build test ERROR on mkp-scsi/for-next linus/master v5.19 next-20220728]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Daniil-Lunev/ufs-core-ufshcd-use-local_clock-for-debugging-timestamps/20220801-123157
base:   https://git.kernel.org/pub/scm/linux/kernel/git/jejb/scsi.git for-next
config: x86_64-randconfig-a001-20220801 (https://download.01.org/0day-ci/archive/20220802/202208020844.RaNi6Dg0-lkp@intel.com/config)
compiler: clang version 16.0.0 (https://github.com/llvm/llvm-project 52cd00cabf479aa7eb6dbb063b7ba41ea57bce9e)
reproduce (this is a W=1 build):
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # https://github.com/intel-lab-lkp/linux/commit/45a46347597e5c368c27a9fe01e400af675eb5e9
        git remote add linux-review https://github.com/intel-lab-lkp/linux
        git fetch --no-tags linux-review Daniil-Lunev/ufs-core-ufshcd-use-local_clock-for-debugging-timestamps/20220801-123157
        git checkout 45a46347597e5c368c27a9fe01e400af675eb5e9
        # save the config file
        mkdir build_dir && cp config build_dir/.config
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=clang make.cross W=1 O=build_dir ARCH=x86_64 SHELL=/bin/bash drivers/ufs/ kernel/

If you fix the issue, kindly add following tag where applicable
Reported-by: kernel test robot <lkp@intel.com>

All errors (new ones prefixed by >>):

>> drivers/ufs/core/ufshcd.c:2143:39: error: call to undeclared function 'local_clock'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
           lrbp->issue_time_stamp_local_clock = local_clock();
                                                ^
   drivers/ufs/core/ufshcd.c:4227:45: error: call to undeclared function 'local_clock'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
                   hba->ufs_stats.last_hibern8_exit_tstamp = local_clock();
                                                             ^
   drivers/ufs/core/ufshcd.c:4729:22: error: call to undeclared function 'local_clock'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
           e->tstamp[e->pos] = local_clock();
                               ^
   drivers/ufs/core/ufshcd.c:5362:40: error: call to undeclared function 'local_clock'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
                   lrbp->compl_time_stamp_local_clock = local_clock();
                                                        ^
   drivers/ufs/core/ufshcd.c:6651:32: error: call to undeclared function 'local_clock'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
           hba->ufs_stats.last_intr_ts = local_clock();
                                         ^
   drivers/ufs/core/ufshcd.c:9553:44: warning: shift count >= width of type [-Wshift-count-overflow]
                   if (!dma_set_mask_and_coherent(hba->dev, DMA_BIT_MASK(64)))
                                                            ^~~~~~~~~~~~~~~~
   include/linux/dma-mapping.h:76:54: note: expanded from macro 'DMA_BIT_MASK'
   #define DMA_BIT_MASK(n) (((n) == 64) ? ~0ULL : ((1ULL<<(n))-1))
                                                        ^ ~~~
   1 warning and 5 errors generated.


vim +/local_clock +2143 drivers/ufs/core/ufshcd.c

  2130	
  2131	/**
  2132	 * ufshcd_send_command - Send SCSI or device management commands
  2133	 * @hba: per adapter instance
  2134	 * @task_tag: Task tag of the command
  2135	 */
  2136	static inline
  2137	void ufshcd_send_command(struct ufs_hba *hba, unsigned int task_tag)
  2138	{
  2139		struct ufshcd_lrb *lrbp = &hba->lrb[task_tag];
  2140		unsigned long flags;
  2141	
  2142		lrbp->issue_time_stamp = ktime_get();
> 2143		lrbp->issue_time_stamp_local_clock = local_clock();
  2144		lrbp->compl_time_stamp = ktime_set(0, 0);
  2145		lrbp->compl_time_stamp_local_clock = 0;
  2146		ufshcd_add_command_trace(hba, task_tag, UFS_CMD_SEND);
  2147		ufshcd_clk_scaling_start_busy(hba);
  2148		if (unlikely(ufshcd_should_inform_monitor(hba, lrbp)))
  2149			ufshcd_start_monitor(hba, lrbp);
  2150	
  2151		spin_lock_irqsave(&hba->outstanding_lock, flags);
  2152		if (hba->vops && hba->vops->setup_xfer_req)
  2153			hba->vops->setup_xfer_req(hba, task_tag, !!lrbp->cmd);
  2154		__set_bit(task_tag, &hba->outstanding_reqs);
  2155		ufshcd_writel(hba, 1 << task_tag, REG_UTP_TRANSFER_REQ_DOOR_BELL);
  2156		spin_unlock_irqrestore(&hba->outstanding_lock, flags);
  2157	}
  2158	

-- 
0-DAY CI Kernel Test Service
https://01.org/lkp