Необычно короткий пост-заметка о наболевшем.

— «я не DBA, я ваши базы не знаю» — хочется мне порой сказать. Как и многим из вас наверное. Однако все таки это не правильное мнение и сейчас я расскажу вам свежую историю о том, как знание баз данных (даже на оч простом уровне) помогает в работе.

Какое-то время назад я писал заметки по mongodb. И вот они мне пригодились — а конкретно про explain запроса)

Короче, история такая — принимаем мы значит у разработки релиз на выкатку в prod. Все вроде хорошо, но вот не задача — на stage падает один автотест (по логам нам прилетает 500-ая ошибка)… как раз на свежую фичу бекенда, которая должна была в этом релизе выкатиться (собственно ради нее все и затевалось).

Ребята, которые у нас занимаются доставкой потыкались — нашли только в логах, что во время этого теста, в ответ на полученный по api запрос, сервер в лог помимо прочего пишет ошибку MongodbNetworkError. И все (из полезного).
Разработчики (конкретная команда ответственная за фичу) — завели привычную песенку «у меня все работает», только звучало это как — «у нас на регрессионном стенде тест проходит это у вас на стейдже с базой какие то проблемы. Не мешайте нам выкатываться- стейдж чините».

Ну что… Пришлось вспомнить что я еще играющий тимлид, расчехлить консольку и встать на защиту чести стейджа)
А дальше — расследование.

Первое что я сделал- собрал все запросы,которые выполнял тест. Посмотрел в логах (на самом сервере, не в elk) — время когда запрос пришел и когда мы на него ответили 500 (ошибка с монгой скрывается внутри, речь идет именно про request-reply с клиентом) — и бац, все запросики у нас выходили по 30 секунд. Ровно! Подозрительно похоже на таймаут.

Ок, расковыриваю что за запрос делается (у нас приложение логирует какой query он кидает в базу) и иду выполняю его вручную через mongoshell — ага, повисает… Добавляю к запросу параметр .maxTimeMS(30000) — получаю ошибку запросы что он не укладывается в 30 сек:

ну это 100 из 100 чт где то кто то с базой продолбался… Иду на регрессию и выполняю похожий запрос (данные запроса отличаются, характер тот же) — отрабатывает.

Начинаю сравнивать — под эту фичу у нас в документ определенной коллекции добавлялись несколько полей и для быстрого поиска по ним строился индекс. На проде ради этого делали отдельное долгое изменение по всем базам (ну прикиньте индекс по 4тб построить).

Результат изысканий:

• поля есть и на регресии и в стейдже
• индекс построен и там и там
• индекс одинаковый (по структуре)
• данные в индексах есть (то есть они сами не пустые).

Сижу чешу репу — что не так… И тут вспоминаю про благословенный exlain…
добавляю к запросу .explain() и что я вижу:

То есть эта сволочь не пытается работать с индексом а идет и просто перебором ищет по всей коллекции. Конечно мы так в 30 сек таймаута не уложимся — на стейдже коллекции большие. Не как в проде но все равно — десятки гигабай.

Ок, думаю — как оно тогда в регресии то работает? Индексы же одинаковые по структуре. Кидаю запрос в регрессионную базу — то же самое, скан коллекции.

Это означает что индекс не работает, а точнее что запрос не попадает в него и база вынуждена искать тупым монотонным перебором.

Так почему же в регрессии запрос при этом отрабатывал а в стейдже падал с таймаутом?
Ларчик просто открывался- размер этой коллекции в регрессии — 133 мегабайта, в стейдже — 175 гигов. В проде естественно еще хуже)))

Пошел натыкал в это разработку. Другая команда благо пришла на помощь и быстро состряпала запрос который давал бы тот же результат но попадал в созданный ранее индекс. Теперь авторы сидят исправляют — ждем следующий релиз с хот фиксом. Вот так вот…