Re: [PATCH v5 8/8] perf: cs-etm: Ensure that Coresight timestamps don't go backwards

From: Arnaldo Carvalho de Melo
Date: Fri Jan 20 2023 - 12:12:40 EST

Em Fri, Jan 20, 2023 at 02:37:01PM +0000, James Clark escreveu:
> There are some edge cases around estimated timestamps that can result
> in them going backwards.
>
> One is that after a discontinuity, the last used timestamp is set to 0.
> The duration of the next range is then subtracted which could result in
> an earlier timestamp than the last instruction. Fix this by not
> resetting the last timestamp used on a discontinuity, and make sure that
> new estimated timestamps are clamped to be later than that.
>
> Another case is that estimated timestamps could compound over time to
> end up being more than the next real timestamp in the trace. Fix this by
> clamping the estimates in cs_etm_decoder__do_soft_timestamp() to be no
> later than it.
>
> cs_etm_decoder__do_soft_timestamp() also updated next_cs_timestamp,
> which meant that the next real timestamp was lost and not stored
> anywhere. Fix that by only updating cs_timestamp for estimates and keep
> next_cs_timestamp untouched.
>
> Finally, use next_cs_timestamp to signify if a timestamp has been
> received previously. Because cs_timestamp has the first range
> subtracted, it could technically go to 0 which would break the logic.
>
> Testing
> =======
>
> It can be verified that timestamps don't go backwards when tracing on a
> single core with the following commands. Across multiple cores it's
> expected that timestamps are interleaved:
>
> $ perf record -e cs_etm/@tmc_etr0/k -C 4 taskset -c 4 sleep 1
> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent > itrace
> $ sed 's/://g' itrace | awk -F ' ' ' { print $4 } ' | awk '{ if ($1 < prev) { print "line:" NR " " $0 } {prev=$1}}'

Trying:

root@roc-rk3399-pc:~# uname -a
Linux roc-rk3399-pc 6.1.0-rc5-00123-g4dd7ff4a0311 #2 SMP PREEMPT Wed Nov 16 19:55:11 UTC 2022 aarch64 aarch64 aarch64 GNU/Linux
root@roc-rk3399-pc:~#
root@roc-rk3399-pc:~# perf record -e cs_etm/@tmc_etr0/k -C 4 taskset -c 4 sleep 1
failed to set sink "tmc_etr0" on event cs_etm/@tmc_etr0/k with 2 (No such file or directory)
root@roc-rk3399-pc:~#

We could have a better message at some point, right? :-)

Something like:

root@roc-rk3399-pc:~# perf record -e cs_etm/@tmc_etr0/k -C 4 taskset -c 4 sleep 1
This system lacks the CoreSight component.
root@roc-rk3399-pc:~#

Anyway, applied the patches and test building now.

- Arnaldo

> Reported-by: Tanmay Jagdale <tanmay@xxxxxxxxxxx>
> Signed-off-by: James Clark <james.clark@xxxxxxx>
> ---
> .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 29 ++++++++++++-------
> 1 file changed, 19 insertions(+), 10 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 440fe844ed17..63afa2d05b46 100644
> --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> @@ -283,15 +283,17 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
> struct cs_etm_packet_queue *packet_queue,
> const uint8_t trace_chan_id)
> {
> + u64 estimated_ts;
> +
> /* No timestamp packet has been received, nothing to do */
> - if (!packet_queue->cs_timestamp)
> + if (!packet_queue->next_cs_timestamp)
> return OCSD_RESP_CONT;
>
> - packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
> + estimated_ts = packet_queue->cs_timestamp +
> + cs_etm_decoder__dec_instr_count_to_ns(&packet_queue->instr_count);
>
> - /* Estimate the timestamp for the next range packet */
> - packet_queue->next_cs_timestamp +=
> - cs_etm_decoder__dec_instr_count_to_ns(&packet_queue->instr_count);
> + /* Estimated TS can never be higher than the next real one in the trace */
> + packet_queue->cs_timestamp = min(packet_queue->next_cs_timestamp, estimated_ts);
>
> /* Tell the front end which traceid_queue needs attention */
> cs_etm__etmq_set_traceid_queue_timestamp(etmq, trace_chan_id);
> @@ -307,6 +309,7 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
> {
> struct cs_etm_packet_queue *packet_queue;
> u64 converted_timestamp;
> + u64 estimated_first_ts;
>
> /* First get the packet queue for this traceID */
> packet_queue = cs_etm__etmq_get_packet_queue(etmq, trace_chan_id);
> @@ -325,7 +328,12 @@ 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->cs_timestamp) {
> + if (packet_queue->next_cs_timestamp) {
> + /*
> + * What was next is now where new ranges start from, overwriting
> + * any previous estimate in cs_timestamp
> + */
> + packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
> packet_queue->next_cs_timestamp = converted_timestamp;
> return OCSD_RESP_CONT;
> }
> @@ -355,10 +363,12 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
> * 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.
> + * executed to the timestamp. Don't estimate earlier than the last used
> + * timestamp though.
> */
> - packet_queue->cs_timestamp = converted_timestamp -
> - (packet_queue->instr_count / INSTR_PER_NS);
> + estimated_first_ts = converted_timestamp -
> + (packet_queue->instr_count / INSTR_PER_NS);
> + packet_queue->cs_timestamp = max(packet_queue->cs_timestamp, estimated_first_ts);
> }
> packet_queue->next_cs_timestamp = converted_timestamp;
> packet_queue->instr_count = 0;
> @@ -373,7 +383,6 @@ 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->cs_timestamp = 0;
> packet_queue->next_cs_timestamp = 0;
> packet_queue->instr_count = 0;
> }
> --
> 2.25.1
>

--

- Arnaldo