From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from bombadil.infradead.org (bombadil.infradead.org [198.137.202.133]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.lore.kernel.org (Postfix) with ESMTPS id 2B05CC05027 for ; Fri, 20 Jan 2023 17:15:55 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=lists.infradead.org; s=bombadil.20210309; h=Sender: Content-Transfer-Encoding:Content-Type:List-Subscribe:List-Help:List-Post: List-Archive:List-Unsubscribe:List-Id:In-Reply-To:MIME-Version:References: Message-ID:Subject:Cc:To:From:Date:Reply-To:Content-ID:Content-Description: Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID: List-Owner; bh=y48bnPq+KC+8JbxOi85fq0E5F3SIVhYcTXCJfqyEqRI=; b=hswgC7aCoCAoTR OD3hE4hiHvHCLemNmNotKP7/C8HIHyStHNGtzCm/vTJhzWMteB78NlYf7/v4vx8cifvee3o3o0fHh /7svRISAnil3RptEMex2P5kDyNJWkS2hoA7LvNanfzVgGLpguYFkMpsO+oKJyEn9WntF7Ndk9EIp8 A7U0te7QN7/K4ZsO0lN1S/hKVXe+q4y7V87Un5UqPpU0vhbV4Cw2Cx2UH8QSJpZ75nqz/izxzEBYJ aUt3o0Yqz6kdwVPrzz2HLTpPqTdu5l7fWxcBwEdPiZccP71EL/vDAiUY5ERDl4Fm3SvVWKDMVdsD5 wmKJh+PnJmAIHqaXoLkg==; Received: from localhost ([::1] helo=bombadil.infradead.org) by bombadil.infradead.org with esmtp (Exim 4.94.2 #2 (Red Hat Linux)) id 1pIuyW-00BU2r-7Y; Fri, 20 Jan 2023 17:14:48 +0000 Received: from casper.infradead.org ([2001:8b0:10b:1236::1]) by bombadil.infradead.org with esmtps (Exim 4.94.2 #2 (Red Hat Linux)) id 1pIuwO-00BT2q-KS for linux-arm-kernel@bombadil.infradead.org; Fri, 20 Jan 2023 17:12:37 +0000 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=infradead.org; s=casper.20170209; h=In-Reply-To:Content-Type:MIME-Version: References:Message-ID:Subject:Cc:To:From:Date:Sender:Reply-To: Content-Transfer-Encoding:Content-ID:Content-Description; bh=/U8a7fWwbob2zPr+8N55d8zj3q+OPdRkY/MZzwkWivI=; b=rpqmym1dT1T/Ss0SmsDjLVjdW9 NrILPb0q+XTBaZsyDshUdXYvuEpygrhDvv0Di4gpqTcZsm2z2PtjqAtci8WYZMKYlNp4/NWIM4ho1 dQOHTCA/OPmc/TqPmgySm57PejmS5zSgiRWAip1o6ZtGiLUEPhI8enEzuZ/Euq2vpmeSE8ijQKpY9 /JejCitJ2qqcBdZNQOFPWjFUTWtGJkQT+HZMwlbEiHhCDztmk5h0kkt3s575f8SkWs9ZhQue+9Gyj ABk53tO/3oq+FcccIzqDyfLdB2RG6fly/OKSMUApuk5WrOb36CACb8xBJrMrCq/R5dvrTbqn79srV rmWxzYCA==; Received: from [187.19.237.165] (helo=quaco.ghostprotocols.net) by casper.infradead.org with esmtpsa (Exim 4.94.2 #2 (Red Hat Linux)) id 1pIuwM-002Fma-6a; Fri, 20 Jan 2023 17:12:35 +0000 Received: by quaco.ghostprotocols.net (Postfix, from userid 1000) id E8B52405BE; Fri, 20 Jan 2023 14:12:30 -0300 (-03) Date: Fri, 20 Jan 2023 14:12:30 -0300 From: Arnaldo Carvalho de Melo To: James Clark 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 , Suzuki K Poulose , John Garry , Will Deacon , Peter Zijlstra , Ingo Molnar , Mark Rutland , Alexander Shishkin , Jiri Olsa , Namhyung Kim , 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 Message-ID: References: <20230120143702.4035046-1-james.clark@arm.com> <20230120143702.4035046-9-james.clark@arm.com> MIME-Version: 1.0 Content-Disposition: inline In-Reply-To: <20230120143702.4035046-9-james.clark@arm.com> X-Url: http://acmel.wordpress.com X-BeenThere: linux-arm-kernel@lists.infradead.org X-Mailman-Version: 2.1.34 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Sender: "linux-arm-kernel" Errors-To: linux-arm-kernel-bounces+linux-arm-kernel=archiver.kernel.org@lists.infradead.org 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:~# Anyway, applied the patches and test building now. - Arnaldo > Reported-by: Tanmay Jagdale > Signed-off-by: James Clark > --- > .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 29 ++++++++++++------- > 1 file changed, 19 insertions(+), 10 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 440fe844ed17..63afa2d05b46 100644 > --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c > +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c > @@ -283,15 +283,17 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq, > struct cs_etm_packet_queue *packet_queue, > const uint8_t trace_chan_id) > { > + u64 estimated_ts; > + > /* No timestamp packet has been received, nothing to do */ > - if (!packet_queue->cs_timestamp) > + if (!packet_queue->next_cs_timestamp) > return OCSD_RESP_CONT; > > - packet_queue->cs_timestamp = packet_queue->next_cs_timestamp; > + estimated_ts = packet_queue->cs_timestamp + > + cs_etm_decoder__dec_instr_count_to_ns(&packet_queue->instr_count); > > - /* Estimate the timestamp for the next range packet */ > - packet_queue->next_cs_timestamp += > - cs_etm_decoder__dec_instr_count_to_ns(&packet_queue->instr_count); > + /* Estimated TS can never be higher than the next real one in the trace */ > + packet_queue->cs_timestamp = min(packet_queue->next_cs_timestamp, estimated_ts); > > /* Tell the front end which traceid_queue needs attention */ > cs_etm__etmq_set_traceid_queue_timestamp(etmq, trace_chan_id); > @@ -307,6 +309,7 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq, > { > struct cs_etm_packet_queue *packet_queue; > u64 converted_timestamp; > + u64 estimated_first_ts; > > /* First get the packet queue for this traceID */ > packet_queue = cs_etm__etmq_get_packet_queue(etmq, trace_chan_id); > @@ -325,7 +328,12 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq, > * Function do_soft_timestamp() will report the value to the front end, > * hence asking the decoder to keep decoding rather than stopping. > */ > - if (packet_queue->cs_timestamp) { > + if (packet_queue->next_cs_timestamp) { > + /* > + * What was next is now where new ranges start from, overwriting > + * any previous estimate in cs_timestamp > + */ > + packet_queue->cs_timestamp = packet_queue->next_cs_timestamp; > packet_queue->next_cs_timestamp = converted_timestamp; > return OCSD_RESP_CONT; > } > @@ -355,10 +363,12 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq, > * or a discontinuity. Since timestamps packets are generated *after* > * range packets have been generated, we need to estimate the time at > * which instructions started by subtracting the number of instructions > - * executed to the timestamp. > + * executed to the timestamp. Don't estimate earlier than the last used > + * timestamp though. > */ > - packet_queue->cs_timestamp = converted_timestamp - > - (packet_queue->instr_count / INSTR_PER_NS); > + estimated_first_ts = converted_timestamp - > + (packet_queue->instr_count / INSTR_PER_NS); > + packet_queue->cs_timestamp = max(packet_queue->cs_timestamp, estimated_first_ts); > } > packet_queue->next_cs_timestamp = converted_timestamp; > packet_queue->instr_count = 0; > @@ -373,7 +383,6 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq, > static void > cs_etm_decoder__reset_timestamp(struct cs_etm_packet_queue *packet_queue) > { > - packet_queue->cs_timestamp = 0; > packet_queue->next_cs_timestamp = 0; > packet_queue->instr_count = 0; > } > -- > 2.25.1 > -- - Arnaldo _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel