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.
…Любопытный момент: минимальный оффсет мусорной записи, который встречается в сообщениях об ошибках – 4080, что чуть-чуть, но меньше размера страницы (4096) – то есть такие записи все-таки начинаются на первой странице. Казалось бы, это опровергает гипотезу? Но если посмотреть внимательно на сообщения об ошибках для таких записей (их всего 5 штук в выборке, так что я их просто отсмотрел глазами) то оказывается, что мусор там был обнаружен только в самых последних байтах записи – и эти последние байты уже попадают на вторую страницу! То есть на самом деле это лишнее подтверждение гипотезы.
Этот пример хорошо иллюстрирует различие контекстов: в DB если бы наш сервер внезапно перезагрузился – мы бы об этом быстро узнали по логам, и не было бы никакой загадки в странном состоянии стораджа после такой перезагрузки.
В JB мы не можем знать, у кого из миллионов пользователей падает ОС. Даже если есть возможность спросить у пользователя – оказывается, что пользователи и сами не всегда об этом знают – а возможность спросить есть не всегда, большинство отчетов об ошибках анонимные. Поэтому приходится искать способы по косвенным признакам понять, что же произошло, где это чинить, и надо ли вообще чинить.
Последний год процентов 20 моего рабочего времени занимает такое вот копание в данных. Это довольно непривычно, хоть и очень интересно – и очень затягивает.
Примечания
Конечно, самый простой способ проверить гипотезу об источнике ошибки – исправить ошибку. Но потерю данных при падении ОС – не так-то просто исправить, мне не хочется ввязываться в разработку самодельной базы данных.↩︎
Линукса нет на графиках, потому что с него мало репортов – слишком мало для статистики. То есть на линуксе тоже нет мусорных записей в пределах первой страницы – но там и нет такой красивой группировки записей в начале второй страницы.↩︎
Комментариев нет:
Отправить комментарий