En ocasiones, el simple registro de SQL (habilitado a través del módulo de registro de Python o mediante el argumento echo=True en create_engine()) puede darle una idea de cuánto demoran las cosas. Por ejemplo si se registra algo bien después de una operación de SQL, que vería 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 accede myapp.somemessage justo después de la operación, usted sabe que tomó 334ms para completar la parte de SQL cosas.
Logging SQL también ilustrará si se están emitiendo docenas/cientos de consultas que podrían organizarse mejor en muchas menos consultas mediante join. Al utilizar SQLAlchemy ORM, la característica "carga ansiosa" se proporciona parcialmente (contains_eager()) o completamente (eagerload(), eagerload_all()) automatice esta actividad, pero sin ORM solo significa usar combinaciones para que los resultados en múltiples tablas puedan cargarse en un conjunto de resultados en lugar de multiplicar números 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, se necesita un desglose de cuánto tiempo se pasó dentro del la base de datos procesa la consulta, envía los resultados a través de la red, es manejada por el DBAPI, y finalmente es recibida por el conjunto de resultados de SQLAlchemy y/o la capa ORM. Cada una de estas etapas puede presentar sus propios cuellos de botella individuales, dependiendo de los detalles.
Para eso necesita utilizar perfiles, como cProfile o hotshot.Aquí es un decorador que utilizo:
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 perfil de una sección de código, colocarlo en una función con el decorador:
@profile
def go():
return Session.query(FooClass).filter(FooClass.somevalue==8).all()
myfoos = go()
La salida de los perfiles se puede utilizar para dar una idea donde el tiempo está siendo gastado 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 ser optimizada, 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 ir a buscar filas, es posible que su consulta regrese más filas de las esperadas: un producto cartesiano como resultado de una combinació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.
La salida de un perfil puede ser un poco desalentadora, 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 complicado de SQLAlchemy perfiling dentro de las pruebas de la unidad SQLAlchemy, si explora 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.
Si está utilizando matraz de SQLAlchemy, añadir 'SQLALCHEMY_ECHO = true' de configuración de su aplicación en su lugar. – henrycjc