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=-9.2 required=3.0 tests=BAYES_00,DKIMWL_WL_HIGH, DKIM_SIGNED,DKIM_VALID,HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS 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 62A4AC11F64 for ; Thu, 1 Jul 2021 13:35:48 +0000 (UTC) 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 mail.kernel.org (Postfix) with ESMTPS id 353F7613FD for ; Thu, 1 Jul 2021 13:35:48 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 353F7613FD Authentication-Results: mail.kernel.org; dmarc=fail (p=none dis=none) header.from=linaro.org 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=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=KnDJjY1VH5EhxQ/GvovVGLjNOtrzobsrM4obxMirRHU=; b=3/hfC+C69d4ssM I3BG28fTNZlK/+ZasOPcf1h0rJOUf0M8i5bArbtg6kryS6trU8q0Lmd/oiczJCUjaLObsON5nnnMr 2kSi8otQtGZzhuBzYlFqzuwxZsZm3hUEru3biXNjc095xFvSubStCrSDVcVW089BDd3D9YfsAhgSz wJcCInVhovPmboWij8sey9rA47dzEgmbZbqcXrY+UqJFtnSsRYfrtO1MD1ShFJszNGbfBAJkGNbza WEY/lmp2aQafpEQBtNlZxWukgfnkw1/ry2Uc71eutJG0VIcionyP7qvWTUjbAukszEap0zZlv+HrX wgqWSzdNOipjvfwojtIg==; Received: from localhost ([::1] helo=bombadil.infradead.org) by bombadil.infradead.org with esmtp (Exim 4.94.2 #2 (Red Hat Linux)) id 1lywpc-00HTzl-0b; Thu, 01 Jul 2021 13:34:16 +0000 Received: from mail-pf1-x42b.google.com ([2607:f8b0:4864:20::42b]) by bombadil.infradead.org with esmtps (Exim 4.94.2 #2 (Red Hat Linux)) id 1lywpY-00HTyj-El for linux-arm-kernel@lists.infradead.org; Thu, 01 Jul 2021 13:34:14 +0000 Received: by mail-pf1-x42b.google.com with SMTP id i6so5954244pfq.1 for ; Thu, 01 Jul 2021 06:34:11 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linaro.org; s=google; h=date:from:to:cc:subject:message-id:references:mime-version :content-disposition:in-reply-to; bh=SnACoHGHKKSUmroSwFVGCmNRDhzoxlH9nVuiVepkb1o=; b=zCKVemtDZL3ehp7PWxjcfKDxDN51pmQ2ck1pts0xLqfsFeTIRas88OmbvMIzA4dFvo M8C2rBowwV3bq02pJRqrx6XT6BjR29xCvuV7POzUMI64aKMRWLZ+0Zq3ucUE2jumf6iy S1rBKYMUWmMh68QFry//g+ZREkHkE1VYaIXTNCg2D4LXneXuiYJExU7IVu5QXgDJGeqa xccvbodoy4FwRziHM0OglEbzyC9lFbIW1M8fV1Yjwhn/Mjk3aSY8bxsyTzx33X/h3z57 AM/7uqC+nxvidyVV7fcMPb0xf5Oek8z+h27/YJPhcxOXeaX1PUr5tXsxCm5NUlkwx1b+ 7Lfw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:date:from:to:cc:subject:message-id:references :mime-version:content-disposition:in-reply-to; bh=SnACoHGHKKSUmroSwFVGCmNRDhzoxlH9nVuiVepkb1o=; b=UT4liapZyKoDZ9zLijeMM7pJBiYRALhT1w7J7DTUFpw/T+O2a4IycZBvwLadmjekh1 u2/kPDMqQOov+SEjsbR21ptEW9LRm4vgzCT1s6QIQGLq7ENNPJMW/SK207Ydo2iMtKUh hQpSOuo4kDIRpum//TOsCUXCk8IOCPOkSY8C9EMiZbVT1gzKOLnTSdjXAxt3CE9Dl6sv qTesEdixqBmeLml+J4iDq3X5mH/94wYiuPgdis+rhtuX8oVCb2Dra5eZpZIKsimsofmc DuH1SsT5kV26Fv+7POwKTp0hBi9wdlyYrFn7LzpiB0VENyhjL61FRkOjuhEkE7XimAuQ Nc8g== X-Gm-Message-State: AOAM533B+4H78uaScYozFID5oaIGfhiln6+ArVH6mxXOHpGVS4twSMHz fltJm+qt8z8rOEXOXpiqgc/SWg== X-Google-Smtp-Source: ABdhPJykFDVO5eAJi3DVkcgV0nKVtx9Poi5lkDhj2P0Tz4JkhKgYevSdgvCDB7Pae/1N5b7+cy/IBw== X-Received: by 2002:a62:4e96:0:b029:305:a36c:fc6 with SMTP id c144-20020a624e960000b0290305a36c0fc6mr35402pfb.70.1625146451190; Thu, 01 Jul 2021 06:34:11 -0700 (PDT) Received: from leoy-ThinkPad-X240s ([103.207.71.35]) by smtp.gmail.com with ESMTPSA id gl17sm10080799pjb.13.2021.07.01.06.34.06 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 01 Jul 2021 06:34:10 -0700 (PDT) Date: Thu, 1 Jul 2021 21:34:04 +0800 From: Leo Yan To: James Clark Cc: acme@kernel.org, mathieu.poirier@linaro.org, coresight@lists.linaro.org, al.grant@arm.com, branislav.rankov@arm.com, denik@chromium.org, suzuki.poulose@arm.com, anshuman.khandual@arm.com, Mike Leach , John Garry , Will Deacon , Mark Rutland , Alexander Shishkin , Jiri Olsa , Namhyung Kim , linux-arm-kernel@lists.infradead.org, linux-perf-users@vger.kernel.org, linux-kernel@vger.kernel.org Subject: Re: [PATCH] perf cs-etm: Delay decode of non-timeless data until cs_etm__flush_events() Message-ID: <20210701133404.GB91264@leoy-ThinkPad-X240s> References: <20210609130421.13934-1-james.clark@arm.com> MIME-Version: 1.0 Content-Disposition: inline In-Reply-To: <20210609130421.13934-1-james.clark@arm.com> X-CRM114-Version: 20100106-BlameMichelson ( TRE 0.8.0 (BSD) ) MR-646709E3 X-CRM114-CacheID: sfid-20210701_063412_547661_C87C8C6D X-CRM114-Status: GOOD ( 30.18 ) 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 Wed, Jun 09, 2021 at 04:04:20PM +0300, James Clark wrote: > Currently, timeless mode starts the decode on PERF_RECORD_EXIT, and > non-timeless mode starts decoding on the fist PERF_RECORD_AUX record. > > This can cause the "data has no samples!" error if the first > PERF_RECORD_AUX record comes before the first (or any relevant) > PERF_RECORD_MMAP2 record because the mmaps are required by the decoder > to access the binary data. > > This change pushes the start of non-timeless decoding to the very end of > parsing the file. The PERF_RECORD_EXIT event can't be used because it > might not exist in system-wide or snapshot modes. > > I have not been able to find the exact cause for the events to be > intermittently in the wrong order in the basic scenario: > > perf record -e cs_etm/@tmc_etr0/u top > > But it can be made to happen every time with the --delay option. This is > because "enable_on_exec" is disabled, which causes tracing to start > before the process to be launched is exec'd. For example: > > perf record -e cs_etm/@tmc_etr0/u --delay=1 top > perf report -D | grep 'AUX\|MAP' > > 0 16714475632740 0x520 [0x40]: PERF_RECORD_AUX offset: 0 size: 0x30 flags: 0 [] > 0 16714476494960 0x5d0 [0x40]: PERF_RECORD_AUX offset: 0x30 size: 0x30 flags: 0 [] > 0 16714478208900 0x660 [0x40]: PERF_RECORD_AUX offset: 0x60 size: 0x30 flags: 0 [] > 4294967295 16714478293340 0x700 [0x70]: PERF_RECORD_MMAP2 8712/8712: [0x557a460000(0x54000) @ 0 00:17 5329258 0]: r-xp /usr/bin/top > 4294967295 16714478353020 0x770 [0x88]: PERF_RECORD_MMAP2 8712/8712: [0x7f86f72000(0x34000) @ 0 00:17 5214354 0]: r-xp /usr/lib/aarch64-linux-gnu/ld-2.31.so > > Another scenario in which decoding from the first aux record fails is a > workload that forks. Although the aux record comes after 'bash', it > comes before 'top', which is what we are interested in. For example: > > perf record -e cs_etm/@tmc_etr0/u -- bash -c top > perf report -D | grep 'AUX\|MAP' > > 4294967295 16853946421300 0x510 [0x70]: PERF_RECORD_MMAP2 8723/8723: [0x558f280000(0x142000) @ 0 00:17 5213953 0]: r-xp /usr/bin/bash > 4294967295 16853946543560 0x580 [0x88]: PERF_RECORD_MMAP2 8723/8723: [0x7fbba6e000(0x34000) @ 0 00:17 5214354 0]: r-xp /usr/lib/aarch64-linux-gnu/ld-2.31.so > 4294967295 16853946628420 0x608 [0x68]: PERF_RECORD_MMAP2 8723/8723: [0x7fbba9e000(0x1000) @ 0 00:00 0 0]: r-xp [vdso] > 0 16853947067300 0x690 [0x40]: PERF_RECORD_AUX offset: 0 size: 0x3a60 flags: 0 [] > ... > 0 16853966602580 0x1758 [0x40]: PERF_RECORD_AUX offset: 0xc2470 size: 0x30 flags: 0 [] > 4294967295 16853967119860 0x1818 [0x70]: PERF_RECORD_MMAP2 8723/8723: [0x5559e70000(0x54000) @ 0 00:17 5329258 0]: r-xp /usr/bin/top > 4294967295 16853967181620 0x1888 [0x88]: PERF_RECORD_MMAP2 8723/8723: [0x7f9ed06000(0x34000) @ 0 00:17 5214354 0]: r-xp /usr/lib/aarch64-linux-gnu/ld-2.31.so > 4294967295 16853967237180 0x1910 [0x68]: PERF_RECORD_MMAP2 8723/8723: [0x7f9ed36000(0x1000) @ 0 00:00 0 0]: r-xp [vdso] > > A third scenario is when the majority of time is spent in a shared > library that is not loaded at startup. For example a dynamically loaded > plugin. > > Testing > ======= > > Testing was done by checking if any samples that are present in the > old output are missing from the new output. Timestamps must be > stripped out with awk because now they are set to the last AUX sample, > rather than the first: > > ./perf script $4 | awk '!($4="")' > new.script > ./perf-default script $4 | awk '!($4="")' > default.script > comm -13 <(sort -u new.script) <(sort -u default.script) > > Testing showed that the new output is a superset of the old. When lines > appear in the comm output, it is not because they are missing but > because [unknown] is now resolved to sensible locations. For example > last putp branch here now resolves to libtinfo, so it's not missing > from the output, but is actually improved: > > Old: > top 305 [001] 1 branches:uH: 402830 _init+0x30 (/usr/bin/top.procps) => 404a1c [unknown] (/usr/bin/top.procps) > top 305 [001] 1 branches:uH: 404a20 [unknown] (/usr/bin/top.procps) => 402970 putp@plt+0x0 (/usr/bin/top.procps) > top 305 [001] 1 branches:uH: 40297c putp@plt+0xc (/usr/bin/top.procps) => 0 [unknown] ([unknown]) > New: > top 305 [001] 1 branches:uH: 402830 _init+0x30 (/usr/bin/top.procps) => 404a1c [unknown] (/usr/bin/top.procps) > top 305 [001] 1 branches:uH: 404a20 [unknown] (/usr/bin/top.procps) => 402970 putp@plt+0x0 (/usr/bin/top.procps) > top 305 [001] 1 branches:uH: 40297c putp@plt+0xc (/usr/bin/top.procps) => 7f8ab39208 putp+0x0 (/lib/libtinfo.so.5.9) > > In the following two modes, decoding now works and the "data has no > samples!" error is not displayed any more: > > perf record -e cs_etm/@tmc_etr0/u -- bash -c top > perf record -e cs_etm/@tmc_etr0/u --delay=1 top > > In snapshot mode, there is also an improvement to decoding. Previously > samples for the 'kill' process that was used to send SIGUSR2 were > completely missing, because the process hadn't started yet. But now > there are additional samples present: > > perf record -e cs_etm/@tmc_etr0/u --snapshot -a > perf script > > stress 19380 [003] 161627.938153: 1000000 instructions:uH: aaaabb612fb4 [unknown] (/usr/bin/stress) > kill 19644 [000] 161627.938153: 1000000 instructions:uH: ffffae0ef210 [unknown] (/lib/aarch64-linux-gnu/ld-2.27.so) > stress 19380 [003] 161627.938153: 1000000 instructions:uH: ffff9e754d40 random_r+0x20 (/lib/aarch64-linux-gnu/libc-2.27.so) > > Also tested was the round trip of 'perf inject' followed by 'perf > report' which has the same differences and improvements. > > Signed-off-by: James Clark Excellent work, James! I learned several things from it :) I went through the testing cases one by one, have verified all elaborated cases (but I don't verify injection cases): Reviewed-by: Leo Yan Tested-by: Leo Yan _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel