Есть приложение для Mac, которое запускает Windows-игры через слой совместимости: внутри Steam для Windows, игры и всё, что они с собой тащат. Когда человек нажимает «Играть», работу делают чужие программы — клиент Steam, сама игра, её программа отчёта о сбоях. Встраиваться в них нельзя. Видно только то, что снаружи: список процессов, окна на экране и журналы, которые Steam пишет на диск.
Из этого вырастают два вопроса, на которые нужен ответ за секунды, а не за минуты:
-
ничего не происходит — это «медленно» или уже «никогда»;
-
игра упала за пару секунд, а процессы опрашиваются раз в три — как вообще узнать, что она была?
Ниже — замеры, правила, которые из них получились, и ошибки, которые нашлись по дороге.
Условия
Тестовый мак — Mac mini на Apple M6, macOS 27.0. Слой совместимости — версии 10.0, графика D3DMetal 3.0. Клиент Steam для Windows — версия 1794536281. Все времена ниже — из журналов этой машины за 14–15 ноября.
Как было
Пока окно приложения открыто, состояние опрашивается раз в 3 секунды, свёрнутое — раз в 9. После «Играть» приложение ждёт процесс игры. Нет его за 120 секунд — карточка «Игра не запустилась». Если Steam при этом сам поднимается ради запуска, предел 300 секунд. Если в журнале Steam о запуске нет ни слова, на карточке есть кнопка «Перезапустить Steam и играть».
Две минуты — не произвол. Первый запуск игры может строить шейдеры, Steam может обновляться, у человека может висеть окно входа. Но в одном частом случае это две минуты впустую.
Steam жив, а запроса как будто не было
Типичная картина из отчёта о сбое: накануне игра нормально шла, сегодня «Играть» — и тишина. В журнале клиента logs/console_log.txt за этот день нет ни одной строки о запуске. Нет даже ExecCommandLine — так Steam отмечает, что получил команду steam.exe -applaunch . При этом процесс клиента жив.
Лечится это перезапуском Steam, и карточка это знает. Вопрос — можно ли сказать раньше двух минут и не соврать.
Сколько Steam обычно молчит
Для ответа время нажатия «Играть» сопоставлено со строкой ExecCommandLine … -applaunch N в журнале Steam. Холодным считается запуск, после которого загрузчик Steam записал, что клиент стартует (Startup - Steam Client launched with в logs/bootstrap_log.txt). Упрощённо:
execs = stamps("logs/console_log.txt", r"ExecCommandLine: .*-applaunch d+")starts = stamps("logs/bootstrap_log.txt", r"Startup - Steam Client launched with")for launch in launches: # момент «Играть» и appid cold = any(0 <= (s - launch.at).total_seconds() = launch.at] print(launch.at, "cold" if cold else "warm", (min(hit) - launch.at) if hit else None)Steam к моменту «Играть»
запусков
от «Играть» до записи в журнале
уже открыт
11
0 с — десять раз, 1 с — один раз
поднимается ради запуска
6
8, 8, 8, 11, 45, 125 с
Открытый клиент записывает команду в ту же секунду. Поднимающийся — когда сможет, и разброс огромный. Откуда 125 секунд, не выяснено.
Правило: длиннее одной строки
Напрашивается «нет записи 30 секунд — Steam завис». С таким правилом карточка «Steam завис» вылезала бы в нескольких безобидных случаях. Поэтому ранний отказ срабатывает только при всех условиях сразу:
-
программа-посыльный
steam.exe -applaunchуже передала команду и вышла с кодом 0. Если посыльный ещё жив, это он сам стал клиентом, то есть Steam не был открыт и старт холодный; -
Steam не ждёт входа и не обновляется;
-
процесс клиента запущен хотя бы за минуту до «Играть»;
-
игра из Steam. Почему это отдельный пункт — ниже.
В коде (сокращено):
if silence == .notReceived, messengerStatus == 0, !steamBusy, let since = steamClientSince, requestedAt.timeIntervalSince(since) >= Self.steamClientSettled { // 60 с self.steamSilence = silence?.note fail(Self.noProcessDetail(limit: Self.steamSilenceGrace, silence: silence), now: now) // 30 с return}Если игра всё-таки появится позже, ошибка снимается: окно «позднего старта» осталось прежним.
У второго условия есть дыра, о которой стоит сказать прямо. «Steam ждёт входа» приложение знает надёжно только для новой бутылки. Если человек входил раньше, а сессия истекла, окно входа так не распознаётся, и вместо двух минут он через 30 секунд увидит «Steam молчит». Поэтому текст карточки начинается с «если Steam просит войти — войдите», и только потом предлагает перезапуск. Настоящая починка — следующая версия.
Тесты, которые проверяют сами себя
На каждое условие — отдельный тест. А чтобы тест не проверял что-то не то, каждое условие по очереди удалялось из кода: тест обязан упасть. Таких «мутантов» четыре — посыльный, занятость Steam, минута с запуска клиента и «игра из Steam». Все четыре тесты поймали.
Что нашло ревью перед выпуском
Перед выпуском код читали отдельно, без моих рассуждений перед глазами. Нашлось то, что тесты не ловили. У игр из Epic номера отрицательные, и Steam о них не пишет ни строчки. В бутылке, где открыт Steam, запуск Epic-игры получал бы «Steam завис, перезапустите Steam» — про игру, к которой Steam отношения не имеет. Хуже: на 120 секундах эта ошибка жила и раньше. Правка — проверка appID > 0 до любых выводов о Steam, и тест на отрицательный номер.
Как проверить, не дожидаясь настоящего зависания
Зависание Steam по заказу не воспроизвести, но его можно изобразить: остановить процесс клиента сигналом.
kill -STOP # процесс жив, но не отвечает# нажать «Играть» и смотретьkill -CONT Прогон 15 ноября, клиент открыт около 35 минут:
-
13:27:16 —
SIGSTOP, 13:27:17 — «Играть»; -
снимок через 20 секунд: обычное «Steam запущен, ждём игру»;
-
снимок через 33 секунды: карточка про молчание Steam. Появилась она где-то между этими двумя снимками, опрос раз в 3 секунды;
-
13:28:36 —
SIGCONT: клиент ожил, а игра за следующую минуту так и не стартовала.
Через 20 секунд — ещё ждём
Через 33 секунды — карточка
Это один прогон, и SIGSTOP — не то же самое, что настоящее зависание. Но одна деталь из него важна: здесь отложенный запрос после «разморозки» не исполнился. Если бы он исполнялся, ранний отказ был бы вреден — человек жал бы «Перезапустить» поверх уже стартующей игры.
Игра упала быстрее, чем на неё посмотрели
Scrap Mechanic на тестовом маке падает при старте. Посекундный список процессов (в ps процесс игры виден как Program):
08:59:29 52762:Program08:59:30 52762:Program08:59:31 52856:BsSndRpt64.exeИгра живёт около двух секунд и запускает BugSplat — программу с окном «отправить отчёт о сбое». Опрос раз в 3 секунды застаёт игру не всегда: 14 ноября застал дважды, 15 ноября три раза подряд промахнулся. Когда промахивался, человек видел «игра не запустилась за 2 минуты», хотя она запустилась и упала. А окно отчёта оставалось на экране: убирать его приложение умело только после сессии, которой с его точки зрения не было. 14 ноября это окно закрыли руками через три с половиной минуты.
Чей это отчёт
Чтобы связать программу отчёта с игрой, обычно хватает пути в её командной строке — он ведёт в папку игры. BugSplat запускается голым именем:
BsSndRpt64.exe /i C:users…TempBsSndRpt.iniПути нет. Зато рабочая папка процесса — папка игры, и macOS отдаёт её без особых прав:
var info = proc_vnodepathinfo()let size = Int32(MemoryLayout.size)guard proc_pidinfo(pid, PROC_PIDVNODEPATHINFO, 0, &info, size) == size else { return nil }let path = withUnsafeBytes(of: info.pvi_cdir.vip_path) { String(cString: $0.baseAddress!.assumingMemoryBound(to: CChar.self))}Этот вызов делается только для процессов, похожих на программу отчёта и запущенных без пути.
Правило
Запуск ещё ждёт игру, а в папке игры появилась программа отчёта о сбое, поднятая не раньше нажатия «Играть», — значит, игра стартовала и упала. Запуск заканчивается словами «вылетела на старте», а окно отчёта через минуту закрывается: минута — чтобы BugSplat успел записать дамп.
Карточка вылета на старте
На тестовом маке правило сработало все три раза из трёх. В двух замерах окно отчёта закрылось через 60 и 63 секунды после появления.
Цена этого правила тоже есть. Окно закрывается через минуту, даже если человек в этот момент пишет в нём что-то разработчику игры. Так было и раньше, для отчётов после обычного падения. Не исправлено.
Две ошибки, найденные по дороге
Точность времени. В коде появилось «выравнивание по целой секунде» с комментарием: время старта процесса якобы приходит из ps, а там секунды. На деле время берётся из proc_bsdinfo — поля pbi_start_tvsec и pbi_start_tvusec, то есть с микросекундами. Выравнивание было лишним, комментарий — неверным. Убраны оба.
Чужой отчёт от прошлого падения. Это опять нашло ревью, и это сценарий из чтения кода, а не случай из жизни. Игра упала, человек сразу жмёт «Играть» ещё раз, а BugSplat от первого падения поднимается через пару секунд — уже после нового нажатия. По правилу новый запуск немедленно объявлялся бы вылетом, хотя игра только стартует. Теперь программа отчёта, появившаяся в течение 10 секунд после конца прошлого запуска той же игры, относится к прошлому.
Попутно: у Windows-процесса в слое совместимости нет нормального родителя
Хотелось закрывать зависший установщик вместе со всеми потомками по родительскому PID. Наблюдение такое: steam.exe, запущенный приложением, — его ребёнок, а steamwebhelper.exe, которого запустил уже сам Steam, — ребёнок launchd с ppid 1. Значит, по Unix-родителю дерево Windows-процессов не собрать.
Пришлось закрывать установщик по признакам: его собственный файл, служебный процесс повышения прав, msiexec.exe, процессы из папки Temp. И только те, что поднялись после запуска установщика. Без последнего условия отмена установки закрыла бы игру, которую человек в это время запустил в той же бутылке. Это тоже нашлось на ревью.
Что из этого можно унести
-
Таймаут для чужой программы — замер, а не круглое число. За «двумя минутами» прятались два разных мира: 0–1 секунда у живого клиента и до 125 у поднимающегося.
-
Ранний отказ — это перечень условий, при которых молчание точно не безобидно. На каждое — тест и мутант.
-
Зависание можно изобразить
SIGSTOP/SIGCONT. Заодно видно, теряется ли отложенная работа после «разморозки». -
Если опрос реже, чем живёт процесс, ищите его следы: программы отчёта о сбоях, рабочие папки, журналы.
-
Чтение кода «без автора за плечом» перед выпуском. Три из четырёх ошибок в этой истории нашлись именно так.
Ограничения: один тестовый мак, одна игра для падения на старте, Steam для Windows под слоем совместимости. Для других лаунчеров цифры будут свои — но снимаются они тем же способом. Если у вас есть лаунчер, чьё поведение интересно измерить так же, — напишите в комментариях.
Источник: habr.com