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 68A0ECA0ECA for ; Tue, 12 Sep 2023 10:58:08 +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:From:References:Cc:To: Subject:MIME-Version:Date:Message-ID:Reply-To:Content-ID:Content-Description: Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID: List-Owner; bh=U+Q/l3AiWfgJxEHeRxa1uhYbEy1EiBiAYPnDnShqovc=; b=458UUFiD+xhVU8 38tEJIn4tKoPlbitSa/sDGz/diDOFBXUQqW+zYTL7s8C1KnWKD2QEPgGvzYkCq0VYQxNGRhSkQ3oX XqRc/wlqGgbDIUCvvtXtEx382PtKtQW5KoBmR/O/Nh/0DWKDabEPQ+A4GR12U1BASQoC75rO/uALA jPqdA87UDhbbgFpXVGSR7bhtzMTF8qrcqsb1TOKtCp2I8TvHJOpYG6Y0KiMl1qfBTS/35J84rKfJx JAwwQWA/d+Q7D/tr9SIeLRrDYASQHTHxVxBgRaC9PtAx8JWkhQvLmp5cS2rzTOHByDgsX9bmNlZgp YfejjLMMW1YU6r7luM6Q==; Received: from localhost ([::1] helo=bombadil.infradead.org) by bombadil.infradead.org with esmtp (Exim 4.96 #2 (Red Hat Linux)) id 1qg15J-0033Jf-2w; Tue, 12 Sep 2023 10:57:33 +0000 Received: from foss.arm.com ([217.140.110.172]) by bombadil.infradead.org with esmtp (Exim 4.96 #2 (Red Hat Linux)) id 1qg15F-0033FO-2h for linux-arm-kernel@lists.infradead.org; Tue, 12 Sep 2023 10:57:31 +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 2CA7CC15; Tue, 12 Sep 2023 03:58:02 -0700 (PDT) Received: from [192.168.1.3] (unknown [172.31.20.19]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPSA id E69673F67D; Tue, 12 Sep 2023 03:57:22 -0700 (PDT) Message-ID: <48c40672-caab-68ef-cbd7-640f5a39e639@arm.com> Date: Tue, 12 Sep 2023 11:57:17 +0100 MIME-Version: 1.0 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Thunderbird/102.9.0 Subject: Re: [PATCH] perf cs-etm: Fix kernel timestamp handling Content-Language: en-US To: Leo Yan Cc: Arnaldo Carvalho de Melo , Suzuki K Poulose , Mike Leach , John Garry , Will Deacon , Peter Zijlstra , Ingo Molnar , Mark Rutland , Alexander Shishkin , Jiri Olsa , Namhyung Kim , Ian Rogers , Adrian Hunter , coresight@lists.linaro.org, linux-arm-kernel@lists.infradead.org, linux-perf-users@vger.kernel.org, linux-kernel@vger.kernel.org References: <20230910092413.53538-1-leo.yan@linaro.org> <04823db9-ed6c-0695-b9de-5a63bfa0aa5a@arm.com> <20230912015204.GA122656@leoy-huanghe> From: James Clark In-Reply-To: <20230912015204.GA122656@leoy-huanghe> X-CRM114-Version: 20100106-BlameMichelson ( TRE 0.8.0 (BSD) ) MR-646709E3 X-CRM114-CacheID: sfid-20230912_035729_988056_2B08E9C1 X-CRM114-Status: GOOD ( 48.78 ) 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 12/09/2023 02:52, Leo Yan wrote: > Hi James, > > On Mon, Sep 11, 2023 at 02:24:09PM +0100, James Clark wrote: > > [...] > >>> The current code can support both timestamp sources when synthesizing >>> samples. However, the decoding flow only relies on the hardware >>> timestamp. If the hardware timestamp is zero, it becomes impossible to >>> decode the trace data. Consequently, in this case, the commands below >>> won't output any samples: >>> >>> perf record -e cs_etm// --per-thread --timestamp -- ls >>> perf script >> >> Hi Leo, >> >> I couldn't reproduce this issue, even when hard coding the hardware >> timestamp to zero in cs_etm_decoder__do_hard_timestamp() like this: >> >> converted_timestamp = 0; > > I reproduced this issue on the Juno-r2 board, its "etm->has_virtual_ts" > is always false and Arm CoreSight timestamp packets are zeros. > > Besides set "converted_timestamp = 0", it might need to hard code > "etm->has_virtual_ts" to false? > >> I'm not sure why this would result in no samples being generated either, >> because we don't actually use the timestamps for anything yet [1]. We >> always wait until the very end of the file before decoding to ensure >> that all of the mmaps are loaded. And the timestamp is just assigned to >> the samples, but they shouldn't affect whether they are generated or not. >> >> Unless there is something else I'm missing? > > Let's review below code. > > cs_etm__queue_first_cs_timestamp() retrieves trace data and decodes it, > and breaks the while loop until it find the timestamp is not zero or no > trace data is avaliable. When the timestamp is always zero, the while > loop continues to drop the CoreSight trace data and don't synthesize > samples. > > cs_etm__queue_first_cs_timestamp() > { > ... > > while(1) { > ret = cs_etm__get_data_block(etmq); > if (ret <= 0) > goto out; > > ret = cs_etm__decode_data_block(etmq); > if (ret) > goto out; > > cs_timestamp = cs_etm__etmq_get_timestamp(etmq, &trace_chan_id); > /* We found a timestamp, no need to continue. */ > if (cs_timestamp) > break; > > cs_etm__clear_all_packet_queues(etmq); > } > } > Ah, I couldn't reproduce it because I was missing your other patch to add Coresight timestamps when Perf timestamps are requested. If I add that patch or force Coresight timestamps then I can reproduce the issue: $ perf record -e cs_etm/timestamp=1/ --per-thread --timestamp -- ls But when running perf script I get this warning: Zero Coresight timestamp found at Idx:39. Decoding may be improved by prepending 'Z' to your current --itrace arguments. And then if I force timeless mode like it says to do I get samples: $ perf script --itrace=Zi1000i I'm not sure if silently making it use the kernel timestamp for sorting makes sense, especially when zero hardware timestamps are a bug, and we already have a warning and a workaround for it. Also it would mean that you are requesting timestamps on a platform that isn't generating them. Maybe the fix could also just be to not request timestamps, and then it uses the timeless decoding flow that also works: $ perf record -e cs_etm/timestamp=0/ --per-thread --timestamp -- ls My worry is that mixing kernel and coresight timestamps for sorting could make the code confusing to reason about, and sorting based on a single static AUX timestamp doesn't make sense logically (it's almost like a hack where the side effect is to make it work). And there isn't really anything that there isn't already a workaround for. Unless you want to explicitly disable the "use the Z option" warning and make it work transparently? Which I'm not sure is the right thing to do. >> Also, in cs_etm__queue_first_cs_timestamp(), cs_timestamp is used for >> sorting the decoding order between CPUs, but if the hardware timestamp >> is 0, then it's 0 on all trace. > > Correct. > >> So the sorting would be the same if you change that to be the kernel >> timestamp. They're all still the same >> static number, but just a different number (because we wait until the >> end of the file, 'latest_kernel_timestamp' is always the timestamp of >> the last AUX event in the file). > > If we use the 'latest_kernel_timestamp' as timestamp, it's non-zero > timestamp rather than all timestamp '0'. Yes, 'latest_kernel_timestamp' > is a coarse kernel timestamp which is shared by all trace data recorded > in the AUX event, though it's a static number, it can allow us to break > the while loop mentioned above. > > I understand 'latest_kernel_timestamp' is inaccurate for sorting, but > as least now it exists in current code, quotes from util/cs-etm.c: > > /* > * Record the latest kernel timestamp available in the header > * for samples so that synthesised samples occur from this point > * onwards. > */ > if (sample->time && (sample->time != (u64)-1)) > etm->latest_kernel_timestamp = sample->time; > >> [1]: I still plan to change the decoding to decode up to the current >> time in the file, rather than waiting for the end of the file before >> starting. That way decoding trace when there were overlapping mmap >> regions in time will be more accurate. > > Thanks for heading up. I am not sure if I understand this correctly, > but seems to me it is a good thing to try for using overlapping mmap > events. > > Just a side topic, if an Arm platform connect the Arm timer counter to > Arm CoreSight, and detect virtual timestamp is false (thus > etm->has_virtual_ts is 0). I think this might happen on some legacy > platforms, can we use some ways to allow users to still use the Arm > CoreSight timestamp in this case? E.g. we can force set > etm->has_virtual_ts to 1 when user specify the config > '-e cs_etm/timestamp/'. > > Thanks, > Leo _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel