[PATCH v3 0/3] perf cs-etm: Handle valid-but-zero timestamps

[PATCH v3 0/3] perf cs-etm: Handle valid-but-zero timestamps

[James Clark]

Changes since v2:

 * Fix typo in last commit message
 * Add reviewed-by tags from Leo Yan

This patchset applies on top of "[PATCH v3 0/2] perf cs-etm: Set
time on synthesised samples to preserve ordering"

James Clark (3):
  perf cs-etm: Move synth_opts initialisation
  perf cs-etm: Start reading 'Z' --itrace option
  perf cs-etm: Prevent and warn on underflows during timestamp
    calculation.

 .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 45 ++++++++++++++-----
 tools/perf/util/cs-etm.c                      | 20 +++++----
 2 files changed, 46 insertions(+), 19 deletions(-)

-- 
2.28.0

[PATCH v3 0/3] perf cs-etm: Handle valid-but-zero timestamps

[James Clark]

Changes since v2:

 * Fix typo in last commit message
 * Add reviewed-by tags from Leo Yan

This patchset applies on top of "[PATCH v3 0/2] perf cs-etm: Set
time on synthesised samples to preserve ordering"

James Clark (3):
  perf cs-etm: Move synth_opts initialisation
  perf cs-etm: Start reading 'Z' --itrace option
  perf cs-etm: Prevent and warn on underflows during timestamp
    calculation.

 .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 45 ++++++++++++++-----
 tools/perf/util/cs-etm.c                      | 20 +++++----
 2 files changed, 46 insertions(+), 19 deletions(-)

-- 
2.28.0


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

[PATCH v3 1/3] perf cs-etm: Move synth_opts initialisation

[James Clark]

Move initialisation of synth_opts earlier in the function
so that synth_opts can be used at an earlier stage in a
later commit.

Reviewed-by: Leo Yan <leo.yan@linaro.org>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/util/cs-etm.c | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index 153fb8393e6e..a752fe06f170 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -2819,6 +2819,14 @@ int cs_etm__process_auxtrace_info(union perf_event *event,
 	if (err)
 		goto err_free_etm;
 
+	if (session->itrace_synth_opts->set) {
+		etm->synth_opts = *session->itrace_synth_opts;
+	} else {
+		itrace_synth_opts__set_default(&etm->synth_opts,
+				session->itrace_synth_opts->default_no_sample);
+		etm->synth_opts.callchain = false;
+	}
+
 	etm->session = session;
 	etm->machine = &session->machines.host;
 
@@ -2863,14 +2871,6 @@ int cs_etm__process_auxtrace_info(union perf_event *event,
 		return 0;
 	}
 
-	if (session->itrace_synth_opts->set) {
-		etm->synth_opts = *session->itrace_synth_opts;
-	} else {
-		itrace_synth_opts__set_default(&etm->synth_opts,
-				session->itrace_synth_opts->default_no_sample);
-		etm->synth_opts.callchain = false;
-	}
-
 	err = cs_etm__synth_events(etm, session);
 	if (err)
 		goto err_delete_thread;
-- 
2.28.0

[PATCH v3 1/3] perf cs-etm: Move synth_opts initialisation

[James Clark]

Move initialisation of synth_opts earlier in the function
so that synth_opts can be used at an earlier stage in a
later commit.

Reviewed-by: Leo Yan <leo.yan@linaro.org>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/util/cs-etm.c | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index 153fb8393e6e..a752fe06f170 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -2819,6 +2819,14 @@ int cs_etm__process_auxtrace_info(union perf_event *event,
 	if (err)
 		goto err_free_etm;
 
+	if (session->itrace_synth_opts->set) {
+		etm->synth_opts = *session->itrace_synth_opts;
+	} else {
+		itrace_synth_opts__set_default(&etm->synth_opts,
+				session->itrace_synth_opts->default_no_sample);
+		etm->synth_opts.callchain = false;
+	}
+
 	etm->session = session;
 	etm->machine = &session->machines.host;
 
@@ -2863,14 +2871,6 @@ int cs_etm__process_auxtrace_info(union perf_event *event,
 		return 0;
 	}
 
-	if (session->itrace_synth_opts->set) {
-		etm->synth_opts = *session->itrace_synth_opts;
-	} else {
-		itrace_synth_opts__set_default(&etm->synth_opts,
-				session->itrace_synth_opts->default_no_sample);
-		etm->synth_opts.callchain = false;
-	}
-
 	err = cs_etm__synth_events(etm, session);
 	if (err)
 		goto err_delete_thread;
-- 
2.28.0


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

[PATCH v3 2/3] perf cs-etm: Start reading 'Z' --itrace option

[James Clark]

Recently the 'Z' --itrace option was added to override detection
of timeless decoding. This is also useful in Coresight to work around
issues with invalid timestamps on some hardware.

When the 'Z' option is provided, the existing timeless decoding mode
will be used, even if timestamps were recorded.

Reviewed-by: Leo Yan <leo.yan@linaro.org>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/util/cs-etm.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index a752fe06f170..64536a6ed10a 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -2473,6 +2473,10 @@ static bool cs_etm__is_timeless_decoding(struct cs_etm_auxtrace *etm)
 	struct evlist *evlist = etm->session->evlist;
 	bool timeless_decoding = true;
 
+	/* Override timeless mode with user input from --itrace=Z */
+	if (etm->synth_opts.timeless_decoding)
+		return true;
+
 	/*
 	 * Circle through the list of event and complain if we find one
 	 * with the time bit set.
-- 
2.28.0

[PATCH v3 2/3] perf cs-etm: Start reading 'Z' --itrace option

[James Clark]

Recently the 'Z' --itrace option was added to override detection
of timeless decoding. This is also useful in Coresight to work around
issues with invalid timestamps on some hardware.

When the 'Z' option is provided, the existing timeless decoding mode
will be used, even if timestamps were recorded.

Reviewed-by: Leo Yan <leo.yan@linaro.org>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/util/cs-etm.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index a752fe06f170..64536a6ed10a 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -2473,6 +2473,10 @@ static bool cs_etm__is_timeless_decoding(struct cs_etm_auxtrace *etm)
 	struct evlist *evlist = etm->session->evlist;
 	bool timeless_decoding = true;
 
+	/* Override timeless mode with user input from --itrace=Z */
+	if (etm->synth_opts.timeless_decoding)
+		return true;
+
 	/*
 	 * Circle through the list of event and complain if we find one
 	 * with the time bit set.
-- 
2.28.0


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

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

[James Clark]

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.

Reviewed-by: Leo Yan <leo.yan@linaro.org>
Signed-off-by: James Clark <james.clark@arm.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 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@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"
 
 /* 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

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

[James Clark]

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.

Reviewed-by: Leo Yan <leo.yan@linaro.org>
Signed-off-by: James Clark <james.clark@arm.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 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@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"
 
 /* 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


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH v3 0/3] perf cs-etm: Handle valid-but-zero timestamps

[Arnaldo Carvalho de Melo]

Em Mon, May 17, 2021 at 04:17:38PM +0300, James Clark escreveu:
> Changes since v2:
> 
>  * Fix typo in last commit message
>  * Add reviewed-by tags from Leo Yan

Thanks, applied.

- Arnaldo

 
> This patchset applies on top of "[PATCH v3 0/2] perf cs-etm: Set
> time on synthesised samples to preserve ordering"
> 
> James Clark (3):
>   perf cs-etm: Move synth_opts initialisation
>   perf cs-etm: Start reading 'Z' --itrace option
>   perf cs-etm: Prevent and warn on underflows during timestamp
>     calculation.
> 
>  .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 45 ++++++++++++++-----
>  tools/perf/util/cs-etm.c                      | 20 +++++----
>  2 files changed, 46 insertions(+), 19 deletions(-)
> 
> -- 
> 2.28.0
> 

-- 

- Arnaldo

Re: [PATCH v3 0/3] perf cs-etm: Handle valid-but-zero timestamps

[Arnaldo Carvalho de Melo]

Em Mon, May 17, 2021 at 04:17:38PM +0300, James Clark escreveu:
> Changes since v2:
> 
>  * Fix typo in last commit message
>  * Add reviewed-by tags from Leo Yan

Thanks, applied.

- Arnaldo

 
> This patchset applies on top of "[PATCH v3 0/2] perf cs-etm: Set
> time on synthesised samples to preserve ordering"
> 
> James Clark (3):
>   perf cs-etm: Move synth_opts initialisation
>   perf cs-etm: Start reading 'Z' --itrace option
>   perf cs-etm: Prevent and warn on underflows during timestamp
>     calculation.
> 
>  .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 45 ++++++++++++++-----
>  tools/perf/util/cs-etm.c                      | 20 +++++----
>  2 files changed, 46 insertions(+), 19 deletions(-)
> 
> -- 
> 2.28.0
> 

-- 

- Arnaldo

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel