Почему запрос в Weaviate тормозит: профилирование по этапам

Фраза «запрос медленный» почти ничего не говорит инженеру. Это жалоба на симптом. Медленный по сравнению с чем и на каком шаге? Фильтр по метаданным, векторный индекс, чтение с диска объектов результата или оценка по ключевым словам? Пока время не привязано к одному из этих этапов, любое изменение — выстрел наугад: добавить памяти, подкрутить ef, уменьшить limit. Иногда что-то помогает, обычно ничего, а настоящая причина так и остаётся неизвестной.

Теперь в Weaviate появилась функция, нацеленная ровно на это слепое пятно. Query Profiling показывает по этапам, на что конкретный медленный запрос потратил время.

Почему журнала медленных запросов мало

Логирование медленных запросов в Weaviate есть давно. Задаёте две переменные окружения, перезапускаете узел, и любой запрос, превысивший порог по времени, попадает в логи с подробностями о таймингах. Для одной задачи это подходит хорошо: тихо замечать регрессии по всему парку серверов на протяжении недель и месяцев.

Но для более частой ситуации, когда конкретный запрос тормозит прямо сейчас и причина нужна немедленно, инструмент плохой. Выделяются четыре недостатка:

• Нужен перезапуск, а перезапуск узла очищает страничный кэш операционной системы. Первые запросы после него читают холодные данные с диска, так что замер отражает перезапуск, а не сам запрос.
• Он работает задним числом. Запись появляется, только когда запрос уже оказался медленным, поэтому нельзя нацелиться на тот запрос, который сейчас перед вами. Остаётся только ждать, пока он снова затормозит.
• Логирование идёт по узлам. Один запрос расходится по шардам на нескольких машинах, и каждая записывает только свою часть, так что полную картину приходится собирать вручную.
• Это временный переключатель, про который надо помнить и который надо вернуть обратно. Поскольку он живёт вне конфигурации развёртывания, он легко рассинхронизируется.

Профилирование на уровне запроса

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

В Python для этого нужен один импорт класса метаданных.

from weaviate.classes.query import MetadataQuery

И флаг в самом запросе.

response = collection.query.near_vector(
    near_vector=[0.1, 0.2, 0.3],
    limit=10,
    return_metadata=MetadataQuery(query_profile=True),
)for shard in response.query_profile.shards:
    print(shard.name, shard.node, shard.searches)

Координирующий узел собирает профили со всех шардов на всех участвовавших узлах и возвращает их вместе, так что один запрос даёт картину по всему кластеру.

Поддерживаются официальные клиенты для Python, JavaScript и TypeScript, Java (v6) и C#, а также чистый gRPC. Функция стала общедоступной в Weaviate v1.38. С выключенным флагом накладные расходы — одна проверка булева значения; с включённым движок добавляет чтения таймеров стоимостью в микросекунды. Это инструмент для отладки, так что держите его подальше от горячего пути в продакшене.

Как читать профиль

Результаты сгруппированы по шардам, а этапы, которые не выполнялись, опускаются. Поэтому обычный векторный поиск даёт другой профиль, чем поиск BM25, а в гибридных запросах есть разделы для обоих. Вот поля, которые стоит знать:

• total_took — реальное время поиска на этом шарде, а все остальные цифры объясняют его части.
• objects_took измеряет чтение итоговых объектов с диска, этот шаг называют гидратацией. Высокое значение говорит, что запрос упирается в диск: посмотрите на страничный кэш, limit и размер полезной нагрузки.
• filters_build_allow_list_took вместе с filters_ids_matched показывают, сколько времени ушло на превращение условия where в список подходящих ID, и размер этого списка. Огромный список значит, что фильтр слишком широкий; короткий список, на который всё равно ушло много времени, намекает на медленное чтение инвертированного индекса с диска.
• vector_search_took и knn_search_layer_0_took описывают обход HNSW. Граф живёт в оперативной памяти, поэтому большое значение здесь означает нагрузку на CPU, а не на диск. Настройте ef, размерность векторов и стратегию фильтрации, прежде чем заказывать новое железо.
• knn_search_rescore_took появляется, только когда включено сжатие. Этот этап читает векторы полной точности, чтобы пересчитать оценки сжатых кандидатов, и это чтение может дойти до диска.
• kwd_3_term_time и kwd_4_bmw_time — два таймера поиска по ключевым словам, которые стоит запомнить. Первый покрывает чтение списков вхождений для каждого термина и зависит от числа терминов и скорости диска. Второй — оценка BlockMax WAND, которая растёт на длинных списках вхождений и при слабой избирательности.

Три профиля, три разных решения

Первый случай: шард, где общее время чуть меньше 50 мс.

total_took: 48.2ms
vector_search_took: 8.4ms
filters_build_allow_list_took: 2.1ms
objects_took: 36.8ms

Фильтрация и поиск здесь дешёвые. Около трёх четвертей времени уходит на загрузку объектов с диска. Стоит посмотреть на страничный кэш и хранилище на этом узле, а меньший limit или более лёгкая полезная нагрузка могут помочь.

Второй случай: запрос с тяжёлым фильтром.

total_took: 61.5ms
filters_build_allow_list_took: 41.2ms
filters_ids_matched: 12,840,000
objects_took: 3.9ms

Двенадцать миллионов совпавших ID. Это проблема не диска и не железа. Фильтр просто слишком широкий. Сузьте его или применяйте широкое условие иначе, а не как предварительный фильтр по всему набору.

Третий случай: сжатый векторный индекс.

vector_search_took: 35.1ms
knn_search_layer_0_took: 9.2ms
knn_search_rescore_took: 25.4ms

Обход графа занимает всего 9 мс. Почти всё время векторного поиска уходит на пересчёт оценок, который подтягивает векторы полной точности с диска. Решение кроется в настройках хранилища и сжатия, а не в графе.

У трёх решений нет ничего общего. Без разбивки все три пришли бы в виде одной и той же жалобы: запрос медленный.

Как закрыть пробел в наблюдаемости

У настройки производительности векторных баз давно есть проблема с наблюдаемостью. Движок всегда знал, куда уходит время; сложно было достать это знание. Профилирование запросов закрывает этот пробел минимальным изменением: один флаг, один запрос, один ответ. Говорят, команда solution engineering в Weaviate первым делом берётся именно за него, когда клиент жалуется на медленную работу: оно превращает расплывчатую жалобу в конкретный этап с конкретным решением.

Командам, которые используют Weaviate в продакшене, стоит добавить query_profile=True в свой набор инструментов для отладки. В следующий раз, когда кто-то скажет, что запрос медленный, ответом будет измеренное число, а не догадка. Подробности есть в полном анонсе под названием Query Profiling: See Where a Slow Query Spends Its Time и на странице о профилировании запросов в официальной документации.