Received: by 2002:ad5:474a:0:0:0:0:0 with SMTP id i10csp3563651imu; Fri, 30 Nov 2018 02:23:08 -0800 (PST) X-Google-Smtp-Source: AFSGD/WBQ9jro7B60nqyG5nygOuUZ55FKgdCntSEaxMLFU8vlIgfyT0ZViPohJCZ55Qv201J3gHs X-Received: by 2002:a65:484c:: with SMTP id i12mr4316729pgs.309.1543573388656; Fri, 30 Nov 2018 02:23:08 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1543573388; cv=none; d=google.com; s=arc-20160816; b=DTl/czoGdtUBGl8Q1qXnh3zJpRV1NgGAHavYLZXXyj/V76juoKRpvXXdJRghM+aItf rkvzLDS+tTsKtM3NZT8hpZHpQOrcpCL7RMql7exGku5PTkkc9CoHMXuG3QsCD73OVMQS NEogyhez7nrTT9FTgnmDiIA/kJhBP1rYQwXHRjRwJLYGWodac7sVNiIUbvGCqd/WH2dE CFWOn4e51ijOqJtOtizsLyyhqNLbRs1+jvPNL9XteexuK3THAavfyEd9HVYBXoBBYfkB 2n0TMscwscLZTySJzhvd3/MWnpIHG/0zegHSnV699LCbkXwnjHSZ2vvRDtTIS+mVqlJX d+aQ== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:sender:user-agent:in-reply-to :content-disposition:mime-version:references:message-id:subject:cc :to:from:date; bh=8eOB3fbcG/9OhXRVYTB1tGJSFCRLLaJPRDEw3nDqxNM=; b=ouYnsZXAMXum7WIufcnDFWOsqNIgn2/JBzImVFKSQ9VdTwfAWBZ2Lm+8ss1byxsAVO yr06nawvYRNEs78cufI+vOMbtmYGodiRn556P1p9beYFXQnfMMp/vi6ddIK3JLHx7ycg ojrDqRJFbmEgf+zHFYWPqvUPuSykPg8Z4x7h/kvGsGXGmOOCOdP26l28nAUETzVy9uBV 1KYiSxnArPmazUXAMr2ZHro9SPDKzWjv+oEA/dm1wzjnmMT3BCiSvrLyw/45Fye7Qdgj WBfJHrnaOzBqfj33aHdmo+n4Iaj/FN2uQCDiwGaEfy80CkvblSUhiFPDdj6utp768YDF qjsw== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=fail (p=NONE sp=NONE dis=NONE) header.from=redhat.com Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id u129si4936423pfu.117.2018.11.30.02.22.54; Fri, 30 Nov 2018 02:23:08 -0800 (PST) Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67; Authentication-Results: mx.google.com; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=fail (p=NONE sp=NONE dis=NONE) header.from=redhat.com Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726881AbeK3Vaq (ORCPT + 99 others); Fri, 30 Nov 2018 16:30:46 -0500 Received: from mx1.redhat.com ([209.132.183.28]:51244 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726582AbeK3Vaq (ORCPT ); Fri, 30 Nov 2018 16:30:46 -0500 Received: from smtp.corp.redhat.com (int-mx02.intmail.prod.int.phx2.redhat.com [10.5.11.12]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 686903001BF8; Fri, 30 Nov 2018 10:21:57 +0000 (UTC) Received: from krava (unknown [10.43.17.17]) by smtp.corp.redhat.com (Postfix) with SMTP id 0BA4560C61; Fri, 30 Nov 2018 10:21:55 +0000 (UTC) Date: Fri, 30 Nov 2018 11:21:54 +0100 From: Jiri Olsa To: Leo Yan Cc: Arnaldo Carvalho de Melo , Alexander Shishkin , Andi Kleen , linux-kernel@vger.kernel.org, Daniel Thompson Subject: Re: [PATCH] perf evsel: Correct clock unit to nanosecond Message-ID: <20181130102154.GA3617@krava> References: <1543572365-11706-1-git-send-email-leo.yan@linaro.org> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <1543572365-11706-1-git-send-email-leo.yan@linaro.org> User-Agent: Mutt/1.10.1 (2018-07-13) X-Scanned-By: MIMEDefang 2.79 on 10.5.11.12 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.45]); Fri, 30 Nov 2018 10:21:57 +0000 (UTC) Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Fri, Nov 30, 2018 at 06:06:05PM +0800, Leo Yan wrote: > Since commit 0aa802a79469 ("perf stat: Get rid of extra clock display > function"), the cpu and task clock unit has been changed from > nanosecond value to millisecond value. This introduces confusion for > CPU run time statistics, we can see in below flow the clock value is > scaled from nanosecond value to millisecond value; but this is > contradiction with statistics type 'STAT_NSECS', which always takes > clock as nanosecond unit. > > perf_stat__update_shadow_stats() > `-> count *= counter->scale; > update_runtime_stat(st, STAT_NSECS, 0, cpu, count); > > And when 'perf stat' calculates frequencies for cpu cycles and other > events, it uses event count to divide clock and it expects divisor unit > has nanosecond value, but actually the clock value has been scaled to > millisecond value. At the end we can exaggerate values in below output > result (e.g. 500M/sec for context-switches, cycle is 1079636.500 GHz). > > # perf stat -- sleep 1 > > Performance counter stats for 'sleep 1': > > 2.29 msec task-clock # 0.002 CPUs utilized > 1 context-switches # 500.000 M/sec > 1 cpu-migrations # 500.000 M/sec > 53 page-faults # 26500.000 M/sec > 2,159,273 cycles # 1079636.500 GHz > 1,281,566 instructions # 0.59 insn per cycle > 171,153 branches # 85576500.000 M/sec > 17,870 branch-misses # 10.44% of all branches > > To fix this issue, this patch changes back clock unit to nanosecond > level, as result we can see the correct frequency calculation: > > # perf stat -- sleep 1 > > Performance counter stats for 'sleep 1': > > 2,461,180 nsec task-clock # 0.002 CPUs utilized > 1 context-switches # 0.406 K/sec > 0 cpu-migrations # 0.000 K/sec > 54 page-faults # 0.022 M/sec > 2,320,634 cycles # 0.943 GHz > 1,284,442 instructions # 0.55 insn per cycle > 171,425 branches # 69.652 M/sec > 17,970 branch-misses # 10.48% of all branches > > This patch has side effect for changing unit field for perf command. > This is tested with below two cases: one is for normal output format and > another is for cvs output format. > > Before: > > # perf stat -e cpu-clock,task-clock -C 0 sleep 3 > > Performance counter stats for 'CPU(s) 0': > > 3,003.50 msec cpu-clock # 1.000 CPUs utilized > 3,003.50 msec task-clock # 1.000 CPUs utilized > > 3.003697880 seconds time elapsed > > Now: > > # perf stat -e cpu-clock,task-clock -C 0 sleep 3 > > Performance counter stats for 'CPU(s) 0': > > 3,003,684,880 nsec cpu-clock # 1.000 CPUs utilized > 3,003,682,780 nsec task-clock # 1.000 CPUs utilized > > 3.003881982 seconds time elapsed > > Before: > > # perf stat -e cpu-clock,task-clock -C 0 -x, sleep 3 > 3003.64,msec,cpu-clock,3003644320,100.00,1.000,CPUs utilized > 3003.64,msec,task-clock,3003643300,100.00,1.000,CPUs utilized > > Now: > > # perf stat -e cpu-clock,task-clock -C 0 -x, sleep 3 > 3003501460,nsec,cpu-clock,3003501660,100.00,1.000,CPUs utilized > 3003499500,nsec,task-clock,3003499500,100.00,1.000,CPUs utilized > > Cc: Daniel Thompson > Signed-off-by: Leo Yan there was fix for this recently, could you please check if it's working for you: 6e269c85dcea perf stat: Fix shadow stats for clock events thanks, jirka