Re: [PATCH v5 8/8] perf: cs-etm: Ensure that Coresight timestamps don't go backwards

From: James Clark <james.clark@arm.com>
To: Arnaldo Carvalho de Melo <acme@kernel.org>
Cc: linux-perf-users@vger.kernel.org, tanmay@marvell.com,
	leo.yan@linaro.org, mike.leach@linaro.org, sgoutham@marvell.com,
	gcherian@marvell.com, lcherian@marvell.com,
	bbhushan2@marvell.com,
	Mathieu Poirier <mathieu.poirier@linaro.org>,
	Suzuki K Poulose <suzuki.poulose@arm.com>,
	John Garry <john.g.garry@oracle.com>,
	Will Deacon <will@kernel.org>,
	Peter Zijlstra <peterz@infradead.org>,
	Ingo Molnar <mingo@redhat.com>,
	Mark Rutland <mark.rutland@arm.com>,
	Alexander Shishkin <alexander.shishkin@linux.intel.com>,
	Jiri Olsa <jolsa@kernel.org>, Namhyung Kim <namhyung@kernel.org>,
	coresight@lists.linaro.org, linux-arm-kernel@lists.infradead.org,
	linux-kernel@vger.kernel.org
Subject: Re: [PATCH v5 8/8] perf: cs-etm: Ensure that Coresight timestamps don't go backwards
Date: Mon, 23 Jan 2023 10:37:37 +0000	[thread overview]
Message-ID: <ec7502e6-b406-3997-c2a5-24f98e5c4854@arm.com> (raw)
In-Reply-To: <Y8rLfroSyYzgr5z9@kernel.org>


On 20/01/2023 17:12, Arnaldo Carvalho de Melo wrote:
> Em Fri, Jan 20, 2023 at 02:37:01PM +0000, James Clark escreveu:
>> There are some edge cases around estimated timestamps that can result
>> in them going backwards.
>>
>> One is that after a discontinuity, the last used timestamp is set to 0.
>> The duration of the next range is then subtracted which could result in
>> an earlier timestamp than the last instruction. Fix this by not
>> resetting the last timestamp used on a discontinuity, and make sure that
>> new estimated timestamps are clamped to be later than that.
>>
>> Another case is that estimated timestamps could compound over time to
>> end up being more than the next real timestamp in the trace. Fix this by
>> clamping the estimates in cs_etm_decoder__do_soft_timestamp() to be no
>> later than it.
>>
>> cs_etm_decoder__do_soft_timestamp() also updated next_cs_timestamp,
>> which meant that the next real timestamp was lost and not stored
>> anywhere. Fix that by only updating cs_timestamp for estimates and keep
>> next_cs_timestamp untouched.
>>
>> Finally, use next_cs_timestamp to signify if a timestamp has been
>> received previously. Because cs_timestamp has the first range
>> subtracted, it could technically go to 0 which would break the logic.
>>
>> Testing
>> =======
>>
>> It can be verified that timestamps don't go backwards when tracing on a
>> single core with the following commands. Across multiple cores it's
>> expected that timestamps are interleaved:
>>
>>  $ perf record -e cs_etm/@tmc_etr0/k -C 4 taskset -c 4 sleep 1
>>  $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent > itrace
>>  $ sed 's/://g' itrace | awk -F ' ' ' { print $4 } ' | awk '{ if ($1 < prev) { print "line:" NR " " $0 } {prev=$1}}'
> 
> Trying:
> 
> root@roc-rk3399-pc:~# uname -a
> Linux roc-rk3399-pc 6.1.0-rc5-00123-g4dd7ff4a0311 #2 SMP PREEMPT Wed Nov 16 19:55:11 UTC 2022 aarch64 aarch64 aarch64 GNU/Linux
> root@roc-rk3399-pc:~#
> root@roc-rk3399-pc:~# perf record -e cs_etm/@tmc_etr0/k -C 4 taskset -c 4 sleep 1
> failed to set sink "tmc_etr0" on event cs_etm/@tmc_etr0/k with 2 (No such file or directory)
> root@roc-rk3399-pc:~#
> 
> We could have a better message at some point, right? :-)
> > Something like:
> 
> root@roc-rk3399-pc:~# perf record -e cs_etm/@tmc_etr0/k -C 4 taskset -c 4 sleep 1
> This system lacks the CoreSight component.
> root@roc-rk3399-pc:~#

Should be possible, I'm having a look now