lkml.org 
[lkml]   [2011]   [Apr]   [24]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH] perf events: Add stalled cycles generic event - PERF_COUNT_HW_STALLED_CYCLES
On Sat, Apr 23, 2011 at 10:14:09PM +0200, Ingo Molnar wrote:
>
> The new PERF_COUNT_HW_STALLED_CYCLES event tries to approximate
> cycles the CPU does nothing useful, because it is stalled on a
> cache-miss or some other condition.

Conceptually looks fine. I'd prefer a more precise name such as:
PERF_COUNT_EXECUTION_STALLED_CYCLES (to differentiate from frontend or
retirement stalls).

In the example below:

==> foo.c <==

foo()
{
}


bar()
{
}

==> test.c <==
#include <stdio.h>
#include <stdlib.h>
#include <stdint.h>

#define FNV_PRIME_32 16777619
#define FNV_OFFSET_32 2166136261U
uint32_t hash1(const char *s)
{
uint32_t hash = FNV_OFFSET_32, i;
for(i = 0; i < 4; i++)
{
hash = hash ^ (s[i]); // xor next byte into the bottom of the hash
hash = hash * FNV_PRIME_32; // Multiply by prime number found to work well
}
return hash;
}

#define FNV_PRIME_WEAK_32 100
#define FNV_OFFSET_WEAK_32 200

uint32_t hash2(const char *s)
{
uint32_t hash = FNV_OFFSET_WEAK_32, i;
for(i = 0; i < 4; i++)
{
hash = hash ^ (s[i]); // xor next byte into the bottom of the hash
hash = hash * FNV_PRIME_WEAK_32; // Multiply by prime number found to work well
}
return hash;
}

int main()
{
int r = random();

while(1) {
r++;
#ifdef HARD
if (hash1((const char *) &r) & 0x500)
#else
if (hash2((const char *) &r) & 0x500)
#endif
foo();
else
bar();
}
}
==> Makefile <==

all:
gcc -O2 test.c foo.c -UHARD -o test.easy
gcc -O2 test.c foo.c -DHARD -o test.hard


# perf stat -e cycles,instructions ./test.hard
^C
Performance counter stats for './test.hard':

3,742,855,848 cycles
4,179,896,309 instructions # 1.117 IPC

1.754804730 seconds time elapsed


# perf stat -e cycles,instructions ./test.easy
^C
Performance counter stats for './test.easy':

3,932,887,528 cycles
8,994,416,316 instructions # 2.287 IPC

1.843832827 seconds time elapsed

i.e. fixing the branch mispredicts could result in
a nearly 2x speedup for the program.

Looking at:

# perf stat -e cycles,instructions,branch-misses,cache-misses,RESOURCE_STALLS:ANY ./test.hard
^C
Performance counter stats for './test.hard':

3,413,713,048 cycles (scaled from 69.93%)
3,772,611,782 instructions # 1.105 IPC (scaled from 80.01%)
51,113,340 branch-misses (scaled from 80.01%)
12,370 cache-misses (scaled from 80.02%)
26,656,983 RESOURCE_STALLS:ANY (scaled from 69.99%)

1.626595305 seconds time elapsed

it's hard to spot the opporunity. On the other hand:

# ./analyze.py
Percent idle: 27%
Retirement Stalls: 82%
Backend Stalls: 0%
Frontend Stalls: 62%
Instruction Starvation: 62%
icache stalls: 0%

does give me a signal about where to look. The script below is
a quick and dirty hack. I haven't really validated it with
many workloads. I'm posting it here anyway hoping that it'd
result in better kernel support for these types of analyses.

Even if we cover this with various generic PERF_COUNT_*STALL events,
we'll still have a need for other events:

* Things that give info about instruction mixes.

Ratio of {loads, stores, floating point, branches, conditional branches}
to total instructions.

* Activity related to micro architecture specific caches

People using -funroll-loops may have a significant performance opportunity.
But it's hard to spot bottlenecks in the instruction decoder.

* Monitoring traffic on Hypertransport/QPI links

Like you observe, most people will not look at these events, so
focusing on getting the common events right makes sense. But I
still like access to all events (either via a mapping file or
a library such as libpfm4). Hiding them in "perf list" sounds
like a reasonable way of keeping complexity out.

-Arun

PS: branch-misses:pp was spot on for the example above.

#!/usr/bin/env python

from optparse import OptionParser
from itertools import izip, chain, repeat
from subprocess import Popen, PIPE
import re, struct

def grouper(n, iterable, padvalue=None):
"grouper(3, 'abcdefg', 'x') --> ('a','b','c'), ('d','e','f'), ('g','x','x')"
return izip(*[chain(iterable, repeat(padvalue, n-1))]*n)

counter_re = re.compile('\s+(?P<count>\d+)\s+(?P<event>\S+)')
def sample(events):
cmd = 'perf stat --no-big-num -a'
ncounters = 4
groups = grouper(ncounters, events)
for g in groups:
# filter padding
g = [ e for e in g if e ]
cmd += ' -e ' + ','.join(g)
cmd += ' -- sleep ' + str(options.time)
process = Popen(cmd, shell=True, stdout=PIPE, stderr=PIPE)
out, err = process.communicate()
ret = process.poll()
if ret: raise "Perf failed: " + err
ret = {}
for line in err.split('\n'):
m = counter_re.match(line)
if not m: continue
ret[m.group('event')] = long(m.group('count'))
return ret

def measure_cycles():
# disable C-states
f = open("/dev/cpu_dma_latency", "wb")
f.write(struct.pack("i", 0))
f.flush()
saved = options.time
options.time = 1 # one sec is sufficient to measure clock
cycles = sample(["cycles"])['cycles']
cycles /= options.time
f.close()
options.time = saved
return cycles

if __name__ == '__main__':
parser = OptionParser()
parser.add_option("-t", "--time", dest="time", default=1,
help="How long to sample events")
parser.add_option("-q", "--quiet",
action="store_false", dest="verbose", default=True,
help="don't print status messages to stdout")

(options, args) = parser.parse_args()
cycles_per_sec = measure_cycles()
c = sample(["cycles", "instructions", "UOPS_ISSUED:ANY:c=1", "UOPS_ISSUED:ANY:c=1:t=1",
"RESOURCE_STALLS:ANY", "UOPS_RETIRED:ANY:c=1:t=1",
"UOPS_EXECUTED:PORT015:t=1", "UOPS_EXECUTED:PORT234_CORE",
"UOPS_ISSUED:ANY:t=1", "UOPS_ISSUED:FUSED:t=1", "UOPS_RETIRED:ANY:t=1",
"L1I:CYCLES_STALLED"])
cycles = c["cycles"] * 1.0
cycles_no_uops_issued = cycles - c["UOPS_ISSUED:ANY:c=1:t=1"]
cycles_no_uops_retired = cycles - c["UOPS_RETIRED:ANY:c=1:t=1"]
backend_stall_cycles = c["RESOURCE_STALLS:ANY"]
icache_stall_cycles = c["L1I:CYCLES_STALLED"]

# Cycle stall accounting
print "Percent idle: %d%%" % ((1 - cycles/(int(options.time) * cycles_per_sec)) * 100)
print "\tRetirement Stalls: %d%%" % ((cycles_no_uops_retired / cycles) * 100)
print "\tBackend Stalls: %d%%" % ((backend_stall_cycles / cycles) * 100)
print "\tFrontend Stalls: %d%%" % ((cycles_no_uops_issued / cycles) * 100)
print "\tInstruction Starvation: %d%%" % (((cycles_no_uops_issued - backend_stall_cycles)/cycles) * 100)
print "\ticache stalls: %d%%" % ((icache_stall_cycles/cycles) * 100)

# Wasted work
uops_executed = c["UOPS_EXECUTED:PORT015:t=1"] + c["UOPS_EXECUTED:PORT234_CORE"]
uops_retired = c["UOPS_RETIRED:ANY:t=1"]
uops_issued = c["UOPS_ISSUED:ANY:t=1"] + c["UOPS_ISSUED:FUSED:t=1"]

print "\tPercentage useless uops: %d%%" % ((uops_executed - uops_retired) * 100.0/uops_retired)
print "\tPercentage useless uops issued: %d%%" % ((uops_issued - uops_retired) * 100.0/uops_retired)


\
 
 \ /
  Last update: 2011-04-24 08:25    [W:0.104 / U:0.708 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site