Czasami wszystko działa, ale chciałoby się lepiej. W poprzednim poście pokazywałem jak poukładać pamięć w aplikacji w C, żeby skorzystać z dobrodziejstw cache procesora. Tym razem trochę o optymalizacji dla Pythona i szukaniu najwolniejszych punktów w programie.
Skąd się wziął problem?
Podczas testów kolejnej wersji CoreCluster cały system zaczął działać zadziwiająco wolno – średnio zapytania do API trwały z dnia na dzień coraz dłużej, aż do kilkunastu sekund(!) dzisiaj. Podobnie zachowywała się kolejka zadań dla agentów, mimo ustawienia interwału pobierania zadań na minimum. Pierwsze podejrzenie padło na ostatni refactoring sieci, który wywrócił połowę driverów w chmurze, z modułu CoreNetwork. Ale po pierwsze to dość spory kawałek do przekopania ręcznie, a po drugie drivery obsługujące start systemu na Management Nodzie i Compute Nodach w CoreCluster nie mają nic wspólnego z API. Jedyna część wspólna do system plików (aczkolwiek nie wszędzie), baza danych i cache (Redis). Jak znaleźć to coś, co łakomie zjada czas i doprowadza użytkownika do irytacji?
Zawołajmy API przez FireBug
To było pierwsze co można było zrobić – popatrzyć jak CoreUI (interfejs w JavaScript) wywołuje coś z API. Działać działa, ale wolno. I do tego potwierdziło, że kilkanaście sekund jest normą. Co zatem dalej?
Spróbujmy wywołać funkcje bezpośrednio
Każda funkcja dostępna przez API CoreCluster musi być odekorowana Pythonową funkcją. Dekorator robi dość sporo roboty związanej z rozpakowaniem jsona, walidacją i autoryzacją użytkownika/noda/tokenu API. Możemy dobrać się do takiej funkcji przez corecluster.views.api.vm.get_list.function, czyli bezpośrednie wywołanie tego co zostało “zawinięte” przez dekorator. Taka funkcja potrzebuje kontekstu, w którym dostarczane są informacje o wywołaniu i o uwierzytelnionym “wołaczu” (ang. Caller, niewiem jak się to tłumaczy :).
Możemy zatem odpalić konsolę pytkona z prekonfigurowanym shellem dla CoreCluster:
sudo cc-admin shell |
… i przygotować takie wywołanie:
from corecluster.utils.context import Context from corecluster.models.core import User from corecluster.views.api import vm u = User.objects.get(name='maciek') c = Context() c.remote_ip='127.0.0.1' c.user_id = u.id c.user = u vm.get_list.function(c) |
Robimy mniej więcej to, co dekorator. Różnica jest taka, że powyższy kod wykonuje się w ułamku sekundy i problemu nie ma. Szukajmy więc dalej
“Prawdziwe” wywołanie API
Po drodze od przeglądarki do funkcji API są:
- Sieć
- Nginx
- uWSGI
- Dekorator
Po Nginxie i uWSGI nie spodziewałbym się niczego złego, podobnie po lokalnej sieci. Wypdało sprawdzić co się dzieje z dekoratorem, gdy funkcja jest wywoływana po Bożemu, już odekorowana. Jak wywołać takie coś, tak samo jak robi to Django? Potrzebny będzie przede wszystkim obiekt HttpRequest, który jest przekazywany do każdego wywołania w Django. Jest on równocześnie “zjadany” przez dekorator i zastępowany przez obiekt Context, który stworzyliśmy ręcznie powyżej.
Django dostarcza kilka fajnych rzeczy do testowania web aplikacji. Między innymi jest to klasa RequestFactory, która pozwala łatwo utworzyć obiekt identyczny z tymm, który utworzyłoby Django podczas normalnej pracy:
from django.test import RequestFactory rf = RequestFactory() url = '/api/vm/get_list' request = rf.post(url, '{"token":"6dbedc0c..."}', 'text/json') |
Drugi parametr w funkcji rf.post to token, którym uwierzytelniam się w chmurze. Powinien on być zapisany w dokładnie takiej formie, w jakiej wysyła go przeglądarka do API (czyli JSON). Tak stworzony obiekt request, który jest klasy HttpResponse możemy przekazać bezpośrednio do funkcji API, już bez wołania “zawiniętej” wrapperem wewnętrznej funkcji:
from corecluster.views.api import vm vm.get_list(request) |
Takie wywołanie trwa już dość długo i można można z dość dużym prawdopodobieństwem szukać problemu w samym dekoratorze. Wywołanie samej odekorowanej funkcji trwało krótko, a tutaj wywołujemy tą samą funkcję, tylko za pośrednictwem dekoratora.
Czy już zamykać się w piwnicy i szukać przez całą noc błędu?
Nie 🙂 Jest jeszcze coś innego, co warto użyć – profiler dla Pythona. Jest to narzędzie, które pokaże ile razy jakie funkcje są wywoływane w naszym (i nie tylko) kodzie. Świetnie się sprawdzi właśnie przy szukaniu takich wolnych punktów w naszym kodzie. Nie służy ono do poprawienia stabilności i przetestowania kodu, ale do poprawienia jego wydajności.
Spróbujmy użyć go do wykonania powyższego skryptu:
import cProfile cProfile.run('vm.get_list(request)', sort='tottime') |
Na pierwszy rzut oka wydaje się dość proste. Za pomocą funkcji run wywołujemy to, co nas interesuje – funkcje vm.get_list z podanym jako parametr obiektem request.
Po wykonaniu cProfile pokaże całą listę wywołanych funkcji, posorotwaną wedug kryterium jakie podaliśmy:
In [9]: cProfile.run('vm.get_list(mr)', sort='tottime') 45373 function calls (43564 primitive calls) in 0.105 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) ... 799/442 0.001 0.000 0.008 0.000 functional.py:30(__get__) 53 0.001 0.000 0.016 0.000 utils.py:76(execute) 2154/2142 0.001 0.000 0.002 0.000 {isinstance} 377 0.001 0.000 0.004 0.000 expressions.py:647(as_sql) 58 0.001 0.000 0.012 0.000 query.py:1117(build_filter) 37 0.001 0.000 0.013 0.000 compiler.py:167(get_select) 2 0.001 0.000 0.001 0.001 connections.py:68(__init__) 125 0.001 0.000 0.004 0.000 query.py:1277(names_to_path) 37 0.001 0.000 0.024 0.001 compiler.py:371(as_sql) 29 0.001 0.000 0.005 0.000 compiler.py:492(get_default_columns) 238 0.001 0.000 0.002 0.000 related.py:589(foreign_related_fields) ... |
Dostajemy (tutaj tylko fragment) listę wszystkich funkcji, które były wywołane podczas uruchamiania podanej do cProfilera linijki kodu. Sortując wg. parametru tottime możemy sprawdzić na czym najwięcej czasu spędził program.
Gdzie był problem?
W moim przypadku okazało się, że problem tkwił w nieskonfigurowanej bazie logów dla CoreCluster. Po dłuższym używaniu domyślna baza Sqlite zapchała się logami i spowalniała cały system. Nie pomagało też ich okresowe dumpowanie przez zadanie Cron, ponieważ testowa instalacja nie działała w nocy. Po zmianie na MySQL wszystko powróciło do normy i całość działa dobrze.
Natomiast sam cProfiler dobrze znać – może się przydać na etapie gdy mamy już gotową aplikację i chcemy wycisnąć z niej jeszcze więcej.
ps.
Jeśli znasz dobry system dla rozproszonego logowania dla Pythona – inny niż zapisywanie do pliku lub bazy danych – zostaw komentarz 🙂