• Google I/O 2010 - Measure in milliseconds: Meet Speed Tracer
• MIT Lecture: Performance Engineering with Profiling Tools
• slides

Credits:

• By Jeff Dean: http://research.google.com/people/jeff/
• Originally by Peter Norvig: http://norvig.com/21-days.html#answers

• Profiler și tehnici de profiling
• Unelte de profiling
• Utilizare perf
• Unelte de debugging

Un profiler este un utilitar de analiză a performanței care ajută programatorul să determine punctele critice – bottleneck – ale unui program. Acest lucru se realizează prin investigarea comportamentului programului, evaluarea consumului de memorie și relația dintre modulele acestuia.

Suportul pentru profilere este disponibil la nivel de:

• bibliotecă C (GNU libc), prin informații legate de timpul de viață al alocărilor de memorie,
• compilator, prin modificarea codului în tehnica de instrumentare se poate realiza ușor în procesul de compilare, compilatorul fiind cel ce inserează secțiunile de cod necesare,
• nucleu al sistemului de operare, prin punerea la dispoziție de apeluri de sistem specifice,
• hardware, unele procesoare sunt dotate cu contoare de temporizare (Time Stamp Counter - TSC) sau contoare de performanță care numără evenimente precum cicluri de procesor sau TLB miss-uri.

Două moduri prin care se realizează profiling-ul sunt prezentate în continuare:

Profiler-ele bazate pe această tehnică necesită de obicei modificări în codul programului: se inserează secțiuni de cod la începutul și sfârșitul funcției ce se dorește analizată. De asemenea, se rețin și funcțiile apelate. Astfel, se poate estima timpul total al apelului în sine cât și al apelurilor de subfuncții. Dezavantajul major al acestor profilere este legat de modificarea codului: în funcții de dimensiune scăzută și des apelate, acest overhead poate duce la o interpretare greșită a rezultatelor.

Profiler-ele bazate pe sampling nu fac schimbări în codul programului, ci verifică periodic procesorul cu scopul de a determina ce funcție (instrucțiune) se execută la momentul respectiv. Apoi estimează frecvența și timpul de execuție al unei anumite funcții într-o perioadă de timp.

În continuare sunt prezentate câteva unelte folosite în profiling.

Majoritatea procesoarelor moderne oferă registre speciale (performance counters) care contorizează diferite tipuri de evenimente hardware: instrucțiuni executate, cache-miss-uri, instrucțiuni de salt anticipate greșit, fără să afecteze performanța nucleului sau a aplicațiilor. Aceste registre pot declanșa întreruperi atunci când se acumulează un anumit număr de evenimente și astfel se pot folosi pentru analiza codului care rulează pe procesorul în cauză.

Subsistemul perfcounters:

• se găsește în nucleul Linux începând cu versiunea 2.6.31 (CONFIG_PERF_COUNTERS=y )
• este înlocuitorul lui oprofile
• oferă suport pentru:
  • evenimente hardware (instrucțiuni, accese cache, ciclii de magistrală).
  • evenimente software (page fault, cpu-clock, cpu migrations).
  • tracepoints (e.g: sys_enter_open, sys_exit_open).

Utilitarul perf este interfața subsistemului perfcounters cu utilizatorul. Oferă o linie de comandă asemănătoare cu git și nu necesită existența unui daemon.

Un tutorial despre perf găsiți aici.

$ perf [--version] [--help] COMMAND [ARGS]

Cele mai folosite comenzi sunt:

• annotate - Citește perf.data și afișează codul cu adnotări
• list - Listează numele simbolice ale tuturor tipurilor de evenimente ce pot fi urmărite de perf
• lock - Analizează evenimentele de tip lock
• record - Rulează o comandă și salvează informațiile de profiling în fișierul perf.data
• report - Citește perf.data (creat de perf record) și afișează profilul
• sched - Utilitar pentru măsurarea proprietăților planificatorului (latențe)
• stat - Rulează o comandă și afișează statisticile înregistrate de subsistemul performance counters
• top - Generează și afișează informații în timp real despre încărcarea unui sistem

• man perf-list

Afișează numele simbolice ale tuturor tipurilor de evenimente ce pot fi urmărite de perf.

$ perf list 
List of pre-defined events (to be used in -e):
 
  cpu-cycles OR cycles                       [Hardware event]
  instructions                               [Hardware event]
 
  cpu-clock                                  [Software event]
  page-faults OR faults                      [Software event]
 
  L1-dcache-loads                            [Hardware cache event]
  L1-dcache-load-misses                      [Hardware cache event]
 
  rNNN                                       [Raw hardware event descriptor]
 
  mem:<addr>[:access]                        [Hardware breakpoint]
 
  syscalls:sys_enter_accept                  [Tracepoint event]
  syscalls:sys_exit_accept                   [Tracepoint event]

Atunci când un eveniment nu este disponibil în forma simbolică, poate fi folosit cu perf în forma procesorului din sistemul analizat.

• perf-stat

Rulează o comandă și afișează statisticile înregistrate de subsistemul performance counters.

$ perf stat ls -R /usr/src/linux
 Performance counter stats for 'ls -R /usr/src/linux':
 
         934.512846  task-clock-msecs         #      0.114 CPUs 
               1695  context-switches         #      0.002 M/sec
                163  CPU-migrations           #      0.000 M/sec
                306  page-faults              #      0.000 M/sec
          725144010  cycles                   #    775.959 M/sec 
          419392509  instructions             #      0.578 IPC   
           80242637  branches                 #     85.866 M/sec 
            5680112  branch-misses            #      7.079 %     
          174667968  cache-references         #    186.908 M/sec 
            4178882  cache-misses             #      4.472 M/sec 
 
        8.199187316  seconds time elapsed

perf stat oferă posibilitatea colectării datelor în urma rulării de mai multe ori a unui program specificând opțiunea -r.

$ perf stat -r 6 sleep 1
 Performance counter stats for 'sleep 1' (6 runs):
 
           1.757147  task-clock-msecs #      0.002 CPUs    ( +-   3.000% )
                  1  context-switches #      0.001 M/sec   ( +-  14.286% )
                  0  CPU-migrations   #      0.000 M/sec   ( +- 100.000% )
                144  page-faults      #      0.082 M/sec   ( +-   0.147% )
            1373254  cycles           #    781.525 M/sec   ( +-   2.856% )
             588831  instructions     #      0.429 IPC     ( +-   0.667% )
             106846  branches         #     60.806 M/sec   ( +-   0.324% )
              11312  branch-misses    #     10.587 %       ( +-   0.851% )
        1.002619407  seconds time elapsed   ( +-   0.012% )

Observați mai sus evenimentele cele mai importante contorizate.

• man perf-top

Generează și afișează informații în timp real despre încărcarea unui sistem.

$ ls -R /home
$ perf top -p $(pidof ls)
--------------------------------------------------------------
   PerfTop:     181 irqs/sec  kernel:72.4% (target_pid: 10421)
--------------------------------------------------------------
             samples  pcnt function             DSO
             _______ _____ ____________________ ___________________
 
              270.00 15.8% __d_lookup           [kernel.kallsyms]  
              145.00  8.5% __GI___strcoll_l     /lib/libc-2.12.1.so
               99.00  5.8% link_path_walk       [kernel.kallsyms]  
               97.00  5.7% find_inode_fast      [kernel.kallsyms]  
               91.00  5.3% __GI_strncmp         /lib/libc-2.12.1.so
               55.00  3.2% move_freepages_block [kernel.kallsyms]  
               44.00  2.6% ext3_dx_find_entry   [kernel.kallsyms]  
               41.00  2.4% ext3_find_entry      [kernel.kallsyms]  
               40.00  2.3% dput                 [kernel.kallsyms]  
               39.00  2.3% ext3_check_dir_entry [kernel.kallsyms]  

Observăm că funcțiile de lucru cu fișiere (parcurgere, căutare) sunt cele care apar cel mai des în outputul lui perf-top corespunzător rulării comenzii de listare recursivă a directorului home.

• man perf-record

Rulează o comandă și salvează informațiile de profiling în fișierul perf.data.

$ perf record wget http://elf.cs.pub.ro/so/wiki/laboratoare/laborator-07
 
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.008 MB perf.data (~334 samples) ]
 
$ ls
laborator-07  perf.data

• man perf-report

Interpretează datele salvate în perf.data în urma analizei folosind perf record. Astfel pentru exemplul wget de mai sus avem:

$ perf report 
# Events: 13  cycles
#
# Overhead  Command      Shared Object  Symbol
# ........  .......  .................  ......
#
    86.43%     wget             e8ee21  [.] 0x00000000e8ee21
    11.03%     wget  [kernel.kallsyms]  [k] prep_new_page
     2.37%     wget  [kernel.kallsyms]  [k] sock_aio_read
     0.11%     wget  [kernel.kallsyms]  [k] perf_event_comm
     0.05%     wget  [kernel.kallsyms]  [k] native_write_msr_safe

strace interceptează şi înregistrează apelurile de sistem făcute de un proces şi semnalele pe care acesta le primeşte. În cea mai simplă formă strace rulează comanda specificată până când procesul asociat se încheie.

$strace cat /proc/cpuinfo
execve("/bin/cat", ["cat", "/proc/cpuinfo"], [/* 30 vars */]) = 0
open("/proc/cpuinfo", O_RDONLY)         = 3
read(3, "processor\t: 0\nvendor_id\t: Genuin"..., 32768) = 3652
write(1, "processor\t: 0$\nvendor_id\t: Genui"..., 7512) = 7512

Cele mai folosite opțiuni pentru strace sunt:

• -f, cu această opțiune vor fi urmărite şi procesele copil create de procesul curent
• -o filename, în mod implicit strace afişează informațiile la stderr. Cu această opțiune, output-ul va fi pus în fişierul filename
• -p pid, pid-ul procesului de urmărit.
• -e expresie, modifică apelurile urmărite.

• daniel@debian$ strace -f -e connect,socket,bind -p $(pidof iceweasel)
  Process 6429 attached with 30 threads - interrupt to quit
  socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 50
  connect(50, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("141.85.227.65")}, 16) = -1 EINPROGRESS
   

Un alt utilitar înrudit cu strace este ltrace. Acesta urmăreşte apelurile de bibliotecă.

Scopul unui debugger (de exemplu GDB, prin comanda gdb) este să ne permită să inspectăm ce se întâmplă în interiorul unui program în timp ce acesta rulează sau la terminarea execuției acestuia, în momentul când s-a produs o eroare fatală, pe baza fișierului coredump creat de către acesta.

Mai multe detalii în secțiunea de resurse.

Valgrind reprezintă o suită de utilitare folosite pentru debugging și profiling. Printre cele mai folosite tool-uri sau unelte din această suită sunt:

• memcheck - Realizează analiza utilizării memoriei
• cachegrind - Realizează analiza performanței cache-ului
• helgrind - Folosit pentru depanarea condițiilor de cursă în cadrul programelor cu multiple fire de execuție (multithreaded).

Mai multe detalii aici.

• Oprofile
• Kernrate este un echivalent al oprofile pentru Windows.
• KCachegrind
• perf-tools
• XPerf
• GNU gprof

Scopul exercițiului este să analizăm numărul de instrucțiuni executate de către procesor pe baza unui executabil. Perf pune la dispoziție un mod de a extrage datele importante din profiling prin suportul de scripting oferit de perf script. Acesta funcționează împreună cu perf record care obține lista de sample-uri și o salvează în fișierul perf.data.

Intrați în directorul 1-custom. Primul pas este să generăm fișierul perf.data care conține sampleurile. Pentru asta executați :

make
sudo perf record -e cycles:pp -c 10000 -d ./hash

Folosiți comanda perf script cu opțiunea -F (investigați man perf-script) astfel încât să gasiți numărul total de valori ale instruction pointer-ului și apoi pe cele aflate în funcția hash_search_index. Având cele două valori, calculați procentul valorilor din funcția hash_search_index.

Opțional, puteți folosi script-ul pus la dispoziție în cadrul laboratorului pentru a calcula numărul de accese în cadrul funcției hash_search_index. Cu ajutorul lui perf script se pot parsa eventurile înregistrate în sample-uri în metoda process_event. Mai multe informații despre perf script se pot găsi la: man perf-script-python și exemplu de utilizare

Verificați rezultatul utilizând comanda perf report.

Folosind utilitarul perf_3.2 dorim să determinăm dacă limbajul C este column-major sau row-major (row-major-order).

Intrați în directorul 2-major și completați programul row.c astfel încât să incrementeze elementele unei matrice pe linii, după care completați programul columns.c astfel încât să incrementeze elementele unei matrice pe coloane.

Determinați numărul de cache-miss-uri comparativ cu numărul de accese la cache folosind perf stat pentru a urmări evenimentul L1-dcache-load-misses. Pentru a vedea evenimentele disponibile folosiți comanda perf list. Folosiți opțiunea -e a utilitarului perf pentru a specifica un anumit eveniment de urmărit (revedeți secțiunea perfcounters).

Intrați în directorul 3-busy și inspectați fișierul busy.c. Rulați programul busy și analizați încărcarea sistemului folosind comanda sudo perf top. Ce funcție pare să încarce sistemul?

Intrați în directorul 4-find-char/ și analizați conținutul fișierului find-char.c. Compilați fișierul find-char.c și rulați executabilul obținut.

Identificați, folosind perf record și perf report, care este funcția care ocupă cel mai mult timp de procesor și încercați să îmbunătățiți performanțele programului.

Intrați în directorul 5-print/ și analizați conținutul fișierului print.c. Folosiți comanda make print pentru a compila programul print. Există fișierul Makefile?

Care este ordinea în care se fac scrierile la consolă? Explicați output-ul.

Puneți o instrucțiune sleep(5) înainte de return 0; în funcția main și folosiți comanda strace -e write ./print pentru a găsi explicația.

Intrați în directorul 6-flowers/ și analizați conținutul fișierului flowers.c. Compilați fișierul flowers.c şi rulați executabilul flowers. Ce se întâmplă? Folosiți valgrind cu opțiunea --tool=memcheck. Afișați valoarea celui de-al treilea element al array-ului flowers, adică flowers[2].

Intrați în directorul 7-exploit/ și analizați conținutul fișierului exploit.c. Folosiți comanda make pentru a compila executabilul exploit. Identificați o problemă în funcția read_name.

Folosiți gdb pentru a investiga stiva înaintea efectuării apelului read.

student@spook:~ gdb ./exploit
(gdb) break read_name
(gdb) run

Afișați adresele variabilelor name și access.

(gdb) print/x &access
(gdb) print/x &name

Observați că diferența între adresa variabilei access și adresa bufferului name este de 0x10 (16) octeți, ceea ce înseamnă că variabila access se află imediat la sfârșitul datelor din bufferul name.

Folosindu-vă de informațiile obținute, construiți un input convenabil pe care să îl oferiți executabilului exploit, astfel încât acesta să vă afișeze stringul “Good job, you hacked me!”.

student@spook:~ python -c 'print "A"*8 + "\x01\x00\x00\x00"' | ./exploit

Intrați în directorul 8-mystery/ unde găsiți executabilul mystery. Investigați și explicați ce face acesta. Revedeți secțiunea strace.

• GNU grof manual
• linux/tools/perf
• [Announce] Performance Counters for Linux, v8
• Profiling tools and techniques
• Is Parallel Programming Hard, And, If So, What Can You Do About It?
• gprof, Valgrind and gperftools – an evaluation of some tools for application level CPU profiling on Linux
• Linux Profiling Tools and Techniques