Come posso profilare un'applicazione alimentata con SQLAlchemy?

Question

Qualcuno ha esperienza nella creazione di profili di un'app Python/SQLAlchemy? E qual è il modo migliore per trovare colli di bottiglia e difetti di progettazione?

Abbiamo un'applicazione Python in cui il livello del database è gestito da SQLAlchemy. L'applicazione utilizza una progettazione batch, quindi molte richieste di database vengono eseguite in modo sequenziale e in un intervallo di tempo limitato. Attualmente richiede un po 'troppo tempo per essere eseguito, quindi è necessaria qualche ottimizzazione. Non usiamo la funzionalità ORM e il database è PostgreSQL.

Answer 1

A volte solo la semplice registrazione SQL (abilitata tramite il modulo di registrazione di Python o tramite l'argomento echo=True su create_engine()) può darti un'idea di quanto tempo ci vuole. Per esempio, se si accede qualcosa di giusto dopo un'operazione di SQL, si vedrebbe qualcosa di simile nel registro:

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] 

se ci si collega myapp.somemessage subito dopo l'operazione, si sa ci sono voluti 334ms per completare la parte di SQL di cose.

Registrazione SQL illustrerà anche se decine/centinaia di query vengono emesse che potrebbero essere meglio organizzate in molte meno query tramite join. Quando si utilizza l'ORM di SQLAlchemy, la funzione "caricamento ansioso" viene fornita parzialmente (contains_eager()) o completamente (eagerload(), eagerload_all()) automatizza questa attività, ma senza l'ORM significa solo utilizzare i join in modo che i risultati su più tabelle possano essere caricati in un set di risultati invece di moltiplicare i numeri di query a più profondità aggiunta (es. r + r*r2 + r*r2*r3 ...)

Se la registrazione rivela che le singole query impiegano troppo tempo, è necessario disporre di una suddivisione di quanto tempo è stato speso all'interno del database che elabora la query, invia i risultati sulla rete, viene gestito dal DBAPI e infine viene ricevuto dal set di risultati di SQLAlchemy e/o dal livello ORM. Ognuna di queste fasi può presentare i propri colli di bottiglia individuali, a seconda delle specifiche.

Per questo è necessario utilizzare la profilatura, ad esempio cProfile o hotshot.Qui è un decoratore che uso:

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'] 

al profilo una sezione di codice, posizionarlo in una funzione con il decoratore:

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

L'uscita di profilatura può essere usato per dare un'idea dove il tempo è stato speso. Se ad esempio si vede tutto il tempo trascorso all'interno di cursor.execute(), si tratta della chiamata DBAPI di basso livello al database e significa che la query deve essere ottimizzata, aggiungendo indici o ristrutturando la query e/o lo schema sottostante. Per questo compito, consiglierei di usare pgadmin insieme alla sua utility grafica EXPLAIN per vedere che tipo di lavoro sta facendo la query.

Se vedete molte migliaia di chiamate relative al recupero di righe, potrebbe significare che la vostra query restituisce più righe del previsto: un prodotto cartesiano a seguito di un join incompleto può causare questo problema. Un altro problema è il tempo trascorso nella gestione dei tipi: un tipo SQLAlchemy come Unicode eseguirà la codifica/decodifica delle stringhe sui parametri di collegamento e sulle colonne dei risultati, che potrebbero non essere necessarie in tutti i casi.

L'output di un profilo può essere un po 'scoraggiante, ma dopo un po' di pratica sono molto facili da leggere. C'era una volta qualcuno sulla mailing list che sosteneva la lentezza, e dopo averlo postare i risultati del profilo, sono stato in grado di dimostrare che i problemi di velocità erano dovuti alla latenza della rete - il tempo trascorso all'interno di cursor.execute() e di tutto il Python i metodi erano molto veloci, mentre la maggior parte del tempo era speso per socket.receive().

Se ti senti ambizioso, c'è anche un esempio più impegnativo di SQLAlchemy profiling all'interno dei test delle unità SQLAlchemy, se fai un salto intorno a http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling. Lì, abbiamo test che usano decoratori che asseriscono un numero massimo di chiamate di metodo usate per operazioni particolari, in modo che se qualcosa di inefficiente viene controllato, i test lo rivelano (è importante notare che in Python le chiamate di funzione hanno il più alto sovraccarico di qualsiasi operazione, e il conteggio delle chiamate è più spesso o quasi proporzionale al tempo trascorso). Di nota sono i test "zoomark" che utilizzano un fantastico schema di "cattura SQL" che elimina il sovraccarico del DBAPI dall'equazione - sebbene questa tecnica non sia realmente necessaria per la profilazione di varietà da giardino.

Answer 2

Ho avuto qualche successo nell'utilizzo di cprofile e guardando i risultati in runsnakerun. Questo almeno mi ha detto quali funzioni e chiamate richiedevano molto tempo e se il database era il problema. La documentazione è here. Hai bisogno di wxpython. Il presentation su di esso è buono per iniziare.
sua facile come

import cProfile 
command = """foo.run()""" 
cProfile.runctx(command, globals(), locals(), filename="output.profile") 

Poi

pitone runsnake.py output.profile

Se stai cercando di ottimizzare le query dovrai postgrsql profiling.

Vale anche la pena effettuare l'accesso per registrare le query, ma non esiste un parser per questo che conosco per ottenere le query a esecuzione prolungata (e non sarà utile per le richieste simultanee).

sqlhandler = logging.FileHandler("sql.log") 
sqllogger = logging.getLogger('sqlalchemy.engine') 
sqllogger.setLevel(logging.info) 
sqllogger.addHandler(sqlhandler) 

e assicurarsi che l'istruzione del motore di creazione abbia echo = True.

Quando l'ho fatto è stato in realtà il mio codice che era il problema principale, quindi la cosa del cprofile mi ha aiutato.

Answer 3

C'è una ricetta profilatura estremamente utile sul SQLAlchemy wiki

Con un paio di piccole modifiche,

from sqlalchemy import event 
from sqlalchemy.engine import Engine 
import time 
import logging 

logging.basicConfig() 
logger = logging.getLogger("myapp.sqltime") 
logger.setLevel(logging.DEBUG) 

@event.listens_for(Engine, "before_cursor_execute") 
def before_cursor_execute(conn, cursor, statement, 
         parameters, context, executemany): 
    context._query_start_time = time.time() 
    logger.debug("Start Query:\n%s" % statement) 
    # Modification for StackOverflow answer: 
    # Show parameters, which might be too verbose, depending on usage.. 
    logger.debug("Parameters:\n%r" % (parameters,)) 


@event.listens_for(Engine, "after_cursor_execute") 
def after_cursor_execute(conn, cursor, statement, 
         parameters, context, executemany): 
    total = time.time() - context._query_start_time 
    logger.debug("Query Complete!") 

    # Modification for StackOverflow: times in milliseconds 
    logger.debug("Total Time: %.02fms" % (total*1000)) 

if __name__ == '__main__': 
    from sqlalchemy import * 

    engine = create_engine('sqlite://') 

    m1 = MetaData(engine) 
    t1 = Table("sometable", m1, 
      Column("id", Integer, primary_key=True), 
      Column("data", String(255), nullable=False), 
     ) 

    conn = engine.connect() 
    m1.create_all(conn) 

    conn.execute(
     t1.insert(), 
     [{"data":"entry %d" % x} for x in xrange(100000)] 
    ) 

    conn.execute(
     t1.select().where(t1.c.data.between("entry 25", "entry 7800")).order_by(desc(t1.c.data)) 
    ) 

uscita è qualcosa di simile:

DEBUG:myapp.sqltime:Start Query: 
SELECT sometable.id, sometable.data 
FROM sometable 
WHERE sometable.data BETWEEN ? AND ? ORDER BY sometable.data DESC 
DEBUG:myapp.sqltime:Parameters: 
('entry 25', 'entry 7800') 
DEBUG:myapp.sqltime:Query Complete! 
DEBUG:myapp.sqltime:Total Time: 410.46ms 

Quindi se trovate un stranamente lento query, è possibile utilizzare la stringa di query, formattare i parametri (può essere eseguito l'operatore di formattazione stringa % per psyco PG2 almeno), con prefisso "spiegano Analyse" e spingere l'uscita piano di query in http://explain.depesz.com/ (trovato tramite this good article on PostgreSQL performance)