Kihagyás

Dinamikus program analízis profile-ozás segítségével

A kód-profilozó eszközök segítik a program 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). A buborék rendezés egy egyszerűbb, lassabb algoritmus és ezt látjuk is az eredményekben. Már egy 1000 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,003s
user    0m0,003s
sys     0m0,000s
time ./qs > /dev/null
real    0m0,001s
user    0m0,001s
sys     0m0,000s

A real a teljes futásidő indítástól befejeződé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öltö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    
 50.22      0.03     0.03  6149290     0.00     0.00  swap
 50.22      0.06     0.03        1    30.13    60.26  bubbleSort
  0.00      0.06     0.00        1     0.00     0.00  printArray

A futásidő 50%-a a bubbleSort függvényben lett eltöltve, 50%-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. Feltűnhet, hogy az összeg nem adja ki a time által mondott teljes futásidőt (nem instrumentált függvények hatása, pl. a printf-nek nyoma sincs az outputban).

Gcov

A kód lefedettségét lehet vele vizsgálni. Ez főleg annak meghatározásában hasznos, hogy ha írtunk teszteket a programhoz, azok mennyire fedik le a kódunk kódsorait illetve elágazásait (~ milyen alaposan van tesztelve a program). Használatához a fordításkor meg kell adni két extra kapcsolót:

1
gcc -Wall -fprofile-arcs -ftest-coverage vigenere.c -o vig

Majd a futtatás(ok) után az alábbi módon lehet az outputot kinyerni:

1
gcov vigenere.c

Ha a korábban használt vigenere.c programot parancssori argumentum nélkül futtatjuk le az alábbi outputot kapjuk:

1
2
3
File 'vigenere.c'
Lines executed:16.67% of 24
Creating 'vigenere.c.gcov'

Vagyis a kódsoroknak csak egy kis hányada fog lefutni. Ha még egyszer lefuttatom és adok a programnak argumentumot, akkor a két lefedettség összegődik.

1
2
3
File 'vigenere.c'
Lines executed:83.33% of 24
Creating 'vigenere.c.gcov'

Rézletesebb, branch (elágazás) szintű lefedettség kapható a -b kapcsolóval:

1
2
3
4
5
6
7
> gcov -b vigenere.c 
File 'vigenere.c'
Lines executed:83.33% of 24
Branches executed:100.00% of 14
Taken at least once:78.57% of 14
Calls executed:66.67% of 6
Creating 'vigenere.c.gcov'

Valgrind

Az egyik leginkább használt profilozó, hibadetektáló eszköz. Sokféle funkcióval, kiegészítő tool-al 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ója talán nem is a mérések elvégzése, hanem hogy segít memóriakezelési hibák detektálásában. Ezt alátámasztja, hogy defaultból a memcheck fut le az elemzett programra.

A valgrind egy virtuális gépen futtatja a programot, eközben végzi az ellenőrzéseket. Dinamikusan újrafordítja a programot, eközben egy köztes reprezentációba lesz lefordítva (IR - Intermediate representation), amit az elemzéshez használt programok manipulálhatnak. Sajnos ez az eljárás jelentősen növeli a futásidőt. 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.

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]
==69911== 
==69911== Events    : Ir
==69911== Collected : 456642926
==69911== 
==69911== I   refs:      456,642,926

A buborékrendezés 5000 elemú tömbön futott le. Ezalatt a valgrind több mint 456 millió "eseményt" röngzített. Ez a végrehajtott assembly utasítások számának fogható fel.

Futás közben keletkezett egy callgrind.out.69911 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 callgrind.out.69911

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  { 
          .     int i, j; 
     25,006     for (i = 0; i < n-1; i++)       
          .    
          .         // Last i elements are already in place    
 75,050,000         for (j = 0; j < n-i-1; j++)  
187,537,500             if (arr[j] > arr[j+1]) 
 86,090,060                swap(&arr[j], &arr[j+1]); 
104,537,930  => bubbleSort.c:swap (6,149,290x)
          4  }

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 6,149,290-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
          .  /* Function to print an array */
          .  void printArray(int arr[], int size) 
          5  { 
          .      int i; 
     20,009      for (i=0; i < size; i++) 
     55,015          printf("%d ", arr[i]); 
  3,130,243  => /build/glibc-WZtAaN/glibc-2.30/stdio-common/printf.c:printf (5,000x)
      1,271  => /build/glibc-WZtAaN/glibc-2.30/elf/../sysdeps/x86_64/dl-trampoline.h:_dl_runtime_resolve_xsave (1x)
          7      printf("\n"); 
        872  => /build/glibc-WZtAaN/glibc-2.30/elf/../sysdeps/x86_64/dl-trampoline.h:_dl_runtime_resolve_xsave (1x)
          3  }

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.

A program két legtöbbet használt függvénye (és a bennük végrehajtott utasításszám):

1
2
348,702,575  bubbleSort.c:bubbleSort [/root/Documents/sort/bs]
104,537,930  bubbleSort.c:swap [/root/Documents/sort/bs]

A gyorsítótár szimuláláshoz a --simulate-cache=yes kapcsolóval kell futtatni a valgrind-et. Ebbe nem megyünk bele, de érdekességképp megtekinthető milyen eredményt ad.

Ha sokalljuk a callgrind outputját, lehet szűrést is megadni neki, mit mérjen! Például így csak az swa szubsztringet tartalmazó függvényekben mér (ami a bubbleSort programunk esetén csak a swap függvényre lesz igaz)

1
2
3
4
5
6
valgrind --tool=callgrind --toggle-collect='*swa*' ./bs
==70102== 
==70102== Events    : Ir
==70102== Collected : 104537930
==70102== 
==70102== I   refs:      104,537,930

Ha pedig a sok szöveges outputból van már elegünk, akkor erre is van megoldás: a KCacheGrind grafikusan jeleníti meg a callgrind általal generált fájlt.

kcachegrind callgrind.out.69911

kcg

A látvány első ránézésre ijesztő, a program rengeteg információt zúdít ránk. Baloldalt a programunkban meghívott függvények listája látható. Legfölül van az, amelyikben a legtöbb időt töltötte. Ha nem értjük mi a legfölső függvény, segít a jobb alul látható hívási gráf kezdemény (Call graph fül). A képen nem látszik az egész gráf, de ez a legfölső függvény a belépési pont: ez fogja meghívni a main függvényt a _start-on és a below main-en át.

A kép jobb fölső részén lévő diagram (Callee Map) azt szemlélteti, hogy mely két függvényben töltötte a legtöbb időt a program. A barna és a kék kockát (bubbleSort, swap függvények) körbebvevő sötétebb illetve világosabb zöld keretek az őket hívó függvényeket (pl. main) reprezentálják.

Az alábbi kép a printArray függvényről kiexportálható hívási gráf: látjuk a hívókat és a meghívottakat (ami érdekesség, hogy látszódnak a printf "alatti" hívások is, amik a tényleges kiíratást végzik)

call_graph

Tehát a KCacheGrind kiválóan alkalmas a program működésének elemzésére (mi lett hívva, mennyiszer, mi mit hívott stb.)

Memóriahasználat

Tekintsük az alábbi programot:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
#include <stdio.h>
#include <string.h>
#include <stdlib.h>

char* wordRepeater(char w[], unsigned short times){
  char * result = malloc(strlen(w) * times);
  if(times > 0){
   times--;
   strcpy(result, w);
  }
  while(times > 0){
   strcat(result,w);
   times--;
  }
  return result;
}

int main(){

  char word[10];
  unsigned short times;
  printf("How many times shall i repeat the word?");
  scanf("%d %9s", &times, word);
  printf("The result:%s\n", wordRepeater(word, times));

  return 0;
}

A program a main függvényben beolvas egy számot és egy sztringet. Ezt a sztringet aztán annyiszor megismétli egy dinamikusan foglalt tömbben, amennyi a beolvasott szám. Hol vannak hibák a programban?

Memória ellenőrzés:

valgrind --leak-check=full --show-leak-kinds=all --track-origins=yes ./memory

Opcionálisan még a verbose kapcsoló is megadható részletesebb outputért.

Egy output részlet:

1
2
3
4
5
6
LEAK SUMMARY:
==19906==    definitely lost: 36 bytes in 1 blocks
==19906==    indirectly lost: 0 bytes in 0 blocks
==19906==      possibly lost: 0 bytes in 0 blocks
==19906==    still reachable: 0 bytes in 0 blocks
==19906==         suppressed: 0 bytes in 0 blocks
  • definetly lost: garantáltan felszabadítatlanul maradt memóriarészek, melyek már nem elérhetőek (megszűnt a rájuk mutató pointer) Példa
  • indirectly lost: elveszett a pointer egy olyan objektumra, ami további dinamikus memóriaterületre mutatott. Példa
  • possibly lost: Elméletileg még elérhető volna a lefoglalt memóriaterület valamilyen trükkel, hogy fel legyen szabadítva a terület, de valószínűleg inkább hibáról van szó (például ha elléptettük a tömb elejére mutató pointert) Példa
  • still reachable: Pl. a dinamikusan foglalt memóriára egy globális változóként tárolt pointer mutat. Vagyis a memória nincs felszabadítva, de még a program futásának a végén is elérhető volna. Példa
  • suppressed: Ha megadunk a valgrindnek egy listát, ide sorolódnak azok a memory leakek, amiket nem akarunk/tudunk javítani (pl. library hibája)

Példafeladatok

Utolsó frissítés: 2023-05-02 09:18:11