HOW-TO: Логирование SQL-запросов в django

Иногда хочется посмотреть, какие запросы генерируются django-ой и где растут ноги этих запросов? Не отказывайте себе в этом!

0. “django.db”: “DEBUG”

Шаг нулевой - убедиться, что у вас правильно сконфигурирован логгер

Для начала можно просто попробовать выставить "DEBUG" уровень для django.db логера.

(здесь и далее `…` - сокращение текста, не несущего смысловой нагрузки)

# project/settings.py
LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'simple': {
            'format': '[%(levelname)s:%(name)s:%(lineno)d] %(message)s'
        },
    },
    'handlers': {
        # ...
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple',
        },
    },
    'loggers': {
        # ...
        'django.db': {
            'handlers': ['console'],
            'level': 'DEBUG',  # <----<<<
            'propagate': False,
        }
    }
}

После этого, в консоли уже можно увидеть желанные строчки с SQL-ем.

[DEBUG:django.db.backends:91] (0.003) SELECT "django_session"."session_key", ...
[DEBUG:django.db.backends:91] (0.003) SELECT "profile_user"."password", "profile_user"...
[DEBUG:django.db.backends:91] (0.002) SELECT COUNT(*) FROM "core_entity" INNER JOIN ...

К большому сожалению, читать такой лог крайне проблематично и неудобно. К тому же, непонятно, окуда был вызван код, который привел к обращению к базе.

Если у вас задача узнать наличие запросов, то в целом, на этом шаге можно и закончить. Если периодически хочется взглянуть на SQL, заботливо отваренный django-ой - будем дальше подтачивать настройки.

1. record.sql = format_sql(record.sql)

Шаг первый - добавим свой фильт, который будет уметь форматировать SQL.

Почему фильтр? Похоже, что это единственное вменяемое место с доступом к LogRecord.

Библиотеку для форматирования можете брать любую. Для примера возьмем sqlparse.

Код может выглядеть следующим образом:

# project/apps/core/debug.py
import logging

try:
    from sqlparse import format as format_sql
except ImportError:
    format_sql = lambda sql, **options: sql


class SqlFilter(logging.Filter):
    INDENT = '\n  '
    MSG = ('Sql query took {record.duration:.3f}s with params={record.params}:'
           '{indent}{record.sql}\n')

    def filter(self, record):
        if hasattr(record, 'sql') and record.sql:
            record.sql = format_sql(record.sql, reindent=True, indent_width=2)  # <----<<<<
            record.sql = record.sql.strip().replace('\n', self.INDENT)
            record.msg = self.MSG.format(record=record, indent=self.INDENT)

        return True

В конце кода мы перезаписываем отформатированную версию SQL в атрибут msg, который, в конечном итоге, и будет выводиться в консоль.

Осталось добавить наш фильт в конфигурацию логирования.

# project/settings.py
LOGGING = {
    # ...
    'filters': {
        'sql_preprocessor': {
            '()': 'project.apps.core.debug.SqlFilter',
        },
    },
    'handlers': {
        # ...
        'console': {
            # ...
            'filters': ['sql_preprocessor']  # <----<<<<
        },
    },
    # ...
}

Уже лучше, читаемость подправили!

[DEBUG:django.db.backends:91] Sql query took 0.002s with params=(...):
  SELECT "django_session"."session_key",
         "django_session"."session_data",
         "django_session"."expire_date"
  FROM "django_session"
  WHERE ("django_session"."session_key" = ...
         AND "django_session"."expire_date" > ...) LIMIT 21

[DEBUG:django.db.backends:91] Sql query took 0.002s with params=(...):
  SELECT "profile_user"."password",
         "profile_user"."last_login",
         "profile_user"."id",
         ...
  FROM "profile_user"
  WHERE ... LIMIT 21

[DEBUG:django.db.backends:91] Sql query took 0.001s with params=(...):
  SELECT COUNT(*)
  FROM "profile_user"
  INNER JOIN ...

Двигаемся дальше, давайте выясним источник запросов.

2. traceback.format_list(source_trace)

Шаг второй - узнаем из call-stack’a потенциального эмитера запроса.

Добавим фильтр, который будет извлекать текущий call-stack и прикреплять его к LogRecord.

# project/apps/core/debug.
import logging
import traceback

# ...

class SqlContextFilter(logging.Filter):

    def filter(self, record):
        if hasattr(record, 'sql') and record.sql:
            record.sql_source_trace = ''.join(
                traceback.format_list(traceback.extract_stack())).strip()

            return True

Осталось вывести его в консоль, но для этого создадим отдельный обработчик, чтобы данный call-stack появлялся как самостоятельная запись в логе, а не как часть лога с отформатированным SQL (мы бы могли просто добавить эту информацию в конец текущего recored.msg).

Итак, обновляем настройки:

# project/settings.py
LOGGING = {
    # ...
    'formatters': {
        # ...
        'simple_sql_source_trace': {
            'format': '[%(levelname)s:%(name)s:%(lineno)d] '
                      'Stacktrace of SQL query producer:'
                      '\n  %(sql_source_trace)s\n'
        },
    },
    'filters': {
        # ...
        'sql_context_filter': {
            '()': 'project.apps.core.debug.SqlContextFilter',
        },
    },
    'handlers': {
        # ...
        'sql_source_trace': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple_sql_source_trace',
            'filters': ['sql_context_filter']
        },
    },
    'loggers': {
        # ...
        'django.db': {
            'handlers': ['console', 'sql_source_trace'],
            'level': 'DEBUG',
            'propagate': False,
        }
        # ...
    }
    # ...
}

Результат:

[DEBUG:django.db.backends:91] Sql query took 0.002s with params=(...):
  SELECT "django_session"."session_key",
         "django_session"."session_data",
         "django_session"."expire_date"
  FROM "django_session"
  WHERE ("django_session"."session_key" = ...
         AND "django_session"."expire_date" > ...) LIMIT 21

[DEBUG:django.db.backends:91] Stacktrace of SQL query producer:
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/threading.py", line 783, in __bootstrap
    self.__bootstrap_inner()
  # 12 lines ...
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/wsgiref/simple_server.py", line 124, in handle
    handler.run(self.server.get_app())
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/wsgiref/handlers.py", line 85, in run
    self.result = application(self.environ, self.start_response)
  # 60 lines ...
  File "/code/edu-dj-log-sql/project/apps/core/debug.py", line 68, in filter
    traceback.format_list(traceback.extract_stack())).strip()

Не совсем то, чего мы ожидали, разбираться легче не стало. Надо сокращать количество строк call-stack’a. Давайте попробуем выделить 3-4 строки, которые будут достаточно релевантны для нас, чтобы указать на место в коде, где запрос начал свой путь.

Можно обрезать стек по определенным маркерам, чтобы не видеть глубоких внутренностей фреймворка.

# project/apps/core/debug.py
import logging
from itertools import takewhile
import traceback

# ...

class SqlContextFilter(logging.Filter):
    STACK_CUTTERS = (
        'django/db/backends/utils.py',
        'django/db/models/query.py',
        'django/db/backends/postgresql_psycopg2/introspection.py',
    )

    STACK_LIMIT = 3

    def filter(self, record):
        if hasattr(record, 'sql') and record.sql:
            source_trace = list(takewhile(lambda frame: not any(map(frame[0].endswith, self.STACK_CUTTERS)),
                                          traceback.extract_stack()))
            record.sql_source_trace = ''.join(traceback.format_list(source_trace[-self.STACK_LIMIT:])).strip()

            return True

Взглянем на вывод в лог:

[DEBUG:django.db.backends:91] Sql query took 0.002s with params=(...):
  SELECT "django_session"."session_key",
         "django_session"."session_data",
         "django_session"."expire_date"
  FROM "django_session"
  WHERE ("django_session"."session_key" = ...
         AND "django_session"."expire_date" > ...) LIMIT 21

[DEBUG:django.db.backends:91] Stacktrace of SQL query producer:
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/site-packages/django/contrib/sessions/backends/base.py", line 182, in _get_session
    self._session_cache = self.load()
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/site-packages/django/contrib/sessions/backends/db.py", line 21, in load
    expire_date__gt=timezone.now()
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/site-packages/django/db/models/manager.py", line 92, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)

[DEBUG:django.db.backends:91] Sql query took 0.002s with params=(...):
  SELECT "profile_user"."password",
         "profile_user"."last_login",
         "profile_user"."id",
         ...
  FROM "profile_user"
  WHERE ... LIMIT 21

[DEBUG:django.db.backends:91] Stacktrace of SQL query producer:
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/site-packages/django/contrib/auth/__init__.py", line 159, in get_user
    user = backend.get_user(user_id)
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/site-packages/django/contrib/auth/backends.py", line 69, in get_user
    return UserModel._default_manager.get(pk=user_id)
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/site-packages/django/db/models/manager.py", line 92, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)

[DEBUG:django.db.backends:91] Sql query took 0.001s with params=(...):
  SELECT COUNT(*)
  FROM "profile_user"
  INNER JOIN ...

[DEBUG:django.db.backends:91] Stacktrace of SQL query producer:
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/site-packages/rest_framework/fields.py", line 1583, in to_representation
    return method(value)
  File "/code/edu-dj-log-sql/project/apps/api/views/response_serializers/profile.py", line 15, in get_blocked_count
    return profile.blocked_users.count()
  File "/home/miph/.pyenv/versions/2.7.8/lib/python2.7/site-packages/django/db/models/manager.py", line 92, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)

Похоже, цель достигнута - можно достаточно легко различать SQL и связанный с ним код.

3. switch it over

Шаг третий - переключатель и предохранитель.

Наверняка, нам не всегда нужен такой режим приложения с выводом подробной информации о запросах, поэтому было бы здрово иметь легкий тумблер для включения этого режима. Такой тумблер уже есть - django.db: DEBUG в настройках логирования.

Можно пойти дальше и вынести это в переменную окружения (мне такой подход оказался удобен в работе):

# project/settings.py
LOGGING = {
    # ...
    'loggers': {
        # ...
        'django.db': {
            'handlers': ['console', 'sql_source_trace'],
            'level': os.getenv('DJANGO_DB_LOGGER_LEVEL', 'INFO'),
            'propagate': False,
        }
        # ...
    }
    # ...
}

Предохранителем для вашего продакшена может служить фильтр django.utils.log.RequireDebugTrue. # но это уже другая история

Пора закругляться

В целом, достаточно несложно настроить удобный вывод логов запросов для локальной отладки. Из минусов - очень большой оверхед на парсинг и форматирование SQL и как результат - заметное замедление работы приложения.

Sources

Настройки:

# project/settings.py
import os


LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'simple': {
            'format': '[%(levelname)s:%(name)s:%(lineno)d] %(message)s'
        },
        'simple_sql_source_trace': {
            'format': '[%(levelname)s:%(name)s:%(lineno)d] '
                      'Stacktrace of SQL query producer:'
                      '\n  %(sql_source_trace)s\n'
        },
    },
    'filters': {
        'sql_preprocessor': {
            '()': 'project.apps.core.debug.SqlFilter',
        },
        'sql_context_filter': {
            '()': 'project.apps.core.debug.SqlContextFilter',
        },
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'handlers': {
        # ...
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple',
            'filters': ['require_debug_true', 'sql_preprocessor']
        },
        'sql_source_trace': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple_sql_source_trace',
            'filters': ['require_debug_true', 'sql_context_filter']
        },
    },
    'loggers': {
        # ...
        'django.db': {
            'handlers': ['console', 'sql_source_trace'],
            'level': os.getenv('DJANGO_DB_LOGGER_LEVEL', 'INFO'),
            'propagate': False,
        }
        # ...
    }
}

Отладочный код:

# project/apps/core/debug.py
import logging
from itertools import takewhile
import traceback

try:
    from sqlparse import format as format_sql
except ImportError:
    format_sql = lambda sql, **options: sql


class SqlFilter(logging.Filter):
    INDENT = '\n  '
    MSG = ('Sql query took {record.duration:.3f}s with params={record.params}:'
           '{indent}{record.sql}\n')

    def filter(self, record):
        if hasattr(record, 'sql') and record.sql:
            record.sql = format_sql(record.sql, reindent=True, indent_width=2)
            record.sql = record.sql.strip().replace('\n', self.INDENT)
            record.msg = self.MSG.format(record=record, indent=self.INDENT)

        return True


class SqlContextFilter(logging.Filter):
    STACK_CUTTERS = (
        'django/db/backends/utils.py',
        'django/db/models/query.py',
        'django/db/backends/postgresql_psycopg2/introspection.py',
    )

    STACK_LIMIT = 3

    def filter(self, record):
        if hasattr(record, 'sql') and record.sql:
            source_trace = list(takewhile(lambda frame: not any(map(frame[0].endswith, self.STACK_CUTTERS)),
                                          traceback.extract_stack()))
            record.sql_source_trace = ''.join(traceback.format_list(source_trace[-self.STACK_LIMIT:])).strip()

            return True