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

[James Clark]

On 07/05/2021 17:09, Mike Leach wrote:
> Hi James,
> 
> 1) Not sure about this particular target - but previously all 0
> timestamps have been the result of not enabling a clock or the
> coresight timestamp generator.
> 
> 2) Given that you can synthesise timestamps when all the values are
> all 0 - does this not imply that they could be synthesised when they
> are not present at all?

Yes they could, perhaps we could change our command line arguments to remove
recording of timestamps completely. But I think that the auto enabling of
timestamps for per-cpu mode is only additive so there is no way to disable
it on the command line.

Perhaps we could make a change there instead to make the event configuration more flexible.

There is a similar concept with the --timestamp argument where it has both
"not set" and "set, but set to false" variables to distinguish between when the user hasn't
provided anything and when they've provided the negative:

	OPT_BOOLEAN_SET('T', "timestamp", &record.opts.sample_time,
			&record.opts.sample_time_set,

opts.sample_time is whether timestamps are on or not and
opts.sample_time_set is whether the user provided any argument, true or false.

Thanks
James

> 
> Cheers
> 
> Mike
> 
> On Fri, 7 May 2021 at 11:02, James Clark <james.clark@xxxxxxx> wrote:
>>
>>
>>
>> On 07/05/2021 12:58, James Clark wrote:
>>> There is an intermittent issue on Trogdor devices that
>>> results in all Coresight timestamps having a value of zero.
>>
>> I've attached a file here that has the issue. From the dump you
>> can see the zero timestamps:
>>
>>         Idx:69; ID:10;  I_TIMESTAMP : Timestamp.; Updated val = 0x0
>>         Idx:71; ID:10;  I_ATOM_F1 : Atom format 1.; E
>>         Idx:72; ID:10;  I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFFFFE723C65824 ~[0x5824]
>>
>> This doesn't have an impact on decoding as they end up being
>> decoded in file order as in with timeless mode.
>>
>> James
>>
>>> Because zero is currently treated as "not found" rather
>>> than "found but zero", this breaks the decoding flow
>>> when it would otherwise work.
>>>
>>> This patch adds an out parameter and return code so
>>> the difference between zero and non-existent timestamps
>>> can be determined.
>>>
>>> There is also a change to fix an underflow.
>>>
>>> Although this is a workaround, the change is technically
>>> a valid way of writing the cs_etm__etmq_get_timestamp()
>>> function. It could have been written similarly to this
>>> without trying to work around this issue, so it's no less
>>> correct. But, because it's a workaround to a problem
>>> elsewhere, I will submit this as an RFC for feedback.
>>>
>>> This patch applies on top of the "[PATCH v2 0/2] perf
>>> cs-etm: Set time on synthesised samples to preserve ordering"
>>> patchset.
>>>
>>> Co-developed-by: Denis Nikitin <denik@xxxxxxxxxxxx>
>>> Signed-off-by: Denis Nikitin <denik@xxxxxxxxxxxx>
>>> Signed-off-by: James Clark <james.clark@xxxxxxx>
>>> ---
>>>  .../perf/util/cs-etm-decoder/cs-etm-decoder.c |  5 ++++-
>>>  tools/perf/util/cs-etm.c                      | 22 +++++++++----------
>>>  2 files changed, 15 insertions(+), 12 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 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;
>>>       packet_queue->next_cs_timestamp = elem->timestamp;
>>>       packet_queue->instr_count = 0;
>>>
>>> diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
>>> index e5c1a1b22a2a..1969921c406a 100644
>>> --- a/tools/perf/util/cs-etm.c
>>> +++ b/tools/perf/util/cs-etm.c
>>> @@ -210,13 +210,14 @@ void cs_etm__etmq_set_traceid_queue_timestamp(struct cs_etm_queue *etmq,
>>>       etmq->pending_timestamp_chan_id = trace_chan_id;
>>>  }
>>>
>>> -static u64 cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
>>> +static int cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
>>> +                                   u64 *timestamp,
>>>                                     u8 *trace_chan_id)
>>>  {
>>>       struct cs_etm_packet_queue *packet_queue;
>>>
>>>       if (!etmq->pending_timestamp_chan_id)
>>> -             return 0;
>>> +             return -ENODATA;
>>>
>>>       if (trace_chan_id)
>>>               *trace_chan_id = etmq->pending_timestamp_chan_id;
>>> @@ -224,13 +225,15 @@ static u64 cs_etm__etmq_get_timestamp(struct cs_etm_queue *etmq,
>>>       packet_queue = cs_etm__etmq_get_packet_queue(etmq,
>>>                                                    etmq->pending_timestamp_chan_id);
>>>       if (!packet_queue)
>>> -             return 0;
>>> +             return -ENODATA;
>>>
>>>       /* Acknowledge pending status */
>>>       etmq->pending_timestamp_chan_id = 0;
>>>
>>>       /* See function cs_etm_decoder__do_{hard|soft}_timestamp() */
>>> -     return packet_queue->cs_timestamp;
>>> +     if (timestamp)
>>> +             *timestamp = packet_queue->cs_timestamp;
>>> +     return 0;
>>>  }
>>>
>>>  static void cs_etm__clear_packet_queue(struct cs_etm_packet_queue *queue)
>>> @@ -864,11 +867,10 @@ static int cs_etm__setup_queue(struct cs_etm_auxtrace *etm,
>>>                * Function cs_etm_decoder__do_{hard|soft}_timestamp() does all
>>>                * the timestamp calculation for us.
>>>                */
>>> -             cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
>>> -
>>> -             /* We found a timestamp, no need to continue. */
>>> -             if (cs_timestamp)
>>> +             if (!cs_etm__etmq_get_timestamp(etmq, &cs_timestamp, &trace_chan_id)) {
>>> +                     /* We found a timestamp, no need to continue. */
>>>                       break;
>>> +             }
>>>
>>>               /*
>>>                * We didn't find a timestamp so empty all the traceid packet
>>> @@ -2286,9 +2288,7 @@ static int cs_etm__process_queues(struct cs_etm_auxtrace *etm)
>>>               if (ret)
>>>                       goto out;
>>>
>>> -             cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id);
>>> -
>>> -             if (!cs_timestamp) {
>>> +             if (cs_etm__etmq_get_timestamp(etmq, &cs_timestamp, &trace_chan_id)) {
>>>                       /*
>>>                        * Function cs_etm__decode_data_block() returns when
>>>                        * there is no more traces to decode in the current
>>>
> 
> 
>