perf stat stddev reporting broken since "perf stat: Introduce read_counters function"
I noticed that perf stat in 4.4 is not printing stddev figures as expected and bisected it to commit 106a94a0f8c2 ("perf stat: Introduce read_counters function").
# Kernel 4.4
# make clean && make prefix=/usr && ./perf stat -r 5 sleep 1 Performance counter stats for 'sleep 1' (5 runs):
0.466683 task-clock (msec) # 0.000 CPUs utilized
1 context-switches # 0.002 M/sec
1 cpu-migrations # 0.002 M/sec
66 page-faults # 0.144 M/sec
1,630,220 cycles # 3.562 GHz
<not supported> stalled-cycles-frontend
<not supported> stalled-cycles-backend
902,686 instructions # 0.66 insns per cycle
185,692 branches # 405.786 M/sec
8,640 branch-misses # 4.63% of all branches1.000855883 seconds time elapsed ( +- 0.01% )
# git checkout 106a94a0f8c207ef4113ce7e32f34a00b3b174e7^ Performance counter stats for 'sleep 1' (5 runs):
0.397939 task-clock (msec) # 0.000 CPUs utilized ( +- 3.37% )
1 context-switches # 0.003 M/sec
0 cpu-migrations # 0.000 K/sec
67 page-faults # 0.169 M/sec ( +- 0.56% )
1,360,763 cycles # 3.420 GHz ( +- 2.14% )
<not supported> stalled-cycles-frontend
<not supported> stalled-cycles-backend
903,901 instructions # 0.66 insns per cycle ( +- 0.24% )
186,472 branches # 468.595 M/sec ( +- 0.29% )
8,599 branch-misses # 4.61% of all branches ( +- 0.77% )1.000761882 seconds time elapsed ( +- 0.00% )
# git checkout 106a94a0f8c207ef4113ce7e32f34a00b3b174e7
Performance counter stats for 'sleep 1' (5 runs):
0.583178 task-clock (msec) # 0.001 CPUs utilized
1 context-switches # 0.002 M/sec
0 cpu-migrations # 0.000 K/sec
67 page-faults # 0.141 M/sec
1,224,416 cycles # 2.585 GHz
<not supported> stalled-cycles-frontend
<not supported> stalled-cycles-backend
892,568 instructions # 0.68 insns per cycle
184,975 branches # 390.554 M/sec
8,512 branch-misses # 4.57% of all branches1.000889249 seconds time elapsed ( +- 0.01% )
I checked and current master in Linus' tree is also broken. Is this change in documented perf stat behaviour intentional?
Signature · 2 lines
Mel Gorman SUSE Labs
Quoted 52 lines · Mel Gorman
I noticed that perf stat in 4.4 is not printing stddev figures as expected and bisected it to commit
106a94a0f8c2("perf stat: Introduceread_countersfunction").# Kernel 4.4
# make clean && make prefix=/usr && ./perf stat -r 5 sleep 1 Performance counter stats for 'sleep 1' (5 runs):0.466683 task-clock (msec) # 0.000 CPUs utilized 1 context-switches # 0.002 M/sec 1 cpu-migrations # 0.002 M/sec 66 page-faults # 0.144 M/sec 1,630,220 cycles # 3.562 GHz <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 902,686 instructions # 0.66 insns per cycle 185,692 branches # 405.786 M/sec 8,640 branch-misses # 4.63% of all branches1.000855883 seconds time elapsed ( +- 0.01% )# git checkout 106a94a0f8c207ef4113ce7e32f34a00b3b174e7^ Performance counter stats for 'sleep 1' (5 runs):0.397939 task-clock (msec) # 0.000 CPUs utilized ( +- 3.37% ) 1 context-switches # 0.003 M/sec 0 cpu-migrations # 0.000 K/sec 67 page-faults # 0.169 M/sec ( +- 0.56% ) 1,360,763 cycles # 3.420 GHz ( +- 2.14% ) <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 903,901 instructions # 0.66 insns per cycle ( +- 0.24% ) 186,472 branches # 468.595 M/sec ( +- 0.29% ) 8,599 branch-misses # 4.61% of all branches ( +- 0.77% )1.000761882 seconds time elapsed ( +- 0.00% )
# git checkout 106a94a0f8c207ef4113ce7e32f34a00b3b174e7Performance counter stats for 'sleep 1' (5 runs):
0.583178 task-clock (msec) # 0.001 CPUs utilized 1 context-switches # 0.002 M/sec 0 cpu-migrations # 0.000 K/sec 67 page-faults # 0.141 M/sec 1,224,416 cycles # 2.585 GHz <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 892,568 instructions # 0.68 insns per cycle 184,975 branches # 390.554 M/sec 8,512 branch-misses # 4.57% of all branches
Quoted 4 lines
1.000889249 seconds time elapsed ( +- 0.01% )
I checked and current master in Linus' tree is also broken. Is this change in documented perf stat behaviour intentional?
nope, not intentional.. I'll check on that, thanks for reporting
jirka
On Tue, Jan 19, 2016 at 08:42:28AM +0100, Jiri Olsa wrote:
SNIP
Quoted 14 lines
Quoted 14 lines
Performance counter stats for 'sleep 1' (5 runs):
0.583178 task-clock (msec) # 0.001 CPUs utilized 1 context-switches # 0.002 M/sec 0 cpu-migrations # 0.000 K/sec 67 page-faults # 0.141 M/sec 1,224,416 cycles # 2.585 GHz <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 892,568 instructions # 0.68 insns per cycle 184,975 branches # 390.554 M/sec 8,512 branch-misses # 4.57% of all branches
Quoted 6 lines
Quoted 4 lines
1.000889249 seconds time elapsed ( +- 0.01% )
I checked and current master in Linus' tree is also broken. Is this change in documented perf stat behaviour intentional?
nope, not intentional.. I'll check on that, thanks for reporting
for some reason we initialized the stat every iteration, (the call is also wrong because it's called only over the first res_stats[0])
attached patch works for me, could you please test? I'll run more tests and put it in my queue
thanks,
jirka
---
tools/perf/util/stat.c +0 -1
@@ -310,7 +310,6 @@ int perf_stat_process_counter(struct perf_stat_config *config,int i, ret; aggr->val = aggr->ena = aggr->run =0 ; -init_stats (ps->res_stats);if (counter->per_pkg)zero_per_pkg (counter);
Mel Gorman
Tested-byQuoted 23 lines · Jiri Olsa
On Tue, Jan 19, 2016 at 08:42:28AM +0100, Jiri Olsa wrote:
SNIP
Quoted 19 lines
Quoted 18 lines
Performance counter stats for 'sleep 1' (5 runs):
0.583178 task-clock (msec) # 0.001 CPUs utilized 1 context-switches # 0.002 M/sec 0 cpu-migrations # 0.000 K/sec 67 page-faults # 0.141 M/sec 1,224,416 cycles # 2.585 GHz <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 892,568 instructions # 0.68 insns per cycle 184,975 branches # 390.554 M/sec 8,512 branch-misses # 4.57% of all branches1.000889249 seconds time elapsed ( +- 0.01% )
I checked and current master in Linus' tree is also broken. Is this change in documented perf stat behaviour intentional?
Quoted 9 lines
Quoted 1 line
nope, not intentional.. I'll check on that, thanks for reporting
for some reason we initialized the stat every iteration, (the call is also wrong because it's called only over the first res_stats[0])
attached patch works for me, could you please test? I'll run more tests and put it in my queue
That works for me too, thanks. Feel free to put this on the patch;
When you send it through, can you make sure it has the following please?
Signature · 2 lines
Mel Gorman SUSE Labs
Quoted 34 lines · Mel Gorman
Quoted 23 lines · Jiri Olsa
On Tue, Jan 19, 2016 at 08:42:28AM +0100, Jiri Olsa wrote:
SNIP
Quoted 19 lines
Quoted 18 lines
Performance counter stats for 'sleep 1' (5 runs):
0.583178 task-clock (msec) # 0.001 CPUs utilized 1 context-switches # 0.002 M/sec 0 cpu-migrations # 0.000 K/sec 67 page-faults # 0.141 M/sec 1,224,416 cycles # 2.585 GHz <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 892,568 instructions # 0.68 insns per cycle 184,975 branches # 390.554 M/sec 8,512 branch-misses # 4.57% of all branches1.000889249 seconds time elapsed ( +- 0.01% )
I checked and current master in Linus' tree is also broken. Is this change in documented perf stat behaviour intentional?
Quoted 9 lines
Quoted 1 line
nope, not intentional.. I'll check on that, thanks for reporting
for some reason we initialized the stat every iteration, (the call is also wrong because it's called only over the first res_stats[0])
attached patch works for me, could you please test? I'll run more tests and put it in my queue
Quoted 7 lines
That works for me too, thanks. Feel free to put this on the patch;
Tested-by Mel Gorman <[email protected]>When you send it through, can you make sure it has the following please?
Cc [email protected] # v4.2+
will do, thanks
jirka