Messages in this thread Patch in this message | | | Date | Fri, 20 Jan 2023 14:12:30 -0300 | From | Arnaldo Carvalho de Melo <> | Subject | Re: [PATCH v5 8/8] perf: cs-etm: Ensure that Coresight timestamps don't go backwards |
| |
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@marvell.com> > Signed-off-by: James Clark <james.clark@arm.com> > --- > .../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
| |