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

[Leo Yan]

On Tue, May 11, 2021 at 04:53:35PM +0300, James Clark wrote:

[...]

> Do you have any idea about what to do in the overflow case?

A quick thinking is to connect the kernel timestamp and correlate the
overflow case for CoreSight's timestamp, but this approach will cause
complexity.  And considering if the overflow occurs for not only once
before the new kernel timestamp is updated, it's hard to handle for
this case.  So seems to me, printing warning is a better choice.

> 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.

Good finding for these options for zero timestamps!

> 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?

Printing two different warnings is okay for me, which is more clear
for users.

> 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)

Do we really need the new argument "indx"?  If print "trace_chan_id",
can it give the info that the timestamp is attached to which tracer?

>  {
>         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;
> +               }

I think this warning and the next warning for overflow, both can use
the macro WARN_ONCE(), so you can avoid to add new variable
"warned_timestamp_zero".

Thanks,
Leo

> +       }
> +       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
> >