Pisanie programów jest zabawne, ale ich przyspieszanie może być uciążliwe. Programy w Pythonie nie są tu wyjątkiem, ale podstawowy zestaw narzędzi do profilowania nie jest tak skomplikowany w użyciu. Chciałbym tutaj pokazać, jak można szybko profilować i analizować kod Pythona, aby znaleźć część kodu, którą należy zoptymalizować.
Profilowanie programu Pythona polega na przeprowadzeniu dynamicznej analizy, która mierzy czas wykonania programu i wszystkiego, co go tworzy. Oznacza to pomiar czasu spędzonego w każdej z jego funkcji. To da ci dane o tym, gdzie twój program spędza czas i jaki obszar może być wart optymalizacji.
To bardzo interesujące ćwiczenie. Wiele osób skupia się na lokalnych optymalizacjach, takich jak np. określenie, która z funkcji Pythona range czy xrange będzie szybsza. Okazuje się, że wiedza o tym, która z nich jest szybsza, może nigdy nie być problemem w twoim programie, a czas uzyskany dzięki jednej z powyższych funkcji może nie być wart czasu spędzonego na badaniu tego lub kłótni o to z kolegą.
Próba ślepej optymalizacji programu bez zmierzenia, gdzie tak naprawdę spędza on swój czas, jest bezużytecznym ćwiczeniem. Podążanie wyłącznie za swoim instynktem nie zawsze jest wystarczające.
Istnieje wiele rodzajów profilowania, tak jak istnieje wiele rzeczy, które można zmierzyć. W tym ćwiczeniu skupimy się na profilowaniu wykorzystania procesora, czyli czasu spędzonego przez każdą funkcję na wykonywaniu instrukcji. Oczywiście, moglibyśmy wykonać wiele innych rodzajów profilowania i optymalizacji, takich jak profilowanie pamięci, które mierzyłoby pamięć używaną przez każdy fragment kodu – coś, o czym mówię w The Hacker’s Guide to Python.
cProfile
Od Pythona 2.5, Python dostarcza moduł C o nazwie cProfile, który ma rozsądny narzut i oferuje wystarczająco dobry zestaw funkcji. Podstawowy sposób użycia sprowadza się do:
Można też uruchomić skrypt, który okazuje się przydatny:
Wypisuje on wszystkie wywołane funkcje, wraz z czasem spędzonym w każdej z nich i liczbą ich wywołań.
Zaawansowana wizualizacja z KCacheGrind
Pomimo że jest przydatny, format wyjściowy jest bardzo podstawowy i nie ułatwia zdobycia wiedzy o kompletnych programach. Dla bardziej zaawansowanej wizualizacji, używam KCacheGrind. Jeśli w ostatnich latach zajmowałeś się programowaniem i profilowaniem w C, być może używałeś tego programu, ponieważ jest on głównie zaprojektowany jako front-end dla wygenerowanych przez Valgrind call-graphs.
Aby go użyć, musisz wygenerować plik wynikowy cProfile, a następnie przekonwertować go do formatu KCacheGrind. W tym celu używam pyprof2calltree.
$ python -m cProfile -o myscript.cprof myscript.py$ pyprof2calltree -k -i myscript.cprofI w magiczny sposób pojawia się okno KCacheGrind!
Concrete case: Optymalizacja Carbonary
Byłem ciekaw wydajności Carbonary, małej biblioteki timeseries, którą napisałem dla Gnocchi. Postanowiłem wykonać podstawowe profilowanie, aby zobaczyć czy jest jakaś oczywista optymalizacja do zrobienia.
Aby profilować program, musisz go uruchomić. Ale uruchomienie całego programu w trybie profilowania może wygenerować wiele danych, na których nam nie zależy i dodać szumu do tego, co próbujemy zrozumieć. Ponieważ Gnocchi ma tysiące testów jednostkowych i kilka dla samej Carbonary, zdecydowałem się na profilowanie kodu używanego przez te testy jednostkowe, ponieważ jest to dobre odzwierciedlenie podstawowych cech biblioteki.
Zauważ, że jest to dobra strategia dla ciekawskiego i naiwnego profilowania pierwszego przejścia.
Nie ma sposobu, aby upewnić się, że hotspoty, które zobaczysz w testach jednostkowych, są rzeczywistymi hotspotami, które napotkasz w produkcji. Dlatego profilowanie w warunkach i ze scenariuszem, który naśladuje to, co widać na produkcji jest często koniecznością, jeśli musisz popchnąć optymalizację swojego programu dalej i chcesz osiągnąć zauważalny i wartościowy zysk.
Uruchamiałem cProfile używając metody opisanej powyżej, tworząc obiekt cProfile.Profile wokół moich testów (właściwie zacząłem to implementować w testtools). Następnie uruchomiłem KCacheGrind, jak opisano powyżej. Używając KCacheGrind, wygenerowałem następujące liczby.
Test, który tutaj sprofilowałem nazywa się test_fetch i jest dość łatwy do zrozumienia: umieszcza dane w obiekcie timeserie, a następnie pobiera zagregowany wynik. Powyższa lista pokazuje, że 88% ticków jest spędzonych w set_values (44 ticki ponad 50). Ta funkcja jest używana do wstawiania wartości do timeserie, a nie do pobierania wartości. Oznacza to, że wstawianie danych jest naprawdę powolne, a pobieranie ich całkiem szybkie.
Przeczytanie reszty listy wskazuje, że kilka funkcji dzieli resztę ticków, update, _first_block_timestamp, _truncate, _resample, itd. Niektóre z funkcji na liście nie są częścią Carbonary, więc nie ma sensu szukać ich optymalizacji. Jedyną rzeczą, którą można zoptymalizować jest, czasami, liczba wywołań tych funkcji.
Wykres wywołań daje mi nieco więcej wglądu w to, co się tutaj dzieje. Korzystając z mojej wiedzy o tym, jak działa Carbonara, nie sądzę, że cały stos po lewej stronie dla _first_block_timestamp ma dużo sensu. Ta funkcja ma znaleźć pierwszy timestamp dla agregatu, np. z timestampem 13:34:45 i okresem 5 minut, funkcja powinna zwrócić 13:30:00. Sposób w jaki to działa obecnie to wywołanie funkcji resample z Pandas na timeserie z tylko jednym elementem, ale to wydaje się być bardzo powolne. Rzeczywiście, obecnie ta funkcja stanowi 25% czasu spędzonego przez set_values (11 ticków na 44).
Na szczęście ostatnio dodałem małą funkcję o nazwie _round_timestamp, która robi dokładnie to, czego potrzebuje _first_block_timestamp bez wywoływania jakiejkolwiek funkcji Pandas, więc nie ma resample. Więc skończyło się na przepisaniu tej funkcji w ten sposób:
A następnie ponownie uruchomiłem dokładnie ten sam test, aby porównać dane wyjściowe cProfile.
Lista funkcji wydaje się tym razem całkiem inna. Ilość czasu spędzonego przez set_values spadła z 88% do 71%.
Stos wywołań dla set_values pokazuje to całkiem dobrze: nie widzimy nawet funkcji _first_block_timestamp, ponieważ jest ona tak szybka, że całkowicie zniknęła z ekranu. Jest ona teraz uważana za nieistotną przez profiler.
Więc właśnie przyspieszyliśmy cały proces wstawiania wartości do Carbonary o ładne 25% w ciągu kilku minut. Nie tak źle jak na pierwsze naiwne przejście, prawda?
Jeśli chcesz wiedzieć więcej, napisałem cały rozdział o optymalizacji kodu w Scaling Python. Sprawdź to!