Przegląd technik profilowania w C ++
W tej odpowiedzi użyję kilku różnych narzędzi do analizy kilku bardzo prostych programów testowych, aby konkretnie porównać działanie tych narzędzi.
Poniższy program testowy jest bardzo prosty i wykonuje następujące czynności:
mainpołączenia fasti maybe_slow3 razy, jeden zmaybe_slow jest wolne
Powolne wywołanie maybe_slowjest 10 razy dłuższe i dominuje w środowisku wykonawczym, jeśli weźmiemy pod uwagę wywołania funkcji potomnej common. Idealnie, narzędzie do profilowania będzie w stanie wskazać nam konkretne wolne połączenie.
zarówno fasti maybe_slowcall common, co stanowi większość wykonania programu
Interfejs programu to:
./main.out [n [seed]]
a program O(n^2)w sumie wykonuje pętle. seedjest po prostu uzyskać inną wydajność bez wpływu na środowisko uruchomieniowe.
main.c
#include <inttypes.h>
#include <stdio.h>
#include <stdlib.h>
uint64_t __attribute__ ((noinline)) common(uint64_t n, uint64_t seed) {
for (uint64_t i = 0; i < n; ++i) {
seed = (seed * seed) - (3 * seed) + 1;
}
return seed;
}
uint64_t __attribute__ ((noinline)) fast(uint64_t n, uint64_t seed) {
uint64_t max = (n / 10) + 1;
for (uint64_t i = 0; i < max; ++i) {
seed = common(n, (seed * seed) - (3 * seed) + 1);
}
return seed;
}
uint64_t __attribute__ ((noinline)) maybe_slow(uint64_t n, uint64_t seed, int is_slow) {
uint64_t max = n;
if (is_slow) {
max *= 10;
}
for (uint64_t i = 0; i < max; ++i) {
seed = common(n, (seed * seed) - (3 * seed) + 1);
}
return seed;
}
int main(int argc, char **argv) {
uint64_t n, seed;
if (argc > 1) {
n = strtoll(argv[1], NULL, 0);
} else {
n = 1;
}
if (argc > 2) {
seed = strtoll(argv[2], NULL, 0);
} else {
seed = 0;
}
seed += maybe_slow(n, seed, 0);
seed += fast(n, seed);
seed += maybe_slow(n, seed, 1);
seed += fast(n, seed);
seed += maybe_slow(n, seed, 0);
seed += fast(n, seed);
printf("%" PRIX64 "\n", seed);
return EXIT_SUCCESS;
}
gprof
gprof wymaga ponownej kompilacji oprogramowania z oprzyrządowaniem, a także stosuje podejście próbkowania wraz z oprzyrządowaniem. Dlatego zachowuje równowagę między dokładnością (próbkowanie nie zawsze jest w pełni dokładne i może pomijać funkcje) a spowolnieniem wykonywania (oprzyrządowanie i próbkowanie są stosunkowo szybkimi technikami, które nie spowalniają zbytnio wykonywania).
gprof jest wbudowany w GCC / binutils, więc wystarczy skompilować z -pgopcją włączenia gprof. Następnie uruchamiamy program normalnie z parametrem CLI rozmiaru, który generuje rozsądny czas trwania kilku sekund ( 10000):
gcc -pg -ggdb3 -O3 -std=c99 -Wall -Wextra -pedantic -o main.out main.c
time ./main.out 10000
Ze względów edukacyjnych przeprowadzimy również bieg bez włączonych optymalizacji. Pamiętaj, że jest to bezużyteczne w praktyce, ponieważ zwykle zależy Ci tylko na optymalizacji wydajności zoptymalizowanego programu:
gcc -pg -ggdb3 -O0 -std=c99 -Wall -Wextra -pedantic -o main.out main.c
./main.out 10000
Po pierwsze, timemówi nam, że czas wykonania zi bez niego -pgbył taki sam, co jest świetne: bez spowolnienia! Widziałem jednak konta 2x - 3x spowolnienia w złożonym oprogramowaniu, np. Jak pokazano na tym bilecie .
Ponieważ się skompilowaliśmy -pg, uruchomienie programu powoduje utworzenie gmon.outpliku zawierającego dane profilowania.
Możemy obserwować ten plik graficznie za pomocą gprof2dotpytania: Czy można uzyskać graficzną reprezentację wyników gprof?
sudo apt install graphviz
python3 -m pip install --user gprof2dot
gprof main.out > main.gprof
gprof2dot < main.gprof | dot -Tsvg -o output.svg
Tutaj gprofnarzędzie odczytuje gmon.outinformacje o śledzeniu i generuje raport czytelny dla człowieka main.gprof, który gprof2dotnastępnie czyta w celu wygenerowania wykresu.
Źródło gprof2dot znajduje się na stronie : https://github.com/jrfonseca/gprof2dot
Podczas biegu obserwujemy -O0:
i na -O3bieg:
Wynik -O0jest dość oczywisty. Na przykład pokazuje, że 3 maybe_slowwywołania i ich wywołania podrzędne zajmują 97,56% całkowitego czasu wykonywania, chociaż maybe_slowsamo wykonanie bez dzieci stanowi 0,00% całkowitego czasu wykonywania, tj. Prawie cały czas spędzony na tej funkcji połączenia z dziećmi.
DO ZROBIENIA: dlaczego mainbrakuje w -O3danych wyjściowych, mimo że widzę to na btGDB? Brakuje mi funkcji wyjściowej GProf. Myślę, że dzieje się tak, ponieważ gprof opiera się na próbkowaniu oprócz skompilowanego oprzyrządowania, a -O3 mainjest po prostu zbyt szybki i nie ma próbek.
Wybieram wyjście SVG zamiast PNG, ponieważ SVG można przeszukiwać za pomocą Ctrl + F, a rozmiar pliku może być około 10 razy mniejszy. Ponadto szerokość i wysokość generowanego obrazu może być humoungous z dziesiątkami tysięcy pikseli dla złożonego oprogramowania, eogaw tym przypadku GNOME 3.28.1 zawiera błędy w przypadku plików PNG, podczas gdy pliki SVG są otwierane automatycznie przez moją przeglądarkę. gimp 2.8 działał jednak dobrze, zobacz także:
ale nawet wtedy będziesz dużo przeciągał obraz, aby znaleźć to, czego szukasz, patrz np. ten obraz z „prawdziwego” przykładu oprogramowania wziętego z tego biletu :
Czy potrafisz łatwo znaleźć najbardziej krytyczny stos wywołań, gdy wszystkie te maleńkie nieposortowane linie spaghetti nachodzą na siebie? dotJestem pewien, że mogą być lepsze opcje, ale nie chcę teraz tam iść. To, czego naprawdę potrzebujemy, to odpowiednia dedykowana przeglądarka, ale jeszcze jej nie znalazłem:
Możesz jednak użyć mapy kolorów, aby nieco złagodzić te problemy. Na przykład na poprzednim ogromnym obrazie w końcu udało mi się znaleźć krytyczną ścieżkę po lewej stronie, kiedy dokonałem genialnego wniosku, że zieleń pojawia się po czerwieni, a następnie ciemniej i ciemniej niebieski.
Alternatywnie możemy również obserwować tekst wyjściowy gprofwbudowanego narzędzia binutils, które wcześniej zapisaliśmy:
cat main.gprof
Domyślnie powoduje to bardzo szczegółowe wyjście, które wyjaśnia, co oznaczają dane wyjściowe. Ponieważ nie potrafię tego lepiej wyjaśnić, pozwolę ci to przeczytać sam.
Po zrozumieniu formatu wyjściowego danych możesz zmniejszyć gadatliwość, aby wyświetlać tylko dane bez samouczka z -bopcją:
gprof -b main.out
W naszym przykładzie wyniki dotyczyły -O0:
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
100.35 3.67 3.67 123003 0.00 0.00 common
0.00 3.67 0.00 3 0.00 0.03 fast
0.00 3.67 0.00 3 0.00 1.19 maybe_slow
Call graph
granularity: each sample hit covers 2 byte(s) for 0.27% of 3.67 seconds
index % time self children called name
0.09 0.00 3003/123003 fast [4]
3.58 0.00 120000/123003 maybe_slow [3]
[1] 100.0 3.67 0.00 123003 common [1]
-----------------------------------------------
<spontaneous>
[2] 100.0 0.00 3.67 main [2]
0.00 3.58 3/3 maybe_slow [3]
0.00 0.09 3/3 fast [4]
-----------------------------------------------
0.00 3.58 3/3 main [2]
[3] 97.6 0.00 3.58 3 maybe_slow [3]
3.58 0.00 120000/123003 common [1]
-----------------------------------------------
0.00 0.09 3/3 main [2]
[4] 2.4 0.00 0.09 3 fast [4]
0.09 0.00 3003/123003 common [1]
-----------------------------------------------
Index by function name
[1] common [4] fast [3] maybe_slow
i dla -O3:
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls us/call us/call name
100.52 1.84 1.84 123003 14.96 14.96 common
Call graph
granularity: each sample hit covers 2 byte(s) for 0.54% of 1.84 seconds
index % time self children called name
0.04 0.00 3003/123003 fast [3]
1.79 0.00 120000/123003 maybe_slow [2]
[1] 100.0 1.84 0.00 123003 common [1]
-----------------------------------------------
<spontaneous>
[2] 97.6 0.00 1.79 maybe_slow [2]
1.79 0.00 120000/123003 common [1]
-----------------------------------------------
<spontaneous>
[3] 2.4 0.00 0.04 fast [3]
0.04 0.00 3003/123003 common [1]
-----------------------------------------------
Index by function name
[1] common
Jako bardzo szybkie podsumowanie każdej sekcji, np .:
0.00 3.58 3/3 main [2]
[3] 97.6 0.00 3.58 3 maybe_slow [3]
3.58 0.00 120000/123003 common [1]
skupia się wokół funkcji, która jest wcięta ( maybe_flow). [3]jest identyfikatorem tej funkcji. Powyżej funkcji znajdują się jej osoby wywołujące, a poniżej osoby odbierające.
Dla -O3zobacz tutaj jak w twórczości graficznej, że maybe_slowi fastnie ma znanego rodzica, który jest co dokumentacja mówi, że <spontaneous>środki.
Nie jestem pewien, czy istnieje fajny sposób na profilowanie linia po linii za pomocą gprof: czas `gprof` spędzony w poszczególnych liniach kodu
valgrind callgrind
valgrind uruchamia program przez maszynę wirtualną valgrind. To sprawia, że profilowanie jest bardzo dokładne, ale powoduje również bardzo duże spowolnienie programu. Wspominałem także wcześniej o kcachegrind: Narzędzia do uzyskania graficznego wywołania funkcji w kodzie kodu
callgrind to narzędzie valgrind do profilowania kodu, a kcachegrind to program KDE, który może wizualizować dane wyjściowe cachegrind.
Najpierw musimy usunąć -pgflagę, aby wrócić do normalnej kompilacji, w przeciwnym razie uruchomienie nie powiedzie sięProfiling timer expired , i tak, jest to tak częste, że zrobiłem to i pojawiło się pytanie o przepełnienie stosu.
Więc kompilujemy i uruchamiamy jako:
sudo apt install kcachegrind valgrind
gcc -ggdb3 -O3 -std=c99 -Wall -Wextra -pedantic -o main.out main.c
time valgrind --tool=callgrind valgrind --dump-instr=yes \
--collect-jumps=yes ./main.out 10000
Włączam --dump-instr=yes --collect-jumps=yes ponieważ powoduje to również zrzut informacji, które pozwalają nam zobaczyć rozkład wydajności na linię montażową, przy stosunkowo niewielkich dodatkowych kosztach ogólnych.
Nietoperz timemówi nam, że wykonanie programu zajęło 29,5 sekundy, więc na tym przykładzie spowolniliśmy około 15x. Oczywiście spowolnienie będzie poważnym ograniczeniem dla większych obciążeń. Na wspomnianym tutaj „prawdziwym przykładzie oprogramowania” zaobserwowałem spowolnienie 80x.
Uruchomienie generuje plik danych profilu o nazwie callgrind.out.<pid>np. callgrind.out.8554W moim przypadku. Ten plik przeglądamy za pomocą:
kcachegrind callgrind.out.8554
który pokazuje graficzny interfejs użytkownika zawierający dane podobne do tekstowego wyniku gprof:
Ponadto, jeśli przejdziemy do zakładki „Call Graph” w prawym dolnym rogu, zobaczymy wykres połączeń, który możemy wyeksportować, klikając go prawym przyciskiem myszy, aby uzyskać następujący obraz z nieuzasadnioną ilością białej ramki :-)
Myślę, że fastnie pokazuje się na tym wykresie, ponieważ kcachegrind musiał uprościć wizualizację, ponieważ to wywołanie zajmuje zbyt mało czasu, prawdopodobnie takie zachowanie będzie pożądane w prawdziwym programie. Menu prawego kliknięcia ma pewne ustawienia kontrolujące, kiedy należy wyciąć takie węzły, ale po szybkiej próbie nie udało mi się wyświetlić tak krótkiego połączenia. Jeśli kliknę na fastlewe okno, wyświetli się wykres wywołań z fast, więc stos został przechwycony. Nikt jeszcze nie znalazł sposobu na wyświetlenie pełnego wykresu wywołań graficznych: Spraw, aby callgrind wyświetlał wszystkie wywołania funkcji w grafie wywołań kcachegrind
TODO na złożonym oprogramowaniu C ++, widzę niektóre wpisy typu <cycle N>, np. <cycle 11>Gdzie spodziewałbym się nazw funkcji, co to znaczy? Zauważyłem, że jest przycisk „Wykrywanie cyklu”, który włącza i wyłącza tę funkcję, ale co to oznacza?
perf od linux-tools
perfwydaje się używać wyłącznie mechanizmów próbkowania jądra Linux. To sprawia, że konfiguracja jest bardzo prosta, ale nie do końca dokładna.
sudo apt install linux-tools
time perf record -g ./main.out 10000
To dodało 0.2s do wykonania, więc jesteśmy w porządku, ale nadal nie widzę większego zainteresowania, po rozwinięciu commonwęzła za pomocą prawej strzałki na klawiaturze:
Samples: 7K of event 'cycles:uppp', Event count (approx.): 6228527608
Children Self Command Shared Object Symbol
- 99.98% 99.88% main.out main.out [.] common
common
0.11% 0.11% main.out [kernel] [k] 0xffffffff8a6009e7
0.01% 0.01% main.out [kernel] [k] 0xffffffff8a600158
0.01% 0.00% main.out [unknown] [k] 0x0000000000000040
0.01% 0.00% main.out ld-2.27.so [.] _dl_sysdep_start
0.01% 0.00% main.out ld-2.27.so [.] dl_main
0.01% 0.00% main.out ld-2.27.so [.] mprotect
0.01% 0.00% main.out ld-2.27.so [.] _dl_map_object
0.01% 0.00% main.out ld-2.27.so [.] _xstat
0.00% 0.00% main.out ld-2.27.so [.] __GI___tunables_init
0.00% 0.00% main.out [unknown] [.] 0x2f3d4f4944555453
0.00% 0.00% main.out [unknown] [.] 0x00007fff3cfc57ac
0.00% 0.00% main.out ld-2.27.so [.] _start
Następnie próbuję przeprowadzić test porównawczy -O0programu, aby zobaczyć, czy to coś pokazuje, i dopiero teraz widzę wykres połączeń:
Samples: 15K of event 'cycles:uppp', Event count (approx.): 12438962281
Children Self Command Shared Object Symbol
+ 99.99% 0.00% main.out [unknown] [.] 0x04be258d4c544155
+ 99.99% 0.00% main.out libc-2.27.so [.] __libc_start_main
- 99.99% 0.00% main.out main.out [.] main
- main
- 97.54% maybe_slow
common
- 2.45% fast
common
+ 99.96% 99.85% main.out main.out [.] common
+ 97.54% 0.03% main.out main.out [.] maybe_slow
+ 2.45% 0.00% main.out main.out [.] fast
0.11% 0.11% main.out [kernel] [k] 0xffffffff8a6009e7
0.00% 0.00% main.out [unknown] [k] 0x0000000000000040
0.00% 0.00% main.out ld-2.27.so [.] _dl_sysdep_start
0.00% 0.00% main.out ld-2.27.so [.] dl_main
0.00% 0.00% main.out ld-2.27.so [.] _dl_lookup_symbol_x
0.00% 0.00% main.out [kernel] [k] 0xffffffff8a600158
0.00% 0.00% main.out ld-2.27.so [.] mmap64
0.00% 0.00% main.out ld-2.27.so [.] _dl_map_object
0.00% 0.00% main.out ld-2.27.so [.] __GI___tunables_init
0.00% 0.00% main.out [unknown] [.] 0x552e53555f6e653d
0.00% 0.00% main.out [unknown] [.] 0x00007ffe1cf20fdb
0.00% 0.00% main.out ld-2.27.so [.] _start
DO ZROBIENIA: co się stało z -O3egzekucją? Jest to po prostu, że maybe_slowi fastzbyt szybko i nie dostać żadnych próbek? Czy działa dobrze z -O3większymi programami, których uruchomienie trwa dłużej? Czy przegapiłem opcję CLI? Dowiedziałem się, że -Fkontroluję częstotliwość próbkowania w hercach, ale podniosłem ją do maksymalnej dozwolonej domyślnie wartości -F 39500((można ją zwiększyć sudo)) i nadal nie widzę wyraźnych połączeń.
Jedną fajną rzeczą perfjest narzędzie FlameGraph firmy Brendan Gregg, które wyświetla czasy stosów wywołań w bardzo zgrabny sposób, który pozwala szybko zobaczyć duże połączenia. Narzędzie jest dostępne na stronie : https://github.com/brendangregg/FlameGraph i jest również wspomniane w jego samouczku perf pod adresem : http://www.brendangregg.com/perf.html#FlameGraphs Kiedy biegałem perfbez sudo, dostałem ERROR: No stack counts foundto teraz zrobię to z sudo:
git clone https://github.com/brendangregg/FlameGraph
sudo perf record -F 99 -g -o perf_with_stack.data ./main.out 10000
sudo perf script -i perf_with_stack.data | FlameGraph/stackcollapse-perf.pl | FlameGraph/flamegraph.pl > flamegraph.svg
ale w tak prostym programie wynik nie jest bardzo łatwy do zrozumienia, ponieważ nie możemy łatwo zobaczyć maybe_slowani fasttego wykresu:
Na bardziej złożonym przykładzie staje się jasne, co oznacza wykres:
DO ZROBIENIA W tym przykładzie znajduje się dziennik [unknown]funkcji, dlaczego tak jest?
Inne interfejsy perf GUI, które mogą być tego warte, to:
Wtyczka Eclipse Trace Compass: https://www.eclipse.org/tracecompass/
Ma to jednak tę wadę, że należy najpierw przekonwertować dane do formatu Common Trace Format, co można zrobić perf data --to-ctf, ale należy je włączyć w czasie kompilacji / mieć perfwystarczająco dużo nowych, z których żaden nie dotyczy perf Ubuntu 18.04
https://github.com/KDAB/hotspot
Minusem tego jest to, że wydaje się, że nie ma pakietu Ubuntu, a jego zbudowanie wymaga Qt 5.10, podczas gdy Ubuntu 18.04 jest w wersji Qt 5.9.
gperftools
Wcześniej nazywany „Google Performance Tools”, źródło: https://github.com/gperftools/gperftools podstawie próbki.
Najpierw zainstaluj gperftools z:
sudo apt install google-perftools
Następnie możemy włączyć profiler CPU gperftools na dwa sposoby: w czasie wykonywania lub w czasie kompilacji.
W czasie wykonywania musimy przekazać ustawienie LD_PRELOADto point, do libprofiler.soktórego można znaleźć locate libprofiler.sonp. W moim systemie:
gcc -ggdb3 -O3 -std=c99 -Wall -Wextra -pedantic -o main.out main.c
LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libprofiler.so \
CPUPROFILE=prof.out ./main.out 10000
Alternatywnie możemy zbudować bibliotekę w czasie łącza, rezygnując z przekazywania LD_PRELOADw czasie wykonywania:
gcc -Wl,--no-as-needed,-lprofiler,--as-needed -ggdb3 -O3 -std=c99 -Wall -Wextra -pedantic -o main.out main.c
CPUPROFILE=prof.out ./main.out 10000
Zobacz także: gperftools - plik profilu nie został zrzucony
Najlepszym sposobem na obejrzenie tych danych, które do tej pory znalazłem, jest ustawienie formatu wyjściowego pprof na taki sam format, jaki przyjmuje kcachegrind jako dane wejściowe (tak, narzędzie Valgrind-project-viewer-narzędzie) i użycie kcachegrind, aby wyświetlić:
google-pprof --callgrind main.out prof.out > callgrind.out
kcachegrind callgrind.out
Po uruchomieniu jedną z tych metod otrzymujemy prof.outplik danych profilu jako wynik. Możemy wyświetlić ten plik graficznie jako plik SVG za pomocą:
google-pprof --web main.out prof.out
co daje znany wykres wywołań jak inne narzędzia, ale z nieporęczną jednostką liczby próbek zamiast sekund.
Alternatywnie możemy również uzyskać dane tekstowe za pomocą:
google-pprof --text main.out prof.out
co daje:
Using local file main.out.
Using local file prof.out.
Total: 187 samples
187 100.0% 100.0% 187 100.0% common
0 0.0% 100.0% 187 100.0% __libc_start_main
0 0.0% 100.0% 187 100.0% _start
0 0.0% 100.0% 4 2.1% fast
0 0.0% 100.0% 187 100.0% main
0 0.0% 100.0% 183 97.9% maybe_slow
Zobacz także: Jak korzystać z narzędzi Google perf
Testowany w Ubuntu 18.04, gprof2dot 2019.11.30, valgrind 3.13.0, perf 4.15.18, jądro Linux 4.15.0, FLameGraph 1a0dc6985aad06e76857cf2a354bd5ba0c9ce96b, gperftools 2.5-2.
