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}}'
Reported-by: Tanmay Jagdale <[email protected]>
Signed-off-by: James Clark <[email protected]>
---
.../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
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 <[email protected]>
> Signed-off-by: James Clark <[email protected]>
> ---
> .../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
On 20/01/2023 17:12, Arnaldo Carvalho de Melo wrote:
> 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:~#
Should be possible, I'm having a look now