Beyond cProfile: Wybór odpowiedniego narzędzia do optymalizacji wydajności

Uwaga: Ten artykuł jest oparty na wykładzie, który wygłosiłem na PyGotham 2019. Możesz obejrzeć wideo tutaj.

Twój program w Pythonie jest zbyt wolny.Może twoja aplikacja internetowa nie może nadążyć, lub niektóre zapytania zajmują dużo czasu.Może masz program wsadowy, którego uruchomienie zajmuje godziny lub nawet dni.

Jak przyspieszyć?

Podstawowy proces, który prawdopodobnie wykonasz, to:

1. Wybierz odpowiednie narzędzie do pomiaru szybkości.
2. Użyj narzędzia, aby dowiedzieć się, co jest wąskim gardłem.
3. Naprawić wąskie gardło.

Ten artykuł skupi się na pierwszym kroku: wyborze odpowiedniego narzędzia.A w szczególności obejmie:

• cProfile: Deterministyczny profiler deterministyczny biblioteki standardowej Pythona.
• Pyinstrument: Profiler próbkujący.
• Eliot: A logging library.

Nie będę wchodził w ogromną ilość szczegółów na temat tego, jak korzystać z tych narzędzi, ponieważ celem jest pomoc w wyborze odpowiedniego z nich. Ale wyjaśnię, co te narzędzia robią, oraz kiedy i dlaczego można wybrać jedno nad drugim.

cProfile: A deterministic profiler

Profiler cProfile jest wbudowany w Pythona, więc prawdopodobnie o nim słyszałeś i może to być domyślne narzędzie, którego używasz.Działa on poprzez śledzenie każdego wywołania funkcji w programie.Dlatego jest to profiler deterministyczny: jeśli uruchomisz go z tymi samymi danymi wejściowymi, da takie same dane wyjściowe.

Domyślnie cProfile mierzy CPU procesu – ile CPU proces wykorzystał do tej pory.Powinieneś zawsze zapytać, co mierzy twój profiler, ponieważ różne miary mogą wykryć różne problemy.Pomiar CPU oznacza, że nie możesz wykryć spowolnienia spowodowanego innymi przyczynami, takimi jak oczekiwanie na odpowiedź zapytania do bazy danych.

Choć cProfile jest zawsze dostępny w twojej instalacji Pythona, ma też pewne problemy – i jak zobaczysz, przez większość czasu nie chcesz go używać.

Używanie cProfile

Używanie cProfile jest całkiem proste.Jeśli masz skrypt, który zazwyczaj uruchamiasz bezpośrednio, jak na przykład:

$ python benchmark.py7855 messages/sec

Wtedy możesz po prostu poprzedzić python -m cProfile, aby uruchomić go pod profilerem:

Istnieje również API profilowania Pythona, więc możesz profilować poszczególne funkcje w podpowiedzi interpretera Pythona lub w notatniku Jupytera.

Formatem wyjściowym jest tabela, która nie jest idealna: każdy wiersz to wywołanie funkcji, które zostało wykonane podczas profilowanego przedziału czasu, ale nie wiesz, jak to wywołanie funkcji jest powiązane z innymi wywołaniami funkcji.Więc jeśli masz funkcję, do której można dotrzeć z wielu ścieżek kodu, może być trudno dowiedzieć się, która ścieżka kodu była odpowiedzialna za wywołanie powolnej funkcji.

Co cProfile może ci powiedzieć

Jeśli spojrzysz na powyższą tabelę, możesz zobaczyć, że:

• _output.py(__call__) zostało wywołane 50,000 razy. Jest to liczba parzysta, ponieważ jest to skrypt wzorcowy, który uruchamia ten sam kod w pętli 10 000 razy. Jeśli nie byłeś celowo wywołujący funkcję wiele razy, może to być przydatne do wykrycia wysokiej liczby wywołań jest przydatne do identyfikacji zajętych pętli wewnętrznych.
• _output.py(send) zużył 0,618 sekundy procesora (w tym czas procesora funkcji, które wywołał) i 0,045 sekundy procesora (nie wliczając funkcji, które wywołał).

Korzystając z tych informacji możesz zauważyć powolne funkcje, które możesz zoptymalizować – powolne, jeśli chodzi o procesor, w każdym razie.

Jak to działa

cProfile mierzy każde pojedyncze wywołanie funkcji.W szczególności, każde wywołanie funkcji w przebiegu jest zawijane w następujący sposób:

start = process_time()try: f()finally: elapsed = process_time() - start

Profiler rejestruje czas procesora na początku i na końcu, a różnica jest przypisywana do konta tej funkcji.

Problemy z cProfile

Chociaż cProfile jest zawsze dostępny w każdej instalacji Pythona, cierpi również na kilka istotnych problemów.

Problem #1: Wysoki narzut i zniekształcone wyniki

Jak możesz sobie wyobrazić, wykonywanie dodatkowej pracy dla każdego wywołania funkcji wiąże się z pewnymi kosztami:

$ python benchmark.py7855 messages/sec$ python -m cProfile benchmark.py5264 messages/sec... cProfile output ...

Zauważ, o ile wolniejsze jest uruchamianie cProfile.A co gorsza, spowolnienie to nie jest jednolite w całym programie: ponieważ jest ono związane z liczbą wywołań funkcji, części kodu z większą liczbą wywołań funkcji będą bardziej spowolnione, więc ten narzut może zniekształcić wyniki.

Problem #2: Zbyt wiele informacji

Jeśli przypomnisz sobie dane wyjściowe cProfile, które widzieliśmy powyżej, zawierają one wiersz dla każdej pojedynczej funkcji, która została wywołana podczas działania programu.Większość z tych wywołań funkcji nie ma znaczenia dla naszego problemu z wydajnością: są one uruchamiane szybko i tylko raz lub dwa razy.

Więc kiedy czytasz dane wyjściowe cProfile, masz do czynienia z dużą ilością dodatkowego szumu maskującego sygnał.

Problem #3: offline’owa miara wydajności

Często twój program będzie powolny tylko wtedy, gdy zostanie uruchomiony w rzeczywistych warunkach, z rzeczywistymi danymi wejściowymi.Może tylko niektóre zapytania od użytkowników spowalniają twoją aplikację internetową, a ty nie wiesz, które to zapytania.Może twój program wsadowy jest powolny tylko z rzeczywistymi danymi.

Ale cProfile, jak widzieliśmy, spowalnia twój program dość mocno, więc prawdopodobnie nie chcesz go uruchamiać w środowisku produkcyjnym. Tak więc, podczas gdy powolność jest powtarzalna tylko w produkcji, cProfile pomaga ci tylko w twoim środowisku programistycznym.

Problem #4: Wydajność jest mierzona tylko dla funkcji

cProfile może ci powiedzieć „slowfunc() jest powolny”, gdzie uśrednia wszystkie dane wejściowe do tej funkcji.I to jest w porządku, jeśli funkcja jest zawsze powolna.

Ale czasami masz jakiś kod algorytmiczny, który jest powolny tylko dla określonych danych wejściowych.Jest całkiem możliwe, że:

• slowfunc(100) jest szybki.
• slowfunc(0) jest powolny.

cProfile nie będzie w stanie powiedzieć, które wejścia spowodowały powolność, co może utrudnić zdiagnozowanie problemu.

cProfile: Zwykle niewystarczający

W wyniku tych problemów, cProfile nie powinien być twoim narzędziem wydajnościowym z wyboru.Zamiast tego, w następnej kolejności będziemy rozmawiać o dwóch alternatywach:

• Pyinstrument rozwiązuje problemy #1 i #2.
• Eliot rozwiązuje problemy #3 i #4.

Pyinstrument: profiler próbkowania

Pyinstrument rozwiązuje dwa z problemów, które omówiliśmy powyżej:

• Ma niższy narzut niż cProfile, i nie zniekształca wyników.

Pyinstrument mierzy czas zegara ściennego, a nie czas procesora, więc może wychwycić powolność spowodowaną przez żądania sieciowe, zapisy na dysku, rywalizację o blokadę i tak dalej.

Jak go używać

Używanie Pyinstrument jest podobne do cProfile; po prostu dodaj prefiks do swojego skryptu:

$ python benchmark.py7561 messages/sec$ python -m pyinstrument benchmark.py6760 messages/sec... pyinstrument output ...

Zauważ, że ma pewien narzut, ale nie tak duży jak cProfile – a narzut jest jednolity.

Pyinstrument posiada również API Pythona, więc możesz go użyć do profilowania poszczególnych fragmentów kodu w interaktywnym interpreterze Pythona lub notatniku Jupyter.

Wyjście

Wyjście Pyinstrumentu to drzewo wywołań, mierzące czas zegara:

W przeciwieństwie do wiersza na funkcję w cProfile, Pyinstrument daje ci drzewo wywołań funkcji, więc możesz zobaczyć kontekst spowolnienia. Funkcja może pojawić się wiele razy, jeśli spowolnienie jest spowodowane przez wiele ścieżek kodu.

W rezultacie, wyjście Pyinstrumentu jest o wiele łatwiejsze do interpretacji i daje o wiele lepsze zrozumienie struktury działania twojego programu niż domyślne wyjście cProfile.

Jak to działa (edycja kota)

Wyobraź sobie, że masz kota.Chciałbyś wiedzieć, jak ten kot spędza swój czas.

Mógłbyś szpiegować każdą jego chwilę, ale to byłoby dużo pracy.Więc zamiast tego decydujesz się na pobieranie próbek: co 5 minut wsadzasz głowę do pokoju, w którym jest kot, i zapisujesz, co robi.

Na przykład:

• 12:00: Spanie 💤
• 12:05: Spanie 💤
• 12:10: Jedzenie 🍲
• 12:15: Korzystanie z kuwety 💩
• 12:20: Spanie 💤
• 12:25: Spanie 💤
• 12:30: Spanie 💤

Kilka dni później możesz podsumować swoje obserwacje:

• 80%: Spanie 💤
• 10%: Jedzenie 🍲
• 9%: Korzystanie z kuwety 💩
• 1%: Gapienie się z tęsknotą przez okno na ptaki 🐦

Więc jak dokładne jest to podsumowanie? O ile twoim celem jest zmierzenie, gdzie kot spędził większość czasu, prawdopodobnie jest to dokładne.A im częstsze obserwacje (== próbki) i im więcej obserwacji, tym dokładniejsze podsumowanie.

Jeśli twój kot spędza większość czasu śpiąc, spodziewałbyś się, że większość obserwacji wykaże, że śpi.I tak, przegapisz niektóre szybkie i rzadkie czynności – ale dla celów „na co kot spędził większość czasu” te szybkie i rzadkie czynności są nieistotne.

Jak to działa (edycja programistyczna)

Dużo jak nasz kot, Pyinstrument próbkuje zachowanie programu Pythona w odstępach czasu: co 1ms sprawdza, jaka funkcja jest aktualnie uruchomiona.To oznacza:

• Jeśli funkcja jest kumulatywnie wolna, będzie się często pojawiać.
• Jeśli funkcja jest kumulatywnie szybka, zwykle w ogóle jej nie zobaczymy.

To oznacza, że nasze podsumowanie wydajności ma mniej szumu: funkcje, które są ledwo używane, będą w większości pomijane.Ale ogólnie podsumowanie jest całkiem dokładne, jeśli chodzi o to, jak program spędził swój czas, tak długo, jak długo braliśmy wystarczająco dużo próbek.

Eliot: A logging library

Ostatnim narzędziem, które omówimy szczegółowo, jest Eliot, biblioteka logowania, którą napisałem.Rozwiązuje ona dwa pozostałe problemy, które widzieliśmy z cProfile:

• Logowanie może być używane w produkcji.
• Logowanie może rejestrować argumenty do funkcji.

Jak zobaczysz, Eliot zapewnia pewne unikalne możliwości, które sprawiają, że jest lepszy w rejestrowaniu wydajności niż zwykłe biblioteki rejestrujące.To powiedziawszy, przy odrobinie dodatkowej pracy możesz uzyskać te same korzyści również z innych bibliotek rejestrujących.

Dodawanie rejestrowania do istniejącego kodu

Rozważmy następujący szkic programu:

Możemy wziąć ten kod i dodać do niego rejestrowanie:

Precyzując, robimy dwie rzeczy:

1. Powiedz Eliotowi, gdzie ma wysyłać komunikaty dziennika (w tym przypadku do pliku o nazwie „out.log”).
2. Dekorujemy funkcje za pomocą dekoratora @log_call.Spowoduje to zapisanie w dzienniku faktu wywołania funkcji, jej argumentów i wartości zwracanej (lub podniesionego wyjątku).

Eliot ma inne, bardziej szczegółowe interfejsy API, ale @log_call wystarczy do zademonstrowania korzyści z logowania.

Wyjście Eliota

Po uruchomieniu programu, możemy spojrzeć na logi używając narzędzia zwanego eliot-tree:

Zauważ, że, trochę jak w Pyinstrument, patrzymy na drzewo akcji.Uprościłem nieco dane wyjściowe – pierwotnie po to, by zmieściły się na slajdzie, którego użyłem w wersji wykładowej tego artykułu – ale nawet w artykule prozatorskim pozwala nam to skupić się na aspekcie wydajnościowym.

W Eliocie każda akcja ma początek i koniec, i może rozpocząć inne akcje – stąd wynikowe drzewo.Ponieważ wiemy, kiedy każda zarejestrowana akcja zaczyna się i kończy, wiemy również, jak długo to trwało.

W tym przypadku każda akcja odwzorowuje jeden do jednego z wywołaniem funkcji.I są pewne różnice w stosunku do danych wyjściowych Pyinstrumentu:

1. Zamiast łączyć wiele wywołań funkcji, widzisz każde pojedyncze wywołanie osobno.
2. Możesz zobaczyć argumenty i wynik zwrotny każdego połączenia.
3. Możesz zobaczyć upływający czas zegara ściennego każdej akcji.

Na przykład możesz zobaczyć, że multiplysum() zajęło 10 sekund, ale zdecydowana większość czasu została spędzona w multiply(), z wejściami 3 i 4.Więc od razu wiesz, że dla optymalizacji wydajności chcesz się skupić na multiply(), i masz kilka początkowych wejść (3 i 4), z którymi możesz się pobawić.

Ograniczenia logowania

Logowanie nie jest wystarczające samo w sobie jako źródło informacji o wydajności.

Po pierwsze, otrzymujesz informacje tylko z kodu, w którym jawnie dodałeś wywołania logowania.Profiler może działać na dowolnym dowolnym kawałku kodu bez wcześniejszego przygotowania, ale z logowaniem musisz wykonać pewną pracę z wyprzedzeniem.

Jeśli nie dodałeś kodu logowania, nie otrzymasz żadnych informacji.Eliot czyni to nieco lepszym, ponieważ struktura drzewa działań daje ci pewne poczucie, gdzie został spędzony czas, ale nadal nie jest to wystarczające, jeśli logowanie jest zbyt rzadkie.

Po drugie, nie możesz dodać rejestrowania wszędzie, ponieważ to spowolni twój program.Rejestrowanie nie jest tanie – jest to wyższy narzut niż cProfile.Więc musisz dodać go rozsądnie, w kluczowych punktach, gdzie zmaksymalizuje informacje, które daje bez wpływu na wydajność.

Wybór właściwych narzędzi

Więc kiedy powinieneś używać każdego z nich?

Zawsze dodawaj logowanie

Każdy nietrywialny program prawdopodobnie potrzebuje logowania, choćby po to, by wyłapywać błędy i usterki.A jeśli już dodajesz logowanie, możesz zadać sobie trud, by rejestrować informacje potrzebne do debugowania wydajności.

Eliot ułatwia to, ponieważ rejestrowanie akcji z natury daje ci czas, który upłynął, ale możesz to zrobić przy odrobinie dodatkowej pracy z dowolną biblioteką logowania.

Logowanie może pomóc ci w znalezieniu konkretnego miejsca, w którym twój program jest powolny, a przynajmniej niektórych danych wejściowych powodujących powolność, ale często jest niewystarczające.Następnym krokiem jest więc użycie profilera, a w szczególności profilera próbkującego, takiego jak Pyinstrument:

• Ma niski narzut, a co ważniejsze nie zniekształca wyników.
• Pomierza czas zegara ściennego, więc nie zakłada, że CPU jest wąskim gardłem.
• Wyświetla tylko wolniejsze funkcje, pomijając nieistotne szybkie funkcje.

Użyj cProfile, jeśli potrzebujesz niestandardowej metryki kosztów

Jeśli kiedykolwiek będziesz potrzebował napisać niestandardowy profiler, cProfile pozwala na podłączenie różnych funkcji kosztów, co czyni go łatwym narzędziem do pomiaru bardziej nietypowych metryk.

Możesz zmierzyć:

• Not-CPU, cały czas spędzony na oczekiwaniu na zdarzenia niezwiązane z procesorem.
• Liczba dobrowolnych przełączeń kontekstu, czyli liczba wywołań systemowych, które zajmują dużo czasu.
• Alokacje pamięci.
• Szerzej, każdy licznik, który idzie w górę.

TL;DR

Jako dobry punkt wyjścia do narzędzi optymalizacji wydajności, sugeruję, abyś:

1. Logował kluczowe wejścia i wyjścia, a także upływający czas kluczowych działań, używając Eliota lub innej biblioteki logowania.
2. Używaj Pyinstrument-lub innego profilera próbkującego-jako domyślnego profilera.
3. Używaj cProfile, gdy potrzebujesz niestandardowego profilera.