| From f52b0b2892b794820c00225909b9dff477de1ad9 Mon Sep 17 00:00:00 2001 |
| From: James Clark <james.clark@arm.com> |
| Date: Mon, 17 May 2021 16:17:41 +0300 |
| Subject: [PATCH 3/3] perf cs-etm: Prevent and warn on underflows during |
| timestamp calculation. |
| |
| 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 occurs, warn every time. |
| 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@arm.com> |
| Reviewed-by: Leo Yan <leo.yan@linaro.org> |
| Cc: Al Grant <al.grant@arm.com> |
| Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com> |
| Cc: Anshuman Khandual <anshuman.khandual@arm.com> |
| Cc: Branislav Rankov <branislav.rankov@arm.com> |
| Cc: Denis Nikitin <denik@chromium.org> |
| Cc: Jiri Olsa <jolsa@redhat.com> |
| Cc: John Garry <john.garry@huawei.com> |
| Cc: Mark Rutland <mark.rutland@arm.com> |
| Cc: Mathieu Poirier <mathieu.poirier@linaro.org> |
| Cc: Mike Leach <mike.leach@linaro.org> |
| Cc: Namhyung Kim <namhyung@kernel.org> |
| Cc: Suzuki Poulouse <suzuki.poulose@arm.com> |
| Cc: Will Deacon <will@kernel.org> |
| Cc: coresight@lists.linaro.org |
| Cc: linux-arm-kernel@lists.infradead.org |
| Link: http://lore.kernel.org/lkml/20210517131741.3027-4-james.clark@arm.com |
| Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> |
| --- |
| .../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 1237364b742c..7e2c0d549712 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@linaro.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" |
| #include "util.h" |
| |
| @@ -295,7 +297,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; |
| |
| @@ -314,14 +317,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 substracting 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; |
| |
| @@ -552,7 +574,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) |
| { |
| @@ -589,7 +611,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.32.0.605.g8dce9f2422-goog |
| |