example - sqlalchemy python

¿Cómo puedo perfilar una aplicación con SQLAlchemy?

Question

¿Alguien tiene experiencia en la creación de perfiles de una aplicación Python / SQLAlchemy? ¿Y cuál es la mejor manera de encontrar cuellos de botella y defectos de diseño?

Tenemos una aplicación de Python donde SQLAlchemy maneja la capa de la base de datos. La aplicación utiliza un diseño por lotes, por lo que muchas solicitudes de bases de datos se realizan de forma secuencial y en un período de tiempo limitado. En la actualidad, demora demasiado tiempo para ejecutarse, por lo que se necesita cierta optimización. No usamos la funcionalidad ORM, y la base de datos es PostgreSQL.

Answer 1

Hay una receta de creación de perfiles extremadamente útil en la wiki de SQLAlchemy

Con un par de modificaciones menores,

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 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 : 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))
)

La salida es algo así como:

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

Entonces, si encuentra una consulta extrañamente lenta, puede tomar la cadena de consulta, formatear en los parámetros (se puede hacer el operador de % string-formatting, para psycopg2 al menos), prefijarlo con "EXPLAIN ANALYZE" e introducir la salida del plan de consulta en http://explain.depesz.com/ (encontrado a través de este buen artículo sobre el rendimiento de PostgreSQL )

Answer 2

Tuve cierto éxito al usar cprofile y ver los resultados en runsnakerun. Esto al menos me dijo qué funciones y llamadas llevaban mucho tiempo y si la base de datos era el problema. La documentación está aquí . Necesitas wxpython. La presentación es buena para comenzar.
Es tan fácil como

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

Entonces

python runsnake.py output.profile

Si busca optimizar sus consultas, necesitará perfiles postgrsql .

También vale la pena iniciar sesión para registrar las consultas, pero no conozco ningún analizador que conozca para obtener las consultas de larga ejecución (y no será útil para solicitudes concurrentes).

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

y asegúrate de que tu declaración de motor de creación tenga echo = True.

Cuando lo hice fue en realidad mi código el principal problema, así que lo de perfil ayudó.

Answer 3

A veces, simplemente el registro de SQL (habilitado a través del módulo de registro de python o mediante el argumento echo=True en create_engine() ) puede darte una idea de cuánto create_engine() cosas. Por ejemplo, si registra algo justo después de una operación de SQL, verá algo como esto en su 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] 

Si registró myapp.somemessage justo después de la operación, sabrá que tomó 334ms completar la parte SQL de las cosas.

El registro de SQL también ilustrará si se están emitiendo docenas / cientos de consultas que podrían organizarse mejor en muchas menos consultas mediante combinaciones. Al usar SQLAlchemy ORM, la función "carga ansiosa" se proporciona parcialmente ( contains_eager() ) o completamente ( eagerload() , eagerload_all() ) automatiza esta actividad, pero sin ORM solo significa usar uniones para que los resultados a través de se pueden cargar varias tablas en un conjunto de resultados en lugar de multiplicar el número de consultas a medida que se agrega más profundidad (es decir, r + r*r2 + r*r2*r3 ...)

Si el registro revela que las consultas individuales tardan demasiado, necesitaría un desglose de cuánto tiempo pasó en la base de datos procesando la consulta, enviando los resultados a través de la red, siendo manejado por el DBAPI, y finalmente siendo recibido por el conjunto de resultados de SQLAlchemy y / o capa ORM. Cada una de estas etapas puede presentar sus propios cuellos de botella individuales, dependiendo de los detalles.

Para eso necesita usar perfiles, como cProfile o hotshot. Aquí hay un decorador que 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'']

Para perfilar una sección de código, colóquelo en una función con el decorador:

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

El resultado del perfilado se puede utilizar para dar una idea de dónde se está gastando el tiempo. Si, por ejemplo, ve todo el tiempo pasado dentro de cursor.execute() , esa es la llamada DBAPI de bajo nivel a la base de datos, y significa que su consulta debe optimizarse, ya sea agregando índices o reestructurando la consulta y / o el esquema subyacente. Para esa tarea, recomendaría usar pgadmin junto con su utilidad gráfica EXPLAIN para ver qué tipo de trabajo está haciendo la consulta.

Si ve muchos miles de llamadas relacionadas con la obtención de filas, puede significar que su consulta está devolviendo más filas de lo esperado: un producto cartesiano como resultado de una unión incompleta puede causar este problema. Otro problema es el tiempo dedicado al manejo de tipos: un tipo de SQLAlchemy como Unicode realizará la codificación / decodificación de cadenas en parámetros de enlace y columnas de resultados, que pueden no ser necesarios en todos los casos.

El resultado de un perfil puede ser un poco desalentador, pero después de un poco de práctica son muy fáciles de leer. Hubo una vez alguien en la lista de correo que alegaba lentitud, y después de haber publicado los resultados del perfil, pude demostrar que los problemas de velocidad se debían a la latencia de la red: el tiempo pasado en cursor.execute () y todos los Python. métodos fue muy rápido, mientras que la mayoría del tiempo se gastó en socket.receive ().

Si se siente ambicioso, también hay un ejemplo más involucrado de SQLAlchemy perfiling dentro de las pruebas de unidad SQLAlchemy, si hojea http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling . Allí, tenemos pruebas usando decoradores que afirman un número máximo de llamadas a métodos que se utilizan para operaciones particulares, de modo que si algo ineficiente se controla, las pruebas lo revelarán (es importante notar que en Python, las llamadas a funciones tienen la mayor sobrecarga de cualquier operación, y el recuento de llamadas casi siempre es proporcional al tiempo invertido). Cabe destacar las pruebas "zoomark" que utilizan un esquema de "captura de SQL" que elimina la sobrecarga de DBAPI de la ecuación, aunque esa técnica no es realmente necesaria para el perfil de variedad de jardín.