[<prev] [next>] [<thread-prev] [day] [month] [year] [list]
Message-ID: <20210516085212.GA942578@leoy-ThinkPad-X240s>
Date: Sun, 16 May 2021 16:52:12 +0800
From: Leo Yan <leo.yan@...aro.org>
To: James Clark <james.clark@....com>
Cc: coresight@...ts.linaro.org, al.grant@....com,
branislav.rankov@....com, denik@...omium.org,
suzuki.poulose@....com, anshuman.khandual@....com,
Mike Leach <mike.leach@...aro.org>,
Mark Rutland <mark.rutland@....com>,
Alexander Shishkin <alexander.shishkin@...ux.intel.com>,
Jiri Olsa <jolsa@...hat.com>,
Namhyung Kim <namhyung@...nel.org>,
John Garry <john.garry@...wei.com>,
Will Deacon <will@...nel.org>,
Mathieu Poirier <mathieu.poirier@...aro.org>,
linux-arm-kernel@...ts.infradead.org,
linux-perf-users@...r.kernel.org, linux-kernel@...r.kernel.org
Subject: Re: [PATCH v2 3/3] perf cs-etm: Prevent and warn on underflows
during timestamp calculation.
On Thu, May 13, 2021 at 05:35:20PM +0300, James Clark wrote:
> When a zero timestamp is encountered, warn once. This is to make
> hardware or configuration issues visible. Also suggest that the issue
> can be worked around with the --itrace=Z option.
>
> When an underflow with a non-zero timestamp occurrs, warn every time.
s/occurrs/occurs
> This is an unexpected scenario, and with increasing timestamps, it's
> unlikely that it would occur more than once, therefore it should be
> ok to warn every time.
>
> Only try to calculate the timestamp by subtracting the instruction
> count if neither of the above cases are true. This makes attempting
> to decode files with zero timestamps in non-timeless mode
> more consistent. Currently it can half work if the timestamp wraps
> around and becomes non-zero, although the behavior is undefined and
> unpredictable.
>
> Signed-off-by: James Clark <james.clark@....com>
All three patches look good to me:
Reviewed-by: Leo Yan <leo.yan@...aro.org>
> ---
> .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 45 ++++++++++++++-----
> 1 file changed, 34 insertions(+), 11 deletions(-)
>
> diff --git a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> index b01d363b9301..3e1a05bc82cc 100644
> --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> @@ -6,6 +6,7 @@
> * Author: Mathieu Poirier <mathieu.poirier@...aro.org>
> */
>
> +#include <asm/bug.h>
> #include <linux/coresight-pmu.h>
> #include <linux/err.h>
> #include <linux/list.h>
> @@ -17,6 +18,7 @@
>
> #include "cs-etm.h"
> #include "cs-etm-decoder.h"
> +#include "debug.h"
> #include "intlist.h"
>
> /* use raw logging */
> @@ -294,7 +296,8 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
> static ocsd_datapath_resp_t
> cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
> const ocsd_generic_trace_elem *elem,
> - const uint8_t trace_chan_id)
> + const uint8_t trace_chan_id,
> + const ocsd_trc_index_t indx)
> {
> struct cs_etm_packet_queue *packet_queue;
>
> @@ -313,14 +316,33 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
> return OCSD_RESP_CONT;
> }
>
> - /*
> - * This is the first timestamp we've seen since the beginning of traces
> - * or a discontinuity. Since timestamps packets are generated *after*
> - * range packets have been generated, we need to estimate the time at
> - * which instructions started by subtracting the number of instructions
> - * executed to the timestamp.
> - */
> - packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
> +
> + if (!elem->timestamp) {
> + /*
> + * Zero timestamps can be seen due to misconfiguration or hardware bugs.
> + * Warn once, and don't try to subtract instr_count as it would result in an
> + * underflow.
> + */
> + packet_queue->cs_timestamp = 0;
> + WARN_ONCE(true, "Zero Coresight timestamp found at Idx:%" OCSD_TRC_IDX_STR
> + ". Decoding may be improved with --itrace=Z...\n", indx);
> + } else if (packet_queue->instr_count > elem->timestamp) {
> + /*
> + * Sanity check that the elem->timestamp - packet_queue->instr_count would not
> + * result in an underflow. Warn and clamp at 0 if it would.
> + */
> + packet_queue->cs_timestamp = 0;
> + pr_err("Timestamp calculation underflow at Idx:%" OCSD_TRC_IDX_STR "\n", indx);
> + } else {
> + /*
> + * This is the first timestamp we've seen since the beginning of traces
> + * or a discontinuity. Since timestamps packets are generated *after*
> + * range packets have been generated, we need to estimate the time at
> + * which instructions started by subtracting the number of instructions
> + * executed to the timestamp.
> + */
> + packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
> + }
> packet_queue->next_cs_timestamp = elem->timestamp;
> packet_queue->instr_count = 0;
>
> @@ -542,7 +564,7 @@ cs_etm_decoder__set_tid(struct cs_etm_queue *etmq,
>
> static ocsd_datapath_resp_t cs_etm_decoder__gen_trace_elem_printer(
> const void *context,
> - const ocsd_trc_index_t indx __maybe_unused,
> + const ocsd_trc_index_t indx,
> const u8 trace_chan_id __maybe_unused,
> const ocsd_generic_trace_elem *elem)
> {
> @@ -579,7 +601,8 @@ static ocsd_datapath_resp_t cs_etm_decoder__gen_trace_elem_printer(
> break;
> case OCSD_GEN_TRC_ELEM_TIMESTAMP:
> resp = cs_etm_decoder__do_hard_timestamp(etmq, elem,
> - trace_chan_id);
> + trace_chan_id,
> + indx);
> break;
> case OCSD_GEN_TRC_ELEM_PE_CONTEXT:
> resp = cs_etm_decoder__set_tid(etmq, packet_queue,
> --
> 2.28.0
>
Powered by blists - more mailing lists