linux-kernel - Re: [PATCH v3 06/11] perf, tools, stat: Support JSON metrics in perf stat

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20170908181014.GD10112@kernel.org>
Date:   Fri, 8 Sep 2017 15:10:14 -0300
From:   Arnaldo Carvalho de Melo <acme@...nel.org>
To:     Andi Kleen <ak@...ux.intel.com>
Cc:     Andi Kleen <andi@...stfloor.org>, jolsa@...nel.org,
        linux-kernel@...r.kernel.org
Subject: Re: [PATCH v3 06/11] perf, tools, stat: Support JSON metrics in perf
 stat

Em Tue, Sep 05, 2017 at 01:37:08PM -0700, Andi Kleen escreveu:
> On Tue, Sep 05, 2017 at 05:07:09PM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Tue, Sep 05, 2017 at 12:52:35PM -0700, Andi Kleen escreveu:
> > > > > I'll check.
> > > > 
> > > > Ok, I couldn't reproduce it anymore, after you check this, please let me
> > > > know if I should pull that perf/intel-json-metrics-2 branch so that
> > > > someone wanting to test this can have it all in one place, ok?
> > > 
> > > Sure please pull.
> > > 
> > > The only missing thing are metrics for Skylake Server, but I can
> > > submit those later.
> > 
> > Ok, so I looked at the commit logs and found them rather dull, how is
> > that option to fake a CPU so that the tool thinks it is running on some
> > specific machine (broadwell, skylake, etc) so that I can augment those
> > with the output of 'perf list metricgroup' for each of them?
> 
> PERF_CPUID=GenuineIntel-...
> 
> See the mapfile.csv for valid codes
> 
> But it's quite a few.

yeah, I'm testing on the ones I have access and on a Skylake machine I'm having
trouble, see below.

That error message is not that helpful, what could be at play here? The kernel
running there is a recent RT variant for the RHEL kernel, with lots of
backports in the perf codebase, so I wasn't expecting that to be an issue,
please take a look.

I'll try later with a more recent kernel, maybe there are kernel patches
supporting Skylake that aren't in this kernel :-\

[root@...enth ~]# uname -a
Linux seventh 3.10.0-703.rt56.630.el7.x86_64 #1 SMP PREEMPT RT Sat Aug 19 22:32:17 EDT 2017 x86_64 x86_64 x86_64 GNU/Linux
[root@...enth ~]# grep "model name" /proc/cpuinfo | head -1
model name	: Intel(R) Core(TM) i5-7500 CPU @ 3.40GHz
[root@...enth ~]# perf list metricgroup

List of pre-defined events (to be used in -e):


Metric Groups:

DSB
FLOPS
Frontend
Frontend_Bandwidth
Memory_BW
Memory_Bound
Memory_Lat
Pipeline
Ports_Utilization
Power
SMT
Summary
TLB
TopDownL1
Unknown_Branches
[root@...enth ~]# perf stat --metric-only -M Summary -a sleep 1
Cannot set up events {inst_retired.any,cycles}:W,{cpu_clk_unhalted.thread}:W,{inst_retired.any}:W,{cpu_clk_unhalted.ref_tsc,msr/tsc/}:W,{fp_arith_inst_retired.scalar_single,fp_arith_inst_retired.scalar_double,fp_arith_inst_retired.128b_packed_double,fp_arith_inst_retired.128b_packed_single,fp_arith_inst_retired.256b_packed_double,fp_arith_inst_retired.256b_packed_single,duration_time}:W,{cpu_clk_thread_unhalted.one_thread_active,cpu_clk_thread_unhalted.ref_xclk_any}:W,{cpu_clk_unhalted.ref_tsc:u,cpu_clk_unhalted.ref_tsc}:W

 Usage: perf stat [<options>] [<command>]

    -M, --metrics <metric/metric group list>
                          monitor specified metrics or metric groups (separated by ,)
[root@...enth ~]#

[root@...enth ~]# perf stat -vv --metric-only -M Summary -a sleep 1
Using CPUID GenuineIntel-6-9E
metric expr 1 / inst_retired.any / cycles for CPI
found event inst_retired.any
found event cycles
metric expr cpu_clk_unhalted.thread for CLKS
found event cpu_clk_unhalted.thread
metric expr inst_retired.any for Instructions
found event inst_retired.any
metric expr cpu_clk_unhalted.ref_tsc / msr@tsc@ for CPU_Utilization
found event cpu_clk_unhalted.ref_tsc
found event msr/tsc/
metric expr ( 1*( fp_arith_inst_retired.scalar_single + fp_arith_inst_retired.scalar_double ) + 2* fp_arith_inst_retired.128b_packed_double + 4*( fp_arith_inst_retired.128b_packed_single + fp_arith_inst_retired.256b_packed_double ) + 8* fp_arith_inst_retired.256b_packed_single ) / 1000000000 / duration_time for GFLOPs
found event fp_arith_inst_retired.scalar_single
found event fp_arith_inst_retired.scalar_double
found event fp_arith_inst_retired.128b_packed_double
found event fp_arith_inst_retired.128b_packed_single
found event fp_arith_inst_retired.256b_packed_double
found event fp_arith_inst_retired.256b_packed_single
found event duration_time
metric expr 1 - cpu_clk_thread_unhalted.one_thread_active / ( cpu_clk_thread_unhalted.ref_xclk_any / 2 ) if #smt_on else 0 for SMT_2T_Utilization
found event cpu_clk_thread_unhalted.one_thread_active
found event cpu_clk_thread_unhalted.ref_xclk_any
metric expr cpu_clk_unhalted.ref_tsc:u / cpu_clk_unhalted.ref_tsc for Kernel_Utilization
found event cpu_clk_unhalted.ref_tsc:u
found event cpu_clk_unhalted.ref_tsc
adding {inst_retired.any,cycles}:W,{cpu_clk_unhalted.thread}:W,{inst_retired.any}:W,{cpu_clk_unhalted.ref_tsc,msr/tsc/}:W,{fp_arith_inst_retired.scalar_single,fp_arith_inst_retired.scalar_double,fp_arith_inst_retired.128b_packed_double,fp_arith_inst_retired.128b_packed_single,fp_arith_inst_retired.256b_packed_double,fp_arith_inst_retired.256b_packed_single,duration_time}:W,{cpu_clk_thread_unhalted.one_thread_active,cpu_clk_thread_unhalted.ref_xclk_any}:W,{cpu_clk_unhalted.ref_tsc:u,cpu_clk_unhalted.ref_tsc}:W
intel_pt default config: tsc,mtc,mtc_period=3,psb_period=3
inst_retired.any -> cpu/event=0xc0/
cpu_clk_unhalted.thread -> cpu/event=0x3c/
inst_retired.any -> cpu/event=0xc0/
cpu_clk_unhalted.ref_tsc -> cpu/umask=0x3,period=2000003,event=0/
Cannot set up events {inst_retired.any,cycles}:W,{cpu_clk_unhalted.thread}:W,{inst_retired.any}:W,{cpu_clk_unhalted.ref_tsc,msr/tsc/}:W,{fp_arith_inst_retired.scalar_single,fp_arith_inst_retired.scalar_double,fp_arith_inst_retired.128b_packed_double,fp_arith_inst_retired.128b_packed_single,fp_arith_inst_retired.256b_packed_double,fp_arith_inst_retired.256b_packed_single,duration_time}:W,{cpu_clk_thread_unhalted.one_thread_active,cpu_clk_thread_unhalted.ref_xclk_any}:W,{cpu_clk_unhalted.ref_tsc:u,cpu_clk_unhalted.ref_tsc}:W

 Usage: perf stat [<options>] [<command>]

    -M, --metrics <metric/metric group list>
                          monitor specified metrics or metric groups (separated by ,)
[root@...enth ~]#


Humm, it doesn't even get to try sys_perf_event_open() it seems to be bailing
out while reading some sysfs event_source files, a better error output seems in
demand:

[root@...enth ~]# perf trace -e perf_* perf stat --metric-only -M Summary -a sleep 1
Cannot set up events {inst_retired.any,cycles}:W,{cpu_clk_unhalted.thread}:W,{inst_retired.any}:W,{cpu_clk_unhalted.ref_tsc,msr/tsc/}:W,{fp_arith_inst_retired.scalar_single,fp_arith_inst_retired.scalar_double,fp_arith_inst_retired.128b_packed_double,fp_arith_inst_retired.128b_packed_single,fp_arith_inst_retired.256b_packed_double,fp_arith_inst_retired.256b_packed_single,duration_time}:W,{cpu_clk_thread_unhalted.one_thread_active,cpu_clk_thread_unhalted.ref_xclk_any}:W,{cpu_clk_unhalted.ref_tsc:u,cpu_clk_unhalted.ref_tsc}:W

 Usage: perf stat [<options>] [<command>]

    -M, --metrics <metric/metric group list>
                          monitor specified metrics or metric groups (separated by ,)
[root@...enth ~]# 

[root@...enth linux]# strace perf stat --metric-only -M Summary -a sleep 1 |& tail -30
getdents(3, /* 0 entries */, 32768)     = 0
close(3)                                = 0
openat(AT_FDCWD, "/sys/bus/event_source/devices/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
getdents(3, /* 8 entries */, 32768)     = 232
getdents(3, /* 0 entries */, 32768)     = 0
close(3)                                = 0
stat("/sys/bus/event_source/devices/msr/format", 0x7ffd36f79480) = -1 ENOENT (No such file or directory)
stat("/sys/bus/event_source/devices/msr/type", 0x7ffd36f79470) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/sys/bus/event_source/devices/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
getdents(3, /* 8 entries */, 32768)     = 232
getdents(3, /* 0 entries */, 32768)     = 0
close(3)                                = 0
write(2, "Cannot set up events {inst_retir"..., 529Cannot set up events {inst_retired.any,cycles}:W,{cpu_clk_unhalted.thread}:W,{inst_retired.any}:W,{cpu_clk_unhalted.ref_tsc,msr/tsc/}:W,{fp_arith_inst_retired.scalar_single,fp_arith_inst_retired.scalar_double,fp_arith_inst_retired.128b_packed_double,fp_arith_inst_retired.128b_packed_single,fp_arith_inst_retired.256b_packed_double,fp_arith_inst_retired.256b_packed_single,duration_time}:W,{cpu_clk_thread_unhalted.one_thread_active,cpu_clk_thread_unhalted.ref_xclk_any}:W,{cpu_clk_unhalted.ref_tsc:u,cpu_clk_unhalted.ref_tsc}:W
) = 529
write(2, "\n Usage: perf stat [<options>] ["..., 43
 Usage: perf stat [<options>] [<command>]
) = 43
write(2, "\n", 1
)                       = 1
write(2, "    ", 4    )                     = 4
write(2, "-M", 2-M)                       = 2
write(2, ", ", 2, )                       = 2
write(2, "--metrics", 9--metrics)                = 9
write(2, " <metric/metric group list>", 27 <metric/metric group list>) = 27
write(2, "\n", 1
)                       = 1
write(2, "                          monito"..., 86                          monitor specified metrics or metric groups (separated by ,)
) = 86
exit_group(129)                         = ?
+++ exited with 129 +++
[root@...enth linux]#