В этой статье Александр Пищулин, перфоманс-инженер в компании YADRO, расскажет об интересном случае траблшутинга в работе с системой хранения данных — он касается выброса времени отклика. По словам Александра, поиск причин сбоев — одно из самых увлекательных занятий в его работе. Зачастую у подобных задач минимальная формализация подхода к решению, каждый раз может быть своего рода открытием или даже челленджем.
Так произошло и в случае, который описан в статье. Путь решения задачи может показаться не оптимальным, но в итоге именно он привел к неожиданной разгадке всей проблемы. Возможно, вы бы начали искать проблему иначе — предлагаем поделиться опытом в комментариях.
Описание проблемы
Один из продуктов компании YADRO, c которым я работаю, — это системы хранения данных TATLIN.UNIFIED. Как и любой другой программный продукт или программно-аппаратный комплекс в процессе разработки, контроля качества и приемо-сдаточных испытаний, наша СХД проходит нагрузочное тестирование. Среди критериев успеха — отсутствие выбросов значения времени выполнения операции ввода-вывода более 1 секунды.
В процессе нагрузочного тестирования на одном из наших стендов в какой-то момент мы начали получать выбросы максимального времени выполнения операции ввода-вывода.
Это было единичное событие, в тесте с интенсивностью ввода-вывода ~200K операций в секунду (IOPS), в промежутке времени 10 минут. Оно статистически не значительно, но имеет неприятно высокое значение.
Терминология
Прежде чем мы начнем погружаться в детали, определимся с терминами. Если вы «в теме», смело переходите к следующему разделу.
FC HBA (Fibre channel host bus adapter)SAS HBA (Serial attached scsi host bus adapter)ИнициаторТаргетБлочное устройствоБлочный стекВремя выполнения операции
Dm (device mapper)Multipath, или многоканальный ввод-вывод
Мажорный номер устройстваМинорный номер устройстваКак бегут данные — от нагрузочного сервера до дисков СХД
В качестве инструмента, создающего нагрузку, мы использовали 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 не увенчались успехом. Утилита просто падала под нагрузкой спустя несколько секунд.
Но, даже если бы нам удалось поймать выброс, обработка результата превратилась бы в не менее увлекательную задачу из-за большого объема данных.
Минимизируем регистрацию событий с помощью технологии ebpf
Часто в процессе трассировки регистрируется гораздо больше событий, чем необходимо для решения проблемы. Это может оказывать влияние на воспроизводимость, дополнительную нагрузку на процессор и подсистему ввода-вывода, усложнять последующий анализ собранных данных.
Есть определенный смысл в том, чтобы минимизировать регистрацию и обработку не интересующих нас событий. Иными словами — регистрировать и обрабатывать только то, что имеет практическое значение. Эту задачу позволяет решить механизм трассировки в ядре 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
Включаем логирование в драйвере QLogic c обеих сторон — как на инициаторе, так и на таргете, заходим на очередной круг воспроизведения выброса:
С полным описанием полей маски можно ознакомиться по ссылке.
Спустя некоторое время мы зарегистрировали выброс и соответствующие ему события. Спутать их было не с чем, поскольку это были единственные записи в логах.
Логи инициатора:
SCSI check condition говорит о том, что устройству SCSI необходимо сообщить об ошибке.
Логи таргета:
Инициатор получает check condition, что приводит к повторной отправке запроса. Примерно в это же время таргет логирует таймаут — Command Transport I/O (CTIO). Когда инициируется операция CTIO, host bus adapter ожидает ответа в течение определенного времени. Если ответ не приходит, то операция CTIO завершается.
В коде таргета можно увидеть значение таймаута — 10 секунд.
Развязка
Причин возникновения таймаута CTIO много: проблемы связи, перегруженная фабрика/коммутатор, недоступность устройства таргета, проблемы в микрокоде HBA.
Учитывая проведенные ранее проверки, мы можем исключить:
- Недоступность таргета. Его исключили еще в самом начале — на этапе локализации участка пути данных, на котором возникает выброс.
- Проблемы в микрокоде HBA. Заметили, что проблема локализуется на одном порту.
- Перегруженную фабрику/коммутатор. В данной конфигурации ее просто нет, топология соединение точка-точка.
Остаются проблемы со связью в цепочке «трансивер — кабель — трансивер». На этом этапе мудрствовать мы не стали и просто решили заменить по порядку все компоненты в цепочке. Причина проблем же оказалась в прямом смысле «где-то посередине» — в волоконно-оптическом кабеле.
Наверняка, обладая некоторым опытом или «наметанным глазом», нашу задачу можно было бы решить гораздо проще — сразу включить отладку в драйвере QLogic. Но, пожалуй, это было бы не так увлекательно. И точно не появилась бы эта статья — с примером решения слабо формализованной задачи.
Были ли у вас подобные случаи в практике? Расскажите о своем опыте траблшутинга в комментариях!
Познавательно. Жаль, что минимизировано описание поиска на стороне СХД. Хотя бы кратко, список инструментов.
Здравствуйте, Олег! Спасибо за ваш вопрос. Поиск на стороне СХД основан на анализе счетчиков времени выполнения операций, реализованных в ПО, на каждом участке пути данных. Они должны быть доступны для сервиса.