Один на 150 миллионов операций: расследуем причины выброса времени отклика в операциях ввода-вывода

Один из продуктов компании YADRO, c которым я работаю, — это системы хранения данных TATLIN.UNIFIED. Как и любой другой программный продукт или программно-аппаратный комплекс в процессе разработки, контроля качества и приемо-сдаточных испытаний, наша СХД проходит нагрузочное тестирование. Среди критериев успеха — отсутствие выбросов значения времени выполнения операции ввода-вывода более 1 секунды.

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

Это было единичное событие, в тесте с интенсивностью ввода-вывода ~200K операций в секунду (IOPS), в промежутке времени 10 минут. Оно статистически не значительно, но имеет неприятно высокое значение.

Прежде чем мы начнем погружаться в детали, определимся с терминами. Если вы «в теме», смело переходите к следующему разделу.

В качестве инструмента, создающего нагрузку, мы использовали vdbench, развернутый на Rocky Linux. Vdbench производит прямые операции записи и чтения в устройство dm-multipath, минуя страничный кеш. Устройство, в свою очередь, собирается из ресурса, экспортируемого с СХД через четыре порта.

Драйвер dm-multipath получает запрос на вход. Основываясь на политике выбора пути, переназначает его одному из нижележащих блочных устройств, которое образует один из возможных путей.

Пример прохождения запроса в блочном стеке через dm-multipath на основе трассы, полученной с помощью утилиты blktrace:

Расшифровка операций в блочном стеке:

• Q — queued (постановка bio в очередь),
• G — get request (подготовка структуры данных запроса),
• I — inserted (передача запроса планировщику ввода-вывода),
• D — issued (отправка запроса в драйвер устройства),
• A — remap (перенаправление запроса).

Далее запрос отправляется в драйвер QLogic и передается через fibre channel на СХД, где проходит путь от SCSI таргета до конечных дисков.

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

Для этого мы последовательно исключаем части архитектуры, в которых не наблюдается выброс. Лучше всего этот подход иллюстрирует метод двоичного поиска — классический алгоритм поиска элемента в отсортированном массиве (векторе), использующий дробление массива на половины.

В первую очередь мы исключили участок пути данных внутри СХД — ни один из счетчиков не показал столь высоких выбросов. Остался канальный уровень и сервер нагрузки.

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

Хорошо, мы получили примерную локализацию проблемы, в текущем ее понимании. Далее логично было бы получить больше деталей — к примеру, с помощью утилиты blktrace, чтобы понять, в каком месте цепочки операций блочного стека возникает выброс. Но если бы все было так просто.

Сложность заключалась в воспроизведении, а точнее в частоте воспроизведения события. Приблизительно один выброс на сто пятьдесят миллионов операций. Попытки снять трассу с задействованных в операциях ввода-вывода блочных устройств с помощью blktrace не увенчались успехом. Утилита просто падала под нагрузкой спустя несколько секунд.

Но, даже если бы нам удалось поймать выброс, обработка результата превратилась бы в не менее увлекательную задачу из-за большого объема данных.

Часто в процессе трассировки регистрируется гораздо больше событий, чем необходимо для решения проблемы. Это может оказывать влияние на воспроизводимость, дополнительную нагрузку на процессор и подсистему ввода-вывода, усложнять последующий анализ собранных данных.

Есть определенный смысл в том, чтобы минимизировать регистрацию и обработку не интересующих нас событий. Иными словами — регистрировать и обрабатывать только то, что имеет практическое значение. Эту задачу позволяет решить механизм трассировки в ядре Linux и технология ebpf.

Что необходимо сделать?

• Зарегистрировать события rq_issue, rq_complete, rq_remap (передачу запроса драйверу, завершение обработки, перенаправление операции ввода-вывода соответственно) на всех блочных устройствах, входящих в multipath и самих dm-multipath устройств.
• Сохранить в хеш-таблицах для каждого устройства метаданные:
  • текущее время и сектор, на основе которых будет вычисляться время выполнения операции,
  • минорный и мажорный номера устройства — для прослеживания связи между dm-multipath и нижележащими блочными устройствами,
  • размер блока.
• Вычислить время выполнения операции на dm-multipath устройстве, основываясь на секторе и разнице во времени между событиями rq_issue и rq_complete.
• Если время меньше порогового, очистить все данные в таблицах, связанные с этой операцией.
• Если время превысило пороговое значение, определить:
  • нижележащее устройство, на которое произошло перенаправление,
  • время от события перенаправления до завершения,
  • время выполнения в операции на нижележащем устройстве.

Структура dm-multipath устройства выглядит следующим образом:

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

Далее по ссылкам скрипт, реализующий приведенный выше алгоритм, — с помощью bcc-инструментария (ссылка на GitHub раз и два). Мажорный и минорные адреса устройств, составляющих пути, и само dm-multipath устройство «захардкожены», но для решения конкретной задачи и передачи смысла считаю это допустимым.

Результатом работы скрипта стала регистрация ряда событий. Пример одного из них:

Какие выводы тут можно сделать?

Время выполнения операций на блочном устройстве, на которое перенаправляется проблемная операция, — в пределах нормы. В отличие от dm-multipath устройства, где временной промежуток от перенаправления до завершения запроса составил ~10 секунд. Помимо этого, все зарегистрированные операции перенаправлялись на один и тот же FC HBA. Это само по себе говорило о вероятной аппаратной составляющей проблемы.

Хорошо. Если время между rq_issue и rq_complete (передачей запроса драйверу и завершением обработки) в пределах нормы, то где же проводит свое время IO? Почему время выполнения на нижележащим устройстве остается в норме? Логично предположить, что происходит событие повторной постановки операции ввода-вывода в очередь на отправку (requeue).

К скрипту выше мы добавили ещё один, регистрирующий событие requeue.

Запущенные параллельно скрипты зарегистрировали связанные события перенаправления и повторной постановки в очередь для одного и того же блочного устройства:

То есть запрос успешно перенаправляется на блочное устройство 66:80, уходит в драйвер, где-то пропадает, а затем происходит повторная постановка в очередь и успешное выполнение.

Что же приводит к событию возврата в очередь? На это раз изобретать велосипед не требуется. В ответе на вопрос нам поможет утилита stackcount из пакета bcc-tools.

Stackcount печатает содержимое стека (call trace) для функции или точки трассировки, заданной в аргументе. Исходя из стека, можно понять, какая часть кода приводит к возникновению события.

qla24xx_process_response_queue и qla2x00_sp_compl — функции, которые выполняются в потоке обработки завершения ответа в драйвере QLogic, источнике события.

Включаем логирование в драйвере QLogic c обеих сторон — как на инициаторе, так и на таргете, заходим на очередной круг воспроизведения выброса:

С полным описанием полей маски можно ознакомиться по ссылке.

Спустя некоторое время мы зарегистрировали выброс и соответствующие ему события. Спутать их было не с чем, поскольку это были единственные записи в логах.

Логи инициатора:

SCSI check condition говорит о том, что устройству SCSI необходимо сообщить об ошибке.

Логи таргета:

Инициатор получает check condition, что приводит к повторной отправке запроса. Примерно в это же время таргет логирует таймаут — Command Transport I/O (CTIO). Когда инициируется операция CTIO, host bus adapter ожидает ответа в течение определенного времени. Если ответ не приходит, то операция CTIO завершается.

В коде таргета можно увидеть значение таймаута — 10 секунд.

Полная версия

Полная версия

Причин возникновения таймаута CTIO много: проблемы связи, перегруженная фабрика/коммутатор, недоступность устройства таргета, проблемы в микрокоде HBA.

Учитывая проведенные ранее проверки, мы можем исключить:

• Недоступность таргета. Его исключили еще в самом начале — на этапе локализации участка пути данных, на котором возникает выброс.
• Проблемы в микрокоде HBA. Заметили, что проблема локализуется на одном порту.
• Перегруженную фабрику/коммутатор. В данной конфигурации ее просто нет, топология соединение точка-точка.

Остаются проблемы со связью в цепочке «трансивер — кабель — трансивер». На этом этапе мудрствовать мы не стали и просто решили заменить по порядку все компоненты в цепочке. Причина проблем же оказалась в прямом смысле «где-то посередине» — в волоконно-оптическом кабеле.

Наверняка, обладая некоторым опытом или «наметанным глазом», нашу задачу можно было бы решить гораздо проще — сразу включить отладку в драйвере QLogic. Но, пожалуй, это было бы не так увлекательно. И точно не появилась бы эта статья — с примером решения слабо формализованной задачи.

Были ли у вас подобные случаи в практике? Расскажите о своем опыте траблшутинга в комментариях!