https://habr.com/ru/company/barsgroup/blog/523068/

• Блог компании БАРС Груп
• Python
• Django

Привет, меня зовут Дмитрий Чернышов, я ведущий разработчик компании «БАРС Груп». Последние несколько лет среди прочих задач нам в команде приходится сталкиваться с необходимостью анализа производительности приложений на Django с большим количеством пользователей и постоянно меняющимися профилями нагрузки. В данной статье я хочу поделиться наработками, которые появились у нас в процессе работы.

Предыстория/Описание проблемы

В Django достаточно средств для того, чтобы организовать логирование запросов к приложению с целью получения ответов на следующие вопросы:

• Какие запросы в среднем работают дольше всего с точки зрения пользователей?
• Каких запросов выполняется больше всего?
• Какие запросы создают больше всего запросов к СУБД?
• В каких запросах самые длинные транзакции?

Демо-приложение

Для начала установим Django 3 версии и создадим простое приложение (первых двух частей туториала будет достаточно). В качестве СУБД будем использовать PostgreSQL. Для тех, кто не хочет собирать приложение с нуля — исходный код, который используется в статье, находится в репозитории. Для каждого шага в статье будет проставлена соответствующая метка в репозитории, чтобы можно было перейти на соответствующее состояние и посмотреть diff с предыдущей/последующей меткой. Базовое приложение без лишних модификаций доступно по метке stage_00.

Логируем время на сервере

Рассмотрим простую задачу: мы хотим логировать продолжительность запросов к приложению. Что для этого мы можем использовать? В Django есть подходящий инструмент, который называется middleware. Как следует из описания — мы можем выполнить некие действия до того, как запрос попадет во view (и нижестоящие middleware), а также обработать результат выполнения запроса, когда он будет возвращаться клиенту. Каким образом нам это может помочь? Мы можем зафиксировать временную отметку, когда запрос придет к нам, а в момент возвращения ответа — вычислить разность между текущим временем и зафиксированной ранее временной отметкой. Давайте реализуем такой middleware:

polls/middleware.py

import time


class RequestTimeMiddleware:
   def __init__(self, get_response):
       self.get_response = get_response

   def __call__(self, request):
       timestamp = time.monotonic()

       response = self.get_response(request)

       print(
           f'Продолжительность запроса {request.path} - '
           f'{time.monotonic() - timestamp:.3f} сек.'
       )

       return response

После реализации необходимо подключить его к нашему приложению. Для этого необходимо указать реализованный middleware в settings.py:

mysite/settings.py

# ...

MIDDLEWARE = [
    'polls.middleware.RequestTimeMiddleware',
    'django.middleware.security.SecurityMiddleware',
    'django.contrib.sessions.middleware.SessionMiddleware',
    # ...   
]

Стоит обратить внимание, что наш middleware лучше поставить как можно выше в списке (в идеале, первым), чтобы в подсчет продолжительности запроса вошло не только время работы view, но и всех подключенных middleware.

После подключения необходимо запустить приложение и выполнить запрос к админ-панеле по адресу http://127.0.0.1:8000/admin/. После выполнения запроса в консоли отобразится вывод, подобный представленному ниже:

Performing system checks...

System check identified no issues (0 silenced).
June 23, 2020 - 21:21:56
Django version 3.0.7, using settings 'mysite.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.
[23/Jun/2020 21:22:01] "GET /admin/ HTTP/1.1" 200 3721
Продолжительность запроса /admin/ - 0.036 сек.
[23/Jun/2020 21:22:01] "GET /static/admin/css/base.css HTTP/1.1" 304 0
[23/Jun/2020 21:22:01] "GET /static/admin/css/dashboard.css HTTP/1.1" 304 0
[23/Jun/2020 21:22:01] "GET /static/admin/css/responsive.css HTTP/1.1" 304 0
[23/Jun/2020 21:22:03] "GET /admin/ HTTP/1.1" 200 3721
Продолжительность запроса /admin/ - 0.021 сек.

В репозитории результат выполнения этой части можно посмотреть по метке stage_01.

Отделяем приложение от СУБД

Кроме выполнения python-кода, приложение выполняет запросы к СУБД. Было бы удобно отделить время выполнения python-кода от времени выполнения запросов к СУБД. Что нам предлагает Django? Для работы с СУБД Django использует механизм engine. В нашем случае он должен уметь логировать время выполнения запросов. Воспользуемся наследованием базового engine. Для реализации логирования используем класс CursorWrapper и разместим наши наработки в файле base.py:

polls/base.py

import time
from contextlib import contextmanager

from django.db.backends.postgresql.base import DatabaseWrapper as DjangoDatabaseWrapper
from django.db.backends.utils import CursorWrapper as DjangoCursorWrapper


@contextmanager
def calc_sql_time(sql):
   timestamp = time.monotonic()

   yield
 
print(
       f'Продолжительность SQL-запроса {sql} - '
       f'{time.monotonic() - timestamp:.3f} сек.'
   )


class CursorWrapper(DjangoCursorWrapper):
   def execute(self, sql, params=None):
       with calc_sql_time(sql):
           return super().execute(sql, params)


class DatabaseWrapper(DjangoDatabaseWrapper):
   def create_cursor(self, name=None):
       cursor = super().create_cursor(name)
       return CursorWrapper(cursor, self)

После того, как мы создали наш engine, необходимо указать его в settings.py:

mysite/settings.py

# ...

DATABASES = {
   'default': {
       'ENGINE': 'polls',
       'NAME': 'mysite',
       'USER': 'postgres',
       'PASSWORD': 'postgres',
   }
}

Теперь запустим приложение и посмотрим, что у нас получилось:

[29/Jun/2020 11:41:05] "GET /admin/ HTTP/1.1" 200 3721
Продолжительность SQL-запроса SELECT "django_session"."session_key", "django_session"."session_data", "django_session"."expire_date" FROM "django_session" WHERE ("django_session"."expire_date" > %s AND "django_session"."session_key" = %s) LIMIT 21 - 0.001 сек.
Продолжительность SQL-запроса SELECT "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "auth_user" WHERE "auth_user"."id" = %s LIMIT 21 - 0.001 сек.
Продолжительность SQL-запроса SELECT COUNT(*) AS "__count" FROM "polls_question" - 0.001 сек.
Продолжительность SQL-запроса SELECT COUNT(*) AS "__count" FROM "polls_question" - 0.000 сек.
Продолжительность SQL-запроса SELECT "polls_question"."id", "polls_question"."question_text", "polls_question"."pub_date" FROM "polls_question" ORDER BY "polls_question"."id" DESC - 0.000 сек.
[29/Jun/2020 11:41:09] "GET /admin/polls/question/ HTTP/1.1" 200 3179
Продолжительность запроса /admin/polls/question/ - 0.034 сек.
Продолжительность SQL-запроса SELECT "django_session"."session_key", "django_session"."session_data", "django_session"."expire_date" FROM "django_session" WHERE ("django_session"."expire_date" > %s AND "django_session"."session_key" = %s) LIMIT 21 - 0.002 сек.
Продолжительность SQL-запроса SELECT "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "auth_user" WHERE "auth_user"."id" = %s LIMIT 21 - 0.001 сек.
Продолжительность запроса /admin/jsi18n/ - 0.012 сек.
[29/Jun/2020 11:41:10] "GET /admin/jsi18n/ HTTP/1.1" 200 3223

В репозитории результат выполнения этой части можно посмотреть по метке stage_02.

Связываем запросы в БД и web-запросы

В некоторых случаях при анализе запросов к БД бывает полезно знать, какой запрос к приложению сгенерировал конкретный SQL-запрос. Это особенно полезно, когда какой-либо базовый механизм используется во многих компонентах системы. Для решения этой задачи можно воспользоваться реализованными ранее middleware и курсором.

Для начала, модифицируем middleware, чтобы зафиксировать текущий path запроса:

polls/middleware.py

import time
from threading import local


thread_locals = local()


class RequestTimeMiddleware:
   def __init__(self, get_response):
       self.get_response = get_response
  def __call__(self, request):
       thread_locals.path = request.path
       timestamp = time.monotonic()

       response = self.get_response(request)

       print(
           f'Продолжительность запроса {request.path} - '
           f'{time.monotonic() - timestamp:.3f} сек.'
       )
       thread_locals.path = ''

       return response

Теперь сохраненный путь можно добавить как комментарий к запросу, который выполняется в курсоре:

polls/base.py

from django.utils.encoding import force_text

from polls.middleware import thread_locals

# ...


def make_safe(s):
   return s.replace('*', '').replace('\\', '').replace('%', '')


class CursorWrapper(DjangoCursorWrapper):
   def execute(self, sql, params=None):
       path = getattr(thread_locals, 'path', '')
       if path:
           path = make_safe(path)
           sql = f'/* {path} */\n{force_text(sql)}\n/* {path} */'

       with calc_sql_time(sql):
           return super().execute(sql, params)

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

Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT "django_session"."session_key", "django_session"."session_data", "django_session"."expire_date" FROM "django_session" WHERE ("django_session"."expire_date" > %s AND "django_session"."session_key" = %s) LIMIT 21
/* /admin/auth/user/ */ - 0.001 сек.
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "auth_user" WHERE "auth_user"."id" = %s LIMIT 21
/* /admin/auth/user/ */ - 0.001 сек.
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT "auth_group"."id", "auth_group"."name" FROM "auth_group" ORDER BY "auth_group"."name" ASC
/* /admin/auth/user/ */ - 0.001 сек.
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT COUNT(*) AS "__count" FROM "auth_user"
/* /admin/auth/user/ */ - 0.000 сек.
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT COUNT(*) AS "__count" FROM "auth_user"
/* /admin/auth/user/ */ - 0.000 сек.
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "auth_user" ORDER BY "auth_user"."username" ASC
/* /admin/auth/user/ */ - 0.000 сек.
Продолжительность запроса /admin/auth/user/ - 0.071 сек.
[29/Jun/2020 12:19:15] "GET /admin/auth/user/ HTTP/1.1" 200 6608
Продолжительность SQL-запроса /* /admin/jsi18n/ */
SELECT "django_session"."session_key", "django_session"."session_data", "django_session"."expire_date" FROM "django_session" WHERE ("django_session"."expire_date" > %s AND "django_session"."session_key" = %s) LIMIT 21
/* /admin/jsi18n/ */ - 0.001 сек.
Продолжительность SQL-запроса /* /admin/jsi18n/ */
SELECT "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "auth_user" WHERE "auth_user"."id" = %s LIMIT 21
/* /admin/jsi18n/ */ - 0.001 сек.
Продолжительность запроса /admin/jsi18n/ - 0.009 сек.
[29/Jun/2020 12:19:15] "GET /admin/jsi18n/ HTTP/1.1" 200 3223
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT "django_session"."session_key", "django_session"."session_data", "django_session"."expire_date" FROM "django_session" WHERE ("django_session"."expire_date" > %s AND "django_session"."session_key" = %s) LIMIT 21
/* /admin/auth/user/ */ - 0.001 сек.
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "auth_user" WHERE "auth_user"."id" = %s LIMIT 21
/* /admin/auth/user/ */ - 0.001 сек.
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT "auth_group"."id", "auth_group"."name" FROM "auth_group" ORDER BY "auth_group"."name" ASC
/* /admin/auth/user/ */ - 0.000 сек.
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT COUNT(*) AS "__count" FROM "auth_user"
/* /admin/auth/user/ */ - 0.000 сек.
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT COUNT(*) AS "__count" FROM "auth_user"
/* /admin/auth/user/ */ - 0.000 сек.
Продолжительность SQL-запроса /* /admin/auth/user/ */
SELECT "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "auth_user" ORDER BY "auth_user"."username" ASC
/* /admin/auth/user/ */ - 0.000 сек.
[29/Jun/2020 12:19:18] "GET /admin/auth/user/ HTTP/1.1" 200 6608
Продолжительность запроса /admin/auth/user/ - 0.045 сек.
Продолжительность SQL-запроса /* /admin/jsi18n/ */
SELECT "django_session"."session_key", "django_session"."session_data", "django_session"."expire_date" FROM "django_session" WHERE ("django_session"."expire_date" > %s AND "django_session"."session_key" = %s) LIMIT 21
/* /admin/jsi18n/ */ - 0.002 сек.
Продолжительность SQL-запроса /* /admin/jsi18n/ */
SELECT "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "auth_user" WHERE "auth_user"."id" = %s LIMIT 21
/* /admin/jsi18n/ */ - 0.001 сек.
Продолжительность запроса /admin/jsi18n/ - 0.013 сек.
[29/Jun/2020 12:19:19] "GET /admin/jsi18n/ HTTP/1.1" 200 3223

Где можно посмотреть добавленный контекст далее? Например, при просмотреть отчета pgBadger. Следует отметить, что таким образом можно пробросить не только url, но и другие атрибуты, например пользователя, который выполняется запрос.

В репозитории результат выполнения этой части можно посмотреть по метке stage_03.

Логируем дополнительные параметры

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

Чтобы решить данную задачу — модифицируем созданные ранее компоненты. Для начала, добавим новые параметры в middleware:

polls/middleware.py

# ...

class RequestTimeMiddleware:
   # ...

   def __call__(self, request):
       thread_locals.path = request.path
       thread_locals.sql_count = 0
       thread_locals.sql_total = 0
       timestamp = time.monotonic()

       response = self.get_response(request)

       print(
           f'Продолжительность запроса {request.path} - '
           f'{time.monotonic() - timestamp:.3f} сек. '
           f'Количество SQL-запросов - {thread_locals.sql_count}. '
           f'Продолжительность SQL-запросов - {thread_locals.sql_total:.3f}.'
       )

       thread_locals.sql_total = 0
       thread_locals.sql_count = 0
       thread_locals.path = ''

       return response

После этого реализуем заполнение данных атрибутов на уровне курсора:

polls/base.py

# ...

@contextmanager
def calc_sql_time(sql):
   timestamp = time.monotonic()

   yield

   if hasattr(thread_locals, 'sql_count'):
       thread_locals.sql_count += 1
       thread_locals.sql_total += time.monotonic() - timestamp

В результате выполненных изменений лог запросов к приложению будет выглядеть следующим образом:

Продолжительность запроса /admin/ - 0.041 сек. Количество SQL-запросов - 3. Продолжительность SQL-запросов - 0.004.
[29/Jun/2020 13:44:49] "GET /admin/ HTTP/1.1" 200 3721
Продолжительность запроса /admin/polls/question/ - 0.031 сек. Количество SQL-запросов - 5. Продолжительность SQL-запросов - 0.004.
[29/Jun/2020 13:44:56] "GET /admin/polls/question/ HTTP/1.1" 200 3179
[29/Jun/2020 13:44:56] "GET /static/admin/js/vendor/jquery/jquery.js HTTP/1.1" 200 287630
[29/Jun/2020 13:44:56] "GET /admin/jsi18n/ HTTP/1.1" 200 3223
Продолжительность запроса /admin/jsi18n/ - 0.011 сек. Количество SQL-запросов - 2. Продолжительность SQL-запросов - 0.002.

В реальных кейсах отслеживаемых атрибутов может быть гораздо больше. Например:

• количество SQL-запросов в разрезе типов (SELECT, INSERT, UPDATE, DELETE)
• время выполнения SQL-запросов в разрезе типов
• количество повторяющихся SQL-запросов
• подсчет количества и времени транзакций
• алиасы базы, в которую выполняются SQL-запросы (для случая использования нескольких БД)

В репозитории результат выполнения этой части можно посмотреть по метке stage_04.

Сохраняем данные для последующего анализа

Статистика нужна, чтобы потом ее проанализировать. Соответственно, текущий подход с выводом данных в консоль не подходит. Реализуем подход с сохранением в файл. Для этого модифицируем middleware:

polls/base.py

import json

# ...

class RequestTimeMiddleware:
   # ...

   def __call__(self, request):
       # ...

       response = self.get_response(request)

       data = {
           'path': request.path,
           'request_total': round(time.monotonic() - timestamp, 3),
           'sql_count': round(thread_locals.sql_count, 3),
           'sql_total': round(thread_locals.sql_total, 3),
       }

       with open('request.log', 'a') as f:
           f.write(json.dumps(data) + '\n')

       thread_locals.sql_total = 0
       thread_locals.sql_count = 0
       thread_locals.path = ''

       return response

В результате в файле request.log будут строки следующего вида:

{"path": "/admin/", "request_total": 0.025, "sql_count": 3, "sql_total": 0.004}
{"path": "/admin/polls/question/", "request_total": 0.029, "sql_count": 5, "sql_total": 0.002}
{"path": "/admin/jsi18n/", "request_total": 0.01, "sql_count": 2, "sql_total": 0.003}
{"path": "/admin/", "request_total": 0.027, "sql_count": 3, "sql_total": 0.003}
{"path": "/admin/auth/user/", "request_total": 0.047, "sql_count": 6, "sql_total": 0.004}
{"path": "/admin/jsi18n/", "request_total": 0.011, "sql_count": 2, "sql_total": 0.003}

В репозитории результат выполнения этой части можно посмотреть по метке stage_05.

Логируем время на клиенте (js)

В некоторых случаях полезно будет знать еще и время выполнения с точки зрения клиента. Для этого нам необходимо зафиксировать момент отправки запроса, а также вычислить продолжительность при поступлении ответа. Рассмотрим вариант, когда приложение представляет из себя SPA. Для начала, реализуем обработчик XHR-запросов:

polls/static/xhr_interceptor.js

'use strict';

/**
* Позволяет выполнить обработку XHR-запросов и ответов на стороне клиента
*/
var XhrInterceptor = {
  /**
   * Публичные атрибуты и методы
   */

  addRequestCallback: function (callback) {
      // Добавляет обработчик к запросу
      this.requestCallbacks.push(callback);
  },

  removeRequestCallback: function (callback) {
      // Удаляет обработчик запроса
      this.arrayRemove(this.requestCallbacks, callback);
  },

  addResponseCallback: function (callback) {
      // Добавляет обработчик к ответу
      this.responseCallbacks.push(callback);
  },

  removeResponseCallback: function (callback) {
      // Удаляет обработчик ответа
      this.arrayRemove(this.responseCallbacks, callback);
  },

  /**
   * Подключает XhrInterceptor к обработке xhr
   */
  wire: function () {
      if (this.wired) throw new Error("Ajax interceptor already wired");

      // Перегрузка метода отправки всех xhr
      XMLHttpRequest.prototype.send = function () {

          // Запустим обработчики запроса до его отправки
          XhrInterceptor.fireCallbacks(XhrInterceptor.requestCallbacks, this);

          // Подключаем обработчики ответов
          if (this.addEventListener) {
              var xhr = this;
              this.addEventListener("readystatechange", function () {
                  XhrInterceptor.fireResponseCallbacksIfCompleted(xhr);
              }, false);
          }
          else {
              XhrInterceptor.proxifyOnReadyStateChange(this);
          }

          XhrInterceptor.RealXHRSend.apply(this, arguments);
      };
      this.wired = true;
  },

  /**
   * Отключает XhrInterceptor от обработки xhr
   */
  unwire: function () {
      if (!this.wired) throw new Error("Ajax interceptor not currently wired");
      XMLHttpRequest.prototype.send = this.RealXHRSend;
      this.wired = false;
  },

  isWired: function () {
      // Возвращает признак того, подключен ли XhrInterceptor
      return this.wired;
  },

  /**
   * Внутренние атрибуты и методы
   */
  // Неизмененный метод отправки xhr-запроса
  RealXHRSend: XMLHttpRequest.prototype.send,
  // Обработчики запроса
  requestCallbacks: [],
  // Обработчики ответа
  responseCallbacks: [],
  // Признак подключения к обработке
  wired: false,

  /**
   * Удаляет элемент из массива
   */
  arrayRemove: function (array, item) {
      var index = array.indexOf(item);
      if (index > -1) {
          array.splice(index, 1);
      } else {
          throw new Error("Could not remove " + item + " from array");
      }
  },
  /**
   * Вызывает обработчики
   */
  fireCallbacks: function (callbacks, xhr) {
      for (var i = 0; i < callbacks.length; i++) {
          callbacks[i](xhr);
      }
  },
  /**
   * Вызывает обработчики ответа, если запрос завершен
   */
  fireResponseCallbacksIfCompleted: function (xhr) {
      if (xhr.readyState === XMLHttpRequest.DONE) {
          this.fireCallbacks(this.responseCallbacks, xhr);
      }
  },
  /**
   * Дополнительное проксирование успешного завершения запроса для случая,
   * когда добавить listener нельзя
   */
  proxifyOnReadyStateChange: function (xhr) {
      var realOnReadyStateChange = xhr.onreadystatechange;
      if (realOnReadyStateChange) {
          xhr.onreadystatechange = function () {
              this.fireResponseCallbacksIfCompleted(xhr);
              realOnReadyStateChange();
          };
      }
  }
};

Далее воспользуемся реализованным обработчиком, чтобы добавить необходимые данные к запросу:

polls/static/request_client.js

function generate_request_guid() {
  function s4() {
      return Math.floor((1 + Math.random()) * 0x10000)
          .toString(16)
          .substring(1);
  }

  return s4() + s4() + s4();
}

var clientUUID = generate_request_guid();

XhrInterceptor.addRequestCallback(function(xhr) {
  try {
      xhr.setRequestHeader('UUID', clientUUID + '#' + generate_request_guid());
      xhr.setRequestHeader('C-STARTED', Date.now());
  } catch (e) {
      console.log("Can't set request headers. Details:", e.error.toString());
  }
});

После этого обработаем ответ, когда он вернется:

polls/static/request_client.js

var logStore = [];
var urlForExclude = '';

XhrInterceptor.addResponseCallback(function(xhr) {
  try {
      var req_uuid = xhr.getResponseHeader('UUID');
      var req_started = xhr.getResponseHeader('C-STARTED');

      if (req_uuid && req_started && !xhr.responseURL.includes(urlForExclude)) {
          req_started = parseInt(req_started, 10);

          var s_total = parseFloat(xhr.getResponseHeader('REQUEST-TOTAL') || 0);

          var record = {
              'uuid': req_uuid,
              'c_total': Math.max(Date.now() - req_started, s_total, 0),
              'started': xhr.getResponseHeader('STARTED') || '',
              'path': xhr.getResponseHeader('PATH') || '',
              'total': s_total,
              'sql_count': parseInt(xhr.getResponseHeader('SQL-COUNT') || 0),
              'sql_total': parseFloat(xhr.getResponseHeader('SQL-TOTAL') || 0),
          };

          record['tr_total'] = (record['c_total'] - record['total']).toFixed(4);
          logStore.push(record);
      }

  } catch (e) {
      console.log("Can't process response. Details:", e.error.toString());
  }
});

Затем подключим обработчики к запросам и настроим отправку собранных данных на клиент:

polls/static/request_client.js

// Подключаемся к запросам
XhrInterceptor.wire();

function startLogging(clientLogUrl, timeout = 10000) {
  function sendRequestStats() {
      if (logStore.length) {
          var log_part = JSON.stringify(logStore.slice());
          logStore = [];

          var xhttp = new XMLHttpRequest();
          xhttp.open("POST", clientLogUrl, true);
          xhttp.setRequestHeader('Content-Type', 'application/x-www-form-urlencoded');
          xhttp.send("logs=" + log_part);
      }
  }

  urlForExclude = clientLogUrl;
  setInterval(sendRequestStats, timeout);
}

Поскольку мы добавили новые атрибуты — необходимо отразить их в middleware:

polls/middleware.py

....

def __call__(self, request):
   thread_locals.path = request.path
   thread_locals.sql_count = 0
   thread_locals.sql_total = 0
   timestamp = time.monotonic()

   response = self.get_response(request)

   data = {
       'uuid': request.META.get('HTTP_UUID'),
       'c_started': request.META.get('HTTP_C_STARTED'),
       'path': request.path,
       'request_total': round(time.monotonic() - timestamp, 3),
       'sql_count': thread_locals.sql_count,
       'sql_total': round(thread_locals.sql_total, 3),
   }

   for key, value in data.items():
       response[key.capitalize().replace("_", "-")] = value

   thread_locals.sql_total = 0
   thread_locals.sql_count = 0
   thread_locals.path = ''

   return response

Для сохранения данных на стороне сервера нам понадобится view:

polls/views.py

import json

from django.http import HttpResponse
from django.template import loader
from django.views.decorators.csrf import csrf_exempt


@csrf_exempt
def save_client_log(request):
  """
  Сохраняет собранные данные с клиента в лог
  """
  logs = request.POST.get('logs', '[]')
  with open('request.log', 'a') as f:
     for log_str in json.loads(logs):
         f.write(json.dumps(log_str) + '\n')

  return HttpResponse()

Для проверки решения создадим две view: одна будет возвращать страницу с кнопкой для асинхронного запроса, вторая — обрабатывать асинхронный запрос и возвращать время:

polls/views.py

import datetime

....

def get_page_with_button(request):
   """
   Возвращает страницу с кнопкой
   """
   template = loader.get_template('polls/index.html')

   return HttpResponse(template.render({}, request))


def get_current_datetime(request):
   """
   Возвращает текущую дату и время
   """
   return HttpResponse(datetime.datetime.now())

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

polls/templates/polls/index.html

<!DOCTYPE html>
<html lang="en">
<head>
    <meta charset="UTF-8">
    {% load static %}
    <script src="{% static 'xhr_interceptor.js' %}"></script>
    <script src="{% static 'request_client.js' %}"></script>
    <script>
        function getDateTime() {
            var xhttp = new XMLHttpRequest();
            xhttp.onreadystatechange = function() {
                if (this.readyState == 4 && this.status == 200) {
                    document.getElementById("datetime").innerHTML = this.responseText;
                }
            };
            xhttp.open("GET", "{% url 'current_datetime' %}", true);
            xhttp.send();
        }
    </script>
    <script>
        startLogging("{% url 'save_client_log' %}");
    </script>

    <title>Title</title>
</head>
<body>

<button type="button" onclick="getDateTime()">Запросить дату и время</button>

<div id="datetime">

</div>

</body>
</html>

Созданные view нужно зарегистрировать в urls.py:

polls/urls.py

from django.urls import path

from . import views


urlpatterns = [
   path('', views.get_page_with_button, name='page_with_button'),
   path('current-datetime', views.get_current_datetime, name='current_datetime'),
   path('save-client-log', views.save_client_log, name='save_client_log'),
]

После запуска приложения перейдем на http://127.0.0.1:8000/polls/, сделаем несколько запросов и убедимся, что в файле request.log появились необходимые строки. В репозитории результат выполнения этой части можно посмотреть по метке stage_06.

Делаем представление данных (визуализация)

Собранные данные в сыром виде разбирать и анализировать не очень удобно. Тем более, что, зачастую, отдельно взятый запрос не интересен. Гораздо важнее увидеть агрегированную статистику для понимания текущего состояния приложения или его состояния в определенный момент времени. Для того, чтобы получить подобное представление данных — воспользуемся стеком ELK. Для установки можно обратиться к данному документу или выбрать одну из множества инструкции в сети.

После установки используем logstash для загрузки данных в elasticsearch, настроив конфиг по следующему шаблону:

input {
  file {
    path => "/путь/до/логов/**/*.log"
    start_position => "beginning"
  }
}
filter {
  json {
      source => "message"
  }
  date {
      match => [ "[started]", "yyyy-MM-dd HH:mm:ss'.'SSSSSS"]
  }
}
output {
  elasticsearch {
    hosts => "http://адрес-elasticsearch"
    manage_template => false
    index => "requests-%{+YYYY.MM.dd}"
    document_type => "%{[@metadata][type]}"
  }
}

Если для сбора используется filebeat, то input следует заменить на следующий:

input {
  beats {
    port => "5044"
    ssl  => false
  }
}

После загрузки данных вариантов работы с ними — великое множество. Можно настроить сборку визуализаций, собрать их в dashboard’ы; можно сделать выборки по конкретным атрибутам и их значениям. Выбранные подходы зависит от конкретных кейсов, которые предстоит решить. Вот несколько примеров того, что можно собрать на основе собранных данных:

Заключение

В рамках статьи мы рассмотрели варианты логирования параметров запросов. За кадром остались различные варианты параметров и аналитик по ним. Их можно будет найти в пакете production-request, который используется на нескольких production-приложениях. По мере разбора различных кейсов пакет дорабатывается улучшается. В планах — перенос пакета на github.