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

Привет! Я Александр Пищулин, перфоманс-инженер в компании 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 и технология ebpf.

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

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

• Сохранить в хеш-таблицах для каждого устройства метаданные:

  • текущее время и сектор, на основе которых будет вычисляться раз и два). Мажорный и минорные адреса устройств, составляющих пути, и само 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'

    То есть запрос успешно перенаправляется на утилита 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 обеих сторон — как на по ссылке.

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

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

    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: +240  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 00

    SCSI 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_TIMEOUT10/* in seconds */

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

    Развязка

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

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

    • Недоступность таргета. Его исключили еще в самом начале — на этапе локализации участка пути данных, на котором возникает выброс.

    • Проблемы в микрокоде HBA. Заметили, что проблема локализуется на одном порту.

    • Перегруженную фабрику/коммутатор. В данной конфигурации ее просто нет, топология соединение точка-точка.

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

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

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