Parfois, juste en plaine SQL (enregistrement activé par du python module de journalisation ou par l'intermédiaire de l' echo=True argument sur create_engine()) peut vous donner une idée de combien de temps les choses sont en train de prendre. Par exemple, si vous vous connectez quelque chose de bien après une opération SQL, vous devriez voir quelque chose comme ceci dans votre journal:
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 vous vous êtes connecté myapp.somemessage immédiatement après l'opération, vous savez qu'il a pris 334ms pour compléter le SQL part des choses.
La journalisation SQL illustre également si des dizaines/centaines de requêtes sont émises qui pourrait être mieux organisé dans beaucoup moins de requêtes via les jointures. Lors de l'utilisation de la SQLAlchemy ORM, le "désireux de chargement" fonctionnalité est fournie partiellement (contains_eager()) ou totalement (eagerload(), eagerload_all()) automatiser cette activité, mais sans l'ORM il signifie juste à utiliser les jointures de sorte que les résultats provenant de plusieurs tables peuvent être chargés dans un jeu de résultats, au lieu de multiplier les nombres de requêtes que plus la profondeur est ajoutée (c - r + r*r2 + r*r2*r3 ...)
Si l'enregistrement révèle que les requêtes individuelles sont trop long, vous auriez besoin d'une ventilation de la façon dont beaucoup de temps a été passé à l'intérieur de la base de données du traitement de la requête, de l'envoi des résultats sur le réseau, géré par l'DBAPI, et enfin d'être reçu par SQLAlchemy de l'ensemble de résultats et/ou de la couche ORM. Chacune de ces étapes peuvent présenter leur propre goulets d'étranglement, en fonction de spécificités.
Pour cela vous devez utiliser le profilage, comme cProfile ou hotshot. Voici un décorateur, j'utilise:
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']
Le profil d'une section de code, placez-le dans une fonction avec le décorateur:
@profile
def go():
return Session.query(FooClass).filter(FooClass.somevalue==8).all()
myfoos = go()
La sortie de profilage peuvent être utilisés pour donner une idée de l'endroit où le temps passé. Si par exemple vous voyez tout le temps dépensé dans cursor.execute(), c'est le faible niveau DBAPI appel à la base de données, et cela signifie que votre requête doit être optimisé, soit par l'ajout d'index ou de la restructuration de la requête et/ou le schéma sous-jacent. Pour cette tâche, je vous conseille d'utiliser pgadmin avec son interface graphique EXPLIQUER utilitaire pour voir quel genre de travail que la requête est en train de faire.
Si vous voyez plusieurs milliers d'appels liés à la récupération des lignes, cela peut signifier que votre requête est de retour plus de lignes que prévu - un produit cartésien comme un résultat d'une incomplète joindre peuvent causer ce problème. Encore un autre problème est le temps passé au sein du type de manipulation - une SQLAlchemy, type Unicode effectuera chaîne de codage/décodage sur lier des paramètres et des colonnes de résultat, qui peut ne pas être nécessaire dans tous les cas.
La sortie d'un profil peut être un peu intimidant, mais après un peu de pratique, ils sont très faciles à lire. Il était une fois quelqu'un sur la liste de diffusion revendiquant la lenteur, et après lui avoir publier les résultats de profil, j'ai été en mesure de démontrer que la vitesse de problèmes étaient dus à la latence du réseau, - le temps passé à l'intérieur du curseur.execute() ainsi que toutes les méthodes Python a été très rapide, alors que la majorité du temps a été passé sur la socket.recevoir().
Si vous vous sentez ambitieux, il est aussi plus impliqués exemple de SQLAlchemy de profilage dans la SQLAlchemy des tests unitaires, si vous faites le tour d' http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling . Là, nous avons des tests à l'aide de décorateurs qui imposent un nombre maximum d'appels de méthode utilisée pour des opérations particulières, de sorte que si quelque chose d'inefficace obtient vérifié dans, les tests révèlent qu'elle (il est important de noter que, dans Python, les appels de fonction ont le plus de frais généraux de fonctionnement et le nombre d'appels est le plus souvent pas à peu près proportionnelle au temps passé). Notez le "zoomark" tests qui utilisent une fantaisie "SQL de capture du régime, qui coupe la surcharge de la DBAPI à partir de l'équation - bien que cette technique n'est pas vraiment nécessaire pour le jardin-variété de profilage.
