Логирование запросов к приложению 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
{% load static %}
Title
Созданные 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.
