Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Subject: Re: [RFC PATCH] perf cs-etm: Handle valid-but-zero timestamps
To:     Mike Leach <mike.leach@linaro.org>
Cc:     Coresight ML <coresight@lists.linaro.org>,
        Mathieu Poirier <mathieu.poirier@linaro.org>,
        Al Grant <al.grant@arm.com>, branislav.rankov@arm.com,
        Denis Nikitin <denik@chromium.org>,
        "Suzuki K. Poulose" <suzuki.poulose@arm.com>,
        Anshuman Khandual <anshuman.khandual@arm.com>,
        Leo Yan <leo.yan@linaro.org>,
        Mark Rutland <mark.rutland@arm.com>,
        Alexander Shishkin <alexander.shishkin@linux.intel.com>,
        Jiri Olsa <jolsa@redhat.com>,
        Namhyung Kim <namhyung@kernel.org>,
        John Garry <john.garry@huawei.com>,
        Will Deacon <will@kernel.org>,
        linux-arm-kernel <linux-arm-kernel@lists.infradead.org>,
        linux-perf-users@vger.kernel.org,
        Linux Kernel Mailing List <linux-kernel@vger.kernel.org>
References: <20210507095814.17933-1-james.clark@arm.com>
 <3926c523-3fdb-66de-8b9c-b68290a5053e@arm.com>
 <CAJ9a7VjAvr9uKYqo9VJhFRB74vt6Jxf0G+Fm2OFm-dxAVdbpsw@mail.gmail.com>
From:   James Clark <james.clark@arm.com>
Message-ID: <b4407fb2-c393-9e85-acaa-80b30b4783ec@arm.com>
Date:   Tue, 11 May 2021 13:07:45 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101
 Thunderbird/68.10.0
MIME-Version: 1.0
In-Reply-To: <CAJ9a7VjAvr9uKYqo9VJhFRB74vt6Jxf0G+Fm2OFm-dxAVdbpsw@mail.gmail.com>
Content-Type: text/plain; charset=utf-8
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Precedence: bulk


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@arm.com> 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@chromium.org>
>>> Signed-off-by: Denis Nikitin <denik@chromium.org>
>>> Signed-off-by: James Clark <james.clark@arm.com>
>>> ---
>>>  .../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
>>>
> 
> 
>