of 45/45
Profiling unter Linux Von langsam nach schnell Hynek Schlawack [email protected] 3. Februar 2010

Profiling unter Linux - hynek.me fileProfiling unter Linux Von langsam nach schnell Hynek Schlawack [email protected] 3. Februar 2010

  • View
    216

  • Download
    0

Embed Size (px)

Text of Profiling unter Linux - hynek.me fileProfiling unter Linux Von langsam nach schnell Hynek...

  • Profiling unter LinuxVon langsam nach schnell

    Hynek Schlawack

    [email protected]

    3. Februar 2010

  • Ich

    2004 Praktika bei u.A. Netopsystem AG (jetzt NOSMicro Ltd.)

    seit 2004 mit Unterbrechungen bei Variomedia AG2006 Diplomarbeit über Analyse & Optimierung

    ...Anhänger von effektiver SoftwareC-Fanboy

  • Fragestellung

    1. Warum ist meine Software langsam?2. ...und was kann ich dagegen tun?

  • Was macht Software langsam?

    I NachlässigkeitI ÜbereifrigkeitI Schlechte KommunikationI 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-APIsI XML für allesI Feature creepI Hammer-Nagel-SyndromI Voreilige Optimierung

  • Speicher ist billig, mehr Code ist okay!!!1!

    I NeinI CPU-CachesI Speicherbus

  • Wer sagt das!?

    Alan Cox (Linux) via Andi Kleen (dito) am Linux Kongress2006

    Speicherzugriff von heute == Festplattenzugriff vongestern.

  • Zahlen!

    mul statt shift 5 TicksBranch falsch vorrausgesagt 10 TicksCache 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 isthe 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 NotwendigkeitI Ist dieser Code schuld?

    I WirksamkeitI Ist der Code nun wirklich schneller?

  • Spekulative Optimierung

    intfoo(int x){return x * 2;

    }

    intbar(int x){return x

  • Spekulative Optimierung$ objdump -d t.o

    00000000 :0: 55 push %ebp1: 89 e5 mov %esp,%ebp3: 8b 45 08 mov 0x8(%ebp),%eax6: 5d pop %ebp7: 01 c0 add %eax,%eax9: c3 ret

    [...]00000010 :10: 55 push %ebp11: 89 e5 mov %esp,%ebp13: 8b 45 08 mov 0x8(%ebp),%eax16: 5d pop %ebp17: 01 c0 add %eax,%eax19: c3 ret

    Compiler besser in Low-Level-Annahmen!

  • Spekulative Optimierung

    voidcopy1(char *dest, char *source, unsigned int length){for (int i = 0; i < length; i++)dest[i] = source[i] ;

    }

    voidcopy2(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 verbringtI ...das Finden von Flaschenhälsen⇒ Notwendigkeit!I ...das Überprüfen der Auswirkungen von Änderungen⇒

    Wirksamkeit!

  • Super!

  • Ansätze

    I Manuell messenI time()/clock()/gettimeofday()I rdtsc

    I SamplingI gprofI OProfile

    I InstrumentationI CallgrindI (Java/Skriptsprachen)

  • Manuelles Messen

    I am präzisestenI am umständlichstenI Bottlenecks müssen von Hand gefunden werden

  • clock()/time()/gettimeofday()

    I ISO CI Genauigkeit abhängig von libcI reicht für Ad-Hoc-Messungen

  • RDTSC

    I Read Time Stamp CounterI Ticks seit letztem ResetI Taktrate für Zeit notwendigI Unportabel⇒ Portable Implementierung:

    http://www.fftw.org/cycle.h

    http://www.fftw.org/cycle.h

  • unsigned long longrdtsc(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?

    voidmeasure(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?

    intmain(void){measure(copy1);measure(copy2);

    }

    $ gcc t.c -O3 -std=c99$ ./a.out16803180

    pWn3d!

  • Manuelles Messen

    I Ideal zum Vergleich von zwei ImplementierungenI Tickszählen aber nur bei hochfrequentieren

    Lowlevel-Funktionen sinnvoll!I Big Picture nicht vergessen!

  • gprof

    I GNU-Projekt (binutils)I SamplingI produziert Callgraphen

  • gprof

    I Ungenau: nur ca. 100 Samples/sek!I benötigt CompileroptionenI Bonus: Thread FUBAR

  • Ulrich Drepper (glibc) anno 2002

    gprof is uselss in today world(Typo und Oettinger-Englisch beibehalten)

  • I KernelerweiterungI SamplingI nutzt CPU-Features

  • I kann Kernelcode und Interrupts profilenI einstellbare GranularitätI benötigt root-Zugriff

  • I Wird über Daemonprozess “opcontrol” bedientI Überwacht Counter, untersucht in definierten Abständen

    alle ProzesseI 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öglichI Ideal zum Gesamtüberblick über größere SystemeI Hat kaum Einfluss aufs vermessende System

  • Callgrind

    I Virtuelle Maschine durch ValgrindI Einheit: VM-Befehle (Ucode)I Kann Cachenutzung messenI 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 nutzlosI Bester zeitlicher Überblick: OProfileI Beste Callgraphen/-counter: CallgrindI Genauste Messung: CPU-Tick-Counter

    Kombinieren!

  • Ich habe meinen Bottleneck, was nun?

    I Algorithmus/DatenstrukturenI Compiler-Features ausreizenI Inlining/Loop-UnrollingI Assembler (Vektorisierung)

  • Algorithmen/Datenstrukturen

    I Bubblesort⇐⇒ Mergesort⇐⇒ Sortiert einfügenI Arrays⇐⇒ Listen⇐⇒ BäumeI 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 minimierenI Nur wenn man weiß, was man tut!I Schmankerl: Duff’s Device

  • Duff’s Device

    voidcopy3(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 ProfilingI Versucht nicht zu clever zu sein

    Was macht Software langsam?Warum Profiling?Wie Profiling?Und dann?