Kihagyás

Profilozás

Profilozás/profiling

A kód-profilozó eszközök segítik a programm működését és erőforrás-felhasználását elemezni (legyez az az erőforrás CPU használat, sávszélesség, órajelek száma, memória használat). Ha optimalizálni akarjuk a kódunkat az első lépés, hogy adatot gyűjtünk róla. Melyik függvényben tölti a legtöbb időt a program? Mi fogyasztja a legtöbb memóriát? A profilozás eredményeire támaszkodva újraírhatjuk a programunk sokat fogyasztó, csekély hatékonyságú részeit, potenciális bugok detektálásban segíthet.

A legtöbb profilozó dinamikus elemzést alkalmaz, vagyis a futó programon végeznek méréseket. (Ezzel szemben a statikus elemzés a program forráskódját elemzi és az alapján következtet). A dinamikus mérések különféle stratégiával végezhetőek. Pl. mérést végző kód injektálása az elemzett programba, program futtatása egy mérésre kialakított, speciális környezetben, erőforrásigények nagy frekvenciájú mérése.

Futásidő mérés a time programmal

Unix rendszereken elérhető a time nevű program. Nagyon egyszerű mérőeszköz. Az egész program futásidejét lehet a segítségével kimérni. Például egyszerűen összevethetjük vele ugyanannak az algoritmusnak többféle megvalósítását. Például vessük össze a buborék rendezés és a gyorsrendezés időigényét ugyanazokon a tömbökön (bubbleSort.c és quickSort.c, illetve hogy biztosak legyünk abban, hogy ugyanazon tömböket használja a két program, így annak megadását szervezzük ki: array.h). A buborék rendezés egy egyszerűbb, lassabb algoritmus és ezt látjuk is az eredményekben. Már egy 10000 méretű tömb rendezésekor is észlelhető a különbség.

1
2
3
4
5
6
7
8
time ./bs > /dev/null
real    0m0,838s
user    0m0,827s
sys     0m0,009s
time ./qs > /dev/null
real    0m0,013s
user    0m0,007s
sys     0m0,005s

A real a teljes futásidő indítástól befejezésig (beleértve azt az időt is, amit a process pl. I/O műveletre való várakozással tölt). A user az az idő, amit a CPU user módban tölt a process futása közben, a sys pedig a kernel módban tölött időt adja meg.

A time nem egy kifinomult profiling eszköz, de unix rendszereken alapból elérhető és használható a már lefordított binárisokon.

gprof

A standard C/Unix profilozó eszköz a gprof. Mérési módszere a snapshot készítés. Leírás itt: https://sourceware.org/binutils/docs-2.16/gprof/

Rendkívül egyszerű a használata, annyi extra igénye van csak, hogy fordításkor kell egy extra kapcsoló. Le kell futtatni a programot, ekkor a gprof előállítja róla az adatokat, melyeket később ki lehet elemezni.

gcc bubbleSort.c -o bs -Wall -pg

A -pg a profilozó kapcsoló. Ez instrumentálja a kódban lévő függvényeket. A gprof hátránya, hogy ha olyan függvény van behívva, ami nem volt instrumentálva (pl. könyvtári függvények), akkor az abban tölött időről nem mond információt.

Ha a -pg-vel fordított programot lefuttatjuk, kapunk egy gmon.out fájlt a bináris mellett. Ezután az elemzés előállítása az alábbi programmal történik:

gprof bs gmon.out > analysis.txt

Minden profiling információ a txt-ben található. A buborék rendező program ezúttal egy 5000 méretű tömböt rendezett. Érdekesség, hogy a time a profilozáshoz instrumentált bináris futását 0,120 másodpercre mérte, míg a normális binárisét csak 0,072 másodpercre. Látható, hogy a profilozás jelentősen lassíthatja a program futását. A gyors rendezés ugyanekkora méretű tömb esetén sajnos túl gyors volt a gprofnak, nem szolgáltatott hozzá használható futásidő adatot. A buborékrendezés analíziséből részlet:

1
2
3
4
5
    %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 88.37      0.30     0.30        1   300.47   340.53  bubbleSort
 11.78      0.34     0.04 24969088     0.00     0.00  swap
  0.00      0.34     0.00        1     0.00     0.00  printArray

A futásidő 88%-a a bubbleSort függvényben lett eltöltve, 12%-a pedig a swap függvényben. Fontos adat még a self seconds oszlop: mennyi idő lett eltöltve csak abban az egy adott függvényben.

valgrind

A memóriaelemzés mellett a valgrind az egyik leginkább használt profilozó, hibadetektáló eszköz. Sokféle funkcióval, kiegészítő tool-lal rendelkezik:

  • Massif: heap profilozó
  • Cachegrind: L1/L2 gyorsítótárakat szimulálja és számlálja hányszor volt hit/miss (megtalált/nem talált meg valamit a gyorsítótárban)
  • Callgrind: a gprof-hoz hasonlóan számolgatja hányszor lett meghívva egy függvény, hány utasítás lett végrehajtva egy függvényben stb. Hívási gráfot is épít.
  • Memcheck

A legfontosabb funkcióját már láttuk, ez az, hogy segíti a memóriakezelési hibák detektálását. Ezt alátámasztja, hogy defaultból a memcheck fut le az elemzett programra.

A valgrind használatához nem kell extra fordítási kapcsoló, de ajánlott debug szimbólumokkal fordítani (-g), hogy pl. sorszámok is kerüljenek a valgrind outputjába.

Valgrind - profilozás

Tekintsük továbbra is a buborékrendezést. A két fő profilozó eszköz a Callgrind és a Cachegrind.

1
2
3
4
5
6
7
8
gcc bubbleSort.c -o bs -g
valgrind --tool=callgrind ./bs
[fölös output kivágva]
==1917185==
==1917185== Events    : Ir
==1917185== Collected : 1830714179
==1917185==
==1917185== I   refs:      1,830,714,179

A buborékrendezés 10000 elemű tömbön futott le. Ezalatt a valgrind több mint 1,8 milliárd "eseményt" rögzített. Ez a végrehajtott assembly utasítások számának fogható fel.

Futás közben keletkezett egy callgrind.out.1917185 nevű fájl is a bináris mellett (ahol a szám a process id). Ez egy szöveges output, de még kevésbé érthető, mint amit a gprof produkál. Feldolgozásában segít a callgrind_annotate program. A program használata:

1
callgrind_annotate --auto=yes callgrind.out.69911

Az --auto=yes opcióval érhetjük el, hogy C utasításonként kapjunk elemzést, egyébként csak függvény szintű lenne.

Egy output részlet:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
          .           // A function to implement bubble sort
          .           void bubbleSort(int arr[], int n)
          5 ( 0.00%)  {
          .              int i, j;
     50,001 ( 0.00%)     for (i = 0; i < n-1; i++)
          .
          .                  // Last i elements are already in place
300,039,993 (16.39%)         for (j = 0; j < n-i-1; j++)
749,925,000 (40.96%)             if (arr[j] > arr[j+1])
349,567,232 (19.09%)                swap(&arr[j], &arr[j+1]);
424,474,496 (23.19%)  => bubble.c:swap (24,969,088x)
          4 ( 0.00%)  }

A számok mutatják, hogy az adott C kódsorhoz mennyi gépi utasítás végrehajtása tartozott. Látszik az is, hogy a swap 349,567,232-szor lett meghívva. Ezek a számok exkluzívak, azaz a meghívott függvényekben lefutott utasítások száma nem adódik hozzá a hívó számaihoz.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
          .           void printArray(int arr[], int size)
          5 ( 0.00%)  {
          .               int i;
     40,005 ( 0.00%)      for (i=0; i < size; i++)
    120,004 ( 0.01%)          printf("%d ", arr[i]);
  6,334,948 ( 0.35%)  => ./stdio-common/./stdio-common/printf.c:printf (10,000x)
        637 ( 0.00%)  => ./elf/../sysdeps/x86_64/dl-trampoline.h:_dl_runtime_resolve_xsave (1x)
          7 ( 0.00%)      printf("\n");
        674 ( 0.00%)  => ./elf/../sysdeps/x86_64/dl-trampoline.h:_dl_runtime_resolve_xsave (1x)
        213 ( 0.00%)  => ./libio/./libio/putchar.c:putchar (1x)
          3 ( 0.00%)  }

A printArray függvény utasításait nézve látjuk, hogy a könyvtári függvények is fel vannak oldva, azokhoz is tartozik utasításszám.