Как сократить время ответа в 2 раза, добавив одну строку кода

Вечером после напряжённого рабочего дня часто хочется расслабиться и посмотреть новый фильм или сериал. Но как выбрать что-то стоящее среди огромного количества контента? Поможет рекомендательная система. Наша команда разработчиков стремится не только предоставлять качественные рекомендации, но и делать это быстро. Если пользователь долго ждёт результата, он может потерять интерес и уйти. По сути, мы отвечаем за наполнение главной страницы Okko, поэтому наши решения должны быть надежны и устойчивы. API сервиса реализован на Flask, а горизонтальное масштабирование позволяет обрабатывать большой объём запросов.

Какая была проблема

Необходимо быстро предоставлять пользователям наполнение главной страницы. Конечно, на сервис есть таймаут, равный 400 мс. Для контроля работы сервиса мы используем мониторинг в Grafana, где построены графики задержки (latency) по 50, 90 и 99 перцентилям. На скриншоте видно, что у нашего сервиса есть проблема. Во-первых, мы находимся очень близко к значению таймаута: 99-й перцентиль составляет около 300 мс. При этом время ответа в 99-м перцентиле в 2 раза больше, чем в 90-м, и в 5 раз больше, чем в 50-м. Попробуем выяснить, на что тратится время, и пофиксить проблему.

Как искали причину

Первым помощником в исследовании стал Jaeger, который мы используем для визуализации трейсов сервиса от OpenTelemetry. Трейс — набор спанов, а спан — это запись о выполнении определенного действия одним сервисом.

Найдя трейс запроса с крайне большим временем ответа, обнаружили нетипичную картину — «дырку» между спанами. «Дыркой» мы называем отсутствие спана в трейсе на определённом периоде времени.

Отметим, что архитектура сервиса позволяет выдавать и строить рекомендации в пайплайне. В нашем понимании пайплайн — последовательность степов, каждый из которых производит определённое действие для изменения коллекции с фильмами (например, Фильмы для вас). В степе мы можем получить коллекцию, обогатить её, отфильтровать, отсортировать элементы в ней. 

Приблизительно так реализован запуск нашего пайплайна: работа каждого степа обёрнута в спан, то есть между степами нет кода с написанной нами логикой, а значит, «дырок» здесь мы точно не ждём.

def run_pipeline(
  title_ids: list[str], meta: BaseStepMeta
) -> RekkoCollection:
    ...

    for step in pipeline_steps:
      with tracer.start_as_current_span(step.name):
        collection = step.run()

Если схематично изобразить трейс с работой пайплайна, то в обычном случае друг за другом шли бы степы, временных простоев между ними не было бы:

Но наш трейс был с «дыркой»:

Что всё-таки происходит? У питониста всегда два главных виновника — GIL и сборка мусора. У нас синхронные эндпоинты на Flask, в приложении нет большого количества тредов. Неужели блокировка главного треда, где записывается спан, занимает столько времени из-за GIL и выполнения кода в другом треде? Мы посчитали это маловероятным, ведь в Python по умолчанию переключение между тредами занимает 5мс, а «дырка» у нас аж на 50 мс. Поэтому для начала решили проверить гипотезу о сборщике мусора.

В Python есть два инструмента, которые удаляют объекты, — алгоритм подсчёта ссылок и сборка мусора по поколениям.

Алгоритм подсчёта ссылок работает очень просто. Если ссылок на объект нет, то он тут же удаляется. К сожалению, это не работает для объектов с циклическими ссылками.

Функционал нахождения циклических ссылок реализован в сборщике мусора с использованием поколений. Сборка запускается, когда разница между количеством аллокаций и деаллокаций превышает пороговое значение для нулевого поколения (threshold0). Для запуска первого поколения (g1) и второго поколения (g2) также существуют счётчики: если количество запусков сборки мусора нулевого поколения (g0) равно пороговому значению первого поколения (threshold1), то запускается сборка мусора первого поколения (g1); если количество запусков сборки мусора g1 равно пороговому значению второго поколения (threshold2), то запускается g2. По умолчанию threshold0 = 700, threshold1 = 10, threshold2 = 10. Таким образом, частая активация сборки мусора может быть вызвана следующими причинами:

1. Создание большого количества новых объектов контейнерного типа (dict, list, set, ...) → влияние на количество аллокаций.

2. Большое количество циклических ссылок → влияние на количество деаллокаций. Так как объекты с циклическими ссылками удаляются только сборщиком мусора по поколениям, они не будут удалены до его запуска.

Подробнее можно ознакомиться с алгоритмом в официальной документации. Сейчас нам важно понять две вещи.

1. Чем выше поколение, тем дольше оно живёт. Значит, в нём больше объектов, и сборка мусора для него занимает больше времени.

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

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

Конечно, работать с таким результатом крайне неудобно. Поэтому мы решили написать собственный функционал для логирования. Реализовали его через колбэки, которые срабатывали до и после сборки мусора. Запуск колбэка до или после сборки регулировался значением фазы (start или stop).

import gc
from time import time
from typing import Any
 
from app.utils.logging import getLogger
 
logger = getLogger(__name__)
 
TIME_PLACEHOLDER = None
 
  
def set_gc_start_time_before_collection(
  phase: str, info: dict[str, Any]
) -> None:
    global TIME_PLACEHOLDER
    if phase != 'start':
        return
      
  TIME_PLACEHOLDER = time()

  
def log_gc_working_info_after_collection(
  phase: str, info: dict[str, Any]
) -> None:
    global TIME_PLACEHOLDER
    if phase != 'stop':
        return

    logger.debug(f'time_taken: time={round(time() - TIME_PLACEHOLDER, 5)}, generation={info["generation"]}')
    logger.debug(f'objects_count: {gc.get_count()}')
    logger.debug(f'{[len(gc.get_objects(generation=gen)) for gen in range(3)]}')
    TIME_PLACEHOLDER = None

    
gc.callbacks.extend(
    [
      set_gc_start_time_before_collection,
      log_gc_working_info_after_collection
    ]
)

Мы включили написанное логирование и начали нагружать сервис локально с помощью locust.  Нам удалось воспроизвести кейс с «дыркой» локально. Оставалось выяснить, происходила ли сборка мусора по поколениям в это время.

Тогда мы распарсили логи от gc в pandas dataframe и посмотрели логи за период времени, когда была «дырка». Если бы dataframe был пустым, значит, в это время сборщик мусора не запускался. Но он не был пустым. Более того, суммарное время работы сборки составило 49 мс, а это и есть точное время нашей «дырки».

Так мы доказали, что виновник - сборщик мусора.

Как анализировали работу сборщика мусора

Решили копнуть глубже и выяснить, как у нас работает сборка мусора по поколениям.

Для начала посмотрели, сколько раз суммарно запускалась сборка мусора и сколько времени это заняло в рамках одного запроса в худшем случае. Мы выполнили серию запросов, собрали для каждого статистику работы сборщика мусора и в конце выбрали самый неблагоприятный результат (максимальное время сборки мусора). Рассматривали именно худший случай, потому что ранее видели, что в 50-м перцентиле всё было в порядке. Проблемы проявлялись именно в 99-м перцентиле, поэтому и было важно проанализировать крайний случай.

Получили следующие результаты:

Конечно, тратить суммарно 67 мс на сборку мусора в одном запросе — это крайне много, особенно учитывая, что таймаут составляет 400 мс. Нужно с этим что-то делать.

Мы заметили, что у нас часто происходит сборка мусора нулевого поколения, и в рамках одного запроса это может происходить до 400 раз. Частая сборка мусора нулевого поколения сама по себе не является проблемой, поскольку она выполняется довольно быстро. Однако она приводит к более частой сборке мусора первого и второго поколений, что уже вызывает большее беспокойство. Мы подумали, что если у нас нет циклических ссылок или их не очень много, то сможем запускать сборку мусора по поколениям реже.

Чтобы определить, есть ли у нас циклические ссылки, мы с помощью библиотеки objgraph построили граф зависимостей.

Для его построения нужно сначала посмотреть, какие объекты копятся в gc.garbage. Мы реализовали это через middleware. Middleware — это функция, которая запускается до или после обработки запроса. Таким образом, после каждого запроса мы локально отслеживали, какие объекты должны были быть удалены сборщиком мусора по поколениям. В результате мы обнаружили, что в garbage накопилось много объектов нашего класса StepSnapshot.

import gc
import objgraph
  
  
def research_circular_references(response: Response) -> Response: 
    gc.set_debug(gc.DEBUG_SAVEALL)
    gc.collect()
    garbage = gc.garbage
  
    objgraph.show_most_common_types(objects=garbage)
      
    return response

После определения типа проблемных объектов можно начинать для них строить граф зависимостей. Сделать это можно также через middleware.

import objgraph
  
  
def research_circular_references(response: Response) -> Response: 
    gc.set_debug(gc.DEBUG_SAVEALL)
    gc.collect()
    garbage = gc.garbage
  
    researching_type = StepSnapshot  # тут указываем тип, который хотим исследовать
    objs_with_req_type = [obj for obj in garbage if isinstance(obj, researching_type)]
    objgraph.show_backrefs(objs_with_req_type[-1], too_many=5, max_depth=10, filename='backrefs_of_garbage_obj.png')
      
    return response

Так мы получили следующий граф зависимостей, красным цветом выделен цикл. Но процент объектов с циклическими ссылками от общего числа объектов, которые собирает сборщик мусора по поколениям, оказался не очень большим — всего лишь 1.4%. Больше мы у себя циклических ссылок не нашли.

Итак, мы выяснили, что циклических ссылок у нас немного, и значит, проблема частого запуска сборки мусора не в этом. Ранее мы также установили, что другой причиной частого запуска сборки является большое количество объектов. Это действительно наш случай, ведь мы передаём сразу много коллекций для главной страницы. Каждая коллекция — это объект, каждый элемент внутри неё — тоже объект, и у элементов есть набор фичей, которые также являются объектами.

Как решали проблему

Как же решить эту проблему? Самый очевидный вариант — переписать код и создавать меньше объектов. Однако мы не можем этого сделать, потому что большое количество абстракций позволяет нам быстро добавлять новые фичи, что очень важно для продуктовой разработки. Поэтому мы решили попробовать найти другое решение.

Из реализации сборщика мусора по поколениям следует, что чем больше пороговые значения, тем реже запускается сборка. В теории это выглядело идеальным решением для нас, так как наши объекты все равно после завершения запроса прекратят быть нужными и соберутся сборщиком по счетчику ссылок. По сути, в нашем случае сборщик по поколениям запускается впустую. Чтобы проверить эту теорию мы решили написать простой скрипт, примерно моделирующий нашу ситуацию.

Пусть у нас есть небольшой dataclass Film с информацией о фильме, и нам нужно получить много фильмов из базы данных. То есть в этом случае нет циклических ссылок, здесь лишь создаётся большое количество объектов. Давайте запустим этот код и посмотрим на его время работы.

import gc
from dataclasses import dataclass
from time import time

  
@dataclass
class Film:
    film_id: int
    weight: float
    actors: list[str]


def get_films_from_db() -> list[Film]:
    films_count = 1_000_000

    films_list = [
        Film(
            film_id=idx,
            weight=0.0,
            actors=['Tom Hanks', 'Brad Pitt', 'Leonardo DiCaprio']
        ) for idx in range(films_count)
    ]
    return films_list

# раскомментировать для уменьшения частоты запуска сборщика мусора по поколениям
# gc.set_threshold(10_000, 50, 20)

start = time()
films = get_films_from_db()
finish = time()
 
print(f'Time: {round(finish - start, 3)} secs')

> Time: 1.304 secs

Если раскомментируем строку с увеличением пороговых значений:

> Time: 0.674 secs

Так с помощью изменения лишь настроек сборщика мусора по поколениям, нам удалось уменьшить время выполнения в 2 раза.

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

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

Полученные результаты внушали оптимизм. И мы решили сравнить статистику на дефолтных значениях и новых.

Так нам удалось сократить общее время сборки мусора с 67 мс до 23 мс.

Как изменилось время ответа

Так как результаты выглядели многообещающе, мы решили выкатить изменения на прод. В 99-м перцентиле получили выигрыш в 2 раза на одной из наших самых главных ручек, из которой мы отдаём содержимое разных коллекций. Также мы видим, что и разница между 90-м и 99-м перцентилями значительно сократилась. Наконец-то нам удалось отдалиться от таймаута в  400мс.

Выводы

В конце хотелось бы сказать:

1. Всегда тщательно продумывайте архитектуру своего сервиса, избегайте излишнего создания большого количества новых объектов.

2. Если вы не можете позволить себе рефакторинг, не можете избавиться от большого количества объектов, попробуйте провести подобное исследование и изменить пороги gc. 

3. Если вы не создаёте большое количество новых объектов или у вас нет большого количества циклических ссылок, не стоит изменять дефолтную конфигурацию.