Jak mogę profilować aplikację SQLAlchemy?

Czasami zwykłe logowanie SQL (włączone przez moduł logowania Pythona lub przez argument echo=True na create_engine()) może dać ci wyobrażenie, jak długo to trwa. Na przykład, jeśli zalogujesz coś zaraz po operacji SQL, zobaczysz coś takiego w swoim dzienniku:

17:37:48,325 INFO  [sqlalchemy.engine.base.Engine.0x...048c] SELECT ...
17:37:48,326 INFO  [sqlalchemy.engine.base.Engine.0x...048c] {<params>}
17:37:48,660 DEBUG [myapp.somemessage] 

Jeśli zalogowałeś się myapp.somemessage zaraz po operacji, wiesz, że ukończenie części SQL zajęło 334ms.

Logowanie SQL pokaże również, czy są wydawane dziesiątki/setki zapytań, które może być lepiej zorganizowany w znacznie mniej zapytań za pomocą łączy. Podczas korzystania z SQLAlchemy ORM, funkcja "eager loading" jest udostępniana częściowo (contains_eager()) lub w pełni (eagerload(), eagerload_all()) automatyzuj tę czynność, ale bez ORM oznacza to po prostu użycie łączników, aby wyniki w wielu tabelach mogły być ładowane w jednym zestawie wyników zamiast mnożenia liczb zapytań w miarę dodawania większej głębokości (np. r + r*r2 + r*r2*r3...)

Jeśli logowanie ujawni, że poszczególne zapytania trwają zbyt długo, potrzebujesz Podział czasu spędzonego w bazie danych na przetwarzaniu zapytania, wysyłaniu wyników przez sieć, obsługiwaniu przez DBAPI i wreszcie odbieraniu przez SQLAlchemy ' s result set i/lub warstwę ORM. Każdy z tych etapów może prezentować własne indywidualne wąskie gardła, w zależności od specyfiki.

W tym celu musisz użyć profilowania, takiego jak cProfile lub hotshot. Oto dekorator, którego używam:

import cProfile as profiler
import gc, pstats, time

def profile(fn):
    def wrapper(*args, **kw):
        elapsed, stat_loader, result = _profile("foo.txt", fn, *args, **kw)
        stats = stat_loader()
        stats.sort_stats('cumulative')
        stats.print_stats()
        # uncomment this to see who's calling what
        # stats.print_callers()
        return result
    return wrapper

def _profile(filename, fn, *args, **kw):
    load_stats = lambda: pstats.Stats(filename)
    gc.collect()

    began = time.time()
    profiler.runctx('result = fn(*args, **kw)', globals(), locals(),
                    filename=filename)
    ended = time.time()

    return ended - began, load_stats, locals()['result']

Aby profilować fragment kodu, umieść go w funkcji z dekorator:

@profile
def go():
    return Session.query(FooClass).filter(FooClass.somevalue==8).all()
myfoos = go()

Wyjście z profilowania może być użyte, aby dać wyobrażenie, gdzie spędzany jest czas. Jeśli na przykład widzisz cały czas spędzony w cursor.execute(), jest to niskopoziomowe wywołanie DBAPI do bazy danych i oznacza to, że Twoje zapytanie powinno zostać zoptymalizowane poprzez dodanie indeksów lub restrukturyzację zapytania i/lub podstawowego schematu. Do tego zadania polecam użycie pgadmin wraz z jego graficznym narzędziem wyjaśniającym, aby zobaczyć, jaki rodzaj pracy wykonuje zapytanie.

Jeśli Zobacz wiele tysięcy wywołań związanych z pobieraniem wierszy, może to oznaczać, że Twoje zapytanie zwraca więcej wierszy niż oczekiwano - produkt kartezjański w wyniku niekompletnego połączenia może spowodować ten problem. Kolejnym problemem jest czas spędzony na obsłudze typów-Typ SQLAlchemy, taki jak Unicode, wykona kodowanie/dekodowanie łańcuchów znaków na parametrach bind i kolumnach wynikowych, które mogą nie być potrzebne we wszystkich przypadkach.

Wyjście profilu może być trochę zniechęcające, ale po pewnej praktyce są bardzo łatwy do odczytania. Kiedyś na liście mailingowej był ktoś, kto twierdził, że powolność, a po tym, jak opublikował wyniki profilu, byłem w stanie wykazać, że problemy z prędkością były spowodowane opóźnieniem sieci - czasem spędzonym w kursorze.execute () jak i wszystkie metody Pythona były bardzo szybkie, podczas gdy większość czasu poświęcano na socket.receive ().

Jeśli czujesz się ambitny, jest też bardziej zaangażowany przykład profilowania SQLAlchemy w testach jednostkowych SQLAlchemy, jeśli poke around http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling . Tam, mamy testy z dekoratorami, które zapewniają maksymalną liczbę wywołań metod używanych do poszczególnych operacji, tak że jeśli coś nieefektywnego zostanie sprawdzone, testy to ujawnią(ważne jest, aby pamiętać ,że w Pythonie wywołania funkcji mają najwyższy narzut z każdej operacji, a liczba wywołań jest częściej niż Nie prawie proporcjonalna do czasu spędzonego). Na uwagę zasługują "zoomark" testuje, które wykorzystują fantazyjny schemat "przechwytywania SQL", który odcina narzut DBAPI z równania-chociaż ta technika nie jest tak naprawdę konieczna do profilowania odmian ogrodowych.