Семь неверных теорий и одно чтение регистра: потерянное прерывание RTL8125

Сервер, который докладывает через то, что сломалось

Hetzner EX44 — одна из трёх реальных машин, на которых загружается nos: Raptor Lake на 20 потоков, без последовательного порта и без IPMI. Единственная консоль у него — сеть, а сеть — это Realtek RTL8125 с драйвером на Rust. Модели этого чипа в QEMU нет, так что до первой загрузки на этом сервере drivers/r8125 ни разу не работал на железе, для которого был написан (подробнее о машине).

Сервер уже дважды зависал под нагрузкой не тяжелее трафика UDP-шелла. Потом мы дали профайлеру материал для работы — netload, UDP-мишень, которая отвечает эхом на каждую датаграмму прямо из receive softirq, а в режиме sink просто её выбрасывает. С этого момента машина глохла по требованию: ядро продолжало работать и передавать, но не принимало больше ни одного пакета.

Для такой машины хуже бага не придумать. Любой канал, через который она может что-то сообщить (шелл, ping, netconsole), требует, чтобы пакеты приходили или уходили, поэтому лог, обрывающийся на NetLoad: started, может означать и зависшее ядро, и вполне живое, которому просто больше нечего сказать. Так что одним из первых изменений стал не фикс, а пульс (064b222): пока идёт нагрузка, мишень раз в секунду пишет строку в трассу, а netconsole, которому нужна только передача, выносит её наружу. Строки продолжали приходить — значит, ядро живо, умер только приём. Счётчик кадров «в полёте» в этих строках дорос до 257 — всё кольцо плюс один — и замер.

Семь теорий, выведенных из кода

Правильному объяснению предшествовали семь неправильных, и под каждое был свой коммит. Вот некоторые из них.

ARP внутри обработчика приёма. Мишень отвечала через SendUdp, а тот при промахе ARP-кэша засыпает на срок до трёх секунд — прямо в пути приёма. Это настоящий баг, и его исправили ответом из принятого кадра с переставленными адресами (8285944). Но зависание вызывал не он.
Исчерпание пула кадров. Под нагрузкой в QEMU пул не промахнулся ни разу, но запас и параметр загрузки всё равно получил (2e2863a).
Путь передачи. В режиме sink, который ничего не передаёт, машина всё равно глохла на 350 пакетах в секунду. Два прогона с эхом вернули 271 и 358 датаграмм, прежде чем замолчать, — примерно одно кольцо приёма (064b222).
Потерянное пробуждение, которое некому восстановить. На кольцо смотрел только receive softirq, а поднимал его только обработчик прерывания. Мы добавили опрос приёма в тик, чтобы потерянное пробуждение стоило десять миллисекунд, а не весь оставшийся аптайм (f0b3c93). На EX44 зависание после этого стало наступать раньше, за считаные секунды, и опрос спрятали за rxpoll=on, по умолчанию выключенный (91e2968).
Обработчик, который не поднимает softirq. Сначала пришлось чинить сам инструмент: irqstat показывал ноль прерываний MSI-X на машине, только что принявшей тринадцать тысяч пакетов, потому что этот счётчик никто не увеличивал (cb0aec7). Затем обработчик стал поднимать receive softirq на каждом прерывании, независимо от битов статуса (0e1d680).
Переполнение FIFO, после которого приёмник надо перезапускать. Следующий прогон продержался 182 секунды и 44 000 пакетов — и всё равно встал. Мы начали считать биты ошибок приёма и трассировать первые десять (f1e3446). Сюда нас привело неверное имя: оба драйвера Realtek называли бит 4 статуса RX_OVERFLOW, хотя это RDU, «Rx Descriptor Unavailable». Имя вело прямиком к вендорскому рецепту от переполнения — перезапуску приёмника — и стоило полного круга сборки, загрузки и чтения логов (c77280d).

Трасса так ни разу и не сработала, а следующий прогон встал через 276 пакетов и две секунды. Коммит, который это зафиксировал, и стал точкой, где поменялся подход (94e035c):

Разброс в сто шестьдесят раз между прогонами одной и той же нагрузки — это не насыщение, это гонка, а 182-секундный прогон, который я назвал трёхкратным улучшением, был одним замером, принятым за тренд.

Все неверные объяснения были выведены из того, что, судя по коду драйвера, должно было делать железо. Машина пережила зависание, и в неё всё ещё можно было вводить команды. Поэтому вместо очередной догадки тот же коммит добавил nicdump — команду, которая спрашивает состояние у самого чипа.

Что сказал чип

nicdump печатает регистр команд, статус и маску прерываний и то, кому принадлежит головной дескриптор приёма. Бит 3 регистра команд — это приёмник: если бы чип его выключил, никакая возня с дескрипторами не вернула бы приём, а ни одна из догадок этого не проверяла. На зависшей машине вывод был такой:

cmd 0xC  rx-en 1 tx-en 1
isr 0x40D5  imr 0x7F
rx head 194  posted 1  own 0

Приёмник включён. Головной дескриптор принадлежит драйверу: чип записал в него корректный кадр длиной 558 байт и вернул его, а драйвер так его и не забрал. Под маской выставлены четыре бита статуса — ROK, TOK, RDU и переполнение FIFO приёма, — и ни один не подтверждён. Обработчик подтверждает статус при каждом запуске, значит, с тех пор он не запускался ни разу. Два снимка ps с интервалом в пять секунд показали, что все двадцать задач softirq спокойно крутятся. Ничего не зависло — прерывание просто не пришло (6c5411e).

Почему прерывание не пришло

INTR_STATUS сбрасывается записью единицы (write-1-to-clear). Чип посылает MSI-X, когда status & mask переходит из 0 в 1, и это переход регистра целиком, а не каждого события в отдельности. Обработчик читал статус один раз и записывал обратно то же самое значение:

read status         -> ROK
[chip sets TOK]        aggregate already non-zero: no message sent
write status (ROK)  -> ROK cleared, TOK still set
return                 TOK set, mask open, nothing pending, nothing
                       ever coming -- the aggregate cannot go 0->1
                       again because it never went back to 0

С этого момента каждое новое событие лишь добавляет бит к статусу, который и так ненулевой, и чип не посылает ничего. Окно — несколько инструкций; при трёхстах событиях в секунду в него рано или поздно попадаешь, поэтому одна и та же нагрузка вставала то через 276 пакетов, то через 44 000. Это же объясняет каждый неудавшийся фикс: поднимать softirq на каждом прерывании бесполезно, когда прерываний нет; трасса ошибок молчала, потому что обработчик не запускался; опрос из тика не помог, потому что сообщение чипа уже было потеряно.

Обиднее всего, что эту гонку мы заметили на четырнадцать часов раньше. Коммит, добавивший опрос из тика, перечисляет её среди находок — «обработчик подтверждает статус, записывая обратно прочитанное слово, и теряет любой бит, который чип выставит в промежутке», — и оставляет как есть, «потому что опрос делает проигрыш этой гонки переживаемым, а это свойство ценнее». Запасной путь был разумной идеей, но баг сидел именно в гонке.

Исправление: выходить только из нуля

Теперь обработчик работает в цикле: подтверждает прочитанное, делает работу, читает снова и возвращается, только когда в регистре не осталось ни одного разрешённого бита. Из этого состояния следующее событие будет переходом 0→1, о котором чип сообщит. Вот как обработчик выглядит сегодня, после работы над NAPI в тот же вечер:

fn isr(dev: &'static R8125Device) {
    let regs = &dev.regs;
    // ...
    const MAX_ROUNDS: u32 = 32;
    let mut round = 0;

    loop {
        let mask = regs.read32(INTR_MASK);
        let status = regs.read32(INTR_STATUS);

        if status == u32::MAX {
            /* All-ones is what a vanished device reads back, not a status
             * with every event set at once. */
            return;
        }

        if status & mask == 0 {
            return;
        }

        regs.write32(INTR_STATUS, status);

        // ... link change, error counters, the transmit softirq ...

        dev.arm(mask & !RX_INTR_BITS);
        softirq::raise(softirq::TYPE_NET_RX);

        round += 1;
        if round >= MAX_ROUNDS {
            regs.write32(INTR_STATUS, u32::MAX);
            return;
        }
    }
}

Две детали здесь намеренные. Цикл выходит по status & mask, а не по status: пока опрос держит источники приёма замаскированными, выставленный бит приёма прерывания не вызовет, и ждать его сброса означало бы крутиться, пока идут пакеты (44cb4eb). А ещё цикл ограничен 32 итерациями, после которых весь регистр подтверждается разом. Работа при этом не теряется — softirq поднимаются на каждом проходе, — а статус, который не затихает за 32 итерации, принадлежит чипу, который устроит шторм прерываний в любом случае. RTL8168 — то же семейство и тот же регистр — имел ту же дыру и получил тот же цикл.

Тем же днём прогнали «лестницу» нагрузки от 500 до 30 000 пакетов в секунду, и коммит констатирует: «теперь он переживает всё это, чего ещё утром не мог» (c8c99df). А к концу дня EX44 принимал 971 310 пакетов в секунду с 64-байтной полезной нагрузкой на одном ядре (cb81e68).

Тот же фронт в новых местах

По сути этот баг — правило обращения с одним регистром, и обработчик был не единственным кодом, способным это правило нарушить. Когда кольцо пустеет, NAPI-опрос снова разрешает источники приёма. Если сделать это, пока в статусе остаются биты приёма, status & mask уже ненулевой, и никакой следующий пакет не даст перехода 0→1. Ревью опроса нашло ровно это: «та самая форма потерянного фронта, из-за которой машина целый день была глухой, — снова, в новом месте» (ea6595b). Теперь опрос сначала очищает статус, потом разрешает источники и после этого ещё раз заглядывает в кольцо:

            /* Clear what the chip has reported, so the next packet is a
             * transition rather than an addition to a status already set. */
            self.regs.write32(INTR_STATUS, RX_INTR_BITS);
            // ...
            if !ring.has_work() {
                /* Empty: hand the ring back to the interrupt. */
                self.arm(INTR_MASK_BITS);

                /* Re-checked after arming. A packet landing between the
                 * harvest above and the write to the mask register was
                 * already counted in the status cleared at the top of this
                 * round, so nothing would come for it. */
                if !ring.has_work() {
                    return;
                }

                /* Raced: it is ours to take, so go silent again. */
                self.arm(INTR_MASK_BITS & !RX_INTR_BITS);
            }

Через день Intel I210 на другом сервере устроил шторм прерываний по обратной причине: в режиме MSI-X его регистр причин прерывания чтением не сбрасывается. Коммит с исправлением так прямо и пишет: «тот же урок, что преподала карта Realtek и который этот драйвер не усвоил: подтверждай явно, а не полагайся на сброс при чтении, определения которого ты не читал» (702753e; вся история — в статье «Десять мегабит на гигабитном линке»).

Что не даёт этому снова стать тихим

Ни RTL8125, ни RTL8168 никто не эмулирует, так что ни один гейт в дереве не поймает этот класс багов на них. Изменение в любом из двух драйверов проверяет компилятор, а затем EX44, у которого единственная консоль — эта самая сетевая карта (о тестировании). После того дня остались инструменты: nicdump, irqstat, который теперь считает прерывания Rust-драйверов, счётчики ошибок приёма и пульс через единственный канал, который выживает.

Опрос из тика остался запасным путём за rxpoll=on (параметры ядра). Через две недели его переключатель молча перестал работать: при переносе сетевого слоя на Rust тик подключили напрямую к опросу, у которого переключателя не было, и опрос стал срабатывать на каждом тике. Скорости держались, но на AX41 флуд занимал по 70% каждого из двух CPU там, где раньше хватало одного. Теперь переключатель живёт в самом DeviceTable::poll_rx (исходник), а netload-test.py проверяет его в обе стороны — при загрузке без него и с ним, — потому что переключатель, сломанный в любую из сторон, выглядит как успех (5eb5535).

Сервер, который докладывает через то, что сломалось#

Семь теорий, выведенных из кода#

Что сказал чип#

Почему прерывание не пришло#

Исправление: выходить только из нуля#

Тот же фронт в новых местах#

Что не даёт этому снова стать тихим#