Jak używać narzędzi Google perf

Question

Właśnie zacząłem używać narzędzi wydajności Google (google-perftools i libgoogle-perftools4 pakietów w Ubuntu), przysięgam, że googlowałem przez około dzień i nie znalazłem odpowiedzi! Problem polega na tym, że nie uzyskuję wyniku dla WSZYSTKICH moich funkcji z profilowaniem procesora. To jest mój kod:

#include "gperftools/profiler.h" 
#include <iostream> 
#include <math.h> 
using namespace std; 
void bar() 
{ 
     int a,b,c,d,j,k; 
     a=0; 
     int z=0; 
     b = 1000; 
     while(z < b) 
     { 
       while (a < b) 
       { 
         d = sin(a); 
         c = cos(a); 
         j = tan(a); 
         k = tan(a); 
         k = d * c + j *k; 
         a++; 
       } 
       a = 0; 
       z++; 
     } 
} 
void foo() 
{ 
     cout << "hey " << endl; 
} 

int main() 
{ 
     ProfilerStart("/home/mohammad/gperf/dump.txt"); 

     int a = 1000; 
     while(a--){foo();} 
     bar(); 
     ProfilerFlush(); 
     ProfilerStop(); 
} 

skompilowane jako g++ test.cc -lprofiler -o a.out

ten sposób uruchomić kod:

CPUPROFILE=dump.txt ./a.out 

próbowałem zostały również to:

CPUPROFILE_FREQUENCY=10000 LD_PRELOAD=/usr/local/lib/libprofiler.so.0.3.0 CPUPROFILE=dump.txt ./a.out 

I jest to, co otrzymuję od google-pprof --text a.out dump.txt:

Using local file ./a.out. 
Using local file ./dump.txt. 
Total: 22 samples 
8 36.4% 36.4%  8 36.4% 00d8cb04 
6 27.3% 63.6%  6 27.3% bar 
3 13.6% 77.3%  3 13.6% __cos (inline) 
2 9.1% 86.4%  2 9.1% 00d8cab4 
1 4.5% 90.9%  1 4.5% 00d8cab6 
1 4.5% 95.5%  1 4.5% 00d8cb06 
1 4.5% 100.0%  1 4.5% __write_nocancel 
0 0.0% 100.0%  3 13.6% __cos 

Ale nie ma informacji o funkcji foo!

mój system informacji: ubuntu 12.04 g ++ 4.6.3

To wszystko!

Answer 1

TL; DR: foo jest szybki i mały, aby uzyskać profilowanie zdarzeń, uruchom go jeszcze 100 razy. Ustawienie częstotliwości było z literówką, a pprof nie pobiera próbek częściej niż CONFIG_HZ (zwykle 250). Lepiej jest przejść na bardziej nowoczesny profiler Linuksa perf (tutorial from its authors, wikipedia).

Długa wersja:

Twoja funkcja foo jest zbyt krótka i prosta - wystarczy zadzwonić dwie funkcje. Zestawione test z g++ test.cc -lprofiler -o test.s -S -g, z filtrowaniem test.s z c++filt programu uczynienia C++ nazwy czytelny:

foo(): 
.LFB972: 
     .loc 1 27 0 
     pushq %rbp 
     movq %rsp, %rbp 
     .loc 1 28 0 
     movl $.LC0, %esi 
     movl std::cout, %edi 
     call std::basic_ostream<char, std::char_traits<char> >& std::operator<< <std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*) 
     movl std::basic_ostream<char, std::char_traits<char> >& std::endl<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&), %esi 
     movq %rax, %rdi 
     call std::basic_ostream<char, std::char_traits<char> >::operator<<(std::basic_ostream<char, std::char_traits<char> >& (*)(std::basic_ostream<char, std::char_traits<char> >&)) 
     .loc 1 29 0 
     popq %rbp 
     ret 
.LFE972: 
     .size foo(), .-foo() 

Tak więc, aby zobaczyć go w profilu należy uruchomić foo wiecej razy, zmieniając int a = 1000; w głównym do czegoś znacznie większego , jak 10000 lub lepiej 100000 (tak jak ja do testu).

Możliwe jest również naprawienie nieprawidłowego "CPUPROFILE_FREQUENC=10000" w celu skorygowania CPUPROFILE_FREQUENCY (zwróć uwagę na Y). Powinienem powiedzieć, że 10000 jest zbyt wysokim ustawieniem dla CPUPROFILE_FREQUENCY, ponieważ zwykle może generować tylko 1000 lub 250 zdarzeń na sekundę w zależności od konfiguracji jądra CONFIG_HZ (większość jądra 3.x ma 250, sprawdź grep CONFIG_HZ= /boot/config*). I domyślne ustawienie dla CPUPROFILE_FREQUENCY w pprof to 100.

Przetestowałem różne wartości CPUPROFILE_FREQUENCY: 100000, 10000, 1000, 250 ze skryptem Bash na Ubuntu 14.04

for a in 100000 100000 10000 10000 1000 1000 300 300 250 250; do 
    echo -n "$a "; 
    CPUPROFILE_FREQUENCY=$a CPUPROFILE=dump$a.txt ./test >/dev/null; 
done 

i wyniki były takie same 120-140 wydarzenia i runtime każdy ./test około 0,5 sekundy, więc cpuprofiler z Google perftools nie może zrobić więcej zdarzeń na sekundę dla pojedynczego wątku niż zestaw CONFIG_HZ w jądrze (moje ma 250).

100000 PROFILE: interrupts/evictions/bytes = 124/1/6584 
100000 PROFILE: interrupts/evictions/bytes = 134/0/7864 
10000 PROFILE: interrupts/evictions/bytes = 125/0/7488 
10000 PROFILE: interrupts/evictions/bytes = 123/0/6960 
1000 PROFILE: interrupts/evictions/bytes = 134/0/6264 
1000 PROFILE: interrupts/evictions/bytes = 125/2/7272 
300 PROFILE: interrupts/evictions/bytes = 137/2/7984 
300 PROFILE: interrupts/evictions/bytes = 126/0/7216 
250 PROFILE: interrupts/evictions/bytes = 123/3/6680 
250 PROFILE: interrupts/evictions/bytes = 137/2/7352 

Z Original = 1000 foo i cout-tych funkcji przebiega zbyt szybko, aby uzyskać jakiekolwiek zdarzenie profilowania (nawet o 250 zdarzeń/s) na nich w każdym biegu, więc nie masz foo, ani dowolnego wejścia/funkcje wyjścia . W niewielkiej liczbie przebiegów, __write_nocancel może mieć próbkowanie, a następnie zgłaszane będą foo i funkcje I/O z biblioteki libstdC++ (gdzieś nie na samym szczycie, więc użyj opcji --text z pprof lub google-pprof) z zerową liczbą zdarzeń automatycznych, oraz liczyć wydarzenie niezerowe dziecko:

.... 
    1 0.9% 99.1%  1 0.9% __write_nocancel 
.... 
    0 0.0% 100.0%  1 0.9% _IO_new_file_overflow 
    0 0.0% 100.0%  1 0.9% _IO_new_file_write 
    0 0.0% 100.0%  1 0.9% __GI__IO_putc 
    0 0.0% 100.0%  1 0.9% foo 
    0 0.0% 100.0%  1 0.9% new_do_write 
    0 0.0% 100.0%  1 0.9% std::endl 
    0 0.0% 100.0%  1 0.9% std::ostream::put 

Z a=100000 foo jest nadal zbyt krótki i szybki, aby dostać własne zdarzenia, ale i/O funkcje dostał kilka. Jest to lista I grepped z długim --text wyjścia:

34 24.6% 24.6%  34 24.6% __write_nocancel 

    1 0.7% 95.7%  35 25.4% __GI__IO_fflush 
    1 0.7% 96.4%  1 0.7% __GI__IO_putc 
    1 0.7% 97.8%  2 1.4% std::operator<< 
    1 0.7% 98.6%  36 26.1% std::ostream::flush 
    1 0.7% 99.3%  2 1.4% std::ostream::put 
    0 0.0% 100.0%  34 24.6% _IO_new_file_sync 
    0 0.0% 100.0%  34 24.6% _IO_new_file_write 
    0 0.0% 100.0%  40 29.0% foo 

    0 0.0% 100.0%  34 24.6% new_do_write 

    0 0.0% 100.0%  2 1.4% std::endl 

Funkcje z zerowymi własnych liczników widoczne tylko dzięki pprof zdolności łańcuchów połączeń czytania (to wie, kto wywołuje funkcje, które dostał próbkę, jeśli informacji rama nie jest pominięty) .

mogę również polecić bardziej nowoczesne, bardziej zdolnych (zarówno programowe i sprzętowe wydarzeń, aż do 5 kHz lub więcej; zarówno w przestrzeni użytkownika i jądra profilowanie) oraz lepsze wsparcie profiler, Linux perf profiler (tutorial from its authors, wikipedia) .

Są wyniki od perf z a=10000:

$ perf record ./test3 >/dev/null 
... skip some perf's spam about inaccessibility of kernel symbols 
... note the 3 kHz frequency here VVVV 
Lowering default frequency rate to 3250. 
Please consider tweaking /proc/sys/kernel/perf_event_max_sample_rate. 
[ perf record: Woken up 1 times to write data ] 
[ perf record: Captured and wrote 0.078 MB perf.data (~3386 samples) ] 

Aby zobaczyć raport tekstowy z perf.data pliku wyjściowego użyję mniej (bo perf report domyślnie startów przeglądarkę profil Interactive):

$ perf report |less 
... skip some extra info about the machine, kernel, and perf starting command 
# Samples: 1K of event 'cycles' 
# Event count (approx.): 1155264208 
# Overhead Command Shared Object   Symbol 
    41.94% test3 libm-2.19.so   [.] __tan_sse2                                          
    16.95% test3 libm-2.19.so   [.] __sin_sse2  
    13.40% test3 libm-2.19.so   [.] __cos_sse2                                          
    4.93% test3 test3    [.] bar()                                           
    2.90% test3 libc-2.19.so   [.] __GI___libc_write  
.... 
    0.20% test3 test3    [.] foo()                                           

Lub perf report -n | less, aby zobaczyć liczniki surowych zdarzeń (próbki):

# Overhead  Samples Command  Shared Object 
    41.94%   663 test3 libm-2.19.so   [.] __tan_sse2                                          
    16.95%   268 test3 libm-2.19.so   [.] __sin_sse2 
    13.40%   212 test3 libm-2.19.so   [.] __cos_sse2                                          
    4.93%   78 test3 test3    [.] bar()                                           
    2.90%   62 test3 libc-2.19.so   [.] __GI___libc_write  
.... 
    0.20%    4 test3 test3    [.] foo()                                           

Answer 2

Spróbuj ustawić LD_PRELOAD tylko

LD_PRELOAD =/usr/local/lib/libprofiler.so

To looks like there are problems przechodząc wspólną bibliotekę, która nie kończy się przyrostkiem .so.