Пошли мы как-то с коллегой на охоту…

Давно я про отладку не писал. Так вот пошли мы как-то с коллегой на Багов охотится. Вышли мы на двух таких матерых, опытных Багов. Их и помотали они нас…

Баг первый.

Захотел мой коллега странного. Хочу, говорит, поддержу USB flash stick на той обрезанной под корень версии Windowы, что мы пользуемся для своих нечеловеческих экспериментов. И не просто поддержку USB stick, но с NTFS на нем. Оказалось, впрочем, что нет ничего проще – достаточно добавить ntfs.sys в образ системы и все должно заработать само собой. Сказано – сделано. Но не работает. Вместо обещанной поддержки, система перестала видеть все USB устройства.

Странно. Коллега сразу же схватился за ружье отладчик и давай копаться в коде PnP. На его беду у него как раз протухли права доступа к исходному коду Windows, а товарищ, ответственный за их раздачу как-то не во время ушел в несознанку. В общем, пока тянулась эта эпопея, процесс отладки несколько усложнился. Тем не менее, через некоторое время коллега добрался до многозначительного сообщения: «Cannot load the configuration file X».

Оказалось, правда, что это просто код пытается вывести юникодную строку с именем файла с помощью ANSI версии printf. «X» был просто первой буквой имени файла. Этот файл был конфигурационный файлом одного из USB устройств. Очевидно, - первым USB устройством, до которого добирался код PnP, после чего все затыкалось. Конфигурационный файл, естественно не менялся со времен царя Гороха. Да и отношения к NTFS никакого не имел.

На следующий день раскопок выяснилось, что вызов ReadFile для чтения этого файла возвращает ошибку ERROR_SECTOR_NOT_FOUND, стоит только добавить ntfs.sys в образ системы. Уже ближе. NTFS, конечно может иметь отношение к ReadFile, однако ntfs.sys даже еще не был загружен в момент возникновения ошибки.

Поиск по исходникам Windows показал, что ошибка ERROR_SECTOR_NOT_FOUND возвращается в случае, если номер сектора превышает общее число секторов на диске. Отследив IRP, коллега выяснил, что драйвер CDFS и драйвер RAM disk не сошлись в оценке размера диска. По версии CDFS диск был на мегабайт больше.

В этот момент пришло озарение. Система грузится из ISO образа, который в процессе загрузки перекладывается на RAM disk для того, чтобы сделать его доступным для записи. Несколькими месяцами ранее мы обрезали размер RAM disk до минимума, чтобы освободить максимум памяти. А размер ntfs.sys – полтора мегабайта. В результате размер ISO получается больше чем может поместиться на RAM disk. А конфигурационный файл случайно оказался в самом конце диска.

Баг второй.

В данный момент я портирую Helios на одну интересную аппаратную платформу. Значительная часть этой работы – адаптация механизма передачи сообщений под эту платформу. И вот в какой-то момент я понимаю, что передача сообщений наконец-то заработала как надо. Осталось доделать пару косметических изменений, которые я откладываю на следующий день. Естественно на следующий день эта пара изменений ломает все к чертовой матери.

Начинаю выяснять что к чему. По симптомам похоже, что пакет портится при передаче. Включаю режим “DMA paranoia”, т.е. режим вычисления и проверки контрольных сумм при передаче. Там в коде забавный комментарий, кстати:

Optional DMA Paranoia, because we had an offset wrong once…

Опциональная DMA паранойя, так как мы однажды уже посчитали смещение неправильно…

Параноидальная проверка подтверждает - пакет портится. Не понятно, правда, почему.

Добавляю вывод отладочной информации, показывающий состояние очереди и первые 16 байт пакетов при передаче и приеме. Ясности это не добавляет. Все выглядит прилично. Указатели пересчитываются именно так как должны. Данные передаются правильно. Повторяю эту процедуру несколько раз: добавляю больше отладочного вывода, медитирую, убеждаюсь что все работает как и должно, но пакеты портятся.

Наконец замечаю, что порча пакетов происходит прямо во время приема очередного пакета. Т.е. сначала я вижу строчку о том, что пакет с такими-то полями получен, а потом я вижу сообщение об испорченном пакете, которое выводит следующий метод, обрабатывающий этот же пакет. «Наверное это потому, что данные пакета пишутся в память асинхронно», - думает голодный мозг по дороге на обед. «Фиг вам, там все синхронизировано в нужных местах», - отвечает сытый мозг по дороге с обеда.

Наверное, это указатели пересчитываются неправильно. Разные ядра видят куски сообщений по разным адресам. При передаче эту указатели пересчитываются. Вывожу все указатели в лог, но указатели пересчитываются правильно.

Но кто же, все-таки, переписывает данные? Фильтрую все операции копирования памяти из логов и загружаю в Excel чтобы посмотреть нет ли перекрытия. Есть перекрытие! Похоже, что ошибка кроется где-то в районе обработки wrap around, - там где указатели переходят из начала очереди в конец.

Загружаю историю состояний указателей очереди в Excel и вижу, что одно из восьми ядер показывает аномальное значение указателя начала очереди, которое нарушает монотонность ряда. Значение правильно выровнено, - значит это ошибка в вычислении указателей очереди. Реконструирую историю значениё этого указателя по всем восьми ядрам. Получается, что это значение туда никто не писал.

Я очень редко ухожу с работы позднее 5-ти. Не смотря на ZBB, дедлайны и проч. В этот раз я задержался до семи вечера. Но недаром говорят, что утро вечера мудренее. Следующим утром, надевая носки на лестнице (извините за подробности), прихожу к выводу, что это больше похоже на аппаратную проблему. Проверить это очень просто, достаточно завести две копии каждого указателя и проверять их на совпадение. Делаю пробный запуск и точно – чтение указателя из памяти иногда возвращает неверное значение.

А дальше был интересный разговор с производителем железки и прочие скучные подробности.