Привет! Я Александр Пищулин, перфоманс-инженер в компании 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 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_TIMEOUT			10	/* in seconds */

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

Развязка

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

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

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

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

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

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

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

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