From: Daniil Lunev <dlunev@chromium.org> To: Adrian Hunter <adrian.hunter@intel.com>, Bart Van Assche <bvanassche@acm.org>, Stanley Chu <chu.stanley@gmail.com> Cc: Daniil Lunev <dlunev@chromium.org>, Stanley Chu <stanley.chu@mediatek.com>, Avri Altman <avri.altman@wdc.com>, Alim Akhtar <alim.akhtar@samsung.com>, Bean Huo <beanhuo@micron.com>, Eric Biggers <ebiggers@google.com>, "James E.J. Bottomley" <jejb@linux.ibm.com>, "Martin K. Petersen" <martin.petersen@oracle.com>, Matthias Brugger <matthias.bgg@gmail.com>, jongmin jeong <jjmin.jeong@samsung.com>, linux-arm-kernel@lists.infradead.org, linux-kernel@vger.kernel.org, linux-mediatek@lists.infradead.org, linux-scsi@vger.kernel.org Subject: [PATCH v5] ufs: core: ufshcd: use local_clock() for debugging timestamps Date: Thu, 4 Aug 2022 06:50:34 +1000 [thread overview] Message-ID: <20220804065019.v5.1.I699244ea7efbd326a34a6dfd9b5a31e78400cf68@changeid> (raw) 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). Signed-off-by: Daniil Lunev <dlunev@chromium.org> Acked-by: Stanley Chu <stanley.chu@mediatek.com> Acked-by: Avri Altman <avri.altman@wdc.com> --- Changes in v5: - Bring over "acks" from the previous iterations Changes in v4: - Use div_u64 instead of "/" 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..3b3c011d81e36 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], div_u64(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, 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); @@ -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), + 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); @@ -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
WARNING: multiple messages have this Message-ID (diff)
From: Daniil Lunev <dlunev@chromium.org> To: Adrian Hunter <adrian.hunter@intel.com>, Bart Van Assche <bvanassche@acm.org>, Stanley Chu <chu.stanley@gmail.com> Cc: Daniil Lunev <dlunev@chromium.org>, Stanley Chu <stanley.chu@mediatek.com>, Avri Altman <avri.altman@wdc.com>, Alim Akhtar <alim.akhtar@samsung.com>, Bean Huo <beanhuo@micron.com>, Eric Biggers <ebiggers@google.com>, "James E.J. Bottomley" <jejb@linux.ibm.com>, "Martin K. Petersen" <martin.petersen@oracle.com>, Matthias Brugger <matthias.bgg@gmail.com>, jongmin jeong <jjmin.jeong@samsung.com>, linux-arm-kernel@lists.infradead.org, linux-kernel@vger.kernel.org, linux-mediatek@lists.infradead.org, linux-scsi@vger.kernel.org Subject: [PATCH v5] ufs: core: ufshcd: use local_clock() for debugging timestamps Date: Thu, 4 Aug 2022 06:50:34 +1000 [thread overview] Message-ID: <20220804065019.v5.1.I699244ea7efbd326a34a6dfd9b5a31e78400cf68@changeid> (raw) 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). Signed-off-by: Daniil Lunev <dlunev@chromium.org> Acked-by: Stanley Chu <stanley.chu@mediatek.com> Acked-by: Avri Altman <avri.altman@wdc.com> --- Changes in v5: - Bring over "acks" from the previous iterations Changes in v4: - Use div_u64 instead of "/" 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..3b3c011d81e36 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], div_u64(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, 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); @@ -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), + 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); @@ -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 _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel
next reply other threads:[~2022-08-03 20:51 UTC|newest] Thread overview: 2+ messages / expand[flat|nested] mbox.gz Atom feed top 2022-08-03 20:50 Daniil Lunev [this message] 2022-08-03 20:50 ` [PATCH v5] ufs: core: ufshcd: use local_clock() for debugging timestamps Daniil Lunev
Reply instructions: You may reply publicly to this message via plain-text email using any one of the following methods: * Save the following mbox file, import it into your mail client, and reply-to-all from there: mbox Avoid top-posting and favor interleaved quoting: https://en.wikipedia.org/wiki/Posting_style#Interleaved_style * Reply using the --to, --cc, and --in-reply-to switches of git-send-email(1): git send-email \ --in-reply-to=20220804065019.v5.1.I699244ea7efbd326a34a6dfd9b5a31e78400cf68@changeid \ --to=dlunev@chromium.org \ --cc=adrian.hunter@intel.com \ --cc=alim.akhtar@samsung.com \ --cc=avri.altman@wdc.com \ --cc=beanhuo@micron.com \ --cc=bvanassche@acm.org \ --cc=chu.stanley@gmail.com \ --cc=ebiggers@google.com \ --cc=jejb@linux.ibm.com \ --cc=jjmin.jeong@samsung.com \ --cc=linux-arm-kernel@lists.infradead.org \ --cc=linux-kernel@vger.kernel.org \ --cc=linux-mediatek@lists.infradead.org \ --cc=linux-scsi@vger.kernel.org \ --cc=martin.petersen@oracle.com \ --cc=matthias.bgg@gmail.com \ --cc=stanley.chu@mediatek.com \ /path/to/YOUR_REPLY https://kernel.org/pub/software/scm/git/docs/git-send-email.html * If your mail client supports setting the In-Reply-To header via mailto: links, try the mailto: linkBe sure your reply has a Subject: header at the top and a blank line before the message body.
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.