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 X-Spam-Level: X-Spam-Status: No, score=-11.0 required=3.0 tests=BAYES_00,DKIMWL_WL_HIGH, DKIM_SIGNED,DKIM_VALID,HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_PATCH, MAILING_LIST_MULTI,NICE_REPLY_A,SPF_HELO_NONE,SPF_PASS,URIBL_BLOCKED, USER_AGENT_SANE_1 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 2DEFEC433B4 for ; Tue, 11 May 2021 13:58:16 +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 877C8613F7 for ; Tue, 11 May 2021 13:58:15 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 877C8613F7 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:In-Reply-To:MIME-Version:Date:Message-ID:From: References:Cc:To:Subject:Reply-To:Content-ID:Content-Description:Resent-Date: Resent-From:Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID:List-Owner; bh=q8+v8H+CVmcWjvpDg2vrZ7Gm5/Rp92zA1bSPlNOZ4Co=; b=GnU1qrbpBGV/qgADYePv1d64S OD7q/3Vl5c95OwbOrvik4kJ5++4cGrsMdW9gt1I40IHSIrFF7EZYWKjd+S3qy3KbRoSFScTcoVhvd XHt3cJcHiMGW4Y8wc53dhbenR1SMHHo0whYQeSviGwAcmaY2egHulkVk7g7G4UMJh8fUVItQme7Cy Rlo9t1OkUdmXOXC2Vll6KWnUarxSerJEH9HUZ9SWttqI00cxCpObZlwV1BmRGAT6GMinSeLX3bkl4 4D0qrZ7fSIhv9CTmj7tVEG+NQhwsXrTW0YWFUJJ+3Dqf/YC2zquOJBz4rgJoVSATlzUgQsOFJ/BlS mP9tsQxbw==; Received: from localhost ([::1] helo=desiato.infradead.org) by desiato.infradead.org with esmtp (Exim 4.94 #2 (Red Hat Linux)) id 1lgSsS-000J7q-EB; Tue, 11 May 2021 13:56:48 +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 1lgSpX-000IEw-L9 for linux-arm-kernel@desiato.infradead.org; Tue, 11 May 2021 13:53:47 +0000 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=infradead.org; s=bombadil.20210309; h=Content-Transfer-Encoding: Content-Type:In-Reply-To:MIME-Version:Date:Message-ID:From:References:Cc:To: Subject:Sender:Reply-To:Content-ID:Content-Description; bh=jM96kkXZnQ+ucwMD8GSlPg8jyZ0CWFEViFExRPLokco=; b=NU9g8U2P1fcQKU2oTf8/lMSMeW 6nwQpaJrRHRVH4QsXjryeY3k9lC1Jb6COQXgxLcFO6/KKnIaU2ojou4XqJDsIrB6mdfmp9KUdY4kP xWjrtWCM4f5EIGlx0nP0/5U5CrEi1/sYoMS5tACoLM3llWD4hbS5cA/dxAbXTKtY8I6s4hclVJCGx sbszxaITHpId4g35iPq0mifcR2dJYTF318G22fv8gVBQMp8aHVSGaC38kKnuPuUuIouMq6i1Yqq5b qajdzfJIv+B5K7EIvwnkxbVPpB6X7fXkDNNS0+52cKnp45m41/OGmE5j+zWtSjUg9DJVAmMSGrxC4 fo12v43A==; Received: from foss.arm.com ([217.140.110.172]) by bombadil.infradead.org with esmtp (Exim 4.94 #2 (Red Hat Linux)) id 1lgSpU-009e1X-LF for linux-arm-kernel@lists.infradead.org; Tue, 11 May 2021 13:53:46 +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 C4AC7101E; Tue, 11 May 2021 06:53:40 -0700 (PDT) Received: from [10.57.81.122] (unknown [10.57.81.122]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPSA id 561543F718; Tue, 11 May 2021 06:53:37 -0700 (PDT) Subject: Re: [RFC PATCH] perf cs-etm: Handle valid-but-zero timestamps To: Leo Yan 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 , 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 References: <20210507095814.17933-1-james.clark@arm.com> <3926c523-3fdb-66de-8b9c-b68290a5053e@arm.com> <20210510053904.GB4835@leoy-ThinkPad-X240s> From: James Clark Message-ID: Date: Tue, 11 May 2021 16:53:35 +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: <20210510053904.GB4835@leoy-ThinkPad-X240s> Content-Language: en-US X-CRM114-Version: 20100106-BlameMichelson ( TRE 0.8.0 (BSD) ) MR-646709E3 X-CRM114-CacheID: sfid-20210511_065344_835000_BA681975 X-CRM114-Status: GOOD ( 28.23 ) 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 On 10/05/2021 08:39, Leo Yan wrote: > Hi James, > [...] > >>> 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. Do you have any idea about what to do in the overflow case? I think I will submit a new patchset that makes the new 'Z' timeless --itrace option work, because that also fixes this issue, without having to do the original workaround change in this RFC. But I'd also like to fix this overflow because it masks the issue by making non-zero timestamps appear even though they aren't valid ones. I was thinking that printing a warning in the overflow case would work, but then I would also print a warning for the zero timestamps, and that would make just a single case, rather than two. Unless we just have slightly different warning text? Something like this? Without the zero timestamp issue, the underflow issue probably wouldn't be encountered. But at least there would be some visibility if it did: 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 059bcec3f651..5d8abccd34ab 100644 --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c @@ -17,6 +17,7 @@ #include "cs-etm.h" #include "cs-etm-decoder.h" +#include "debug.h" #include "intlist.h" /* use raw logging */ @@ -294,9 +295,11 @@ 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; + static bool warned_timestamp_zero = false; /* First get the packet queue for this traceID */ packet_queue = cs_etm__etmq_get_packet_queue(etmq, trace_chan_id); @@ -320,7 +323,20 @@ 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->timestamp = elem->timestamp - packet_queue->instr_count; + if (!elem->timestamp) { + packet_queue->timestamp = 0; + if (!warned_timestamp_zero) { + pr_err("Zero Coresight timestamp found at Idx:%" OCSD_TRC_IDX_STR + ". Decoding may be improved with --itrace=Z...\n", indx); + warned_timestamp_zero = true; + } + } + else if (packet_queue->instr_count >= elem->timestamp) { + packet_queue->timestamp = 0; + pr_err("Timestamp calculation underflow at Idx:%" OCSD_TRC_IDX_STR "\n", indx); + } + else + packet_queue->timestamp = elem->timestamp - packet_queue->instr_count; packet_queue->next_timestamp = elem->timestamp; packet_queue->instr_count = 0; @@ -542,7 +558,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 +595,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, James > > Thanks, > Leo > _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel