[PATCH v3 0/2] perf cs-etm: Set time on synthesised samples to preserve ordering

[PATCH v3 0/2] perf cs-etm: Set time on synthesised samples to preserve ordering

[James Clark]

Changes since v2:
  * Collect acked and reviewed-by tags from v1 that were
    missed in v2
  * Add comment and commit message suggestions from Suzuki
  * Rebase onto next-20210510 (also applies to perf/core)

Thanks
James


James Clark (2):
  perf cs-etm: Refactor timestamp variable names
  perf cs-etm: Set time on synthesised samples to preserve ordering

 .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 18 +++---
 tools/perf/util/cs-etm.c                      | 57 +++++++++++--------
 tools/perf/util/cs-etm.h                      |  4 +-
 3 files changed, 44 insertions(+), 35 deletions(-)

-- 
2.28.0

[PATCH v3 0/2] perf cs-etm: Set time on synthesised samples to preserve ordering

[James Clark]

Changes since v2:
  * Collect acked and reviewed-by tags from v1 that were
    missed in v2
  * Add comment and commit message suggestions from Suzuki
  * Rebase onto next-20210510 (also applies to perf/core)

Thanks
James


James Clark (2):
  perf cs-etm: Refactor timestamp variable names
  perf cs-etm: Set time on synthesised samples to preserve ordering

 .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 18 +++---
 tools/perf/util/cs-etm.c                      | 57 +++++++++++--------
 tools/perf/util/cs-etm.h                      |  4 +-
 3 files changed, 44 insertions(+), 35 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/2] perf cs-etm: Refactor timestamp variable names

[James Clark]

Remove ambiguity in variable names relating to timestamps.
A later commit will save the sample kernel timestamp in one
of the etm structs, so name all elements appropriately to
avoid confusion.

This is also removes some ambiguity arising from the fact
that the --timestamp argument to perf record refers to
sample kernel timestamps, and the /timestamp/ event modifier
refers to CS timestamps, so the term is overloaded.

Signed-off-by: James Clark <james.clark@arm.com>
---
 .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 18 ++++----
 tools/perf/util/cs-etm.c                      | 42 +++++++++----------
 tools/perf/util/cs-etm.h                      |  4 +-
 3 files changed, 31 insertions(+), 33 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 059bcec3f651..b01d363b9301 100644
--- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
+++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
@@ -276,13 +276,13 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
 				  const uint8_t trace_chan_id)
 {
 	/* No timestamp packet has been received, nothing to do */
-	if (!packet_queue->timestamp)
+	if (!packet_queue->cs_timestamp)
 		return OCSD_RESP_CONT;
 
-	packet_queue->timestamp = packet_queue->next_timestamp;
+	packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
 
 	/* Estimate the timestamp for the next range packet */
-	packet_queue->next_timestamp += packet_queue->instr_count;
+	packet_queue->next_cs_timestamp += packet_queue->instr_count;
 	packet_queue->instr_count = 0;
 
 	/* Tell the front end which traceid_queue needs attention */
@@ -308,8 +308,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
 	 * Function do_soft_timestamp() will report the value to the front end,
 	 * hence asking the decoder to keep decoding rather than stopping.
 	 */
-	if (packet_queue->timestamp) {
-		packet_queue->next_timestamp = elem->timestamp;
+	if (packet_queue->cs_timestamp) {
+		packet_queue->next_cs_timestamp = elem->timestamp;
 		return OCSD_RESP_CONT;
 	}
 
@@ -320,8 +320,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
 	 * which instructions started by subtracting the number of instructions
 	 * executed to the timestamp.
 	 */
-	packet_queue->timestamp = elem->timestamp - packet_queue->instr_count;
-	packet_queue->next_timestamp = elem->timestamp;
+	packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
+	packet_queue->next_cs_timestamp = elem->timestamp;
 	packet_queue->instr_count = 0;
 
 	/* Tell the front end which traceid_queue needs attention */
@@ -334,8 +334,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
 static void
 cs_etm_decoder__reset_timestamp(struct cs_etm_packet_queue *packet_queue)
 {
-	packet_queue->timestamp = 0;
-	packet_queue->next_timestamp = 0;
+	packet_queue->cs_timestamp = 0;
+	packet_queue->next_cs_timestamp = 0;
 	packet_queue->instr_count = 0;
 }
 
diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index 7e63e7dedc33..533f6f2f0685 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -38,8 +38,6 @@
 #include <tools/libc_compat.h>
 #include "util/synthetic-events.h"
 
-#define MAX_TIMESTAMP (~0ULL)
-
 struct cs_etm_auxtrace {
 	struct auxtrace auxtrace;
 	struct auxtrace_queues queues;
@@ -86,7 +84,7 @@ struct cs_etm_queue {
 	struct cs_etm_decoder *decoder;
 	struct auxtrace_buffer *buffer;
 	unsigned int queue_nr;
-	u8 pending_timestamp;
+	u8 pending_timestamp_chan_id;
 	u64 offset;
 	const unsigned char *buf;
 	size_t buf_len, buf_used;
@@ -208,7 +206,7 @@ void cs_etm__etmq_set_traceid_queue_timestamp(struct cs_etm_queue *etmq,
 	 * be more than one channel per cs_etm_queue, we need to specify
 	 * what traceID queue needs servicing.
 	 */
-	etmq->pending_timestamp = trace_chan_id;
+	etmq->pending_timestamp_chan_id = trace_chan_id;
 }
 
 static u64 cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
@@ -216,22 +214,22 @@ static u64 cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
 {
 	struct cs_etm_packet_queue *packet_queue;
 
-	if (!etmq->pending_timestamp)
+	if (!etmq->pending_timestamp_chan_id)
 		return 0;
 
 	if (trace_chan_id)
-		*trace_chan_id = etmq->pending_timestamp;
+		*trace_chan_id = etmq->pending_timestamp_chan_id;
 
 	packet_queue = cs_etm__etmq_get_packet_queue(etmq,
-						     etmq->pending_timestamp);
+						     etmq->pending_timestamp_chan_id);
 	if (!packet_queue)
 		return 0;
 
 	/* Acknowledge pending status */
-	etmq->pending_timestamp = 0;
+	etmq->pending_timestamp_chan_id = 0;
 
 	/* See function cs_etm_decoder__do_{hard|soft}_timestamp() */
-	return packet_queue->timestamp;
+	return packet_queue->cs_timestamp;
 }
 
 static void cs_etm__clear_packet_queue(struct cs_etm_packet_queue *queue)
@@ -814,7 +812,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
 	int ret = 0;
 	unsigned int cs_queue_nr;
 	u8 trace_chan_id;
-	u64 timestamp;
+	u64 cs_timestamp;
 	struct cs_etm_queue *etmq = queue->priv;
 
 	if (list_empty(&queue->head) || etmq)
@@ -854,7 +852,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
 
 		/*
 		 * Run decoder on the trace block.  The decoder will stop when
-		 * encountering a timestamp, a full packet queue or the end of
+		 * encountering a CS timestamp, a full packet queue or the end of
 		 * trace for that block.
 		 */
 		ret = cs_etm__decode_data_block(etmq);
@@ -865,10 +863,10 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
 		 * Function cs_etm_decoder__do_{hard|soft}_timestamp() does all
 		 * the timestamp calculation for us.
 		 */
-		timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
+		cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
 
 		/* We found a timestamp, no need to continue. */
-		if (timestamp)
+		if (cs_timestamp)
 			break;
 
 		/*
@@ -892,7 +890,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
 	 * queue and will be processed in cs_etm__process_queues().
 	 */
 	cs_queue_nr = TO_CS_QUEUE_NR(queue_nr, trace_chan_id);
-	ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, timestamp);
+	ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, cs_timestamp);
 out:
 	return ret;
 }
@@ -2221,7 +2219,7 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
 	int ret = 0;
 	unsigned int cs_queue_nr, queue_nr;
 	u8 trace_chan_id;
-	u64 timestamp;
+	u64 cs_timestamp;
 	struct auxtrace_queue *queue;
 	struct cs_etm_queue *etmq;
 	struct cs_etm_traceid_queue *tidq;
@@ -2283,9 +2281,9 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
 		if (ret)
 			goto out;
 
-		timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
+		cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
 
-		if (!timestamp) {
+		if (!cs_timestamp) {
 			/*
 			 * Function cs_etm__decode_data_block() returns when
 			 * there is no more traces to decode in the current
@@ -2308,7 +2306,7 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
 		 * this queue/traceID.
 		 */
 		cs_queue_nr = TO_CS_QUEUE_NR(queue_nr, trace_chan_id);
-		ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, timestamp);
+		ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, cs_timestamp);
 	}
 
 out:
@@ -2380,7 +2378,7 @@ static int cs_etm__process_event(struct perf_session *session,
 				 struct perf_tool *tool)
 {
 	int err = 0;
-	u64 timestamp;
+	u64 sample_kernel_timestamp;
 	struct cs_etm_auxtrace *etm = container_of(session->auxtrace,
 						   struct cs_etm_auxtrace,
 						   auxtrace);
@@ -2394,11 +2392,11 @@ static int cs_etm__process_event(struct perf_session *session,
 	}
 
 	if (sample->time && (sample->time != (u64) -1))
-		timestamp = sample->time;
+		sample_kernel_timestamp = sample->time;
 	else
-		timestamp = 0;
+		sample_kernel_timestamp = 0;
 
-	if (timestamp || etm->timeless_decoding) {
+	if (sample_kernel_timestamp || etm->timeless_decoding) {
 		err = cs_etm__update_queues(etm);
 		if (err)
 			return err;
diff --git a/tools/perf/util/cs-etm.h b/tools/perf/util/cs-etm.h
index 36428918411e..d65c7b19407d 100644
--- a/tools/perf/util/cs-etm.h
+++ b/tools/perf/util/cs-etm.h
@@ -171,8 +171,8 @@ struct cs_etm_packet_queue {
 	u32 head;
 	u32 tail;
 	u32 instr_count;
-	u64 timestamp;
-	u64 next_timestamp;
+	u64 cs_timestamp;
+	u64 next_cs_timestamp;
 	struct cs_etm_packet packet_buffer[CS_ETM_PACKET_MAX_BUFFER];
 };
 
-- 
2.28.0

[PATCH v3 1/2] perf cs-etm: Refactor timestamp variable names

[James Clark]

Remove ambiguity in variable names relating to timestamps.
A later commit will save the sample kernel timestamp in one
of the etm structs, so name all elements appropriately to
avoid confusion.

This is also removes some ambiguity arising from the fact
that the --timestamp argument to perf record refers to
sample kernel timestamps, and the /timestamp/ event modifier
refers to CS timestamps, so the term is overloaded.

Signed-off-by: James Clark <james.clark@arm.com>
---
 .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 18 ++++----
 tools/perf/util/cs-etm.c                      | 42 +++++++++----------
 tools/perf/util/cs-etm.h                      |  4 +-
 3 files changed, 31 insertions(+), 33 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 059bcec3f651..b01d363b9301 100644
--- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
+++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
@@ -276,13 +276,13 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
 				  const uint8_t trace_chan_id)
 {
 	/* No timestamp packet has been received, nothing to do */
-	if (!packet_queue->timestamp)
+	if (!packet_queue->cs_timestamp)
 		return OCSD_RESP_CONT;
 
-	packet_queue->timestamp = packet_queue->next_timestamp;
+	packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
 
 	/* Estimate the timestamp for the next range packet */
-	packet_queue->next_timestamp += packet_queue->instr_count;
+	packet_queue->next_cs_timestamp += packet_queue->instr_count;
 	packet_queue->instr_count = 0;
 
 	/* Tell the front end which traceid_queue needs attention */
@@ -308,8 +308,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
 	 * Function do_soft_timestamp() will report the value to the front end,
 	 * hence asking the decoder to keep decoding rather than stopping.
 	 */
-	if (packet_queue->timestamp) {
-		packet_queue->next_timestamp = elem->timestamp;
+	if (packet_queue->cs_timestamp) {
+		packet_queue->next_cs_timestamp = elem->timestamp;
 		return OCSD_RESP_CONT;
 	}
 
@@ -320,8 +320,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
 	 * which instructions started by subtracting the number of instructions
 	 * executed to the timestamp.
 	 */
-	packet_queue->timestamp = elem->timestamp - packet_queue->instr_count;
-	packet_queue->next_timestamp = elem->timestamp;
+	packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
+	packet_queue->next_cs_timestamp = elem->timestamp;
 	packet_queue->instr_count = 0;
 
 	/* Tell the front end which traceid_queue needs attention */
@@ -334,8 +334,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
 static void
 cs_etm_decoder__reset_timestamp(struct cs_etm_packet_queue *packet_queue)
 {
-	packet_queue->timestamp = 0;
-	packet_queue->next_timestamp = 0;
+	packet_queue->cs_timestamp = 0;
+	packet_queue->next_cs_timestamp = 0;
 	packet_queue->instr_count = 0;
 }
 
diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index 7e63e7dedc33..533f6f2f0685 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -38,8 +38,6 @@
 #include <tools/libc_compat.h>
 #include "util/synthetic-events.h"
 
-#define MAX_TIMESTAMP (~0ULL)
-
 struct cs_etm_auxtrace {
 	struct auxtrace auxtrace;
 	struct auxtrace_queues queues;
@@ -86,7 +84,7 @@ struct cs_etm_queue {
 	struct cs_etm_decoder *decoder;
 	struct auxtrace_buffer *buffer;
 	unsigned int queue_nr;
-	u8 pending_timestamp;
+	u8 pending_timestamp_chan_id;
 	u64 offset;
 	const unsigned char *buf;
 	size_t buf_len, buf_used;
@@ -208,7 +206,7 @@ void cs_etm__etmq_set_traceid_queue_timestamp(struct cs_etm_queue *etmq,
 	 * be more than one channel per cs_etm_queue, we need to specify
 	 * what traceID queue needs servicing.
 	 */
-	etmq->pending_timestamp = trace_chan_id;
+	etmq->pending_timestamp_chan_id = trace_chan_id;
 }
 
 static u64 cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
@@ -216,22 +214,22 @@ static u64 cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
 {
 	struct cs_etm_packet_queue *packet_queue;
 
-	if (!etmq->pending_timestamp)
+	if (!etmq->pending_timestamp_chan_id)
 		return 0;
 
 	if (trace_chan_id)
-		*trace_chan_id = etmq->pending_timestamp;
+		*trace_chan_id = etmq->pending_timestamp_chan_id;
 
 	packet_queue = cs_etm__etmq_get_packet_queue(etmq,
-						     etmq->pending_timestamp);
+						     etmq->pending_timestamp_chan_id);
 	if (!packet_queue)
 		return 0;
 
 	/* Acknowledge pending status */
-	etmq->pending_timestamp = 0;
+	etmq->pending_timestamp_chan_id = 0;
 
 	/* See function cs_etm_decoder__do_{hard|soft}_timestamp() */
-	return packet_queue->timestamp;
+	return packet_queue->cs_timestamp;
 }
 
 static void cs_etm__clear_packet_queue(struct cs_etm_packet_queue *queue)
@@ -814,7 +812,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
 	int ret = 0;
 	unsigned int cs_queue_nr;
 	u8 trace_chan_id;
-	u64 timestamp;
+	u64 cs_timestamp;
 	struct cs_etm_queue *etmq = queue->priv;
 
 	if (list_empty(&queue->head) || etmq)
@@ -854,7 +852,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
 
 		/*
 		 * Run decoder on the trace block.  The decoder will stop when
-		 * encountering a timestamp, a full packet queue or the end of
+		 * encountering a CS timestamp, a full packet queue or the end of
 		 * trace for that block.
 		 */
 		ret = cs_etm__decode_data_block(etmq);
@@ -865,10 +863,10 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
 		 * Function cs_etm_decoder__do_{hard|soft}_timestamp() does all
 		 * the timestamp calculation for us.
 		 */
-		timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
+		cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
 
 		/* We found a timestamp, no need to continue. */
-		if (timestamp)
+		if (cs_timestamp)
 			break;
 
 		/*
@@ -892,7 +890,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
 	 * queue and will be processed in cs_etm__process_queues().
 	 */
 	cs_queue_nr = TO_CS_QUEUE_NR(queue_nr, trace_chan_id);
-	ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, timestamp);
+	ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, cs_timestamp);
 out:
 	return ret;
 }
@@ -2221,7 +2219,7 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
 	int ret = 0;
 	unsigned int cs_queue_nr, queue_nr;
 	u8 trace_chan_id;
-	u64 timestamp;
+	u64 cs_timestamp;
 	struct auxtrace_queue *queue;
 	struct cs_etm_queue *etmq;
 	struct cs_etm_traceid_queue *tidq;
@@ -2283,9 +2281,9 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
 		if (ret)
 			goto out;
 
-		timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
+		cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
 
-		if (!timestamp) {
+		if (!cs_timestamp) {
 			/*
 			 * Function cs_etm__decode_data_block() returns when
 			 * there is no more traces to decode in the current
@@ -2308,7 +2306,7 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
 		 * this queue/traceID.
 		 */
 		cs_queue_nr = TO_CS_QUEUE_NR(queue_nr, trace_chan_id);
-		ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, timestamp);
+		ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, cs_timestamp);
 	}
 
 out:
@@ -2380,7 +2378,7 @@ static int cs_etm__process_event(struct perf_session *session,
 				 struct perf_tool *tool)
 {
 	int err = 0;
-	u64 timestamp;
+	u64 sample_kernel_timestamp;
 	struct cs_etm_auxtrace *etm = container_of(session->auxtrace,
 						   struct cs_etm_auxtrace,
 						   auxtrace);
@@ -2394,11 +2392,11 @@ static int cs_etm__process_event(struct perf_session *session,
 	}
 
 	if (sample->time && (sample->time != (u64) -1))
-		timestamp = sample->time;
+		sample_kernel_timestamp = sample->time;
 	else
-		timestamp = 0;
+		sample_kernel_timestamp = 0;
 
-	if (timestamp || etm->timeless_decoding) {
+	if (sample_kernel_timestamp || etm->timeless_decoding) {
 		err = cs_etm__update_queues(etm);
 		if (err)
 			return err;
diff --git a/tools/perf/util/cs-etm.h b/tools/perf/util/cs-etm.h
index 36428918411e..d65c7b19407d 100644
--- a/tools/perf/util/cs-etm.h
+++ b/tools/perf/util/cs-etm.h
@@ -171,8 +171,8 @@ struct cs_etm_packet_queue {
 	u32 head;
 	u32 tail;
 	u32 instr_count;
-	u64 timestamp;
-	u64 next_timestamp;
+	u64 cs_timestamp;
+	u64 next_cs_timestamp;
 	struct cs_etm_packet packet_buffer[CS_ETM_PACKET_MAX_BUFFER];
 };
 
-- 
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 1/2] perf cs-etm: Refactor timestamp variable names

[Mathieu Poirier]

On Mon, May 10, 2021 at 05:32:47PM +0300, James Clark wrote:
> Remove ambiguity in variable names relating to timestamps.
> A later commit will save the sample kernel timestamp in one
> of the etm structs, so name all elements appropriately to
> avoid confusion.
> 
> This is also removes some ambiguity arising from the fact
> that the --timestamp argument to perf record refers to
> sample kernel timestamps, and the /timestamp/ event modifier
> refers to CS timestamps, so the term is overloaded.
> 
> Signed-off-by: James Clark <james.clark@arm.com>
> ---
>  .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 18 ++++----
>  tools/perf/util/cs-etm.c                      | 42 +++++++++----------
>  tools/perf/util/cs-etm.h                      |  4 +-
>  3 files changed, 31 insertions(+), 33 deletions(-)

Reviewed-by: Mathieu Poirier <mathieu.poirier@linaro.org>

> 
> 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 059bcec3f651..b01d363b9301 100644
> --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> @@ -276,13 +276,13 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
>  				  const uint8_t trace_chan_id)
>  {
>  	/* No timestamp packet has been received, nothing to do */
> -	if (!packet_queue->timestamp)
> +	if (!packet_queue->cs_timestamp)
>  		return OCSD_RESP_CONT;
>  
> -	packet_queue->timestamp = packet_queue->next_timestamp;
> +	packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
>  
>  	/* Estimate the timestamp for the next range packet */
> -	packet_queue->next_timestamp += packet_queue->instr_count;
> +	packet_queue->next_cs_timestamp += packet_queue->instr_count;
>  	packet_queue->instr_count = 0;
>  
>  	/* Tell the front end which traceid_queue needs attention */
> @@ -308,8 +308,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>  	 * Function do_soft_timestamp() will report the value to the front end,
>  	 * hence asking the decoder to keep decoding rather than stopping.
>  	 */
> -	if (packet_queue->timestamp) {
> -		packet_queue->next_timestamp = elem->timestamp;
> +	if (packet_queue->cs_timestamp) {
> +		packet_queue->next_cs_timestamp = elem->timestamp;
>  		return OCSD_RESP_CONT;
>  	}
>  
> @@ -320,8 +320,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>  	 * which instructions started by subtracting the number of instructions
>  	 * executed to the timestamp.
>  	 */
> -	packet_queue->timestamp = elem->timestamp - packet_queue->instr_count;
> -	packet_queue->next_timestamp = elem->timestamp;
> +	packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
> +	packet_queue->next_cs_timestamp = elem->timestamp;
>  	packet_queue->instr_count = 0;
>  
>  	/* Tell the front end which traceid_queue needs attention */
> @@ -334,8 +334,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>  static void
>  cs_etm_decoder__reset_timestamp(struct cs_etm_packet_queue *packet_queue)
>  {
> -	packet_queue->timestamp = 0;
> -	packet_queue->next_timestamp = 0;
> +	packet_queue->cs_timestamp = 0;
> +	packet_queue->next_cs_timestamp = 0;
>  	packet_queue->instr_count = 0;
>  }
>  
> diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
> index 7e63e7dedc33..533f6f2f0685 100644
> --- a/tools/perf/util/cs-etm.c
> +++ b/tools/perf/util/cs-etm.c
> @@ -38,8 +38,6 @@
>  #include <tools/libc_compat.h>
>  #include "util/synthetic-events.h"
>  
> -#define MAX_TIMESTAMP (~0ULL)
> -
>  struct cs_etm_auxtrace {
>  	struct auxtrace auxtrace;
>  	struct auxtrace_queues queues;
> @@ -86,7 +84,7 @@ struct cs_etm_queue {
>  	struct cs_etm_decoder *decoder;
>  	struct auxtrace_buffer *buffer;
>  	unsigned int queue_nr;
> -	u8 pending_timestamp;
> +	u8 pending_timestamp_chan_id;
>  	u64 offset;
>  	const unsigned char *buf;
>  	size_t buf_len, buf_used;
> @@ -208,7 +206,7 @@ void cs_etm__etmq_set_traceid_queue_timestamp(struct cs_etm_queue *etmq,
>  	 * be more than one channel per cs_etm_queue, we need to specify
>  	 * what traceID queue needs servicing.
>  	 */
> -	etmq->pending_timestamp = trace_chan_id;
> +	etmq->pending_timestamp_chan_id = trace_chan_id;
>  }
>  
>  static u64 cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
> @@ -216,22 +214,22 @@ static u64 cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
>  {
>  	struct cs_etm_packet_queue *packet_queue;
>  
> -	if (!etmq->pending_timestamp)
> +	if (!etmq->pending_timestamp_chan_id)
>  		return 0;
>  
>  	if (trace_chan_id)
> -		*trace_chan_id = etmq->pending_timestamp;
> +		*trace_chan_id = etmq->pending_timestamp_chan_id;
>  
>  	packet_queue = cs_etm__etmq_get_packet_queue(etmq,
> -						     etmq->pending_timestamp);
> +						     etmq->pending_timestamp_chan_id);
>  	if (!packet_queue)
>  		return 0;
>  
>  	/* Acknowledge pending status */
> -	etmq->pending_timestamp = 0;
> +	etmq->pending_timestamp_chan_id = 0;
>  
>  	/* See function cs_etm_decoder__do_{hard|soft}_timestamp() */
> -	return packet_queue->timestamp;
> +	return packet_queue->cs_timestamp;
>  }
>  
>  static void cs_etm__clear_packet_queue(struct cs_etm_packet_queue *queue)
> @@ -814,7 +812,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
>  	int ret = 0;
>  	unsigned int cs_queue_nr;
>  	u8 trace_chan_id;
> -	u64 timestamp;
> +	u64 cs_timestamp;
>  	struct cs_etm_queue *etmq = queue->priv;
>  
>  	if (list_empty(&queue->head) || etmq)
> @@ -854,7 +852,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
>  
>  		/*
>  		 * Run decoder on the trace block.  The decoder will stop when
> -		 * encountering a timestamp, a full packet queue or the end of
> +		 * encountering a CS timestamp, a full packet queue or the end of
>  		 * trace for that block.
>  		 */
>  		ret = cs_etm__decode_data_block(etmq);
> @@ -865,10 +863,10 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
>  		 * Function cs_etm_decoder__do_{hard|soft}_timestamp() does all
>  		 * the timestamp calculation for us.
>  		 */
> -		timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
> +		cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
>  
>  		/* We found a timestamp, no need to continue. */
> -		if (timestamp)
> +		if (cs_timestamp)
>  			break;
>  
>  		/*
> @@ -892,7 +890,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
>  	 * queue and will be processed in cs_etm__process_queues().
>  	 */
>  	cs_queue_nr = TO_CS_QUEUE_NR(queue_nr, trace_chan_id);
> -	ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, timestamp);
> +	ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, cs_timestamp);
>  out:
>  	return ret;
>  }
> @@ -2221,7 +2219,7 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
>  	int ret = 0;
>  	unsigned int cs_queue_nr, queue_nr;
>  	u8 trace_chan_id;
> -	u64 timestamp;
> +	u64 cs_timestamp;
>  	struct auxtrace_queue *queue;
>  	struct cs_etm_queue *etmq;
>  	struct cs_etm_traceid_queue *tidq;
> @@ -2283,9 +2281,9 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
>  		if (ret)
>  			goto out;
>  
> -		timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
> +		cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
>  
> -		if (!timestamp) {
> +		if (!cs_timestamp) {
>  			/*
>  			 * Function cs_etm__decode_data_block() returns when
>  			 * there is no more traces to decode in the current
> @@ -2308,7 +2306,7 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
>  		 * this queue/traceID.
>  		 */
>  		cs_queue_nr = TO_CS_QUEUE_NR(queue_nr, trace_chan_id);
> -		ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, timestamp);
> +		ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, cs_timestamp);
>  	}
>  
>  out:
> @@ -2380,7 +2378,7 @@ static int cs_etm__process_event(struct perf_session *session,
>  				 struct perf_tool *tool)
>  {
>  	int err = 0;
> -	u64 timestamp;
> +	u64 sample_kernel_timestamp;
>  	struct cs_etm_auxtrace *etm = container_of(session->auxtrace,
>  						   struct cs_etm_auxtrace,
>  						   auxtrace);
> @@ -2394,11 +2392,11 @@ static int cs_etm__process_event(struct perf_session *session,
>  	}
>  
>  	if (sample->time && (sample->time != (u64) -1))
> -		timestamp = sample->time;
> +		sample_kernel_timestamp = sample->time;
>  	else
> -		timestamp = 0;
> +		sample_kernel_timestamp = 0;
>  
> -	if (timestamp || etm->timeless_decoding) {
> +	if (sample_kernel_timestamp || etm->timeless_decoding) {
>  		err = cs_etm__update_queues(etm);
>  		if (err)
>  			return err;
> diff --git a/tools/perf/util/cs-etm.h b/tools/perf/util/cs-etm.h
> index 36428918411e..d65c7b19407d 100644
> --- a/tools/perf/util/cs-etm.h
> +++ b/tools/perf/util/cs-etm.h
> @@ -171,8 +171,8 @@ struct cs_etm_packet_queue {
>  	u32 head;
>  	u32 tail;
>  	u32 instr_count;
> -	u64 timestamp;
> -	u64 next_timestamp;
> +	u64 cs_timestamp;
> +	u64 next_cs_timestamp;
>  	struct cs_etm_packet packet_buffer[CS_ETM_PACKET_MAX_BUFFER];
>  };
>  
> -- 
> 2.28.0
> 

Re: [PATCH v3 1/2] perf cs-etm: Refactor timestamp variable names

[Mathieu Poirier]

On Mon, May 10, 2021 at 05:32:47PM +0300, James Clark wrote:
> Remove ambiguity in variable names relating to timestamps.
> A later commit will save the sample kernel timestamp in one
> of the etm structs, so name all elements appropriately to
> avoid confusion.
> 
> This is also removes some ambiguity arising from the fact
> that the --timestamp argument to perf record refers to
> sample kernel timestamps, and the /timestamp/ event modifier
> refers to CS timestamps, so the term is overloaded.
> 
> Signed-off-by: James Clark <james.clark@arm.com>
> ---
>  .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 18 ++++----
>  tools/perf/util/cs-etm.c                      | 42 +++++++++----------
>  tools/perf/util/cs-etm.h                      |  4 +-
>  3 files changed, 31 insertions(+), 33 deletions(-)

Reviewed-by: Mathieu Poirier <mathieu.poirier@linaro.org>

> 
> 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 059bcec3f651..b01d363b9301 100644
> --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> @@ -276,13 +276,13 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
>  				  const uint8_t trace_chan_id)
>  {
>  	/* No timestamp packet has been received, nothing to do */
> -	if (!packet_queue->timestamp)
> +	if (!packet_queue->cs_timestamp)
>  		return OCSD_RESP_CONT;
>  
> -	packet_queue->timestamp = packet_queue->next_timestamp;
> +	packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
>  
>  	/* Estimate the timestamp for the next range packet */
> -	packet_queue->next_timestamp += packet_queue->instr_count;
> +	packet_queue->next_cs_timestamp += packet_queue->instr_count;
>  	packet_queue->instr_count = 0;
>  
>  	/* Tell the front end which traceid_queue needs attention */
> @@ -308,8 +308,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>  	 * Function do_soft_timestamp() will report the value to the front end,
>  	 * hence asking the decoder to keep decoding rather than stopping.
>  	 */
> -	if (packet_queue->timestamp) {
> -		packet_queue->next_timestamp = elem->timestamp;
> +	if (packet_queue->cs_timestamp) {
> +		packet_queue->next_cs_timestamp = elem->timestamp;
>  		return OCSD_RESP_CONT;
>  	}
>  
> @@ -320,8 +320,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>  	 * which instructions started by subtracting the number of instructions
>  	 * executed to the timestamp.
>  	 */
> -	packet_queue->timestamp = elem->timestamp - packet_queue->instr_count;
> -	packet_queue->next_timestamp = elem->timestamp;
> +	packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
> +	packet_queue->next_cs_timestamp = elem->timestamp;
>  	packet_queue->instr_count = 0;
>  
>  	/* Tell the front end which traceid_queue needs attention */
> @@ -334,8 +334,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>  static void
>  cs_etm_decoder__reset_timestamp(struct cs_etm_packet_queue *packet_queue)
>  {
> -	packet_queue->timestamp = 0;
> -	packet_queue->next_timestamp = 0;
> +	packet_queue->cs_timestamp = 0;
> +	packet_queue->next_cs_timestamp = 0;
>  	packet_queue->instr_count = 0;
>  }
>  
> diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
> index 7e63e7dedc33..533f6f2f0685 100644
> --- a/tools/perf/util/cs-etm.c
> +++ b/tools/perf/util/cs-etm.c
> @@ -38,8 +38,6 @@
>  #include <tools/libc_compat.h>
>  #include "util/synthetic-events.h"
>  
> -#define MAX_TIMESTAMP (~0ULL)
> -
>  struct cs_etm_auxtrace {
>  	struct auxtrace auxtrace;
>  	struct auxtrace_queues queues;
> @@ -86,7 +84,7 @@ struct cs_etm_queue {
>  	struct cs_etm_decoder *decoder;
>  	struct auxtrace_buffer *buffer;
>  	unsigned int queue_nr;
> -	u8 pending_timestamp;
> +	u8 pending_timestamp_chan_id;
>  	u64 offset;
>  	const unsigned char *buf;
>  	size_t buf_len, buf_used;
> @@ -208,7 +206,7 @@ void cs_etm__etmq_set_traceid_queue_timestamp(struct cs_etm_queue *etmq,
>  	 * be more than one channel per cs_etm_queue, we need to specify
>  	 * what traceID queue needs servicing.
>  	 */
> -	etmq->pending_timestamp = trace_chan_id;
> +	etmq->pending_timestamp_chan_id = trace_chan_id;
>  }
>  
>  static u64 cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
> @@ -216,22 +214,22 @@ static u64 cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
>  {
>  	struct cs_etm_packet_queue *packet_queue;
>  
> -	if (!etmq->pending_timestamp)
> +	if (!etmq->pending_timestamp_chan_id)
>  		return 0;
>  
>  	if (trace_chan_id)
> -		*trace_chan_id = etmq->pending_timestamp;
> +		*trace_chan_id = etmq->pending_timestamp_chan_id;
>  
>  	packet_queue = cs_etm__etmq_get_packet_queue(etmq,
> -						     etmq->pending_timestamp);
> +						     etmq->pending_timestamp_chan_id);
>  	if (!packet_queue)
>  		return 0;
>  
>  	/* Acknowledge pending status */
> -	etmq->pending_timestamp = 0;
> +	etmq->pending_timestamp_chan_id = 0;
>  
>  	/* See function cs_etm_decoder__do_{hard|soft}_timestamp() */
> -	return packet_queue->timestamp;
> +	return packet_queue->cs_timestamp;
>  }
>  
>  static void cs_etm__clear_packet_queue(struct cs_etm_packet_queue *queue)
> @@ -814,7 +812,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
>  	int ret = 0;
>  	unsigned int cs_queue_nr;
>  	u8 trace_chan_id;
> -	u64 timestamp;
> +	u64 cs_timestamp;
>  	struct cs_etm_queue *etmq = queue->priv;
>  
>  	if (list_empty(&queue->head) || etmq)
> @@ -854,7 +852,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
>  
>  		/*
>  		 * Run decoder on the trace block.  The decoder will stop when
> -		 * encountering a timestamp, a full packet queue or the end of
> +		 * encountering a CS timestamp, a full packet queue or the end of
>  		 * trace for that block.
>  		 */
>  		ret = cs_etm__decode_data_block(etmq);
> @@ -865,10 +863,10 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
>  		 * Function cs_etm_decoder__do_{hard|soft}_timestamp() does all
>  		 * the timestamp calculation for us.
>  		 */
> -		timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
> +		cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
>  
>  		/* We found a timestamp, no need to continue. */
> -		if (timestamp)
> +		if (cs_timestamp)
>  			break;
>  
>  		/*
> @@ -892,7 +890,7 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
>  	 * queue and will be processed in cs_etm__process_queues().
>  	 */
>  	cs_queue_nr = TO_CS_QUEUE_NR(queue_nr, trace_chan_id);
> -	ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, timestamp);
> +	ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, cs_timestamp);
>  out:
>  	return ret;
>  }
> @@ -2221,7 +2219,7 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
>  	int ret = 0;
>  	unsigned int cs_queue_nr, queue_nr;
>  	u8 trace_chan_id;
> -	u64 timestamp;
> +	u64 cs_timestamp;
>  	struct auxtrace_queue *queue;
>  	struct cs_etm_queue *etmq;
>  	struct cs_etm_traceid_queue *tidq;
> @@ -2283,9 +2281,9 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
>  		if (ret)
>  			goto out;
>  
> -		timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
> +		cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
>  
> -		if (!timestamp) {
> +		if (!cs_timestamp) {
>  			/*
>  			 * Function cs_etm__decode_data_block() returns when
>  			 * there is no more traces to decode in the current
> @@ -2308,7 +2306,7 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
>  		 * this queue/traceID.
>  		 */
>  		cs_queue_nr = TO_CS_QUEUE_NR(queue_nr, trace_chan_id);
> -		ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, timestamp);
> +		ret = auxtrace_heap__add(&etm->heap, cs_queue_nr, cs_timestamp);
>  	}
>  
>  out:
> @@ -2380,7 +2378,7 @@ static int cs_etm__process_event(struct perf_session *session,
>  				 struct perf_tool *tool)
>  {
>  	int err = 0;
> -	u64 timestamp;
> +	u64 sample_kernel_timestamp;
>  	struct cs_etm_auxtrace *etm = container_of(session->auxtrace,
>  						   struct cs_etm_auxtrace,
>  						   auxtrace);
> @@ -2394,11 +2392,11 @@ static int cs_etm__process_event(struct perf_session *session,
>  	}
>  
>  	if (sample->time && (sample->time != (u64) -1))
> -		timestamp = sample->time;
> +		sample_kernel_timestamp = sample->time;
>  	else
> -		timestamp = 0;
> +		sample_kernel_timestamp = 0;
>  
> -	if (timestamp || etm->timeless_decoding) {
> +	if (sample_kernel_timestamp || etm->timeless_decoding) {
>  		err = cs_etm__update_queues(etm);
>  		if (err)
>  			return err;
> diff --git a/tools/perf/util/cs-etm.h b/tools/perf/util/cs-etm.h
> index 36428918411e..d65c7b19407d 100644
> --- a/tools/perf/util/cs-etm.h
> +++ b/tools/perf/util/cs-etm.h
> @@ -171,8 +171,8 @@ struct cs_etm_packet_queue {
>  	u32 head;
>  	u32 tail;
>  	u32 instr_count;
> -	u64 timestamp;
> -	u64 next_timestamp;
> +	u64 cs_timestamp;
> +	u64 next_cs_timestamp;
>  	struct cs_etm_packet packet_buffer[CS_ETM_PACKET_MAX_BUFFER];
>  };
>  
> -- 
> 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/2] perf cs-etm: Set time on synthesised samples to preserve ordering

[James Clark]

The following attribute is set when synthesising samples in
timed decoding mode:

    attr.sample_type |= PERF_SAMPLE_TIME;

This results in new samples that appear to have timestamps but
because we don't assign any timestamps to the samples, when the
resulting inject file is opened again, the synthesised samples
will be on the wrong side of the MMAP or COMM events.

For example, this results in the samples being associated with
the perf binary, rather than the target of the record:

    perf record -e cs_etm/@tmc_etr0/u top
    perf inject -i perf.data -o perf.inject --itrace=i100il
    perf report -i perf.inject

Where 'Command' == perf should show as 'top':

    # Overhead  Command  Source Shared Object  Source Symbol           Target Symbol           Basic Block Cycles
    # ........  .......  ....................  ......................  ......................  ..................
    #
        31.08%  perf     [unknown]             [.] 0x000000000040c3f8  [.] 0x000000000040c3e8  -

If the perf.data file is opened directly with perf, without the
inject step, then this already works correctly because the
events are synthesised after the COMM and MMAP events and
no second sorting happens. Re-sorting only happens when opening
the perf.inject file for the second time so timestamps are
needed.

Using the timestamp from the AUX record mirrors the current
behaviour when opening directly with perf, because the events
are generated on the call to cs_etm__process_queues().

The ETM trace could optionally contain time stamps, but there is
no way to correlate this with the kernel time. So, the best available
time value is that of the AUX_RECORD header. This patch uses
the timestamp from the header for all the samples. The ordering of the
samples are implicit in the trace and thus is fine with respect to
relative ordering.

Acked-by: Suzuki K Poulos <suzuki.poulose@arm.com>
Reviewed-by: Leo Yan <leo.yan@linaro.org>
Reviewed-by: Mathieu Poirier <mathieu.poirier@linaro.org>
Co-developed-by: Al Grant <al.grant@arm.com>
Signed-off-by: Al Grant <al.grant@arm.com>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/util/cs-etm.c | 15 +++++++++++++--
 1 file changed, 13 insertions(+), 2 deletions(-)

diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index 533f6f2f0685..153fb8393e6e 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -54,6 +54,7 @@ struct cs_etm_auxtrace {
 	u8 sample_instructions;
 
 	int num_cpu;
+	u64 latest_kernel_timestamp;
 	u32 auxtrace_type;
 	u64 branches_sample_type;
 	u64 branches_id;
@@ -1192,6 +1193,8 @@ static int cs_etm__synth_instruction_sample(struct cs_etm_queue *etmq,
 	event->sample.header.misc = cs_etm__cpu_mode(etmq, addr);
 	event->sample.header.size = sizeof(struct perf_event_header);
 
+	if (!etm->timeless_decoding)
+		sample.time = etm->latest_kernel_timestamp;
 	sample.ip = addr;
 	sample.pid = tidq->pid;
 	sample.tid = tidq->tid;
@@ -1248,6 +1251,8 @@ static int cs_etm__synth_branch_sample(struct cs_etm_queue *etmq,
 	event->sample.header.misc = cs_etm__cpu_mode(etmq, ip);
 	event->sample.header.size = sizeof(struct perf_event_header);
 
+	if (!etm->timeless_decoding)
+		sample.time = etm->latest_kernel_timestamp;
 	sample.ip = ip;
 	sample.pid = tidq->pid;
 	sample.tid = tidq->tid;
@@ -2412,9 +2417,15 @@ static int cs_etm__process_event(struct perf_session *session,
 	else if (event->header.type == PERF_RECORD_SWITCH_CPU_WIDE)
 		return cs_etm__process_switch_cpu_wide(etm, event);
 
-	if (!etm->timeless_decoding &&
-	    event->header.type == PERF_RECORD_AUX)
+	if (!etm->timeless_decoding && event->header.type == PERF_RECORD_AUX) {
+		/*
+		 * Record the latest kernel timestamp available in the header
+		 * for samples so that synthesised samples occur from this point
+		 * onwards.
+		 */
+		etm->latest_kernel_timestamp = sample_kernel_timestamp;
 		return cs_etm__process_queues(etm);
+	}
 
 	return 0;
 }
-- 
2.28.0

[PATCH v3 2/2] perf cs-etm: Set time on synthesised samples to preserve ordering

[James Clark]

The following attribute is set when synthesising samples in
timed decoding mode:

    attr.sample_type |= PERF_SAMPLE_TIME;

This results in new samples that appear to have timestamps but
because we don't assign any timestamps to the samples, when the
resulting inject file is opened again, the synthesised samples
will be on the wrong side of the MMAP or COMM events.

For example, this results in the samples being associated with
the perf binary, rather than the target of the record:

    perf record -e cs_etm/@tmc_etr0/u top
    perf inject -i perf.data -o perf.inject --itrace=i100il
    perf report -i perf.inject

Where 'Command' == perf should show as 'top':

    # Overhead  Command  Source Shared Object  Source Symbol           Target Symbol           Basic Block Cycles
    # ........  .......  ....................  ......................  ......................  ..................
    #
        31.08%  perf     [unknown]             [.] 0x000000000040c3f8  [.] 0x000000000040c3e8  -

If the perf.data file is opened directly with perf, without the
inject step, then this already works correctly because the
events are synthesised after the COMM and MMAP events and
no second sorting happens. Re-sorting only happens when opening
the perf.inject file for the second time so timestamps are
needed.

Using the timestamp from the AUX record mirrors the current
behaviour when opening directly with perf, because the events
are generated on the call to cs_etm__process_queues().

The ETM trace could optionally contain time stamps, but there is
no way to correlate this with the kernel time. So, the best available
time value is that of the AUX_RECORD header. This patch uses
the timestamp from the header for all the samples. The ordering of the
samples are implicit in the trace and thus is fine with respect to
relative ordering.

Acked-by: Suzuki K Poulos <suzuki.poulose@arm.com>
Reviewed-by: Leo Yan <leo.yan@linaro.org>
Reviewed-by: Mathieu Poirier <mathieu.poirier@linaro.org>
Co-developed-by: Al Grant <al.grant@arm.com>
Signed-off-by: Al Grant <al.grant@arm.com>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/util/cs-etm.c | 15 +++++++++++++--
 1 file changed, 13 insertions(+), 2 deletions(-)

diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index 533f6f2f0685..153fb8393e6e 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -54,6 +54,7 @@ struct cs_etm_auxtrace {
 	u8 sample_instructions;
 
 	int num_cpu;
+	u64 latest_kernel_timestamp;
 	u32 auxtrace_type;
 	u64 branches_sample_type;
 	u64 branches_id;
@@ -1192,6 +1193,8 @@ static int cs_etm__synth_instruction_sample(struct cs_etm_queue *etmq,
 	event->sample.header.misc = cs_etm__cpu_mode(etmq, addr);
 	event->sample.header.size = sizeof(struct perf_event_header);
 
+	if (!etm->timeless_decoding)
+		sample.time = etm->latest_kernel_timestamp;
 	sample.ip = addr;
 	sample.pid = tidq->pid;
 	sample.tid = tidq->tid;
@@ -1248,6 +1251,8 @@ static int cs_etm__synth_branch_sample(struct cs_etm_queue *etmq,
 	event->sample.header.misc = cs_etm__cpu_mode(etmq, ip);
 	event->sample.header.size = sizeof(struct perf_event_header);
 
+	if (!etm->timeless_decoding)
+		sample.time = etm->latest_kernel_timestamp;
 	sample.ip = ip;
 	sample.pid = tidq->pid;
 	sample.tid = tidq->tid;
@@ -2412,9 +2417,15 @@ static int cs_etm__process_event(struct perf_session *session,
 	else if (event->header.type == PERF_RECORD_SWITCH_CPU_WIDE)
 		return cs_etm__process_switch_cpu_wide(etm, event);
 
-	if (!etm->timeless_decoding &&
-	    event->header.type == PERF_RECORD_AUX)
+	if (!etm->timeless_decoding && event->header.type == PERF_RECORD_AUX) {
+		/*
+		 * Record the latest kernel timestamp available in the header
+		 * for samples so that synthesised samples occur from this point
+		 * onwards.
+		 */
+		etm->latest_kernel_timestamp = sample_kernel_timestamp;
 		return cs_etm__process_queues(etm);
+	}
 
 	return 0;
 }
-- 
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/2] perf cs-etm: Set time on synthesised samples to preserve ordering

[Mathieu Poirier]

On Mon, May 10, 2021 at 05:32:46PM +0300, James Clark wrote:
> Changes since v2:
>   * Collect acked and reviewed-by tags from v1 that were
>     missed in v2
>   * Add comment and commit message suggestions from Suzuki
>   * Rebase onto next-20210510 (also applies to perf/core)
> 
> Thanks
> James
>

Arnaldo,

Please condiser for inclusion in your tree.

Thanks,
Mathieu
 
> 
> James Clark (2):
>   perf cs-etm: Refactor timestamp variable names
>   perf cs-etm: Set time on synthesised samples to preserve ordering
> 
>  .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 18 +++---
>  tools/perf/util/cs-etm.c                      | 57 +++++++++++--------
>  tools/perf/util/cs-etm.h                      |  4 +-
>  3 files changed, 44 insertions(+), 35 deletions(-)
> 
> -- 
> 2.28.0
> 

Re: [PATCH v3 0/2] perf cs-etm: Set time on synthesised samples to preserve ordering

[Mathieu Poirier]

On Mon, May 10, 2021 at 05:32:46PM +0300, James Clark wrote:
> Changes since v2:
>   * Collect acked and reviewed-by tags from v1 that were
>     missed in v2
>   * Add comment and commit message suggestions from Suzuki
>   * Rebase onto next-20210510 (also applies to perf/core)
> 
> Thanks
> James
>

Arnaldo,

Please condiser for inclusion in your tree.

Thanks,
Mathieu
 
> 
> James Clark (2):
>   perf cs-etm: Refactor timestamp variable names
>   perf cs-etm: Set time on synthesised samples to preserve ordering
> 
>  .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 18 +++---
>  tools/perf/util/cs-etm.c                      | 57 +++++++++++--------
>  tools/perf/util/cs-etm.h                      |  4 +-
>  3 files changed, 44 insertions(+), 35 deletions(-)
> 
> -- 
> 2.28.0
> 

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