Три фикса, четыре ошибки, один файл

Как мы четыре раза неправильно диагностировали зависание на джобе 281 339

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

Напомню контекст: мы небольшой командой пишем на Rust + Vulkan редактор топологий интегральных схем + верификатор (DRC/LVS/Antenna/PEX) с прицелом на российский рынок. Команда — три человека, я в роли CTO направляю архитектуру и принимаю основные решения. В том числе неверные, о которых ниже. Тестовый основной дизайн всё тот же — Caravel SkyWater SKY130: 4,4 миллиона полигонов, 1014 уникальных ячеек, 22 уровня иерархии, 278 МБ GDS (недавно воспользовались прекрасным проектом TinyTapeout — для прогона на различных gds).

К моменту этой истории мы только что закончили перф-кампанию по паразитной экстракции (PEX). Если коротко: чтобы посчитать ёмкости, нужно сначала собрать цепи — обойти иерархию чипа BFS-ом от каждого «сида» (точки на цепи устройства) и выяснить, какие фигуры электрически связаны. На Caravel это 537 748 сидов. Кампания ужала полный холодный прогон с 962 секунд до 70: пространственный грид вместо квадратичного перебора пар, параллельные трейсы на 14 потоках, кеш результата. Все гейты бит-идентичности зелёные, CLI летает.

И вот я открываю GUI, нажимаю «Запустить PEX» — и смотрю, как тот же самый бинарник на том же самом чипе считает девятую минуту.

Симптом

Скорость трейса в CLI — около 13 тысяч джобов в секунду. В GUI — около 1,1 тысячи. Тот же код, та же машина, тот же файл. Прогресс-бар честно показывает «трейс 224 617 / 537 748», время идёт, спиннер крутится.

Дальше — четыре диагноза. Каждый звучал убедительно. Под каждый есть артефакты. Каждый оказался неверным.

Диагноз №1: переменная окружения

Идея. У нас есть рубильник EDA_NET_BUILD_THREADS для отладочных прогонов в один поток. Я сам недавно тестировал им fallback — и вполне мог экспортировать его в шелл, из которого потом запустил GUI. Унаследованный =1 объясняет серийную скорость идеально: код оправдан, виноват шелл.

Версия была настолько правдоподобной, что мы под неё сразу сделали инструмент: количество потоков теперь печатается в стартовой строке лога и прямо в спиннере панели — чтобы misconfig такого класса был виден с одного взгляда.

Инструмент сработал на первом же скриншоте. Следующий прогон: «трейс 224 688 / 537 748 · 14 пот.» — и та же серийная скорость. Четырнадцать потоков, резолв отработал, окружение чистое. Диагноз похоронен собственным памятником.

Мораль №1. Первое, что обязан показывать любой долгий процесс, — свою фактическую конфигурацию. Мы добавили threads в спиннер, чтобы подтвердить диагноз, а пригодился он, чтобы его опровергнуть. Это лучшее, что умеет делать хороший инструмент.

Диагноз №2: планировщик — QoS и хвосты батчей

Идея. Раз потоков 14, а скорость одного — значит, потоки есть, но не работают. Сняли sample с живого процесса. Картина: воркеры на месте, on-CPU, но в переписи нитей у них пониженная полоса приоритета — на Apple Silicon это билет на E-ядра. Плюс нашлась честная структурная проблема: трейс шёл батчами с фиксированными чанками, и батч ждал самый дорогой чанк — пока один воркер дожёвывает кластер тяжёлых сидов, остальные тринадцать уже умерли. В Activity Monitor это выглядело как осцилляция загрузки 336 ↔ 1000%: всплеск полным фронтом, потом три нити доедают хвост.

Сделали два фикса. Work-stealing внутри батча — воркеры разбирают джобы по одному через атомарный индекс, хвост батча сжимается до одного джоба. И вынесли запуск билдов в отдельный долгоживущий поток, созданный до старта оконного цикла, — чтобы воркеры наследовали нормальный QoS.

Результат: work-stealing дал +15% в CLI (трейс 47,7 → 41,5 секунды — настоящий, измеренный выигрыш, который остался с нами навсегда). GUI — без изменений.

Мораль №2. Если фикс улучшил метрику, но не убрал симптом — ты починил что-то другое. Это полезно, и это ловушка: «+15%» очень убедительно шепчет, что ты на верном пути. Хвосты батчей были реальны. Причиной они не были.

Диагноз №3: App Nap

По дороге мы упёрлись в то, что не можем гонять GUI-репродукции скриптами, и сделали хук автозапуска: переменная окружения — и PEX стартует сам после загрузки чипа. Хук немедленно открыл нам неприятное: macOS демотирует GUI-процесс целиком, если его окно не в фокусе и перекрыто. Наши скриптовые прогоны зависали не потому, что баг воспроизводился, а потому что система усыпляла приложение. Кстати, это полноценный продуктовый вывод: пользователь, запустивший двухминутный расчёт и ушедший в почту, получает пятнадцатиминутный. Теперь у нас на время билда стоит assertion активности.

Заодно App Nap стал диагнозом №3 для основного симптома: «окно теряло фокус, процесс душился». Опровергся за один вечер наблюдением с натуры: деградация начинается на ~220-й тысяче джобов и не зависит от того, трогаю я машину или нет. Окно поверх, руки за спиной — ползёт одинаково.

Мораль №3. Наблюдатель влияет на эксперимент: мы как минимум трижды портили замеры, переключаясь в Activity Monitor и закрывая окно подопытного. Долгие GUI-замеры мы теперь делаем так: запустил, отошёл от машины, вернулся к логам.

Диагноз №4: память

Идея. «Быстро стартует, прогрессирует к деградации, фокус не влияет» — классический профиль своп-спирали. Сняли кривые RSS по фазам. Числа выглядели как приговор: на машине 24 ГБ своп хронически занят 7,7 ГБ чужими процессами, свободно ~600 МБ; пик нашей warm-фазы — 6,7 ГБ; плюс GUI-резидент 1,9 ГБ и рендер, конкурирующий за страницы. Я написал в отчёте: «гипотеза подтверждена числом».

Сделали три фикса: потоковую вставку результатов warm-фазы вместо накопления (пик −1 ГБ), троттлинг репейнта во время билда до 10 Гц, компактизацию главной структуры связности — HashMap<слот, нет> заменили на плоский Vec<u32> в обоих местах, где она жила.

Компактизация попутно опровергла собственное обоснование: плато памяти не сдвинулось ни на гигабайт, потому что хешмапы, которые мы оценили в «~1 ГБ накладных расходов», по честной арифметике весили 100–200 МБ. Зато прямая индексация убрала хеширование из горячего цикла и дала новый рекорд скорости CLI — 69,6 секунды. Уже четвёртый раз за историю измерение било красивую атрибуцию, и снова в обе стороны: и мою, и чужую.

А GUI? GUI завис. На джобе 281 339. Я посмотрел на вчерашний скриншот: вчера он завис на джобе 281 339. Цифра в цифру. На параллельном коде с work-stealing’ом, где порядок исполнения недетерминирован.

Мораль №4. «Подтверждено числом» — опасная фраза, если число снято с прокси. Все наши кривые памяти были сняты с CLI-процесса, потому что его удобно мерить. Болел — GUI.

Джоб 281 339

В этот момент мы остановились и сделали то, что нужно было сделать месяцем раньше: таблицу противоречий. Не гипотез — противоречий между уже собранными фактами. Несколько строк из неё:

• «Зависает навсегда» — ни один GUI-прогон никто не ждал дольше таймаута. «Навсегда» никогда не было измерено.

• «Счётчик замер» — а в сэмплах за 7,7 секунды живут ~240 короткоживущих воркеров. Очередь крутится.

• «Память душит» — а воркеры в сэмплах чисто on-CPU, без единой блокировки на page fault, и пиковый footprint пройден и отпущен. Давление так не выглядит.

• Значения счётчика 280 202 / 281 736 / 281 339 существуют только как скриншоты. В stderr они не дублировались ни разу.

И отдельным списком — предположения, которые вся команда считала проверенными, но которые ни разу не проверялись живым замером. Первым пунктом стояло: «GUI и CLI считают с одинаковой конфигурацией».

У нас есть отпечаток конфигурации — хеш карты слоёв и via-связей, по нему ключуется кеш результатов. GUI печатал его в каждом прогоне. CLI печатал cfg=-, потому что в батч-режиме отладочный ключ просто не прокидывался. Полгода два пути жили рядом, и никто ни разу не положил два отпечатка в один diff.

Одна строка кода, чтобы CLI печатал свой cfg. Один запуск:

GUI: cfg=0x85ada0c133767403

CLI: cfg=0xbd85cc678191623b

Разошлись.

Мораль №5. Предположение, которое все считают проверенным, опаснее предположения, которое все считают спорным. Спорное хотя бы проверяют.

Вскрытие

Дальше всё рассыпалось за два дня, как и положено, когда тянешь за правильную нитку.

Полоса, а не стена. Очередной «зависший» прогон мы впервые не убили, а оставили жить. Счётчик полз: 281 339 → 281 826. Полтора-два джоба в секунду. Не зависание — полоса монструозно дорогих джобов.

Арифметика батчей. Трейс идёт батчами по threads × 64 = 896 джобов. 314 × 896 − 5 = 281 339: счётчик замирал ровно на границе батча минус пять недоеденных монстров. Поэтому два прогона на разных запусках показывали одинаковую цифру — это структурная граница, а не случайность.

Имена монстров. Дамп сидов показал: джобы с 200 000 по 281 292 — это сплошняком транзисторные примитивы, 49 217 сидов pfet и 32 076 nfet, на слоях poly и diff. Исторические «точки зависания» легли ровно на хвост этой полосы: 280 202 — poly-сид pfet’а, 281 339 и 281 736 — первые ячейки стандартной библиотеки сразу за полосой.

Механизм. Diff конфигов дал два призрачных ребра связности, которых нет в каноне:

• diff-слой как проводник. GUI собирал карту слоёв не из tech-файла, а из отображаемых имён слоёв интерфейса — всех подряд, включая те, у которых tech-записи нет. Правила связности, сматченные по таким именам, сделали диффузию проводником. Один diff-прямоугольник закорачивает исток и сток транзистора — ровно та опасность, про которую в экстракторе devices лежал предупреждающий комментарий.

• плоскость met3 как «виа». А это уже не код. Рядом с GDS на рабочем столе лежал tech-файл — sidecar, который приложение вежливо подхватывает при загрузке. Файл был старый, с тех времён, когда нумерация слоёв была другой. В его карте каждый провод met3 работал переходным отверстием между met2 и met4.

Сложите: закороченные транзисторы плюс «виа» размером с целую плоскость металла — и весь чип сливается в один мега-блоб. А теперь главное: трейс идёт от каждого сида, и дедупликация «эта цепь уже есть» срабатывает только после обхода. Каждый из 81 тысячи транзисторных сидов честно обходил мега-блоб целиком, до миллионов размещений, прежде чем узнать, что результат уже посчитан. В канонической конфигурации та же зона летит со скоростью 35 тысяч джобов в секунду.

CLI всем этим не болел, потому что строил карту из tech-файла по парам (layer, datatype) — как и было задумано.

Неправильная вселенная

Самое красивое случилось в конце. Тот прогон, который мы не убили, доехал. Впервые в истории проекта GUI-билд завершился — и выдал результат из параллельной вселенной: 2 726 цепей и 17 398,278 фФ против канонических 3 644 цепей и 16 981,134 фФ.

Меньше цепей — потому что ложный мост met2↔met4 сливал нумерацию цепей внутри ячеек, и одинаковые паттерны схлопывались при дедупликации. А дельту +417,14 фФ мы разложили поэлементно: +984,88 фФ площади на li1 (площадь слитого мега-нета учитывается с инфляцией перекрытий), −569,66 фФ периметра там же (дедуп съел границы поглощённых кусков), +1,93 фФ на met1, осевшие в крупнейшей цепи. Поэлементно — потому что вклад poly сошёлся бит в бит в обеих вселенных: 12 177,07 фФ, до последнего знака.

После фикса я сделал контрольный прогон и положил два скриншота рядом. Площадь li1: 1601,66 → 616,78. Минус 984,88. Периметр li1: 314,44 → 884,11. Плюс 569,67. Крупнейшая цепь: 3243,122 → 3241,192. Минус 1,93. Теория, сошедшаяся с экраном до сотых фемтофарады, — редкое удовольствие в отладке.

Фикс

Скучный, как и положено правильному фиксу. Один канонический конструктор карты слоёв — из tech-файла, по парам (layer, datatype), для обоих путей. Отображаемые имена слоёв больше никогда не попадают в конфигурацию экстракции: переименование слоя пользователем не имеет права менять результат верификации. Отпечаток конфигурации пересобран от структур, которые реально влияют на связность. Sidecar-файлы при загрузке теперь сверяются со встроенным пресетом, и при расхождении пользователь видит предупреждение с обоими отпечатками.

И бонус-находка, за которую отдельное спасибо неправильной вселенной: объясняя, почему met2–met5 не вносят ни фемтофарады, мы поняли, что наша оценка ёмкости первого уровня системно покрывает только приборные слои (poly/li1/met1) — это граница метода, которую мы теперь честно документируем, а не открываем случайно.

Цифры до и после

Что я как CTO вынес из этого

Сага заняла около двух недель. Правильный диагноз — после того как мы сели за таблицу противоречий — занял два дня. Соотношение знакомое по прошлой статье, но причина блужданий другая. Тогда мы оптимизировали не ту операцию. Здесь мы проверяли не те утверждения.

Бит-стабильный не значит правильный. У нас образцовые гейты эквивалентности: параллельный код сверяется с серийным до бита, результаты воспроизводятся строково от прогона к прогону. Все были зелёными всю дорогу — потому что они доказывают тождество при одной конфигурации, а не правильность конфигурации. Неправильная вселенная была идеально воспроизводимой. Теперь у нас есть гейт и на саму конфигурацию: отпечатки всех путей обязаны совпадать.

Предположения убиваются живым замером, а не грепом. QoS получил алиби по грепу («в коде никто не понижает приоритеты») — и был пойман живой переписью нитей. «Зависает навсегда» прожило три диагноза, потому что его никто не измерил. Теперь у каждой гипотезы в наших отчётах два обязательных поля: «чем доказано» и «каким живым замером можно убить».

Окружение — часть конфигурации. Файл на рабочем столе молча менял результаты физической верификации. Не код, не настройки, не флаги сборки — файл рядом с данными. Всё, что приложение подхватывает из среды, должно валидироваться на границе и быть видимым в логе.

Наблюдение с экрана — не артефакт. Ключевые значения счётчика неделю существовали только в виде скриншотов и моей уверенности. Когда мы продублировали прогресс в stderr, спорить с фактами стало не о чем. Если число важно — оно пишется в лог, точка.

Неверные диагнозы оплатили себя инструментами. Это, пожалуй, главное утешение: от каждой похороненной гипотезы остался кипер. От окружения — конфигурация в спиннере и стартовой строке. От планировщика — work-stealing на +15% и нормальный поток для билдов. От App Nap — автозапуск для репродукций и assertion активности. От памяти — RSS-метрики в логах и минус гигабайт пика. Похороны были не бесплатными, но и не напрасными.

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