From patchwork Mon May 17 13:17:41 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: James Clark X-Patchwork-Id: 12261955 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-17.1 required=3.0 tests=BAYES_00,DKIMWL_WL_HIGH, DKIM_SIGNED,DKIM_VALID,HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER, INCLUDES_PATCH,MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,URIBL_BLOCKED, USER_AGENT_GIT autolearn=unavailable autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 88D7AC433ED for ; Mon, 17 May 2021 13:24:44 +0000 (UTC) Received: from desiato.infradead.org (desiato.infradead.org [90.155.92.199]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id 0C2E461059 for ; Mon, 17 May 2021 13:24:44 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 0C2E461059 Authentication-Results: mail.kernel.org; dmarc=fail (p=none dis=none) header.from=arm.com Authentication-Results: mail.kernel.org; spf=none smtp.mailfrom=linux-arm-kernel-bounces+linux-arm-kernel=archiver.kernel.org@lists.infradead.org DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=lists.infradead.org; s=desiato.20200630; h=Sender:Content-Transfer-Encoding :Content-Type:List-Subscribe:List-Help:List-Post:List-Archive: List-Unsubscribe:List-Id:MIME-Version:References:In-Reply-To:Message-Id:Date: Subject:Cc:To:From:Reply-To:Content-ID:Content-Description:Resent-Date: Resent-From:Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID:List-Owner; bh=3IDbMAF5WqBZ/fV+P1jMu2BDe6JmfzQAi7umV2GWS4Y=; b=H9jrD2/OoR3YIS4nwe7ELTgEk wwrxdBFzqWYCy15actEPCQBGX/OOlDXF7d0/7L3YMoFbCjLfiB/3TbLUXQJlMi1tT1gQf/KeYYSgO Q7K8tfIgvMg2IUMs92nPbg4dzb6NMqo8DEdX1YHt32sYe1e0/Ot8S1xf9FmgdHEBXmXo0WUXmEgZ0 i/Uqs07zafcGISzPY+HrDWE22RM4ICsiiPf7kW4E/bpz8LeOvItMBYF0y0x12wRH8yAjF4ay1a7Nb uWqosytR5szDqG+6cjrtg+BetsbrJp00cwvIbW/Ge2R7EhQN1J1MpGFl1nrR1Imta6pcruxO5r7To GUoScuxug==; Received: from localhost ([::1] helo=desiato.infradead.org) by desiato.infradead.org with esmtp (Exim 4.94 #2 (Red Hat Linux)) id 1lidCX-00F3Fh-5A; Mon, 17 May 2021 13:22:37 +0000 Received: from bombadil.infradead.org ([2607:7c80:54:e::133]) by desiato.infradead.org with esmtps (Exim 4.94 #2 (Red Hat Linux)) id 1lid8P-00F2Ry-Jj for linux-arm-kernel@desiato.infradead.org; Mon, 17 May 2021 13:18:14 +0000 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=infradead.org; s=bombadil.20210309; h=Content-Transfer-Encoding: MIME-Version:References:In-Reply-To:Message-Id:Date:Subject:Cc:To:From:Sender :Reply-To:Content-Type:Content-ID:Content-Description; bh=jdVkh25OQo38CI4uAQkJEqiGrMsnynJcox8q4KHzraU=; b=k7pigHTwl7pEgV4sAQt/i/N3LX elBTPaSrDkkr4fIRLiQR9y91BH0pClTIzbWps3mtrcvg+eJ/NZDe/9O6soQAkIyLdcgRvSu82LIa6 SJ8KcLRvJ4yizWc534VN1YjdBwnWVgOLeLXczGL2sd17FL2nTWvpbvRYWscnBfOXFuZmIX/7bv9nl MPxT5NT7XQIIxWEp8JmkFgCDMiDf9vJ3Axa5+U59GaDYlO59X4UDIrFhmULoMZs3P6ySjk99/JUxu Jb1Bn2hpS3p6U1xy6no0J7U2anHe+8pu89Avk7SESO8kKA8RlTolkeT8WhHU9mM80QYGD+ZJnlZwB BJg/O33Q==; Received: from foss.arm.com ([217.140.110.172]) by bombadil.infradead.org with esmtp (Exim 4.94 #2 (Red Hat Linux)) id 1lid8J-00DnBC-Dx for linux-arm-kernel@lists.infradead.org; Mon, 17 May 2021 13:18:12 +0000 Received: from usa-sjc-imap-foss1.foss.arm.com (unknown [10.121.207.14]) by usa-sjc-mx-foss1.foss.arm.com (Postfix) with ESMTP id 5D24A1424; Mon, 17 May 2021 06:18:06 -0700 (PDT) Received: from e121896.arm.com (unknown [10.57.3.96]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPA id 7D96B3F73B; Mon, 17 May 2021 06:18:03 -0700 (PDT) From: James Clark To: acme@kernel.org, mathieu.poirier@linaro.org, coresight@lists.linaro.org, leo.yan@linaro.org Cc: al.grant@arm.com, branislav.rankov@arm.com, denik@chromium.org, suzuki.poulose@arm.com, anshuman.khandual@arm.com, James Clark , Mike Leach , Mark Rutland , Alexander Shishkin , Jiri Olsa , Namhyung Kim , John Garry , Will Deacon , linux-arm-kernel@lists.infradead.org, linux-perf-users@vger.kernel.org, linux-kernel@vger.kernel.org Subject: [PATCH v3 3/3] perf cs-etm: Prevent and warn on underflows during timestamp calculation. Date: Mon, 17 May 2021 16:17:41 +0300 Message-Id: <20210517131741.3027-4-james.clark@arm.com> X-Mailer: git-send-email 2.28.0 In-Reply-To: <20210517131741.3027-1-james.clark@arm.com> References: <20210517131741.3027-1-james.clark@arm.com> MIME-Version: 1.0 X-CRM114-Version: 20100106-BlameMichelson ( TRE 0.8.0 (BSD) ) MR-646709E3 X-CRM114-CacheID: sfid-20210517_061807_583841_E1CE8488 X-CRM114-Status: GOOD ( 18.36 ) 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: , Sender: "linux-arm-kernel" Errors-To: linux-arm-kernel-bounces+linux-arm-kernel=archiver.kernel.org@lists.infradead.org When a zero timestamp is encountered, warn once. This is to make hardware or configuration issues visible. Also suggest that the issue can be worked around with the --itrace=Z option. When an underflow with a non-zero timestamp occurs, warn every time. This is an unexpected scenario, and with increasing timestamps, it's unlikely that it would occur more than once, therefore it should be ok to warn every time. Only try to calculate the timestamp by subtracting the instruction count if neither of the above cases are true. This makes attempting to decode files with zero timestamps in non-timeless mode more consistent. Currently it can half work if the timestamp wraps around and becomes non-zero, although the behavior is undefined and unpredictable. Reviewed-by: Leo Yan Signed-off-by: James Clark --- .../perf/util/cs-etm-decoder/cs-etm-decoder.c | 45 ++++++++++++++----- 1 file changed, 34 insertions(+), 11 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..3e1a05bc82cc 100644 --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c @@ -6,6 +6,7 @@ * Author: Mathieu Poirier */ +#include #include #include #include @@ -17,6 +18,7 @@ #include "cs-etm.h" #include "cs-etm-decoder.h" +#include "debug.h" #include "intlist.h" /* use raw logging */ @@ -294,7 +296,8 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq, static ocsd_datapath_resp_t cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq, const ocsd_generic_trace_elem *elem, - const uint8_t trace_chan_id) + const uint8_t trace_chan_id, + const ocsd_trc_index_t indx) { struct cs_etm_packet_queue *packet_queue; @@ -313,14 +316,33 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq, return OCSD_RESP_CONT; } - /* - * This is the first timestamp we've seen since the beginning of traces - * 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. - */ - packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count; + + if (!elem->timestamp) { + /* + * Zero timestamps can be seen due to misconfiguration or hardware bugs. + * Warn once, and don't try to subtract instr_count as it would result in an + * underflow. + */ + packet_queue->cs_timestamp = 0; + WARN_ONCE(true, "Zero Coresight timestamp found at Idx:%" OCSD_TRC_IDX_STR + ". Decoding may be improved with --itrace=Z...\n", indx); + } else if (packet_queue->instr_count > elem->timestamp) { + /* + * Sanity check that the elem->timestamp - packet_queue->instr_count would not + * result in an underflow. Warn and clamp at 0 if it would. + */ + packet_queue->cs_timestamp = 0; + pr_err("Timestamp calculation underflow at Idx:%" OCSD_TRC_IDX_STR "\n", indx); + } else { + /* + * This is the first timestamp we've seen since the beginning of traces + * 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. + */ + packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count; + } packet_queue->next_cs_timestamp = elem->timestamp; packet_queue->instr_count = 0; @@ -542,7 +564,7 @@ cs_etm_decoder__set_tid(struct cs_etm_queue *etmq, static ocsd_datapath_resp_t cs_etm_decoder__gen_trace_elem_printer( const void *context, - const ocsd_trc_index_t indx __maybe_unused, + const ocsd_trc_index_t indx, const u8 trace_chan_id __maybe_unused, const ocsd_generic_trace_elem *elem) { @@ -579,7 +601,8 @@ static ocsd_datapath_resp_t cs_etm_decoder__gen_trace_elem_printer( break; case OCSD_GEN_TRC_ELEM_TIMESTAMP: resp = cs_etm_decoder__do_hard_timestamp(etmq, elem, - trace_chan_id); + trace_chan_id, + indx); break; case OCSD_GEN_TRC_ELEM_PE_CONTEXT: resp = cs_etm_decoder__set_tid(etmq, packet_queue,