Django + MySQL なシステムで、時間のかかっているクエリを調べる

はじめまして、プロダクト開発グループでサーバーサイドのエンジニアをしている増田です。

　弊社のシステムではサーバーアプリケーションとして Django を、データベースエンジンとして MySQL を使用しているものがいくつかあります。時々、特定のAPI呼び出しに対してレイテンシーが増加したりして、調査としてクエリの処理時間を調べるのですが、その時に行うことを紹介したいと思います。ローカルの検証環境は全て Docker で立ち上げていたので、その簡単なあしらいも含めて記載します。

構成図

※　実際にはリバースプロキシ等がありますが簡略化して記載しています。

Django のSQLログ

Djangoのログは設定ファイル（settings.py）を編集してしまうのが、手がかからず簡単かと思います。 アプリケーションが発行しているSQLのログは、django.db.backend ロガーから出力されるので、これを標準出力にわたすようにします。 特に、時間がかかっているログのみを出力したい場合は、以下のようにCallbackFilter を使ったフィルターを設定すると便利です。

DEBUG = True

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        # 0.1 秒以上かかっているクエリを出力
        'slow_query': {
            '()': 'django.utils.log.CallbackFilter',
            'callback': lambda record: record.duration >= 0.1
        },
    },
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'filters': ['slow_query'],
        },
    },
    'loggers': {
        'django.db.backends': {
            'handlers': ['console'],
            'level': 'DEBUG',
        },
    },
}

上記の設定をした後、ログを確認します。標準出力へログを流しているので、docker logs コマンドでコンテナの外から確認できます。

$ docker logs django_container

# 以下のような出力がなされます。
# ()内がクエリ実行にかかった時間、argsはクエリ作成時にアプリケーション内で使われた引数です。
(0.254) SELECT "table_name"."id", "table_name"."contents" FROM "table_name" WHERE "table_name"."id" = 1; args=(1,)

MySQL の slow_query_log

　上記の django 内のログが出力できれば、比較的簡単に調査ができるかと思いますが、django のバージョン等によってはクエリがうまく出力されないことがあります。その場合は、mysqlのログを直接見に行きます。

　まずはコンテナ内の MySQL サーバーにログインします。（下記を実行後にパスワードを入力）

$ docker exec -it mysql_container mysql -u user_name -p

　続いて slow_query_log の出力設定を行います。こちらはファイル出力にしてみました。

mysql > set global slow_query_log_file = '/path/to/log/file';
mysql > -- long_query_timeに指定された値（秒）以上の時間がかかったクエリをログに記録されます。
mysql > set global long_query_time = 0.1;
mysql > set global slow_query_log = ON;

　出力されたログファイルを tailして確認します。

$ docker exec -it mysql_container tail '/path/to/log/file';

# 以下のような出力がなされます。
# Query_time: 0.254  Lock_time: 0.0706 Rows_sent: 1  Rows_examined: 1
SET timestamp=1611296557;
SELECT "table"."id", "table"."contents" FROM "table" WHERE "table_name"."id" = 1

　以上、簡単ですが、Django + MySQL なシステムで、時間のかかっているクエリを調べる方法を紹介いたしました。