◀ 9.

Django で SQL ログを出力する方法|django.db.backends と N+1 の発見

▶

DjangoのSQL診断は「組立て表示」「実行時の捕捉」「本数の比較」を分けます。本番DEBUGやDB設定は変更せず、合成データの短い範囲から確認します。

SQLの組立て表示は実行の証拠ではなく、同一aliasの評価を囲んで計測し同じ結果を比較する

この記事の要点
  • loggerのDEBUGレベルとsettings.DEBUGは別です。通常条件とforce_debug_cursor/CaptureQueriesContextを区別します。
  • queryの文字列表現は実行記録でも再実行用SQLでもありません。explainはDBへ問い合わせます。
  • 測るalias・評価範囲・キャッシュ・上限をそろえ、N+1は同じ結果で比較します。
  • SQLの120/500文字への切詰めは匿名化ではありません。例外やparamsの秘密値にも注意します。
  • 元のコード9ブロックは各注意の直後に保持していますが、本番で実行する手順ではありません。

教材はPython 3.12.10 / Django 5.2.18 / SQLite 3.49.1の専用環境で検証しました。既存アプリのsettingsやモデルを置き換えず、教材のテストだけが独立したインメモリDBにschema_editorで最小表を用意します。migrate・外部DB接続・実資格情報・Toolbar導入は使いません。

方法 1: settings.py で全 SQL をログに出す

旧例の注意:旧設定例:loggerとhandlerの実効レベル・filterを確認します。この辞書で既存LOGGING全体を上書きしないでください。通常はDEBUG=Trueが前提ですが、Django 5.2.18では対象接続のforce_debug_cursor=TrueやCaptureQueriesContextでもDEBUG=Falseのまま記録されます。本番DEBUGを変更する手順ではありません。SQL・argsの秘密値がstderrや収集先へ出得ます。

# settings.py
LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "sql": {"format": "[%(asctime)s] %(message)s"},
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "sql",
        },
    },
    "loggers": {
        "django.db.backends": {
            "handlers": ["console"],
            "level": "DEBUG",        # ここを DEBUG にすると SQL が出る
            "propagate": False,
        },
    },
}

実行すると、かかった秒数付きで次のように出力されます。

旧例の注意:旧出力見本:DB種別・版・aliasで書式は変わります。argsには値が含まれ、見た目をコピーして再実行するための正規SQLではありません。時間はDBサーバー内部の純粋な実行時間やリクエスト全体時間ではありません。

(0.001) SELECT "app_user"."id", "app_user"."name" FROM "app_user" WHERE "app_user"."active"; args=(True,)

通常のSQLデバッグはDEBUG=Trueで記録します。ただしDjango 5.2.18の接続はforce_debug_cursorでも記録を有効化し、CaptureQueriesContextはその値を一時的にTrueへ変えて元に戻します。これはテスト/限定診断の仕組みであり、SQL秘匿や本番の常時収集を保証しません。loggerのDEBUG指定だけで記録が有効になるわけではありません。

方法 2: 特定のクエリの SQL だけ見る

表示と実行を別々に捕捉する

次は専用SQLite教材のrepresentation.pyです。str(qs.query)は通常のこのQuerySetでは0本、list(qs)は1本、qs.explain()はEXPLAIN QUERY PLANを1本発行することをテストします。str(qs.query)とrepr(qs)は別で、後者は評価を起こします。文字列化のSQLは値の正しい引用や実行済みの証拠ではありません。選択alias用コンパイラも診断用途に留め、SQL/paramsをログや画面へ無条件に出しません。

from django.db import connections
from django.test.utils import CaptureQueriesContext

from sql_fixture.models import User


def inspect_query(alias="default"):
    conn = connections[alias]
    qs = User.objects.using(alias).filter(name="Ada").order_by("rank", "pk")
    with CaptureQueriesContext(conn) as representation:
        display = str(qs.query)
        sql, params = qs.query.get_compiler(using=qs.db).as_sql()
    with CaptureQueriesContext(conn) as execution:
        rows = list(qs)
    with CaptureQueriesContext(conn) as explanation:
        plan = qs.explain()  # Only the isolated SQLite fixture. No ANALYZE.
    return {"representation_count": len(representation),
            "execution_count": len(execution), "explain_count": len(explanation),
            "display": display, "sql": sql, "params": params,
            "names": [u.name for u in rows], "plan": plan,
            "explain_sql": explanation[0]["sql"]}

explainの対応オプション・出力はDB/版で変わります。この例は隔離SQLiteでのみ実行し、本番やANALYZEの実行手順にはしません。

旧例の注意:旧例は一括実行しない:Userの定義/importは省略されています。created_atだけの並びは同時刻で不定なのでpkも指定します。queryの文字列表現・sql_with_paramsと、DBへ実際に問い合わせるexplainは別です。analyze=Trueは元の検索自体を実行し得て、関数やトリガーの副作用・ロック・高負荷があります。本番で試さないでください。複数DBではsql_with_params()の既定コンパイラとqs.dbの違いにも注意します。

qs = User.objects.filter(active=True).order_by("-created_at")[:10]

print(qs.query)        # 実行せずに SQL 文字列を得る
# SELECT "app_user"."id", ... FROM "app_user" WHERE "app_user"."active" = True
#   ORDER BY "app_user"."created_at" DESC LIMIT 10

# パラメータを分けて見たいとき
print(qs.query.sql_with_params())

# 実行計画まで見たいとき(PostgreSQL / MySQL)
print(qs.explain())
print(qs.explain(analyze=True))

qs.query の出力は値が埋め込まれた見た目になり、そのまま DB に貼っても動かない場合があります。原因調査には十分ですが、対象接続で捕捉した実行時記録も診断用の表現です。DBドライバへ渡したSQLテンプレートとparams、ネットワーク上の内容、DBサーバー側での実行は同一視せず、文字列を組み立て直して実行しません。

方法 3: 実行済みクエリの一覧

connectionはdefault接続へのショートカットです。別DBへusing(alias)したQuerySetを測るならconnections[qs.db]を指定します。一つのcontextは他alias・別スレッド/非同期タスク・別プロセスの総数ではありません。遅延評価するlist/ループ/テンプレートの関連参照までcontext内へ入れます。既に評価済みならキャッシュで0本にもなります。捕捉配列は秘密値を含み得るため、完成例では本数と合成データの結果だけを取り出します。

旧例の注意:旧計測例:reset_queriesは既存診断記録を消します。profileが存在しなければ例外になり、接続aliasや未評価/既存キャッシュにより本数も変わります。sql[:120]でも先頭に秘密値が残ります。len(connection.queries)をアプリ全体の総数と扱わず、新しい短いCaptureQueriesContextで評価範囲を囲みます。

from django.db import connection, reset_queries

reset_queries()                     # 計測開始

users = list(User.objects.all())
for u in users:
    print(u.profile.nickname)       # ここで N+1 が起きる

print(len(connection.queries))      # 発行された本数
for q in connection.queries:
    print(q["time"], q["sql"][:120])

Django 5.2.18のconnection.queries_logは既定maxlen=9000のdequeです。無限に増え続けるわけではなく、上限超過で古い記録が落ち、総数や差分が不正確になります。CaptureQueriesContextもこの記録を使うので大規模/長時間の総数計にはしません。DEBUG=Falseかつforce_debug_cursor=Falseなら通常は蓄積せず、0本でも未実行の証明にはなりません。reset_queriesは全aliasの記録を消し、通常のリクエスト開始でもリセットされます。記録の共有/メモリ/ログ出力自体の負荷は別途考慮します。

N+1 問題を見つける

同じ関連・同じ結果を比較する

専用教材sql_fixture/models.pyは認証Userとは別の最小モデルです。rankが同値でもpkで順序を確定します。3ユーザー、profileあり2件/なし1件、ordersが2件/1件/0件という固定データです。毎回新しいQuerySetで同じ列・同じ関連を読み、結果配列の一致もassertします。

from django.db import models


class User(models.Model):
    name = models.CharField(max_length=40)
    rank = models.IntegerField(default=0)


class Profile(models.Model):
    user = models.OneToOneField(User, on_delete=models.CASCADE, related_name="profile")
    nickname = models.CharField(max_length=40)


class Order(models.Model):
    user = models.ForeignKey(User, on_delete=models.CASCADE, related_name="orders")
    label = models.CharField(max_length=40)

    class Meta:
        ordering = ["pk"]
from django.db import connections
from django.test.utils import CaptureQueriesContext

from sql_fixture.models import Profile, User


def profiles(qs):
    rows = []
    for user in qs:
        try:
            nickname = user.profile.nickname
        except Profile.DoesNotExist:
            nickname = None
        rows.append((user.pk, user.name, nickname))
    return rows


def orders(qs):
    return [(u.pk, u.name, tuple(o.label for o in u.orders.all())) for u in qs]


def measure(read, qs):
    with CaptureQueriesContext(connections[qs.db]) as captured:
        result = read(qs)
    return len(captured), result


def compare(alias="default"):
    def fresh():
        return User.objects.using(alias).order_by("rank", "pk")

    p0 = measure(profiles, fresh())
    p1 = measure(profiles, fresh().select_related("profile"))
    p2 = measure(profiles, fresh().prefetch_related("profile"))
    o0 = measure(orders, fresh())
    o1 = measure(orders, fresh().prefetch_related("orders"))
    assert p0[1] == p1[1] == p2[1]
    assert o0[1] == o1[1]
    return {"profile_counts": [p0[0], p1[0], p2[0]],
            "order_counts": [o0[0], o1[0]],
            "profiles": p0[1], "orders": o0[1]}

検証結果:profileの素朴な参照は4本(1+N)、select_relatedは1本、prefetch_relatedは2本で、3つとも同じユーザーID・名前・nickname(欠落はNone)です。ordersは4本と2本で同じ注文リスト(空は空tuple)を返します。多値のordersをselect_relatedへ置き換える比較ではありません。

この本数は固定データの結果で一般則の保証ではありません。逆OneToOneの欠落は例外を処理し、空の親結果ならprefetchの2本目は発行されない場合があります。none()は0本、DB検索の空結果は1本です。既に評価したQuerySetや関連キャッシュの再利用は本数を変えます。prefetch後のorders.filter(...)や別のorder_by(...)はall()のキャッシュを使わず追加SQLになり得ます。絞込みが必要ならPrefetchのqueryset/to_attr等を設計して同じ結果を比較します。件数の改善だけでメモリ・転送量・時間の改善まで断定しません。

旧例の注意:旧比較は不公平:profileを読む処理とordersを数える処理は同じ結果ではありません。旧contextmanagerには例外時のfinallyもなく、DEBUG=Falseなら誤って0本に見えます。「同じ関連・同じ結果を比較する」の完成例と区別してください。

from django.db import connection, reset_queries
from contextlib import contextmanager

@contextmanager
def count_queries(label):
    reset_queries()
    yield
    print(f"{label}: {len(connection.queries)} 本")

with count_queries("最適化なし"):
    for u in User.objects.all():
        print(u.profile.nickname)        # 1 + N 本

with count_queries("select_related"):
    for u in User.objects.select_related("profile"):
        print(u.profile.nickname)        # 1 本(JOIN される)

with count_queries("prefetch_related"):
    for u in User.objects.prefetch_related("orders"):
        print(len(u.orders.all()))       # 2 本(別クエリでまとめて取得)
関係使うもの
ForeignKey / OneToOneField(1 対 1・多対 1)select_related()
逆参照 / ManyToManyField(1 対多・多対多)prefetch_related()

方法 4: django-debug-toolbar

2026年10月26日に公式文書を確認しました。latestには未リリース項目もあり、ページの表示タイトルだけで最新リリースや採用版を判断せず、利用する版の要件と変更履歴を照合します。この作業ではToolbarをインストールしておらず、画面や統合動作は未検証です。参照した文書はdebug_toolbar_urls()を使う導線を案内しています。旧include方式の利用可否は採用版で確認し、既存設定を置換しません。文書はasync/ASGI対応も説明しますが、同時リクエスト処理の制限も記載しています。DEBUGやIPだけを秘密情報のアクセス制御の保証にしません。

旧例の注意:旧導入コマンドは記録用です。この教材では実行せず、既存環境の依存も変更しません。対象Python/Djangoに対応する版を確認し、採用は別の開発用環境で判断してください。

pip install django-debug-toolbar

旧例の注意:旧設定はそのまま転用しない:INSTALLED_APPSだけでなくURL・middleware・表示条件も開発環境へ限定します。middlewareを無条件に先頭へ入れず、GZipMiddlewareより後など公式の順序条件を確認します。INTERNAL_IPSやURL設定を一括上書きせず、利用版のURL APIを確認します。

# settings.py
INSTALLED_APPS += ["debug_toolbar"]
MIDDLEWARE.insert(0, "debug_toolbar.middleware.DebugToolbarMiddleware")
INTERNAL_IPS = ["127.0.0.1"]

# urls.py
from django.urls import include, path
import debug_toolbar

urlpatterns += [path("__debug__/", include(debug_toolbar.urls))]

画面の右側にパネルが出て、SQL の本数・実行時間・重複回数・実行計画が一覧できます。同じSQLの反復はN+1の手掛かりですが、正当な反復処理もあり、それだけで確定しません。SQL形状が違うN+1もあります。HTMLへの挿入条件・staticfiles・テンプレート・middleware・接続元IP・表示callbackを確認し、APIのJSON等では同じパネルが出るとは限りません。全設定を開発環境に限定し、公開環境には露出させません。

本番で SQL を確認したいとき

SQLもparamsも保持しない局所集計

metrics.pyとmetrics_usage.pyは短い同期処理の対象aliasにだけexecute_wrapperを付けます。SQL・params・例外メッセージ・ユーザー識別子を保存/出力せず、固定上限までの呼出回数と経過秒だけを集計します。上限は既定100、許容1〜1000です。capped=Trueならsampled_callsは下限であり、elapsed_secondsも最初の上限回だけの合計です。上限後も業務SQLは通常どおり実行されるので、クエリ制限・タイムアウト・総数計ではありません。

from time import perf_counter


class QueryMetrics:
    def __init__(self, limit=100):
        if not isinstance(limit, int) or isinstance(limit, bool) or not 1 <= limit <= 1000:
            raise ValueError("limit must be 1..1000")
        self.limit = limit
        self.sampled_calls = 0
        self.elapsed_seconds = 0.0
        self.capped = False

    def __call__(self, execute, sql, params, many, context):
        if self.sampled_calls >= self.limit:
            self.capped = True
            return execute(sql, params, many, context)
        self.sampled_calls += 1
        start = perf_counter()
        try:
            return execute(sql, params, many, context)
        finally:
            self.elapsed_seconds += perf_counter() - start

    def summary(self):
        return {"sampled_calls": self.sampled_calls,
                "elapsed_seconds": self.elapsed_seconds, "capped": self.capped}
from django.db import connections

from metrics import QueryMetrics
from sql_fixture.models import User


def count_without_values(alias="default"):
    conn = connections[alias]
    metrics = QueryMetrics(limit=100)
    with conn.execute_wrapper(metrics):
        result = list(User.objects.using(alias).order_by("pk").values_list("pk", flat=True))
    return result, metrics.summary()

execute/executemanyの呼出回数であり、executemanyの行数ではありません。失敗した呼出しもfinallyで時間に含め、例外はそのまま再送出します。perf_counterの差はcursor呼出周辺の経過時間で、後続のfetch・Python整形・リクエスト全体やDB内部時間とは違います。withを抜けると例外時もwrapperが除去されます。別aliasには別contextが必要で、context外の遅延評価、StreamingHttpResponseの後続処理、別スレッド/非同期タスクを自動的に覆いません。既存のSQLロガー・DBログやエラーログを停止/匿名化するコードでもありません。本番採用には負荷・情報管理・対象期間・解除手順の別途レビューが必要です。

DEBUG = True を本番で有効にしてはいけません。設定値やソースコードが画面に露出します。DB側ログの設定変更は別途承認が必要です。必要なら短い実行範囲の値を含まない集計などを設計しますが、この教材は本番へ導入しません。

旧例の注意:旧DB設定SQLは実行禁止の記録です。SET GLOBALはサーバーの設定変更で、Djangoの局所計測とは違います。既存接続/新規接続への作用、権限、出力先、負荷、復旧値の審査が必要です。PostgreSQLの設定変更/reloadもここでは行いません。本番でDBログしか選べないという意味ではありません。

-- MySQL: 遅いクエリだけ残す
SET GLOBAL slow_query_log = ON;
SET GLOBAL long_query_time = 1;      -- 1 秒以上
SHOW VARIABLES LIKE 'slow_query_log_file';

-- PostgreSQL: postgresql.conf
-- log_min_duration_statement = 1000  (ミリ秒)
-- SELECT pg_reload_conf();

アプリ側で残したい場合は、connection.execute_wrapper() で自前のフックを差し込む方法もあります。こちらは DEBUG に依存しません。

旧例の注意:旧フックは転用しない:sql[:500]は匿名化ではなく、先頭500文字にも秘密値が含まれ得ます。paramsを出さなくても安全とは限りません。finallyでDB例外のメッセージやSQLを出すのも避けます。「SQLもparamsも保持しない局所集計」の完成例は値を保持せず、元例は比較用だけ残しています。

import logging
import time
from django.db import connection

logger = logging.getLogger("sql")

def log_slow(execute, sql, params, many, context):
    start = time.monotonic()
    try:
        return execute(sql, params, many, context)
    finally:
        elapsed = time.monotonic() - start
        if elapsed > 0.5:                       # 0.5 秒以上だけ記録
            logger.warning("slow %.3fs %s", elapsed, sql[:500])

# ミドルウェアやビューの中で
with connection.execute_wrapper(log_slow):
    list(User.objects.all())

SQL には検索条件として個人情報が入り得ます。ログに残す前に、出力先の権限と保存期間を決めておいてください。

関連

検証範囲と公式資料

2026年10月26日確認。追加教材のSQLiteで同一結果/本数・欠落/空・alias・キャッシュ・表示0本/実行1本/EXPLAIN1本・DEBUG=False時の捕捉・例外時の復元・上限・値を保持しない集計を検査しています。実MySQL/PostgreSQL、実トラフィックの性能、本番ログ収集、Toolbar画面、async/ASGI/streamingの動作は未検証です。隔離試験を本番での導入許可とは扱いません。

公式資料:Django SQL診断FAQ、SQL logger、QuerySetの評価・関連取得・explain、execute_wrapper、5.2.18の接続と記録上限、5.2.18のCaptureQueriesContext、Python perf_counter、Toolbar導入条件、Toolbar表示設定、Toolbar変更履歴。

子ページ

子ページはありません

同階層のページ
  1. 環境構築とプロジェクト/アプリの作成
  2. MVC(MVT)のそれぞれの使い方と説明
  3. データベースへの接続と操作
  4. Django Administration
  5. git管理
  6. エラー一覧
  7. バージョンの確認方法
  8. ログ出力方法
  9. SQLのログ出力方法
  10. ログのローテート設定
  11. settings.pyの定数にアクセスする方法
  12. 本番環境へのインストールとアプリのデプロイ(apache編)
  13. 本番環境へのインストールとアプリのデプロイ(nginx編)
  14. djangoアプリの本番の開始URLを変更する
  15. 静的(static)ファイルの置き場所と読み込み(画像、css、js )
  16. CSRFトークンをAjaxで使用する方法
  17. ajaxの使用例(POST編)
  18. ファイルのアップロードとファイルの名前
  19. クイックスタート/チュートリアル
  20. ログイン機能
  21. テンプレート側のログイン判定
  22. ビュー側のログイン判定
  23. 管理者ユーザーの作成/判定と管理画面
  24. モデルのjson化とレスポンス
  25. runserverでポートを指定する方法
  26. cronによるバッチ実行
  27. テンプレートで利用する共通のcontextを定義する方法
  28. プログラムが本番サーバーで反映されない場合の対処法
  29. APIの作成
  30. cron用コマンド・ファイルの作成

最近更新/作成されたページ