Profiling unter Linux - hynek.me ??ling unter Linux Von langsam nach schnell Hynek Schlawack schlawack@variomedia.de…

Profiling unter Linux Von langsam nach schnell

Hynek Schlawack

schlawack@variomedia.de

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?