Привет, меня зовут Дмитрий Чернышов, я ведущий разработчик компании «БАРС Груп». Последние несколько лет среди прочих задач нам в команде приходится сталкиваться с необходимостью анализа производительности приложений на 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.
ссылка на оригинал статьи https://habr.com/ru/company/barsgroup/blog/523068/
Добавить комментарий