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;
Date:   Mon, 10 May 2021 13:39:04 +0800
From:   Leo Yan <leo.yan@linaro.org>
To:     James Clark <james.clark@arm.com>
Cc:     coresight@lists.linaro.org, mathieu.poirier@linaro.org,
        al.grant@arm.com, branislav.rankov@arm.com, denik@chromium.org,
        suzuki.poulose@arm.com, anshuman.khandual@arm.com,
        Mike Leach <mike.leach@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@lists.infradead.org,
        linux-perf-users@vger.kernel.org, linux-kernel@vger.kernel.org
Subject: Re: [RFC PATCH] perf cs-etm: Handle valid-but-zero timestamps
Message-ID: <20210510053904.GB4835@leoy-ThinkPad-X240s>
References: <20210507095814.17933-1-james.clark@arm.com>
 <3926c523-3fdb-66de-8b9c-b68290a5053e@arm.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <3926c523-3fdb-66de-8b9c-b68290a5053e@arm.com>
Precedence: bulk

Hi James,

On Fri, May 07, 2021 at 01:02:35PM +0300, James Clark 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.

Just remind, as Mike has mentioned that if the timestamp is zero, it
means the hardware setting for timestamp is not enabled properly.  So
for system wide or per CPU mode tracing, it's better to double check
what's the reason the timestamp is not enabled properly.

IIUC, this patch breaks the existed rational in the code.  Let's think
about there have 4 CPUs, every CPU has its own AUX trace buffer, and
when decode the trace data, it will use 4 queues to track the packets
and every queue has its timestamp.

  CPU0: cs_etm_queue -> ... -> packet_queue->timestamp
  CPU1: cs_etm_queue -> ... -> packet_queue->timestamp
  CPU2: cs_etm_queue -> ... -> packet_queue->timestamp
  CPU3: cs_etm_queue -> ... -> packet_queue->timestamp

The issue is if all CPUs' timestamp are zero, it's impossible to find
a way to synthesize samples in the right time order.

[...]

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

Thanks,
Leo