line-by-line time based profiler

 ( BimbaLaszlo | 2012. szeptember 22., szombat - 14:35 )

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 
        -:    2:#include 
        -:    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 :
         :      #include 
         :      #include 
         :
         :      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 
    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.

Hozzászólás megjelenítési lehetőségek

A választott hozzászólás megjelenítési mód a „Beállítás” gombbal rögzíthető.

gperf-re nezzel ra, regebben neztem, akkor - ha jol emlekszem ra - kellett hozza kernel tamogatas is (hwpmc)

https://perf.wiki.kernel.org/index.php/Main_Page
___
info

Nagyjából ezt a megoldást kerestem, köszönöm szépen. (de nem gperf, csak perf és a kernelbe van építve, de pl. Debian-on a linux-tools csomaggal érhető el)
--
Azt akarom, hogy az emberek ne kényszerből tanuljanak, hanem azért, mert tudni akarnak.

Intel VTune (a non-commercial ingyenes Linuxra).

Ha a nyelv Perl lenne, a Devel::NYTProf pontosan azt tudná, amire szükséged van.

Az igényed teljesen alap, de sajnos egyszerűen nem teljesíthető. :)

Egy fontos dolog az elejére. A végrehajtási időt nem szabad összekeverni azzal, hogy mennyiszer hajtotta végre az adott függvényhívást/utasítást a processzor. Ahogy Te is írtad, a "különböző utasítások különböző időt vehetnek igénybe" (a feltételes mód nem is kell igazából bele).

Másodszor egy fontos kérdés. Milyen időre van szükséged?
1) relatív user (csak a saját programod idejét számítod user space-ben)
2) relatív user+kernel (csak a saját programod idejét számítod user és kernel space-ben)
3) wallclock (a részek összege a valós eltelt időt adja meg)

A relatív user idő segítségével tunningolhatod a programod részeit, de ettől még lehet, hogy lassú marad, mert kernelben elvesztegeted az időt. Saját algoritmikus problémák megtalálására teljesen jó.

A relatív user+kernel kicsit jobb, de pl. ha lock-ban vársz, akkor azt nem látod.

A wallclock a valós eltelt időt mutatja (ami tartalmazza az összes olyan várakozást, amin a programod ugyan nem teker, de attól még az idő telik). Itt bukik ki az, hogy fut a programod, de nem tudja kihajtani a processzort (pl. latencia miatt).

Problémák:
1) A gcc/gprof csak user time-ot mér.
2) A perf és az oprofile különböző számlálók (performance counters) segítségével dolgozik (ld. perf list). Ez nem jó neked, ha wallclock időre vagy kíváncsi.

És akkor mi a megoldás? Két lehetőség van. Az egyik az, hogy szépen belepakolsz a programodba saját számlálókat és mérési pontokat. Ez akkor jó, ha már nagyjából sejted, hogy hol a hiba és kis overheaddel konkrét méréseket szeretnél végezni. A másik lehetőség a megfelelő program használata. :) Az egyik az Intel VTune, ahogy azt már írták. Ezt még nem próbáltam, de jókat olvastam róla. A másik lehetőség, amit én többször használtam az a callgrind.

Használata: valgrind --tool=callgrind --callgrind-out-file=callg_$1.%p.log --dump-instr=yes --trace-jump=yes --separate-threads=yes --collect-systime=yes ./progi

A collect-systime megadásával fog wallclock időt mérni. Az kimenetének feldolgozására ajánlom a kcachegrind-ot.

Azt hozzá kell tennem, hogy a valgrind egy virtuális gép, úgyhogy nem gyors és ez bizonyos fajta méréseket teljesen elronthat (ilyenkor jön a saját kód).

Még egy hasznos program a mutrace (mutex profiler). Egyszerűen használható, minimális az overheadje.

Először is köszönöm a tanító jellegű választ.
Ahogy nézem, Te tényleg érthetsz ehhez a témakörhöz, örülnék, ha pár dologra válaszolnál:
Miért nem elegendő nekem a userspace idővel törődnöm? Úgy értem, hogy pl. a kernelben eltöltött időn (tudtommal) nem tudok változtatni, akkor miért foglalkozzak vele? Másfelől meg ez a wallclock idő, ha jól sejtem a rendszer által a progira fordított időnek felel meg. (bocsánat, ha nem így van, nem volt időm utánnanézni) Ha az előbbi mondat megfelel a valóságnak, akkor ezen se tudok változtatni - talán a nice szintjének változtatásával - ezért aztán ez se kellene, hogy érdekeljen szerintem.
Örülnék, ha ezen kérdéseim tisztázására tudnál pár linket adni, ami a témakörrel kezdők számára is érthető módon foglalkozik.
--
Azt akarom, hogy az emberek ne kényszerből tanuljanak, hanem azért, mert tudni akarnak.

> Úgy értem, hogy pl. a kernelben eltöltött időn (tudtommal) nem tudok változtatni, akkor miért foglalkozzak vele?

nyilvan az alkalmazastol is fugg, de ez igy nem teljesen igaz. az mplayerben pl igenis szamitott, hogy a kulso hivasok (pl. hangkartya device irasa) meddig tartanak, es ezen lehetett is segiteni pl. a blockmeret valtoztatassal, select()-el stb... ugyanez igaz pl. a halozati alkalmazasokra is.

A'rpi

> Ahogy nézem, Te tényleg érthetsz ehhez a témakörhöz

Csak annyira, hogy tudjam, hogy mennyire nem értek még hozzá. :)

> Miért nem elegendő nekem a userspace idővel törődnöm?

A'rpi nagyjából leírta a lényeget, csak pár szóval kiegészítem. Az össz kernel space-ben töltött időt két módon lehet csökkenteni:
1) kevesebb syscall
2) megfelelő adatkezelés (blokk méret)

A két mód gyakran együtt jár. A megfelelő adatkezelés nem csak a kernelre vonatkozik, hanem minden olyan API-ra illetve layer-re, ami blokkokkal dolgozik (tipikus példa a diszk és a hálózat). Syscall esetén pedig nem csak azzal kell számolni, amit csinál, hanem azzal az overheaddel is, amibe a syscall hívás kerül (ezért csinálták vsyscall-t).

Az, hogy ezzel kell-e foglalkoznod, az a programodtól függ. A példaprogramod esetén a time szépen kiírja, hogy gyakorlatilag az egész user space-ben futott. Ebben az esetben nincs mit optimalizálni kernel oldalról.

> Másfelől meg ez a wallclock idő, ha jól sejtem a rendszer által a progira fordított időnek felel meg.

Nem. A wallclock idő az, ami a faliórán eltelik a programod futása alatt. A rendszer W wallclock idő alatt T (0<T<=W) időt fordít a programra (az egyenlőség jel necces, csak nagyon kis W esetén lehet igaz multitask oprendszernél).

$ time sleep 5

real 0m5.005s
user 0m0.000s
sys 0m0.000s

Ebben az esetben W=5.005s és a rendszer (user+system) T=0s időt fordított a programodra (valójában persze nem 0, csak nagyon kicsi).

$ time md5sum /bin/bash
748c6ee926dd3cf55bcfb60ce928d367 /bin/bash

real 0m0.004s
user 0m0.004s
sys 0m0.000s

Ebben az esetben W=0.004s és a rendszer (user+system) T=0.004s időt fordított a programodra. Továbbá az is látszik, hogy az egész időt user space-ben töltötte (ami persze szintén nem igaz, csak olyan keveset volt kernel space-ben, hogy az kerekítési hiba áldozata lett). Amennyiben a fájl egy hálózati meghajtón lett volna, akkor mindjárt látszódna a sys-nél is valamennyi idő.

Ha T<W, akkor a programod az idő egy részében "nem csinál semmit". Ez lehet, hogy rendben van így (pl. egy szerver vár, hogy megszólítsa egy kliens), de lehet, hogy valahol van benne valamilyen tervezési hiba vagy ez a rendszer sajátossága, amivel együtt kell élni (pl. nem kapja elég gyorsan az adatokat a feldolgozó, ezért az várakozik). Ami a szép az egészben, hogy a másik oldal (T=W) is lehet egy hiba jelzője (pl. a programnak nem kellene csinálnia semmit, mivel nem kapott még adatot, de mégis eszi a CPU-t).

Száz szónak is egy a vége, komplex rendszer esetén e performancia tuning nagyon összetett feladat és a rendszer összes elemének a mélyreható ismeretét igényli.

> Örülnék, ha ezen kérdéseim tisztázására tudnál pár linket adni, ami a témakörrel kezdők számára is érthető módon foglalkozik.

Sajnos ilyennel nem tudok szolgálni. Ha van konkrét kérdésed, akkor megpróbálok válaszolni.

Miért nem elegendő nekem a userspace idővel törődnöm? Úgy értem, hogy pl. a kernelben eltöltött időn (tudtommal) nem tudok változtatni, akkor miért foglalkozzak vele?
Na igen, tulajdonkeppen a userspace-ben toltott ido a legerdekesebb szamodra, mivel az az egyetlen a harom kozul, ami a rendszer allapotatol fuggetlen. Viszont a rendszerhivasok altal felhasznalt idonek is van informaciotartalma, kulonosen ha noveled a mintavetelek szamat ;) Kepet kaphatsz arrol, mennyire intenziven hasznalod az interfeszt es milyen hatekonyan. Ami a profiling tool-okat illeti, kaptal mar par tippet, en meg talan a google-perftools-t emlitenem, szerintem egesz jol hasznalhato, ha C++-ban tolod. Egyebkent meg a sajat meresi pontokra eskuszom, erre irhatsz magadnak sajat megoldast, de pl. a Boost kinalataban is talalsz hasznos dolgokat (pl. Chrono).

bookmark