| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <DM6PR04MB65757B61628255C6E4F5941FFC9D9@DM6PR04MB6575.namprd04.prod.outlook.com>
Date: Tue, 2 Aug 2022 07:18:51 +0000
From: Avri Altman <Avri.Altman@....com>
To: Daniil Lunev <dlunev@...omium.org>,
Adrian Hunter <adrian.hunter@...el.com>,
Bart Van Assche <bvanassche@....org>,
Stanley Chu <chu.stanley@...il.com>
CC: Alim Akhtar <alim.akhtar@...sung.com>,
Bean Huo <beanhuo@...ron.com>,
Daejun Park <daejun7.park@...sung.com>,
"James E.J. Bottomley" <jejb@...ux.ibm.com>,
"Martin K. Petersen" <martin.petersen@...cle.com>,
"linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
"linux-scsi@...r.kernel.org" <linux-scsi@...r.kernel.org>
Subject: RE: [PATCH v3] ufs: core: ufshcd: 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().
>
> 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@....com>
>
> Signed-off-by: Daniil Lunev <dlunev@...omium.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@...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
Powered by blists - more mailing lists