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 vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id A0D20C54EBE for ; Wed, 11 Jan 2023 10:58:00 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S236243AbjAKK5i (ORCPT ); Wed, 11 Jan 2023 05:57:38 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:39762 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S238898AbjAKK44 (ORCPT ); Wed, 11 Jan 2023 05:56:56 -0500 Received: from foss.arm.com (foss.arm.com [217.140.110.172]) by lindbergh.monkeyblade.net (Postfix) with ESMTP id 5817016595; Wed, 11 Jan 2023 02:56:39 -0800 (PST) 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 20B2BFEC; Wed, 11 Jan 2023 02:57:21 -0800 (PST) Received: from [10.57.45.242] (unknown [10.57.45.242]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPSA id 046343F587; Wed, 11 Jan 2023 02:56:35 -0800 (PST) Message-ID: <5acce414-eabb-3d22-4907-da6b64b85a9c@arm.com> Date: Wed, 11 Jan 2023 10:56:34 +0000 MIME-Version: 1.0 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Thunderbird/102.4.2 Subject: Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps Content-Language: en-US To: Tanmay Jagdale , "linux-perf-users@vger.kernel.org" , "leo.yan@linaro.org" , "mike.leach@linaro.org" Cc: Sunil Kovvuri Goutham , George Cherian , Linu Cherian , Bharat Bhushan , Mathieu Poirier , Suzuki K Poulose , John Garry , Will Deacon , Peter Zijlstra , Ingo Molnar , Arnaldo Carvalho de Melo , Mark Rutland , Alexander Shishkin , Jiri Olsa , Namhyung Kim , "coresight@lists.linaro.org" , "linux-arm-kernel@lists.infradead.org" , "linux-kernel@vger.kernel.org" References: <20230103162042.423694-1-james.clark@arm.com> From: James Clark In-Reply-To: Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 10/01/2023 16:42, Tanmay Jagdale wrote: [...] >> >> base-commit: 09e6f9f98370be9a9f8978139e0eb1be87d1125f > I have tested this patch set on our platform and able to see updated > timestamp values in perf script's output. > > $ perf record -e cs_etm/cycacc,@tmc_etr0/k -C 9 taskset -c 9 sleep 2 > $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent > > At certain points noticed that hardware emits same timestamp packets > but with updated cycle count (CC) values. A small snippet of the log: > > Idx:100; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086A761C ~[0x761C] > Idx:103; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3d > Idx:107; ID:12; I_ATOM_F2 : Atom format 2.; EN > Idx:108; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3f > Idx:112; ID:12; I_ATOM_F1 : Atom format 1.; N > Idx:113; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x45 > Idx:116; ID:12; I_ATOM_F1 : Atom format 1.; E > Idx:117; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086B52D4 ~[0x152D4] > > Since the source of timestamp is the Generic Timer block and the CPUs > run at higher frequencies, this behaviour could be possible on high > performance ARM cores. > > Having consecutive timestamps with same value is resulting in a > slightly jumbled order (in nanosecs) in perf script's time column. > A snippet corresponding to the Coresight trace data mentioned above: > ... > perf 965/965 [001] 3182.286629044: instructions:k: return 0 ffff8000086a761c coresight_timeout+0xc8 > perf 965/965 [001] 3182.286629044: instructions:k: return 0 ffff8000086a7620 coresight_timeout+0xcc > perf 965/965 [001] 3182.286629046: instructions:k: jmp 0 ffff8000086a75c8 coresight_timeout+0x74 > perf 965/965 [001] 3182.286629046: instructions:k: jmp 0 ffff8000086a75cc coresight_timeout+0x78 > perf 965/965 [001] 3182.286629044: instructions:k: jcc 0 ffff8000086a75d0 coresight_timeout+0x7c > perf 965/965 [001] 3182.286629044: instructions:k: jcc 0 ffff8000086a75d4 coresight_timeout+0x80 > perf 965/965 [001] 3182.286629044: instructions:k: jcc 0 ffff8000086a75d8 coresight_timeout+0x84 > perf 965/965 [001] 3182.286629044: instructions:k: jcc 0 ffff8000086a75dc coresight_timeout+0x88 > perf 965/965 [001] 3182.286629044: instructions:k: jcc 0 ffff8000086a75e0 coresight_timeout+0x8c > perf 965/965 [001] 3182.286629044: instructions:k: jcc 0 ffff8000086a75e4 coresight_timeout+0x90 > perf 965/965 [001] 3182.286629044: instructions:k: jcc 0 ffff8000086a75e8 coresight_timeout+0x94 > perf 965/965 [001] 3182.286629044: instructions:k: jcc 0 ffff8000086a75ec coresight_timeout+0x98 > > Perf's do_soft_timestamp() logic in cs_etm_decoder.c file is incrementing > the HW timestamp based on instruction count. Since the next timestamp > also has the same value, it could be leading to this jumbled order. > > We would like to know if this has been observed on other platforms ? > And what could be a solution in SW for this ? Nice catch. If I'm understanding this correctly it looks like the issue is a combination of the cycle count in the packet being ignored by Perf, and the instruction count being reset to 0 when a new timestamp is received. It looks like it can be fixed by some combination of combining the cycle count and instruction count and maybe not resetting instruction count if the newly received timestamp is the same as the last one. I will look into this. We haven't noticed it on any other platforms, but we haven't been looking too closely at the timestamps until now. Perhaps I can add a test that checks if the trace in a known function goes in the correct time order. Thanks James