10 июня 2024 г.

Отладка через статистику

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

Это придает разработке непривычный, но и очень интересный аспект: миллионы пользователей, причем десктопных – это огромное разнообразие и hardware/software конфигураций, и сценариев работы. В этом множестве комбинаций конфигураций и сценариев работы случаются самые странные и неочевидные ошибки – некоторые из них очень сложно воспроизвести. Тем более сложно, что диагностика, которую удается получить от пользователей, обычно довольно скромная.

Этим ситуация сильно отличается от in-house разработки, которой я занимался в DB: там разнообразие конфигураций было очень мало – наши приложения работали всего на нескольких десятках серверов, с хорошо известным, high-end железом и софтом, с минимальным различием между тестовым и рабочим окружением, под присмотром квалифицированных админов, с очень-очень подробными логами всего и вся. Сложновоспроизводимые ошибки случались и здесь, но все-таки их было не так много – обычно по логам удавалось довольно неплохо сообразить, что и где пошло не так.

Однако в этом месте вступает в игру второе отличие JB: поскольку аудитория многомиллионная, и часть аудитории разрешает IDE отправлять нам всякую статистику – в частности, автоматически репортить происходящие ошибки – то даже самые редкие ошибки репортит более чем один человек. Сильно более, чем один человек. И иногда причину можно вытащить (или подтвердить) статистическим анализом.

Конечно, иногда никакого статистического анализа не нужно: вот стактрейс – пошел, да исправил. Но я говорю о тех случаях, когда пялишься на стактрейс часами, не веря своим глазам: как, черт подери, вот здесь могло получиться вот так?

Свежий пример: есть сторадж, реализованный поверх memory-mapped file. Файл расширяется и мэппится в память крупными кусками, а заголовок файла хранит offset последней реально аллоцированной записи. После этой последней записи в файле должны быть только нули – я принудительно заполняю нулями каждый новый кусок файла перед тем, как отобразить его в память.

Но это сухая теория, а древо жизни всегда найдет, как стукнуть яблоком по голове: сразу же после введения в строй нового стораджа стали приходить ошибки, когда при добавлении новой записи обнаруживается, что в этом месте уже записан какой-то мусор – хотя должны быть только нули.

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

Прошло несколько месяцев, я написал кучу дополнительных тестов, runtime-проверок, и исключил ряд гипотез: ошибки многопоточности, использование стораджа >1 процессом IDE, и так далее – все эти версии отпали.

Гипотеза, которая пришла мне в голову последней: может, это последствия падения (нештатной перезагрузки) ОС?

В рамках этой гипотезы ошибки возникают так: offset последней записи отмечается и сохраняется в заголовке. Заголовок – самая часто читаемая/обновляемая часть файла, поэтому страница виртуальной памяти с заголовком чаще всего будет "горячей" в файловом кэше ОС.

Поскольку заголовочная (=первая) страница горячая в кэше, ОС редко будет ее из кэша вытеснять – а значит и редко будет ее сохранять на диск. А вот остальные страницы файла сильно менее горячие в кэше, чем заголовочная – поэтому их ОС будет вытеснять из кэша чаще, и при вытесении они будут чаще сохраняться на диск.

Такая разница в частоте сохранения не важна, пока ОС стабильна: eventually, все данные из памяти будут сохранены на диск. Но вот если ОС внезапно падает, то она не сохранит текущие страницы файлового кэша на диск. И в этом случае сохраненная на диске версия заголовочной страницы скорее всего будет более старой, чем сохраненные версии остальных страниц.

Так и может получиться, что в заголовке лежит lastAllocatedOffset=10000, но на самом деле перед падением ОС были уже созданы и заполнены записи 10000..10014, и страницу с этими записями ОС успела вытеснить из кэша, и сохранить – а вот заголовочная страница с обновленным lastAllocatedOffsetID=10014 осталась в кэше, и потому сохраниться не успела. И теперь, после перезапуска, мы пытаемся создать новую запись #10001, и видим, что на ее месте уже лежит какой-то мусор – который не выглядит как мусор, а выглядит как реальная запись.

…Это только гипотеза – звучит реалистично, но единственное свидетельство в ее пользу это то, что мусор выглядит похоже на реальные записи.

Как получить более прямое свидетельство в пользу этой гипотезы1? Гипотеза предсказывает, что "мусорные" данные могут возникать только за границами первой страницы. Если такая закономерность правда есть, ее сложно объяснить чем-то, кроме эффекта на уровне ОС: в коде стораджа размер страницы виртуальной памяти нигде не фигурирует. Кроме того у Intel и Apple Silicon разные размеры страниц по-умолчанию: 4к и 16к – и это различие, если оно действительно проявится в данных, будет еще более сильным аргументом.

К счастью, в тексте ошибки есть информация об offset, где обнаружился мусор. Так что я распарсил все отчеты об ошибках – коих накопилось уже тысячи – и построил гистограммы значений garbage offset в разрезе по ОС.

И да, мусор действительно никогда не появлялся на первой странице – зато уже на второй странице такие записи встречаются. И да, на MacOS есть два пика на гистограмме garbage offsets – на 4к и на 16к – что как раз соответствует размеру страниц Intel/Apple Silicon. На Windows аналогичного пика на 16к нет 2.