Привет, это Константин Евтушенко и Артём Хакимов, разработчики R&D-команды в Cloud.ru. В предыдущей серии Санта-Барбары про pNFS наш коллега Сергей Баширов @sbashiro описал, как настроить стенд pNFS. Рассказ про эти «страдания» вам так понравился, что мы с коллегами просто не можем оставить публику без продолжения. Без доработки у нас ничего не завелось, поэтому сегодня расскажем, как мы настроили окружение для отладки: Wireshark, gdb, trace-cmd ядра Linux, а также разберем трудности, с которыми столкнулись. В качестве подопытного у нас будет все тот же стенд на Ubuntu 22.04. Поехали!
Описание стенда
Мы настроили стенд из нескольких хостов с примерно сотней клиентских виртуальных машин на каждом и отдельной виртуальной машиной для pNFS-сервера. Когда мы впервые запустили на стенде простенький вариант записи в файл с помощью утилиты dd — все работало правильно, и мы решили перейти к бенчмаркам с помощью FIO (flexible input-output). Но более интенсивный ввод-вывод вскрыл несколько проблем. Вооружаемся отладочными средствами и начинаем изучать логи ошибок.
Как и обещали, делимся сорцами. Если собрать драйверы NFS из этого бранча, то по инструкции из первой части статьи должно всё работать.
Принцип работы
Перед тем как погрузиться с головой в отладку, не мешает вспомнить, как работает протокол pNFS на уровне RPC. Ниже приведена трасса из Wireshark, полученная во время работы FIO: записываем один небольшой файл (1 ГБ) и проверяем, что все записалось верно. Для наглядности используем версию NFS 4.2
Давайте посмотрим, как все устроено.
Сначала клиент пытается открыть файл на сервере. Если он обнаруживает, что файл отсутствует, его необходимо создать.
Для начального размещения файла на сервере используется вызов ALLOCATE. В процессе работы с файлом клиенту нужно узнать, как именно файл размещен на диске.
Для этого клиент запрашивает у сервера информацию о размещении (с помощью вызова LAYOUTGET), получает lock — «блокировку» для работы с файлом, и далее работает с диском напрямую, не обращаясь к серверу с помощью RPC-вызовов.
После того как работа с диском завершена, клиент сообщает серверу об изменении состояния экстентов используя вызов LAYOUTCOMMIT.
Завершается процесс возвратом блокировки через запрос LAYOUTRETURN.
Если размер файла изначально известен, запрос LAYOUTGET позволяет получить данные о размещении всего файла или его большой части. В случае использования протокола версии 4.1, вместо вызова ALLOCATE клиент использует функцию allocate из библиотеки glibc. Функция записывает нулевые байты в начало каждого 4K блока файла, что приводит к генерации большого количества запросов LAYOUTGET и эпизодическим вызовам LAYOUTCOMMIT. Такой процесс работает довольно медленно.
Первые проблемы: FIO io_error
Оценим обстановку: FIO выдает ошибки во время записи и в dmesg-логе MDS сервера появляются ошибки вида: «RPC: fragment too large». Первое, что приходит в голову — попробовать увеличить I/O буфер (/proc/fs/nfsd/max_block_size), но это не помогло. Не забываем про этот буфер: изменение его размера нам еще пригодится.
FIO log
fio: io_u error on file /mnt/nfs/test00.raw: Input/output error: write offset=954728448, buflen=131072
fio: pid=2230, err=5/file:io_u.c:1845, func=io_u error, error=Input/output error
MDS dmesg
svc: svc_tcp_read_marker nfsd RPC fragment too large: 1111468
svc: svc_tcp_read_marker nfsd RPC fragment too large: 1111468
net_ratelimit: 26 callbacks suppressed
Настройка отладочного вывода NFS в Linux
Попробуем собрать побольше информации. Для этого включим все возможные отладочные сообщения в драйвере. Вывод dprintk() в клиенте и сервере управляется при помощи файлов /proc/sys/sunrpc/nfs_debug и /proc/sys/sunrpc/nfsd_debug соответственно. Запускаем и видим: включение отладочных сообщений приводит к замедлению системы до такой степени, что первоначальные проблемы перестают ее волновать по двум причинам:
Драйвер клиента начинает работать так медленно, что клиент не успевает добавить в буфер большое количество экстентов. В результате и проблемы, которые обычно возникают из-за быстрого добавления большого числа экстентов, не проявляются.
При замедлении кода снижается и вероятность возникновения «состояний гонки» (race conditions): это когда несколько процессов одновременно пытаются изменить общие данные без должной синхронизации.
Включаем dprintk
echo 65535 > /proc/sys/sunrpc/nfs_debug
Тогда мы принялись искать способы увеличить количество отладочной информации, которую выводят NFS-клиент и сервер без их существенного замедления.
Плагин для Wireshark
Решено было подключить Wireshark и посмотреть, что же происходит на уровне запросов. Из коробки инструмент поддерживает NFS-протокол. В трассе находим еще пару ошибок: BAD_XDR и INVAL в ответ на запрос LAYOUTCOMMIT, который возвращает обновленную схему размещения файла (layout) в MDS. Такие ошибки возникают на этапе декодирования формата XDR (External Data Representation). Но, как мы упоминали в обзорной статье про pNFS, — существуют различные типы layout. К сожалению, Wireshark парсит только общую для всех часть RPC-сообщений. А специфичные для блочного layout аргументы, такие как, например, список экстентов, не парсятся.
Мы раньше никогда не писали для Wireshark плагины, да и на Lua не программировали. Но все-таки решили вложиться и потратили лишний день, чтобы по-быстрому разобраться в этом и настроить окружение. Код наверняка получился не идеальный, но свое дело делает.
pnfs_block_layout.lua
f_rpc_msgtyp = Field.new("rpc.msgtyp")
f_nfs_opcode = Field.new("nfs.opcode")
f_nfs_layout = Field.new("nfs.layout")
f_nfs_layoutupdate = Field.new("nfs.layoutupdate")
pnfs_block_layout_proto = Proto("pnfs_block_layout", "pNFS block layout content")
pnfs_bex_layout_proto = Proto("bex_layout", "Block extent layout")
bex_count = ProtoField.uint32("pnfs_block_layout.bex_count", "bex_count", base.DEC)
bex_vol_id = ProtoField.bytes("pnfs_block_layout.bex_vol_id", "bex_vol_id", base.NONE)
bex_file_offset = ProtoField.uint64("pnfs_block_layout.bex_file_offset", "bex_file_offset", base.HEX)
bex_length = ProtoField.uint64("pnfs_block_layout.bex_length", "bex_length", base.HEX)
bex_storage_offset = ProtoField.uint64("pnfs_block_layout.bex_storage_offset", "bex_storage_offset", base.HEX)
bex_state = ProtoField.uint32("pnfs_block_layout.bex_state", "bex_state", base.HEX)
OP_LAYOUTGET = 50
OP_LAYOUTCOMMIT = 49
OP_TYPE_REPLY = 1
pnfs_block_layout_proto.fields = { bex_count,
bex_vol_id,
bex_file_offset,
bex_length,
bex_storage_offset,
bex_state }
function pnfs_block_layout_proto.dissector(buffer, pinfo, tree)
local rpc_msgtyp = f_rpc_msgtyp()
if not rpc_msgtyp then
return
end
local nfs_opcode = nil
for _, opcode in ipairs({ f_nfs_opcode() }) do
if (opcode and opcode.value == OP_LAYOUTGET and rpc_msgtyp.value == OP_TYPE_REPLY)
or (opcode and opcode.value == OP_LAYOUTCOMMIT and rpc_msgtyp.value ~= OP_TYPE_REPLY) then
nfs_opcode = opcode
break
end
end
if not nfs_opcode then
return
end
local data = nil
if nfs_opcode.value == OP_LAYOUTGET then
data = f_nfs_layout().value:tvb("Layoutget Segment Content")
elseif nfs_opcode.value == OP_LAYOUTCOMMIT then
data = f_nfs_layoutupdate().value:tvb("Layoutcommit Segment Content")
else
end
layout_subtree = tree:add(pnfs_block_layout_proto, "pNFS Block Layout Extents")
layout_subtree:add(bex_count, data:range(0, 4))
local bex_size = 44
local last_bex_idx = data:range(0, 4):uint() - 1
-- local count = data:range(0, 4)
-- layout_subtree:add(bex_count, count)
for i = 0, last_bex_idx do
bex_subtree = layout_subtree:add(pnfs_bex_layout_proto, string.format("BEX[%u]", i))
bex_subtree:add(bex_vol_id, data:range(i * bex_size + 4, 16))
bex_subtree:add(bex_file_offset, data:range(i * bex_size + 20, 8))
bex_subtree:add(bex_length, data:range(i * bex_size + 28, 8))
bex_subtree:add(bex_storage_offset, data:range(i * bex_size + 36, 8))
bex_subtree:add(bex_state, data:range(i * bex_size + 44, 4))
end
end
register_postdissector(pnfs_block_layout_proto)
Файл нужно положить в папку ~/.local/lib/wireshark/plugins
, откуда Wireshark загружает пользовательские плагины. Как показала дальнейшая практика – этот плагин нам помог ещё не раз и усилия потраченные на его создание окупились многократно.
Теперь, изучив полностью разобранный RPC-запрос от клиента, мы сравнили его с описанием поведения в стандарте и пришли к выводу, что клиент формирует корректный запрос. Значит, проблема на стороне сервера, но из логов было непонятно, в чем конкретно ошибка. В коде сервера есть всего несколько мест, которые связаны с расшифровкой запроса LAYOUTCOMMIT и возвращают этот статус. Самое время подключать GDB к серверу, чтобы попытаться понять, как этот результат получается. Подготовим же виртуальные машины для отладки.
Подготовка GDB
Подготавливаем конфигурацию виртуальных машин:
Подготовка виртуальных машин
Редактируем domain xml:
virsh edit your-virt-host-name
Порт по умолчанию (1234):
<domain type='kvm'
xmlns:qemu='http://libvirt.org/schemas/domain/qemu/1.0' >
<qemu:commandline>
<qemu:arg value='-s'/>
</qemu:commandline>
Установка порта вручную (1235):
<domain type='kvm'
xmlns:qemu='http://libvirt.org/schemas/domain/qemu/1.0' >
<qemu:commandline>
<qemu:arg value='-gdb'/>
<qemu:arg value='tcp::1235'/>
</qemu:commandline>
Проверяем версию ядра. Это понадобится в следующих шагах для того, чтобы скачать правильные исходники и символы.
lsb_release -cs
Подготавливаем ПО внутри ВМ:
Сборка ядра
#Компиляция модулей для текущего ядра такой же версии
cd ...../linux-source-5.15.0/fs/nfs
make -C /lib/modules/$(uname -r)/build M=$PWD -j16 clean
make -C /lib/modules/$(uname -r)/build M=$PWD -j16 modules
cd ...../linux-source-5.15.0/fs/nfsd
make -C /lib/modules/$(uname -r)/build M=$PWD -j16 clean
make -C /lib/modules/$(uname -r)/build M=$PWD -j16 modules
cd ...../linux-source-5.15.0/net/sunrpc/
make -C /lib/modules/$(uname -r)/build M=$PWD -j16 clean
make -C /lib/modules/$(uname -r)/build M=$PWD -j16 modules
Исходники ядра с патчами, ветка ubuntu-5.15.0-89-pNFS
#Установка скомпилированных модулей
#backup:
sudo cp -v /usr/lib/modules/$(uname -r)/kernel/fs/nfs/blocklayout/blocklayoutdriver.ko{,.bak}
sudo cp -v /usr/lib/modules/$(uname -r)/kernel/fs/nfsd/nfsd.ko{,.bak}
sudo cp -v /usr/lib/modules/$(uname -r)/kernel/fs/nfs/nfs.ko{,.bak}
sudo cp -v /usr/lib/modules/$(uname -r)/kernel/fs/nfs/nfsv2.ko{,.bak}
sudo cp -v /usr/lib/modules/$(uname -r)/kernel/fs/nfs/nfsv3.ko{,.bak}
sudo cp -v /usr/lib/modules/$(uname -r)/kernel/fs/nfs/nfsv4.ko{,.bak}
sudo cp -v /usr/lib/modules/5.15.0-97-generic/kernel/net/sunrpc/sunrpc.ko{,.bak}
# install:
cd linux-source-5.15.0/
sudo cp -v ./fs/nfs/blocklayout/blocklayoutdriver.ko /usr/lib/modules/$(uname -r)/kernel/fs/nfs/blocklayout/
sudo cp -v ./fs/nfsd/nfsd.ko /usr/lib/modules/$(uname -r)/kernel/fs/nfsd/
sudo cp -v ./fs/nfs/nfs{,v2,v3,v4}.ko /usr/lib/modules/$(uname -r)/kernel/fs/nfs/
sudo cp -v ./net/sunrpc/sunrpc.ko /usr/lib/modules/$(uname -r)/kernel/net/sunrpc/
Исходный код NFS расположен в папках linux/fs/nfs_common
, linux/fs/nfs
, linux/fs/nfsd
, linux/net/sunrpc
. А чтобы подцепиться к ядру с помощью GDB и иметь пошаговую отладку на уровне исходного кода, можно воспользоваться одним из двух способов:
Можно скомпилировать ядро со статически встроенными NFS-драйверами, тогда GDB будет сразу подхватывать символы сам.
Можно поставить пакет с символами из репозитория и подгружать символы вручную, указав путь до пакета и адрес в памяти, куда загрузился модуль драйвера. Если же необходимо внести изменения в драйвер, то компилируем его отдельно, подгружаем в ядро как модуль и используем символы из директории сборки.
Использование внешних символов и стандартного ядра
Настройка хоста:
Создаем список для репозиториев с символами:
bash sudo touch /etc/apt/sources.list.d/ddebs.list
Добавляем репозитории с дебажными пакетами. Вывод lsb_release берём из пункта 1.c
echo "deb http://ddebs.ubuntu.com $(lsb_release -cs) main restricted universe multiverse" | sudo tee -a /etc/apt/sources.list.d/ddebs.list
echo "deb http://ddebs.ubuntu.com $(lsb_release -cs)-updates main restricted universe multiverse" | sudo tee -a /etc/apt/sources.list.d/ddebs.list
echo "deb http://ddebs.ubuntu.com $(lsb_release -cs)-proposed main restricted universe multiverse" | sudo tee -a /etc/apt/sources.list.d/ddebs.list
Импортируем ключи:
sudo apt install ubuntu-dbgsym-keyring
Обновляем список доступных пакетов:
sudo apt update
Устанавливаем символы и исходники:
sudo apt install linux-source-5.15.0
sudo apt install linux-headers-5.15.0-72-generic
sudo apt install linux-image-5.15.0-72-generic-dbgsym
Разархивируем исходники в удобное место. Они лежат тут: /usr/src.
Скачиваем vmlinux из виртуальной машины.
Устанавливаем GDB:
sudo apt install gdb
Запускаем с указанием пути до vmlinuz, который мы скачали из виртуальной машины:
gdb -tui /PATH/TO/VMLINUZ/vmlinuz
Настраиваем окружение GDB, соединяемся с DUT, подгружаем исходники:
set history save on
set history size unlimited
set architecture i386:x86-64:intel
target remote localhost:1234
set substitute-path /build/prefix /actual/prefix
add-symbol-file /path/to/kernel/symbols
Если мы хотим дебажить подгружаемый модуль, то нужно выяснить куда он загрузился на таргете, а потом загрузить по соответствующему адресу дебаг в GDB:
В таргете:
sudo cat /sys/module/blocklayoutdriver/sections/.text
0xffffffffc0bdd000
В gdb:
add-symbol-file /usr/lib/debug/lib/modules/5.15.0-72-generic/kernel/fs/nfs/blocklayout/blocklayoutdriver.ko 0xffffffffc0bdd000
Если всё сделано верно, то при установке breakpoint на символ GDB не должен ругаться, что прямо сейчас его не видно.
В конечном итоге мы получили возможность исследовать исходный код во время работы NFS-клиента и сервера.
Ошибка сервера NFSERR_BADXDR
Цепляем GDB к виртуальной машине, на которой работает MDS и ставим breakpoints на все места в коде обработки запроса LAYOUTCOMMIT, которые возвращают ошибку BAD_XDR. Запускаем тестирование и локализуем проблему:
Оказалось, что сервер не мог распарсить большое число экстентов, когда суммарный размер массива экстентов в RPC-запросе становился больше 4 КБ. Решили, что будем проверять размер массива, а обработку проводить далее порционно и с ручным выделением нужного количества памяти.
Починили, пересобрали, запустили тесты и FIO начал проходить. Добавили опции валидации записанного файла и обнаружили, что файлы получаются битые.
Ошибка клиента file size и потерянные экстенты
Что именно происходит? Внимательно смотрим на ошибки FIO и файлы, и видим, что некоторые блоки не записались и полностью состоят из нулей.
FIO log
…
verify: bad magic header 0, wanted acca at file /mnt/nfs/test00.raw offset 3238002688, length 131072 (requested block: offset=3238002688, length=131072)
…
Принялись изучать код и обнаружили, что в коде клиента некорректно выполнена обработка дерева экстентов. Если из-за недостаточного размера буфера формирование запроса завершилось с ошибкой, то статус подготовленных к отправке экстентов не менялся (они не отмечались снова как необработанные), и во время следующей попытки их отправить эти экстенты терялись.
Кроме того, в запросе некорректно выставлялось поле last_write_offset, которое как раз отвечает в том числе и за изменение размера файла. Немного переработали эту логику и продолжили тестировать.
Null pointer dereference
Но и теперь в коде клиента не все гладко. На ряде клиентских машин можно было наблюдать серьезные сообщения об ошибках в журнале dmesg, исходящие от модуля blocklayout. Проведя детальный анализ, мы выяснили, что на этапе повторного формирования запроса LAYOUTCOMMIT после неудачной попытки разместить в нем все extent-ы, в функции ext_tree_prepare_commit переменная layoutupdate_pages содержит массив указателей, которые еще не были инициализированы. Это никуда не годится, надо исправлять.
Далее, используя механизмы трассировки событий ядра Linux (Linux kernel event traces), мы установили, что процесс накопления «грязных» экстентов идет очень быстро из-за высокой интенсивности операций ввода-вывода. «Грязные» экстенты — это блоки данных, которые в оперативной памяти изменились и ждут, пока их запишут на диск, но физически там еще не сохранены. Когда количество таких «грязных» экстентов превысило объем заранее выделенного для них буфера, система попыталась выделить дополнительную память, чтобы вместить оставшиеся данные для перекодировки и так несколько раз.
Решением этой проблемы стало изменение политики выделения памяти: мы отказались от пошагового подхода к выделению памяти в пользу более агрессивной стратегии, начав выделять память целыми страницами. Такой подход позволил нам более эффективно управлять памятью при большом количестве «грязных» экстентов, устраняя необходимость в многочисленных попытках повторного выделения памяти.
Заметка о Linux kernel event traces
Как уже было сказано, нас интересовал вопрос о том, как можно получать информацию о работе драйвера, когда вывод текстовых логов и тем более остановка исполнения при попадании на точку останова в GDB слишком замедляют работу драйвера и некоторые эффекты становятся неразличимы. Оказывается, в ядре есть встроенный механизм, который позволяет нам добиться задуманного: Linux kernel event traces. Он позволяет получать информацию о ходе исполнения даже без пересборки, а уж если пересобирать драйвер, то можно добавлять и свои события.
Преимущество этого метода в том, что вместо текстового вывода работает запись бинарных структур в специальную область памяти на первом этапе, а на втором, когда мы хотим получить информацию, можно преобразовать бинарные данные в текстовый лог при помощи специального плагина, который собирается вместе с модулем. Управлять событиями можно как вручную, так и при помощи удобной утилиты trace-cmd. Примеры реализации событий можно посмотреть в Gitverse.
Кроме того инструмент позволяет трассировать функции если компилятор не избавился от них либо в процессе оптимизации либо по указанию программиста, например при использовании inline.
Пример запуска trace-cmd:
trace-cmd record -e nfs_* -p function_graph -l disk_* -l bd_*
В этом примере мы запускаем сбор трасс, которые будут состоять из функций, подпадающих под шаблоны disk_* и bd_*. После сбора трассы появится файл trace.dat, который необходимо расшифровать при помощи команды trace-cmd report. Более подробные примеры использования есть в статье дальше.
Превышение MAX_RPC_SIZE в запросе LAYOUTCOMMIT
Очередной запуск тестирования: данные на диске, записанные с помощью FIO, все еще некорректные, а на стороне MDS видим ошибку NFS4ERR_INVAL в трассе Wireshark и RPC: fragment too large в dmesg. После изучения кода стало ясно, что клиент пытается за раз закоммитить все имеющиеся «грязные» экстенты (файлы были изменены клиентом и записаны на диск, но метаданные не обновлены сервером). Периодически экстентов накапливается настолько много, что один RPC становится слишком большим для сервера и возникают описанные выше ошибки. Мы переработали эту систему, и теперь драйвер умеет дробить запрос LAYOUTCOMMIT на куски подходящего всем размера (отправляем несколько RPC вместо одного).
После исправления всех вышеперечисленных багов, pNFS-клиенты и сервер стали работать без очевидных ошибок и мы попробовали нагрузить систему, дабы убедиться, что под нагрузкой ничего не разваливается.
Проверка на стабильность
Мы решили запустить все ВМ разом и создать тем самым большую нагрузку на сервер. В процессе тестирования оказалось, что на некоторых клиентах процесс FIO (и процесс драйвера NFS) зависают при попытке записать первый байт. Нам сразу стало понятно, что виноват клиент: проблема возникает не на всех клиентах, а набор клиентов, испытывающих проблемы, меняется при каждом новом запуске теста. Налицо симптомы какого-то «состояния гонки» (race conditions) в коде клиента, а отлавливать такого рода нестабильные баги особенно сложно.
Race condition в blkmapd
Мы решили подступиться к проблеме следующим образом: будем собирать сразу на всех клиентах отладочные логи, потом выяснять, в каком клиенте произошло зависание, и именно у этого клиента будем забирать логи, сравнивая их с логами успешно отработавших клиентов. Всю эту логику воспроизведения бага мы оформили в виде bash-скрипта, который с помощью Ansible массово рассылает консольные команды клиентам, а на выходе мы получаем готовые логи.
Логи мы собирали одновременно нескольких видов: системные логи syslog и dmesg, события trace-cmd и сетевой трафик tshark.
Сбор логов
Запуск:
echo '' > /var/log/syslog ; for service in rpc nfs nfsd nlm ; do echo 65535 > /proc/sys/sunrpc/${service}_debug ; done
dmesg -wHT </dev/null >/root/dmesg.log 2>&1 &
cd /root/ ; rm trace.dat ; trace-cmd record -p function_graph -l nfs4_* -l nfs_* -l pnfs_* -l bl_* -l add_wait_queue -l rpc_queue_upcall -l remove_wait_queue -l schedule -l remove_wait_queue -l bl_resolve_deviceid </dev/null >/dev/null 2>&1 &
tshark -i enp1s0 -w /root/pnfs.pcap </dev/null >/dev/null 2>&1 &
Здесь даем какую-нибудь нагрузку с помощью fio или dd.
Остановка:
killall -2 trace-cmd ; killall -9 dmesg ; killall -2 tshark
Детектируем поломку:
mount | grep test
Копируем логи:
/var/log/syslog
/root/dmesg.log
/root/trace.dat
/root/pnfs.pcap
Распаковываем trace.dat:
trace-cmd report > trace.log
После перебора разных событий для trace-cmd стало понятно, какой участок кода виноват, Но заглянуть ещё глубже было нельзя потому, что код ядра там состоял преимущественно из inline-функций.
Вот так выглядят логи trace-cmd с зависшим ядром
fio-1251 | nfs4_proc_layoutget() {
fio-1251 | pnfs_layout_process() {
fio-1251 | bl_alloc_lseg() {
fio-1251 | nfs4_find_get_deviceid() {
fio-1251 | nfs4_proc_getdeviceinfo() {
fio-1251 | nfs4_call_sync_sequence() {
fio-1251 | nfs4_xdr_enc_getdeviceinfo();
fio-1251 | nfs4_xdr_dec_getdeviceinfo();
fio-1251 | }
fio-1251 | }
fio-1251 | bl_alloc_deviceid_node() {
fio-1251 | bl_parse_deviceid() {
fio-1251 | bl_resolve_deviceid() {
fio-1251 | add_wait_queue();
fio-1251 | rpc_queue_upcall() {
blkmapd-612 | remove_wait_queue();
blkmapd-612 | remove_wait_queue();
blkmapd-612 | bl_pipe_destroy_msg();
blkmapd-612 | schedule() {
blkmapd-612 | }
blkmapd-612 | bl_pipe_downcall();
blkmapd-612 | add_wait_queue();
blkmapd-612 | add_wait_queue();
blkmapd-612 | schedule() {
fio-1251 | }
fio-1251 | schedule() {
Решили оптимизации ядра не выключать (наша «гонка» могла в этом случае самоисцелиться), а вместо этого интересующий нас участок кода нашпиговали отладочными dprintk(). И после этого суть проблемы стала понятна.
Ядро устанавливало связь с демоном blkmapd через pipefs, чтобы по UUID блочного устройства найти его в системе. Иногда blkmapd отрабатывал свои задачи слишком быстро, до того, как ядро начинало ожидание ответа. Это приводило к тому, что ядро «зависало», поскольку ожидание ответа никогда не заканчивалось. Сбойный участок кода использовал устаревшие небезопасные методы для работы с потоками.
Чтобы проверить эту гипотезу мы просто вставили sleep(100ms) в код blkmapd, чтобы замедлить его выполнение и это сработало! Демон притормаживал, давая возможность планировщику провернуться и ядру установить ловушку на событие. Далее, конечно, нужно было заменить sleep() на что-то поумнее.
Мы обновили код в устаревшем участке используя wait_event_timeout() — рекомендуемый способ ожидать событие с таймаутом. По прошествии таймаута возникает ошибка, которую нужно обработать, но выполнение кода в любом случае продолжается.
На этом наши страдания завершились, баги были выловлены, код хорошо работает, все танцуют.
pNFS 4.1 vs 4.2
Важно отметить, что мы начали работу с версии 4.1, у которой есть свои минусы. Например, в этой версии нет функции allocate() для файлов. Это приводит к большому числу запросов LAYOUTGET, потому что сервер не может знать, какого размера будет файл в итоге, и поэтому выделяет ровно столько места, сколько запрашивается, но не больше. Это сказывается, во-первых, на производительности, а во-вторых, приводит к ошибкам в коде драйверов, которые, похоже, не тестировались ранее в подобных режимах. Как уже было отмечено в предыдущей статье, использование протокола версии 4.2 решает часть наших проблем.
Вот таким вот хэппи эндом заканчивается этот эпос о pNFS. Мы показали некоторые методы и утилиты для отладки модулей ядра Linux, сложности, которые возникали у нас в процессе отладки, и способы их решения. А еще чуть детальнее рассмотрели реализацию pNFS в Cloud.ru. Надеемся, это было полезно, поскольку готовой инструкции, как проворачивать такое, мы нигде не нашли, хотя очень хорошо искали.
Другие статьи в блоге: