Profiliranje C/C++ koda

Glavna zadaća profiliranja koda je ustanoviti koji djelovi programa su uska grla u izvršavanju kako bi kasnije mogli te djelove zamijeniti sa efikasnijim implementacijama.

Predstavljamo dva alata za profiliranje i njihovo korištenje pod linux-om: valgrind --tool=callgrind i gprof. Smatramo da ukoliko su oba alata dostupna, valgrind je bolji izbor. Isto tako, preporuka je da za profiliranje programa računalo koje koristite bude u što "mirnijem" stanju kako bi ste dobili točnije rezultate.

Samostalno mjerenje

Za najjednostavnije slučajeve, pod linuxom moguće je koristiti naredbu time koja mjeri vrijeme izvršavanja neke naredbe:

$ time find /etc > /dev/null

real    0m0.066s
user    0m0.024s
sys     0m0.044s

real vrijeme je vrijeme koje mjeri vanjski promatrač. user vrijeme je vrijeme koje je proces proveo izvršavajući svoje naredbe, dok je sys vrijeme u kojem program čeka na odgovor od jezgre operacijskog sustava. Vrijedi .

Ovaj način dobar nam je za mjeriti razlike u cijelim programima, npr. radi li brute force algoritam sporije od pravog rješenja zadatka? No, ako želimo mjeriti određeni dio programa, na raspolaganju imamo funkciju clock().

#include <cstdio>
#include <ctime>

int main() {
  clock_t t0 = clock();
  for (int j = 0; j < 1e9; ++j);
  printf("Poziv je trajao %.3lfs\n",
            (double) (clock() - t0) / CLOCKS_PER_SEC);
  return 0;
}

Postoje i precizniji načini za mjerenje vremena u samom programu, no ovaj je najjednostavniji.

gprof

Kako bi program bio profiliran s gprof-om, potrebno je pri kompajliranju dodati zastavice -pg:

$ g++ -pg -oprogram program.cpp

Nakon što pokrenemo takav program i on se izvrši i exit-a svojom voljom, u radnom direktoriju vidimo datoteku gmon.out.

$ ./program; ls
gmon.out  program  program.cpp

Analizu izrvšavanja dobivamo pokretanjem naredbe:

$ gprof ./program

valgrind

Kako bi smo profilirali program s alatom valgrind, nije potrebno dodavati zastavice prilikom kompajliranja, no ipak rezultati će biti lakše čitljiviji ako imamo zastavicu za debug simbole -g, kao što smo imali i u primjeru sa gprof.

Program pokrećemo pod valgrindom na sljedeći način:

$ valgrind --tool=callgrind ./program; ls
callgrind.out.1817  program  program.cpp

Nakon izvršavanja u radnom direktoriju postojati će datoteka callgrind.out.PID, gdje je PID identifikator procesa koji je profiliran.

Analizu izvršavanja dobivamo izvršavanjem naredbe:

$ callgrind_anotate callgrind.out.*

Ukoliko vaše okruženje ima grafičko sučelje, program kcachegrind prikazati će ovaj rezultat grafički. Nedostatak alata valgrind je brzina izvršavanja. Naime, program koji se pokreće pod valgrind-om, nekoliko je puta sporiji.

primjer

Slijedi program koji će se koristiti za primjer. Kako bi ste poredali funkcije a(), b(), c() po brzini izvršavanja?

int a(int x) {
  for (int j = 0; j < x; ++j)
    if (x*(x+1)*(x+2)*(x+3)*(x+4));
}

void b(int x) {
  for (int j = 0; j < x; ++j)
    if (x % 3373 + x % 331);
}

void c(int x) {
  for (int j = 0; j < x; ++j)
    for (int k = 0; k < 5; ++k);
}

int main() {
  for (int i = 0; i < 500; ++i) a(1e5);
  for (int i = 0; i < 500; ++i) b(1e5);
  for (int i = 0; i < 500; ++i) c(1e5);
  return 0;
}

Analiza umetanjem clock() poziva

$ g++ -oprogram program-clock.cpp && ./program > clock-analiza.txt

Analiza alatom gprof

$ g++ -pg -oprogram program.cpp && ./program && gprof ./program > gprof-analiza.txt

Analiza alatom valgrind

$ g++ -g -oprogram program.cpp && valgrind --tool=callgrind ./program && callgrind_annotate callgrind.out.* > valgrind-analiza.txt

rezultati

a: 0.200s
b: 0.450s
c: 0.830s

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 56.76      0.84     0.84      500     1.68     1.68  c(int)
 29.73      1.28     0.44      500     0.88     0.88  b(int)
 13.51      1.48     0.20      500     0.40     0.40  a(int)

(...)

(...)

--------------------------------------------------------------------------------
           Ir  file:function
--------------------------------------------------------------------------------
1,850,006,000  header.h:c(int) [/root/profil/program]
1,700,007,500  header.h:b(int) [/root/profil/program]
  300,006,000  header.h:a(int) [/root/profil/program]

(...)

Zaključujemo da je funkcija a uvjerljivo najbrža, dok su b i c otprilike izjednačene po broju instrukcija, no c je uvjerljivo vremenski sporija. Razlog tome da se vremena mjerena u procesorskim instrukcijama i stvarnim sekundama razlikuju za funkcije b i c, možemo pronaći u činjenici da c koristi dodatnu varijablu koju program sprema u memoriju što može u nekim slučajevima uzrokovati skupi cache miss.

• Mikro-optimizacije, iskorištavanje cache sustava procesora