Re: [PATCH v2 3/3] perf cs-etm: Prevent and warn on underflows during timestamp calculation.

From: Leo Yan
Date: Sun May 16 2021 - 04:52:28 EST


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@xxxxxxx>

All three patches look good to me:

Reviewed-by: Leo Yan <leo.yan@xxxxxxxxxx>

> ---
> .../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@xxxxxxxxxx>
> */
>
> +#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
>