カカドゥ開発者ブログ

株式会社カカドゥのエンジニアブログです。Python, Django, SEO成分が多めです。

DjangoのModel操作をしたときに内部で発行されたSQLログを確認する方法

こんにちは。カカドゥの増田です。

DjangoのORM(ORマッパー)はとても便利ですね。僕は以下の様な点でDjangoのORMがとても気に入ってます。

  • メソッド名が直感的(filter, exclude, annotate, aggregate...)
  • ドキュメントをよく読めば習得コストもそれほど高くない
  • ビジネスロジックの中に少ないコードでModel操作が書ける

そんな便利なORMですが、内部で実行されたSQLが効率的なものになっているか気になることがあります。

Djangoの場合は、以下のようにしてやれば内部で実行されたSQLを確認することができます。

from django.db import connection

print connection.queries

ログ処理の実装は以下のようになっており、実行されたSQLと、実行にかかった時間をミリ秒レベルで確認することができます。

self.db.queries_log.append({
    'sql': sql,
    'time': "%.3f" % duration,
})

# django.db.backends.utilsより抜粋

なお、connection.queriesは内的にはcollections.dequeによるリストのようデータ構造になっており、runserverのときは1リクエスト処理するときに実行されたSQLが、shellのときはshell起動中に実行されたSQLが、最大で9000件記録されています。永続化されてどこかに残っているわけではないです。

また、DjangoのModel操作は遅延評価されるため、views.pyの中でデバッグ文的に

print connection.queries

と書いてても、評価されていない(SQL実行されていない)DBアクセスは当然queriesに記録されていませんので、ご注意ください。(自分がそれでハマった)