Привет! Я Александр Пищулин, перфоманс-инженер в компании YADRO. Сегодня я расскажу об одном интересном случае траблшутинга в работе с системой хранения данных — он касается выброса времени отклика. Поиск причин сбоев, наверное, одно из самых увлекательных занятий в моей работе. Зачастую у подобных задач минимальная формализация подхода к решению, каждый раз может быть своего рода открытием или, если угодно, челленджем.
Так произошло и в случае, который я описываю под катом. Путь решения задачи может показаться не оптимальным, но в итоге именно он привел к неожиданной разгадке всей проблемы. Возможно, вы бы начали искать проблему иначе — предлагаю поделиться вашими соображениями или опытом в комментариях.
Описание проблемы
Один из продуктов компании YADRO, c которым я работаю, — это системы хранения данных TATLIN.UNIFIED. Как и любой другой программный продукт или программно-аппаратный комплекс в процессе разработки, контроля качества и приемо-сдаточных испытаний, наша СХД проходит нагрузочное тестирование. Среди критериев успеха — отсутствие выбросов значения времени выполнения операции ввода-вывода более 1 секунды.
В процессе нагрузочного тестирования на одном из наших стендов в какой-то момент мы начали получать выбросы максимального времени выполнения операции ввода-вывода.
Это было единичное событие, в тесте с интенсивностью ввода-вывода ~200K операций в секунду (IOPS), в промежутке времени 10 минут. Оно статистически не значительно, но имеет неприятно высокое значение.
Терминология
Прежде чем мы начнем погружаться в детали, определимся с терминами. Если вы «в теме», смело переходите к следующему разделу.
Эти термины и аббревиатуры вы встретите в тексте и на схемах
FC HBA (Fibre channel host bus adapter). Хост-адаптер для подключения внешних устройств по протоколу fibre channel (fc). Fibre channel — семейство протоколов для высокоскоростной передачи данных. Используется как стандартный способ подключения к системам хранения данных уровня предприятия.
SAS HBA (Serial attached scsi host bus adapter). Хост-адаптер для подключения внешних устройств по протоколу Serial Attached SCSI. SAS SCSI — последовательный компьютерный интерфейс, разработанный для подключения различных устройств хранения данных — например, жестких дисков и ленточных накопителей. SAS разработан для замены параллельного интерфейса SCSI и основывается во многом на терминологии и наборах команд SCSI.
Инициатор. В протоколе SCSI это точка, которая инициирует сеанс, то есть отправляет команду SCSI. Инициатор обычно не предоставляет номера логических устройств (LUN).
Таргет. В протоколе SCSI это конечная точка, которая не инициирует сеансы, а вместо этого ожидает команд инициаторов и обеспечивает необходимую передачу входных/выходных данных. Таргет обычно предоставляет инициаторам один или несколько LUN.
Блочное устройство. В ОС, основанных на ядре Linux, — устройство хранения, которое позволяет адресовать фрагменты данных в виде блоков с произвольным доступом к последним — например, жесткий диск.
Блочный стек. Набор кода в поддиректории block исходного кода ядра Linux. Его назначение — предоставление абстрактного интерфейса доступа для взаимодействия с разнообразными физическими устройствами хранения.
Время выполнения операции. Время, затраченное на выполнение операции, с учетом времени ожидания в очереди.
Dm (device mapper). Это фреймворк, предоставляемый ядром Linux, для отображения физических блочных устройств на виртуальные блочные устройства более высокого уровня. Он лежит в основе менеджера логических томов (LVM), программных RAID-массивов, драйвера многоканального доступа (dm-multipath).
Multipath, или многоканальный ввод-вывод. Технология определяет более одного физического пути доступа между процессором вычислительной системы и устройствами хранения данных через соединяющие их шины, контроллеры, коммутаторы и мостовые устройства. Обеспечивает отказоустойчивость и повышение производительности системы.
Мажорный номер устройства. Определяет драйвер, связанный с устройством. Часть из них зарезервирована за конкретными драйверами, часть выделяется динамически. Ядро использует мажорный номер в момент открытия устройства для передачи запроса на обработку соответствующему драйверу.
Минорный номер устройства. Используется только тем драйвером, который указан мажорным номером. Прочие части ядра его не используют, а просто передают драйверу. Обычно драйвер управляет несколькими устройствами, минорный номер позволяет драйверу их различать.
Как бегут данные — от нагрузочного сервера до дисков СХД
В качестве инструмента, создающего нагрузку, мы использовали vdbench, развернутый на Rocky Linux. Vdbench производит прямые операции записи и чтения в устройство dm-multipath, минуя страничный кеш. Устройство, в свою очередь, собирается из ресурса, экспортируемого с СХД через четыре порта.
Драйвер dm-multipath получает запрос на вход. Основываясь на политике выбора пути, переназначает его одному из нижележащих блочных устройств, которое образует один из возможных путей.
Пример прохождения запроса в блочном стеке через dm-multipath на основе трассы, полученной с помощью утилиты blktrace:
+-- Мажорный и минорный номера блочного устройства
| +-- Ядро, на котором выполнялась операция
| | +-- Порядковый номер IO
| | | +-- Временная метка от начала трассировки
| | | | +-- PID
| | | | | +-- Операция в блочном стеке
| | | | | | +-- Тип операции ввода-вывода
| | | | | | | +-- Сектор
| | | | | | | | +-- Размер блока в секторах
| | | | | | | | | +-- Имя процесса
| | | | | | | | | |
# Постановка bio в очередь
253,2 49 117 0.089649684 9635 Q WS 20443363840 + 128 [IO_task /dev/ma]
# Подготовка структуры данных запроса
253,2 49 118 0.089652110 9635 G WS 20443363840 + 128 [IO_task /dev/ma]
# Передача запроса планировщику ввода-вывода
253,2 49 121 0.089653806 9635 I WS 20443363840 + 128 [IO_task /dev/ma]
# Отправка запроса в драйвер устройства
253,2 49 122 0.089660692 1087 D WS 20443363840 + 128 [kworker/49:1H]
# перенаправление запроса драйвером dm-mpath на нижележащее устройство
8,16 49 15 0.089663089 1087 A W 20443363840 + 128 <- (253,2) 20443363840
# Отправка запроса в драйвер устройства
8,16 49 16 0.089664842 1087 D WS 20443363840 + 128 [kworker/49:1H]
# Завершение от драйвера устройства
8,16 51 8 0.091055638 615 C WS 20443363840 + 128 [0]
# Завершение от dm-multipath
253,2 51 15 0.091059967 615 C WS 20443363840 + 128 [0]
253,2 51 16 0.091077083 320 C WS 20443363840 [0]Расшифровка операций в блочном стеке:
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 устройства выглядит следующим образом:
R2D2_ssd_pool0_res3 (3614529010a5400a44000800000000004) dm-7 YADRO,TATLIN
size=512G features='1 queue_if_no_path' hwhandler='1 alua' wp=rw
`-+- policy='service-time 0' prio=50 status=active
|- 14:0:0:4 sdh 8:112 active ready running
|- 16:0:0:4 sdr 65:16 active ready running
|- 17:0:0:4 sdab 65:176 active ready running
`- 18:0:0:4 sdal 66:80 active ready runningТаких устройств было четыре, но для упрощения и сокращения количества текста рассматривать будем только одно из них.
Далее по ссылкам скрипт, реализующий приведенный выше алгоритм, — с помощью bcc-инструментария (ссылка на GitHub раз и два). Мажорный и минорные адреса устройств, составляющих пути, и само dm-multipath устройство «захардкожены», но для решения конкретной задачи и передачи смысла считаю это допустимым.
Результатом работы скрипта стала регистрация ряда событий. Пример одного из них:
+--- имя процесса
| +--- PID
| | +----- процессор/ядро
| | | +-- прерывания отключены
| | | | +-- глубина запрета преимущественного вытеснения = 4
| | | | | +-- временная метка
| | | | | | +-- функция
| | | | | | | +-- поле текстового вывода
| | | | | | | |
kworker/65:11-318865 [065] d..4 255765.757738: bpf_trace_printk: Sector: 23bff400, lat: 9986
kworker/65:11-318865 [065] d..4 255765.757741: bpf_trace_printk: Maj: 253 Min: 7 Op: WS
# Зарегистрирован запрос на запись в сектор 23bff400 устройства 257:7 (dm-7) с временем, прошедшим от момента отправки запроса до регистрации события, равным 9986ms
kworker/65:11-318865 [065] d..4 255765.757743: bpf_trace_printk: Remap sector: 23bff400, size: 32768, lat 9986
kworker/65:11-318865 [065] d..4 255765.757743: bpf_trace_printk: Remap dev: 66:80
# Зарегистрирована операция перенаправления в сектор 23bff400 устройства 66:80 (sdal) с временем, прошедшим от регистрации события remap до завершения запроса, равным 9986ms
kworker/65:11-318865 [065] d..4 255765.757745: bpf_trace_printk: Maj: 66 Min: 80 lat: 2
# Время выполнения запроса на запись в устройство 66:80 (sdal) – 2msКакие выводы тут можно сделать?
Время выполнения операций на блочном устройстве, на которое перенаправляется проблемная операция, — в пределах нормы. В отличие от dm-multipath устройства, где временной промежуток от перенаправления до завершения запроса составил ~10 секунд. Помимо этого, все зарегистрированные операции перенаправлялись на один и тот же FC HBA. Это само по себе говорило о вероятной аппаратной составляющей проблемы.
Дорабатываем скрипт для проверки гипотезы
Хорошо. Если время между rq_issue и rq_complete (передачей запроса драйверу и завершением обработки) в пределах нормы, то где же проводит свое время IO? Почему время выполнения на нижележащим устройстве остается в норме? Логично предположить, что происходит событие повторной постановки операции ввода-вывода в очередь на отправку (requeue).
К скрипту выше мы добавили еще один, регистрирующий событие requeue.
Запущенные параллельно скрипты зарегистрировали связанные события перенаправления и повторной постановки в очередь для одного и того же блочного устройства:
+--- имя процесса
| +--- PID
| | +----- процессор/ядро
| | | +-- прерывания отключены
| | | | +-- глубина запрета преимущественного вытеснения = 4
| | | | | +-- временная метка
| | | | | | +-- функция
| | | | | | | +-- Поле текстового вывода
| | | | | | | |
kworker/42:0-345443 [042] d..4 290023.581427: bpf_trace_printk: Requeue Dev: 66:80 Sector: 7d1e080'
kworker/42:0-345443 [042] d..4 290023.583529: bpf_trace_printk: Sector: 7d1e080 size: 65536 lat: 9949
kworker/42:0-345443 [042] d..4 290023.583530: bpf_trace_printk: Dev: 253:7 Op: WS'
kworker/42:0-345443 [042] d..4 290023.583531: bpf_trace_printk: Remap sector: 7d1e080, size: 65536, lat 9949
kworker/42:0-345443 [042] d..4 290023.583532: bpf_trace_printk: Remap dev: 66:80'
kworker/42:0-345443 [042] d..4 290023.583533: bpf_trace_printk: Maj: 66 Min: 80 lat: 2'То есть запрос успешно перенаправляется на блочное устройство 66:80, уходит в драйвер, где-то пропадает, а затем происходит повторная постановка в очередь и успешное выполнение.
Что же приводит к событию возврата в очередь? На это раз изобретать велосипед не требуется. В ответе на вопрос нам поможет утилита stackcount из пакета bcc-tools.
Stackcount печатает содержимое стека (call trace) для функции или точки трассировки, заданной в аргументе. Исходя из стека, можно понять, какая часть кода приводит к возникновению события.
# /usr/share/bcc/tools/stackcount t:block:block_rq_requeue
Tracing 1 functions for "t:block:block_rq_requeue"... Hit Ctrl-C to end.
^C
b'__blk_mq_requeue_request'
b'__blk_mq_requeue_request'
b'blk_mq_requeue_request'
b'qla2x00_sp_compl'
b'qla24xx_process_response_queue'
b'qla_do_work'
b'process_one_work'
b'worker_thread'
b'kthread'
b'ret_from_fork'qla24xx_process_response_queue и qla2x00_sp_compl — функции, которые выполняются в потоке обработки завершения ответа в драйвере QLogic, источнике события.
От трассировки стека ввода-вывода — к отладке драйвера QLogic
Включаем логирование в драйвере QLogic c обеих сторон — как на инициаторе, так и на таргете, заходим на очередной круг воспроизведения выброса:
+ -- Init debug + MBX debug + Device discovery debug
|+ -- IO tracing debug + DPC thread debug +Async event debug + Timer debug
||+ -- User Space Interations Debug + Task Management Debug + AER/EEH Debug + MultiQ Debug
|||+ -- P3P specific Debug + Virtual Port Debug + dumping the buffer/regs + dumping all other
||||+ -- More verbosity for each level + Target mode
|||||+ -- Target mode dif
||||||
echo 0x7fffb800 > /sys/module/qla2xxx/parameters/ql2xextended_error_loggingС полным описанием полей маски можно ознакомиться по ссылке.
Спустя некоторое время мы зарегистрировали выброс и соответствующие ему события. Спутать их было не с чем, поскольку это были единственные записи в логах.
Логи инициатора:
Jun 9 20:45:44 bench-srv-01 kernel: qla2xxx [0000:af:00.3]-301c:18: Check condition Sense data, nexus18:0:31 cmd=00000000bf3ed085.
Jun 9 20:45:44 bench-srv-01 kernel: qla2xxx [0000:af:00.3]-302b:18: +24 0 1 2 3 4 5 6 7 8 9 A B C D E F
Jun 9 20:45:44 bench-srv-01 kernel: qla2xxx [0000:af:00.3]-302b:18: ----- -----------------------------------------------
Jun 9 20:45:44 bench-srv-01 kernel: qla2xxx [0000:af:00.3]-302b:18: 0000: 70 00 0b 00 00 00 00 0a 00 00 00 00 29 03 00 00
Jun 9 20:45:44 bench-srv-01 kernel: qla2xxx [0000:af:00.3]-302b:18: 0010: 00 00 00 00 00 00 00 00SCSI check condition говорит о том, что устройству SCSI необходимо сообщить об ошибке.
Логи таргета:
[Fri Jun 9 17:45:54 2023] qla2xxx [0003:09:00.0]-f058:3: qla_target(0): CTIO with status 0xb received, state 1, se_cmd 000000007c52f02f, (LIP_RESET=e, ABORTED=2, TARGET_RESET=17, TIMEOUT=b, INVALID_RX_ID=8)Инициатор получает check condition, что приводит к повторной отправке запроса. Примерно в это же время таргет логирует таймаут — Command Transport I/O (CTIO). Когда инициируется операция CTIO, host bus adapter ожидает ответа в течение определенного времени. Если ответ не приходит, то операция CTIO завершается.
В коде таргета можно увидеть значение таймаута — 10 секунд.
static void qlt_24xx_retry_term_exchange(struct scsi_qla_host *vha,
struct qla_qpair *qpair, response_t *pkt, struct qla_tgt_mgmt_cmd *mcmd)
{
...
ctio->timeout = cpu_to_le16(QLA_TGT_TIMEOUT);
...
} #define QLA_TGT_TIMEOUT 10 /* in seconds */Развязка
Причин возникновения таймаута CTIO много: проблемы связи, перегруженная фабрика/коммутатор, недоступность устройства таргета, проблемы в микрокоде HBA.
Учитывая проведенные ранее проверки, мы можем исключить:
Недоступность таргета. Его исключили еще в самом начале — на этапе локализации участка пути данных, на котором возникает выброс.
Проблемы в микрокоде HBA. Заметили, что проблема локализуется на одном порту.
Перегруженную фабрику/коммутатор. В данной конфигурации ее просто нет, топология соединение точка-точка.
Остаются проблемы со связью в цепочке «трансивер – кабель – трансивер». На этом этапе мудрствовать мы не стали и просто решили заменить по порядку все компоненты в цепочке. Причина проблем же оказалась в прямом смысле «где-то посередине» — в волоконно-оптическом кабеле.
Наверняка, обладая некоторым опытом или «наметанным глазом», нашу задачу можно было бы решить гораздо проще — сразу включить отладку в драйвере QLogic. Но, пожалуй, это было бы не так увлекательно. И точно не появилась бы эта статья — с примером решения слабо формализованной задачи.
Были ли у вас подобные случаи в практике? Расскажите о своем опыте траблшутинга в комментариях!
