Olyan profiler-t (azaz olyan programot, ami statisztikát készít egy másik programról) keresek elsősorban Linux-ra, amely a forráskódban soronként jelzi, hogy melyik utasítás mennyi ideig tartott. Van ugyan egy-két hasznosnak tűnő profiler, de egyik sem képes kellően részletes kimutatásra. (tudtommal)
Például itt van a
gcov
: kiírja a teljes forráskódot és a sorok mellé odaírja, hogy mennyiszer hajtotta végre a program.
~/tmp $ gcc progi.c -o progi -fprofile-arcs -ftest-coverage
~/tmp $ ./progi
~/tmp $ gcov progi.c
File 'progi.c'
Lines executed:100.00% of 12
progi.c:creating 'progi.c.gcov'
~/tmp $ cat progi.c.gcov
-: 0:Source:progi.c
-: 0:Graph:progi.gcno
-: 0:Data:progi.gcda
-: 0:Runs:1
-: 0:Programs:1
-: 1:#include <stdio.h>
-: 2:#include <string.h>
-: 3:
-: 4:void
999999: 5:fuggveny( void )
-: 6:{
-: 7: static unsigned long int
-: 8: i = 0;
-: 9:
-: 10: char
999999: 11: src[ 10000 ] = { 255 },
999999: 12: dst[ 10000 ] = { 0 };
-: 13:
999999: 14: memcpy( dst, src, 1000 );
999999: 15: memcpy( dst, src, 10 );
-: 16:
999999: 17: i = (986 % 32) << (i / 1000);
-: 18:
999999: 19: return;
-: 20:}
-: 21:
-: 22:int
1: 23:main( void )
-: 24:{
-: 25: long int
1: 26: i = 999999;
-: 27:
1000001: 28: while( --i >= 0 )
-: 29: {
999999: 30: fuggveny();
-: 31: }
-: 32:
1: 33: return( 0 );
-: 34:}
Nem rossz, csak az a baj, hogy a végrehajtás mennyiségét ki lehet számolni, de az ideje nem olyan egyértelmű.
Emellett itt van a
gprof
: kiírja a függvények végrehajtásának idejét.
~/tmp $ gcc progi.c -o progi -pg
~/tmp $ time ./progi
real 0m2.186s
user 0m2.184s
sys 0m0.000s
~/tmp $ gprof -bp progi
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ns/call ns/call name
95.65 0.22 0.22 999999 220.00 220.00 fuggveny
4.35 0.23 0.01 main
Egy fokkal talán hasznosabb (lenne, ha érteném az összefüggést a
time
és a
gprof
idejei között), de egy függvényen belül a különböző utasítások különböző időt vehetnek igénybe, így nem mindig egyértelmű, hogy mitől lassú a függvény.
Végsősoron ennek a kettőnek az egyesülése tetszene: soronként írja ki az adott sor, vagy legalább egy blokk futtatásának idejét. Létezik-e ilyen, vagy ez a kettő esetleg képes rá, csak én nem tudom hogyan?
Megoldás
Hogy megnézzük, melyik függvény használja a legtöbb időt:
~/tmp $ gcc progi.c -o progi
~/tmp $ perf record -gf ./progi
[ perf record: Woken up 11 times to write data ]
[ perf record: Captured and wrote 1.528 MB perf.data (~66755 samples) ]
~/tmp $ perf report -d ./progi
# dso: ./progi
# Samples: 2380
#
# Overhead Command Symbol
# ........ ........... ......
#
99.08% progi [.] fuggveny
|
|--99.24%-- main
| __libc_start_main
| 0x8048351
|
--0.76%-- __libc_start_main
0x8048351
0.71% progi [.] main
0.21% progi [.] 0x00000000000320
#
# (For a higher level overview, try: perf report --sort comm,dso)
#
Hogy megtudjuk a függvény részleteit:
~/tmp $ gcc progi.c -o progi -ggdb
~/tmp $ perf record -gf ./progi
[ perf record: Woken up 11 times to write data ]
[ perf record: Captured and wrote 1.546 MB perf.data (~67553 samples) ]
~/tmp $ perf annotate fuggveny
------------------------------------------------
Percent | Source code & Disassembly of progi
------------------------------------------------
:
:
:
: Disassembly of section .text:
:
: 080483e4 <fuggveny>:
: #include <stdio.h>
: #include <string.h>
:
: void
: fuggveny( void )
: {
0.12 : 80483e4: 55 push %ebp
0.00 : 80483e5: 89 e5 mov %esp,%ebp
0.00 : 80483e7: 57 push %edi
0.12 : 80483e8: 56 push %esi
0.16 : 80483e9: 53 push %ebx
0.12 : 80483ea: 81 ec 4c 4e 00 00 sub $0x4e4c,%esp
: static unsigned long int
: i = 0;
:
: char
: src[ 10000 ] = { 255 },
0.00 : 80483f0: 8d 85 d8 d8 ff ff lea -0x2728(%ebp),%eax
0.00 : 80483f6: ba 10 27 00 00 mov $0x2710,%edx
0.16 : 80483fb: 89 54 24 08 mov %edx,0x8(%esp)
0.00 : 80483ff: c7 44 24 04 00 00 00 movl $0x0,0x4(%esp)
0.00 : 8048406: 00
0.08 : 8048407: 89 04 24 mov %eax,(%esp)
0.20 : 804840a: e8 11 ff ff ff call 8048320 <memset@plt>
0.67 : 804840f: c6 85 d8 d8 ff ff ff movb $0xff,-0x2728(%ebp)
...
Bár jobb lenne, ha az időfelhasználást százalék helyett a valódi értékével írná ki - mert ha a progi mondjuk kibővül egy újabb függvénnyel, akkor arányában ez a függvény kevesebb időt vesz igénybe, de ugyanannyi másodpercig tart, mint a program módosítása előtt - de így is nagyon hasznos információkkal szolgál.