Profiling unter Linux
Von langsam nach schnell
Hynek Schlawack
[email protected]
3. Februar 2010
Ich
2004 Praktika bei u.A. Netopsystem AG (jetzt NOS
Micro Ltd.)
seit 2004 mit Unterbrechungen bei Variomedia AG
2006 Diplomarbeit über Analyse & Optimierung
...Anhänger von effektiver Software
C-Fanboy
Fragestellung
1. Warum ist meine Software langsam?
2. ...und was kann ich dagegen tun?
Was macht Software langsam?
I Nachlässigkeit
I Übereifrigkeit
I Schlechte Kommunikation
I Schachteln(Schachteln(Schachteln()))
Ultimatives Beispiel für Nachlässigkeit
for (int i = 0; i < 42; i++)
v[i] += atoi(str);
Beispiele für Übereifrigkeit
I Mega-APIs
I XML für alles
I Feature creep
I Hammer-Nagel-Syndrom
I Voreilige Optimierung
Speicher ist billig, mehr Code ist okay!!!1!
I Nein
I CPU-Caches
I Speicherbus
Wer sagt das!?
Alan Cox (Linux) via Andi Kleen (dito) am Linux Kongress
2006
Speicherzugriff von heute == Festplattenzugriff von
gestern.
Zahlen!
mul statt shift 5 Ticks
Branch falsch vorrausgesagt 10 Ticks
Cache Miss 250 Ticks
Quelle: http://dl.fefe.de/optimizer-isec.pdf
http://dl.fefe.de/optimizer-isec.pdf
Aber, aber...Optimierung ist doch was Gutes?
Donald Knuth (TAoCP/TeX!) / C. A. R. Hoare (Quicksort!)
Premature optimization is
the root of all evil.
Schön! Und wo kommt Profiling ins Spiel?
Daniel J. Bernstein (qmail, djbdns)
Profile. Don’t speculate.
Spekulation möglich über...
I Notwendigkeit
I Ist dieser Code schuld?
I Wirksamkeit
I Ist der Code nun wirklich schneller?
Spekulative Optimierung
int
foo(int x)
{
return x * 2;
}
int
bar(int x)
{
return x
Spekulative Optimierung
$ objdump -d t.o
00000000 :
0: 55 push %ebp
1: 89 e5 mov %esp,%ebp
3: 8b 45 08 mov 0x8(%ebp),%eax
6: 5d pop %ebp
7: 01 c0 add %eax,%eax
9: c3 ret
[...]
00000010 :
10: 55 push %ebp
11: 89 e5 mov %esp,%ebp
13: 8b 45 08 mov 0x8(%ebp),%eax
16: 5d pop %ebp
17: 01 c0 add %eax,%eax
19: c3 ret
Compiler besser in Low-Level-Annahmen!
Spekulative Optimierung
void
copy1(char *dest, char *source, unsigned int length)
{
for (int i = 0; i < length; i++)
dest[i] = source[i] ;
}
void
copy2(char *dest, char *source, unsigned int length)
{
while (length--)
*dest++ = *source++;
}
copy1() ist schneller! Besser: Absicht vermitteln!
Profiling ermöglicht...
I ...die Untersuchung wo ein Programm seine Zeit verbringt
I ...das Finden von Flaschenhälsen⇒ Notwendigkeit!
I ...das Überprüfen der Auswirkungen von Änderungen⇒
Wirksamkeit!
Super!
Ansätze
I Manuell messen
I time()/clock()/gettimeofday()
I rdtsc
I Sampling
I gprof
I OProfile
I Instrumentation
I Callgrind
I (Java/Skriptsprachen)
Manuelles Messen
I am präzisesten
I am umständlichsten
I Bottlenecks müssen von Hand gefunden werden
clock()/time()/gettimeofday()
I ISO C
I Genauigkeit abhängig von libc
I reicht für Ad-Hoc-Messungen
RDTSC
I Read Time Stamp Counter
I Ticks seit letztem Reset
I Taktrate für Zeit notwendig
I Unportabel⇒ Portable Implementierung:
http://www.fftw.org/cycle.h
http://www.fftw.org/cycle.h
unsigned long long
rdtsc(void)
{
unsigned int a, d;
__asm__ __volatile__("rdtsc" : "=d" (d),
"=a" (a));
return ((unsigned long long) d
Beispiel für RDTSC: Welche Funktion ist schneller?
void
measure(void (*func)(char *, char *, unsigned int))
{
char *src, *dst;
long long a, b;
src = malloc(512); dst = malloc(512);
func(dst, src, 512);
a = rdtsc();
func(dst, src, 512);
b = rdtsc();
printf("%d\n", b-a);
free(src); free(dst);
}
Beispiel für RDTSC: Welche Funktion ist schneller?
int
main(void)
{
measure(copy1);
measure(copy2);
}
$ gcc t.c -O3 -std=c99
$ ./a.out
1680
3180
pWn3d!
Manuelles Messen
I Ideal zum Vergleich von zwei Implementierungen
I Tickszählen aber nur bei hochfrequentieren
Lowlevel-Funktionen sinnvoll!
I Big Picture nicht vergessen!
gprof
I GNU-Projekt (binutils)
I Sampling
I produziert Callgraphen
gprof
I Ungenau: nur ca. 100 Samples/sek!
I benötigt Compileroptionen
I Bonus: Thread FUBAR
Ulrich Drepper (glibc) anno 2002
gprof is uselss in today world
(Typo und Oettinger-Englisch beibehalten)
I Kernelerweiterung
I Sampling
I nutzt CPU-Features
I kann Kernelcode und Interrupts profilen
I einstellbare Granularität
I benötigt root-Zugriff
I Wird über Daemonprozess “opcontrol” bedient
I Überwacht Counter, untersucht in definierten Abständen
alle Prozesse
I Anschließend Analyse mittels “opreport” möglich
- Beispielaufruf
$ opcontrol --reset
$ opcontrol --setup --callgraph=42 \
--event=CPU_CLK_UNHALTED:2200000:0:1:1
$ opcontrol --start
$ ./programm
$ opcontrol --shutdown
- Beispielausgabe
$ opreport --demangle=smart --symbols ./pingpong_neon
CPU: Athlon, speed 2194.44 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) \
with a unit mask of 0x00 (No unit mask) count 45000
samples % image name symbol name
6110 15.7726 pingpong_neon progress_engine
3252 8.3949 pingpong_neon NEON_Put
2805 7.2410 pingpong_neon internal_send
[...]
I Callgraphen auch möglich
I Ideal zum Gesamtüberblick über größere Systeme
I Hat kaum Einfluss aufs vermessende System
Callgrind
I Virtuelle Maschine durch Valgrind
I Einheit: VM-Befehle (Ucode)
I Kann Cachenutzung messen
I Liefert präzise Callgraphen und Callcounter
Callgrind
==20660== Events : Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw
==20660== Collected : 741317 249914 157204 2713 3706 591 1913 1907 436
==20660==
==20660== I refs: 741,317
==20660== I1 misses: 2,713
==20660== L2i misses: 1,913
==20660== I1 miss rate: 0.36%
==20660== L2i miss rate: 0.25%
==20660==
==20660== D refs: 407,118 (249,914 rd + 157,204 wr)
==20660== D1 misses: 4,297 ( 3,706 rd + 591 wr)
==20660== L2d misses: 2,343 ( 1,907 rd + 436 wr)
==20660== D1 miss rate: 1.0% ( 1.4% + 0.3% )
==20660== L2d miss rate: 0.5% ( 0.7% + 0.2% )
==20660==
==20660== L2 refs: 7,010 ( 6,419 rd + 591 wr)
==20660== L2 misses: 4,256 ( 3,820 rd + 436 wr)
==20660== L2 miss rate: 0.3% ( 0.3% + 0.2% )
KCachegrind
KCachegrind
Fazit
Allheilmittel gibt es nicht!
I gprof ist nutzlos
I Bester zeitlicher Überblick: OProfile
I Beste Callgraphen/-counter: Callgrind
I Genauste Messung: CPU-Tick-Counter
Kombinieren!
Ich habe meinen Bottleneck, was nun?
I Algorithmus/Datenstrukturen
I Compiler-Features ausreizen
I Inlining/Loop-Unrolling
I Assembler (Vektorisierung)
Algorithmen/Datenstrukturen
I Bubblesort⇐⇒ Mergesort⇐⇒ Sortiert einfügen
I Arrays⇐⇒ Listen⇐⇒ Bäume
I Worst Case⇐⇒ Common Case hinterfragen
Compilerfeatures ausreizen
I Optimierungsoptionen: -O1/2/3/s, -march=ARCH,
-ffast-math
I Branchprediction mit __builtin_expect(EXPR, RESULT)
I Automatisch BP: -fprofile-generate/-fprofile-use
Inlining/Loop-Unrolling
I Sprünge minimieren
I Nur wenn man weiß, was man tut!
I Schmankerl: Duff’s Device
Duff’s Device
void
copy3(char *to, char *from, unsigned long count)
{
long n = (count + 7) / 8;
switch (count % 8) {
case 0: do { *to++ = *from++;
case 7: *to++ = *from++;
case 6: *to++ = *from++;
case 5: *to++ = *from++;
case 4: *to++ = *from++;
case 3: *to++ = *from++;
case 2: *to++ = *from++;
case 1: *to++ = *from++;
} while(--n > 0);
}
}
Zusammenfassung
I Profile. Don’t speculate.
I Richtige Werkzeug fürs richtige Profiling
I Versucht nicht zu clever zu sein
Was macht Software langsam?
Warum Profiling?
Wie Profiling?
Und dann?
