[RFC PATCH] perf cs-etm: Handle valid-but-zero timestamps

[James Clark]

On 10/05/2021 08:39, Leo Yan wrote:
> Hi James,
> 

[...]
> 
>>> 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..947e44413c6e 100644
>>> --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
>>> +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
>>> @@ -320,7 +320,10 @@ 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->cs_timestamp = elem->timestamp - packet_queue->instr_count;
>>> +	if (packet_queue->instr_count >= elem->timestamp)
>>> +		packet_queue->cs_timestamp = 0;
>>> +	else
>>> +		packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
> 
> Actually here have two situations: one case is "elem->timestamp" is zero,
> another case is the overflow for "elem->timestamp".
> 
> So the change should be like:
> 
>    if (!elem->timestamp)
>        packet_queue->cs_timestamp = 0;
>    else if (packet_queue->instr_count >= elem->timestamp)
>        /* handle overflow? */
>    else
>       packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
> 
> It's better to think about how to handle the overflow in this case.

Do you have any idea about what to do in the overflow case? I think I will submit a
new patchset that makes the new 'Z' timeless --itrace option work, because that also
fixes this issue, without having to do the original workaround change in this RFC.

But I'd also like to fix this overflow because it masks the issue by making non-zero
timestamps appear even though they aren't valid ones.

I was thinking that printing a warning in the overflow case would work, but then I would
also print a warning for the zero timestamps, and that would make just a single case,
rather than two. Unless we just have slightly different warning text?

Something like this? Without the zero timestamp issue, the underflow issue probably wouldn't
be encountered. But at least there would be some visibility if it did:

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..5d8abccd34ab 100644
--- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
+++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
@@ -17,6 +17,7 @@
 
 #include "cs-etm.h"
 #include "cs-etm-decoder.h"
+#include "debug.h"
 #include "intlist.h"
 
 /* use raw logging */
@@ -294,9 +295,11 @@ 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;
+       static bool warned_timestamp_zero = false;
 
        /* First get the packet queue for this traceID */
        packet_queue = cs_etm__etmq_get_packet_queue(etmq, trace_chan_id);
@@ -320,7 +323,20 @@ 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;
+       if (!elem->timestamp) {
+               packet_queue->timestamp = 0;
+               if (!warned_timestamp_zero) {
+                       pr_err("Zero Coresight timestamp found at Idx:%" OCSD_TRC_IDX_STR
+                               ". Decoding may be improved with --itrace=Z...\n", indx);
+                       warned_timestamp_zero = true;
+               }
+       }
+       else if (packet_queue->instr_count >= elem->timestamp) {
+               packet_queue->timestamp = 0;
+               pr_err("Timestamp calculation underflow at Idx:%" OCSD_TRC_IDX_STR "\n", indx);
+       }
+       else
+               packet_queue->timestamp = elem->timestamp - packet_queue->instr_count;
        packet_queue->next_timestamp = elem->timestamp;
        packet_queue->instr_count = 0;
 
@@ -542,7 +558,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 +595,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,


James

> 
> Thanks,
> Leo
>