FPS не падай, девайс не грейся

от автора

В октябре 2020 года в техническую поддержку Авито стали обращаться пользователи с проблемами нагрева девайса и просадками FPS вплоть до полного фриза iOS-приложения. Проблема, как казалось, была глобальной. Она не относилась к какой-то конкретной функциональности приложения и поэтому не подходила в бэклоги продуктовых команд. Выход был один: засучить рукава и самому разобраться, что пошло не так. Не даром же я performance engineer.

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

Сигналы из космоса

Жалобы на лаги в основном были связаны с экранами выдачи и карточки объявления. Это два самых популярных экрана в приложении. По статистике, если что-то происходит на них, то это происходит во всем приложении глобально. Неудивительно, что счётчик обращений быстро рос.

От одного из пользователей поддержка получила такое видео:

В глобальности крылась основная проблема лично для меня. Если всё так, то где искать баг в огромном приложении Авито? У нас больше 200 экранов, куча демонов, фоновых процессов, БД для мессенджера, логирование аналитики и это ещё не конец. Произойти могло что угодно и где угодно. Например, какой-то не удалившийся вовремя из памяти экран мог начать потреблять ресурсы процессора. Или что-то начинало бесконечно перерисовываться.

Вариантов рождалось бесконечное количество. Загвоздка в том, что воспроизвести проблему не получалось ни у меня, ни у коллег. В один момент мы даже пригласили в офис пользователя, чтобы воспроизвести и отбежать лаги на его девайсе. Но из этой идеи ничего не вышло. Когда юзер оказался в офисе, всё работало как часы. Ha-ha, classic!

Я проверил все варианты, которые мог, чтобы воспроизвести проблему. Зависимости от типа девайса, сети, геолокации, версии оси и других факторов не было. При этом даже эпловые метрики main thread hang time от MetricKit, которые мы собираем в Графану, показывали неладное:

Что сделает перформанс-инженер в данном случае?

Просадка есть, а если найду?

Мне пришла в голову следующая идея. Команда перфоманса собирает множество различных метрик производительности приложения с продакшена, а также в Авито очень любят A/B-тесты и смотреть на метрики. Я решил воспользоваться протоптанной дорожкой и собрать ещё больше метрик для бога метрик. Вообще, у меня давно выработалось правило: что-то не понял — собери больше метрик! Когда собрал, можно проанализировать данные, понять, чего не хватает, и собрать ещё метрик. Перемешать и повторить.

В итоге план был такой:

  1. Быстро на коленке собрать метрики о том, как часто происходят просадки.

  2. Проверить, насколько много метрик набралось и как много просадок.

  3. Подумать, как выйти на причину проблемы и собрать детальные метрики.

  4. Повторять пункт 3, пока не появится ясность или мне не станет плохо.

Но как собрать нужные метрики? Как понять, что приложению стало плохо? Измерять загрузку CPU, следить за нагревом девайса, сделать вотчдог на мейн тред? В какую сторону бежать в первую очередь?

Ну, если проблема с FPS, то туда и стоит бежать, подумал я. Встроил в приложение демона — FpsDrawdownTracker, работающего поверх DisplayLink. Он собирает статистику кадров за последние 30 секунд и, если FPS просаживается больше, чем на половину, генерирует событие, что FPS просажен.

Трешхолд в половину выбирался рандомно, исходя из понимания, что он не должен быть слишком высоким, чтобы не создавать шума, и слишком низким, чтобы хоть что-то детектировать. Половина показалась здравым решением, ведь в нормальной жизни FPS не просаживается на 30 секунд так сильно. Как оказалось, этот выбор был удачным.

Если можешь взять что-то рандомно и не грузить мозги — сделай так. Потом проанализируешь данные и разберёшься.

Так говорил во мне внутренний аналитик.

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

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

Логика подсчёта получилась такая:

  1. FpsDrawdownTracker накапливает длины и тайминги кадров в течение секунды.

  2. Получает FPS из накопленных кадров и кладёт результат в отдельный массив.

  3. При накоплении 30 результатов измерения FPS (иначе 30 секунд) вычисляет среднее значение из них.

  4. Проверяет, больше ли полученное среднее, чем трешхолд — 30 FPS на девайсах c 60 FPS.

  5. Если значение не больше трешхолда, генерирует нон-фатал в Crashlytics.

Сделал, запушил, раскатил, включил тоггл на логирование.

За первую неделю раскатки нон-фаталы вышли на пик в 50 000 событий за сутки. Цифра внушительная даже для Авито. Для примера, топовый краш в приложении происходит примерно в 20 раз реже. А этот результат означал только одно: проблема точно есть, она глобальна, распространена, и нужно докопаться до её корней. Ну и плюс у меня был индикатор проблемности.

Нон-фаталы просадок FPS растут
Нон-фаталы просадок FPS растут

Здесь начинается безумие 

Как понять, что именно приводит к просадке, если воспроизвести её никак не удаётся? Мой ответ вы уже знаете — добавить данных в метрики. 

Мне до сих пор было непонятно, куда копать, поэтому я обложился всем, чем смог и начал слать в нон-фатал следующие данные в качестве кастомных ключей и значений:

  1. Текущий FPS.

  2. Пробитый трешхолд.

  3. Дефолтный — максимальный — FPS для девайса.

  4. Загрузку процессора в момент просадки.

  5. Количество тредов в приложении.

  6. Информацию о исполняемых тредах.

Выглядело это так:

Дополнительные данные к нон-фаталу
Дополнительные данные к нон-фаталу

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

К сожалению, в нон-фаталах нет стектрейса потоков, только трейс вызова самого нон-фатала. Это явно не то, что мне нужно. Как получить все стекстрейсы? Можно заморочиться по-разному и долго мучаться, чтобы эти трейсы собрать, а потом ещё и символизировать. Но зачем, если Crashlytics всё это умеет? Нужно лишь… крашить приложение, когда произошла просадка! Отчаянная мера, но тот, кто не рискует… Ну и я всегда мечтал крашить приложение по своей воле. Какая беспредельная власть!

Я сделал логику, которая помимо нон-фатала в Crashlytics генерировала NSException со всеми теми же полями, но с несколькими важными отличиями. Краш происходил только один раз для установки приложения, проверяя ключ в UserDefaults, и эксепшен выкидывался на фоновом потоке. Если бы он отрабатывал на главном, то в стектрейсе главного потока я бы видел одно и то же — трейс выкидывания NSException. А мне нужно видеть, чем главный поток может быть занят в текущий момент.

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

Админка тоглов. На самом деле там 30 секунд, просто описание кривое
Админка тоглов. На самом деле там 30 секунд, просто описание кривое

Когда я включил тогл на 5% пользователей, и данные начали литься, то сильно понятней картинка не стала. Но всплыли некоторые подозрительные стектрейсы. Это дало пищу для ума и потребовало времени на размышления. Вот кусочек одного из трейсов:

Стектрейс
com.apple.main-thread 0  libsystem_kernel.dylib         0x1d99f72d0 mach_msg_trap + 8 1  libsystem_kernel.dylib         0x1d99f6660 mach_msg + 76 2  libdispatch.dylib              0x1ac729888 _dispatch_mach_send_and_wait_for_reply + 528 3  libdispatch.dylib              0x1ac729c24 dispatch_mach_send_with_result_and_wait_for_reply + 56 4  libxpc.dylib                   0x1f5f59e68 xpc_connection_send_message_with_reply_sync + 240 5  RunningBoardServices           0x1b5e81240 -[RBSXPCMessage sendToConnection:error:] + 416 6  RunningBoardServices           0x1b5e8199c -[RBSXPCMessage invokeOnConnection:withReturnCollectionClass:entryClass:error:] + 96 7  RunningBoardServices           0x1b5e64464 -[RBSConnection acquireAssertion:error:] + 376 8  RunningBoardServices           0x1b5e6121c -[RBSAssertion acquireWithError:] + 208 9  WebKit                         0x1b9197dbc WebKit::ProcessAssertion::ProcessAssertion(int, WTF::String const&, WebKit::ProcessAssertionType) + 748 10 WebKit                         0x1b919857c WebKit::ProcessAndUIAssertion::ProcessAndUIAssertion(int, WTF::String const&, WebKit::ProcessAssertionType) + 24 11 WebKit                         0x1b90bfe24 WebKit::ProcessThrottler::setAssertionType(WebKit::ProcessAssertionType) + 272 12 WebKit                         0x1b90bfba8 WebKit::ProcessThrottler::updateAssertionIfNeeded() + 436 13 WebKit                         0x1b90c49f4 WebKit::ProcessThrottler::Activity<(WebKit::ProcessThrottler::ActivityType)1>::Activity(WebKit::ProcessThrottler&, WTF::ASCIILiteral) + 80 14 WebKit                         0x1b911e4a4 WebKit::WebPageProxy::runJavaScriptInFrameInScriptWorld(WebCore::RunJavaScriptParameters&&, WTF::Optional<WTF::ObjectIdentifier<WebCore::FrameIdentifierType> >, API::ContentWorld&, WTF::Function<void (API::SerializedScriptValue*, WTF::Optional<WebCore::ExceptionDetails>, WebKit::CallbackBase::Error)>&&) + 224 15 WebKit                         0x1b9025e30 -[WKWebView _evaluateJavaScript:asAsyncFunction:withSourceURL:withArguments:forceUserGesture:inFrame:inWorld:completionHandler:] + 1372 16 WebKit                         0x1b8de5170 -[WKWebView evaluateJavaScript:completionHandler:] + 100 17 AvitoFoundation                0x101b889f4 __destroy_helper_block_e8_40s48r56r64r + 24456 18 AvitoFoundation                0x101b76fb0 __destroy_helper_block_e8_32s40w48w + 23180 19 AvitoFoundation                0x101b7ffbc __destroy_helper_block_e8_32s40w48w + 60056 20 AvitoFoundation                0x101b76f40 __destroy_helper_block_e8_32s40w48w + 23068 21 AvitoFoundation                0x101b75408 __destroy_helper_block_e8_32s40w48w + 16100 22 AvitoFoundation                0x101b839fc __destroy_helper_block_e8_40s48r56r64r + 3984 23 AvitoFoundation                0x101b8357c __destroy_helper_block_e8_40s48r56r64r + 2832 24 libdispatch.dylib              0x1ac70f24c _dispatch_call_block_and_release + 32 25 libdispatch.dylib              0x1ac710db0 _dispatch_client_callout + 20 26 libdispatch.dylib              0x1ac71e7ac _dispatch_main_queue_callback_4CF + 836 27 CoreFoundation                 0x1aca9811c __CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ + 16 28 CoreFoundation                 0x1aca92120 __CFRunLoopRun + 2508 29 CoreFoundation                 0x1aca9121c CFRunLoopRunSpecific + 600 30 GraphicsServices               0x1c3b10784 GSEventRunModal + 164 31 UIKitCore                      0x1af4ca200 -[UIApplication _run] + 1072 32 UIKitCore                      0x1af4cfa74 UIApplicationMain + 168 33 Avito                          0x10056ef4c main + 112 (main.m:112) 34 libdyld.dylib                  0x1ac7516c0 start + 4

Во втором мелькало что-то про GADNetwork, но найти его при написании статьи я уже не смог.

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

  1. GADNetwork — это гугловая реклама.

  2. 18 строка стектрейса — выполнение JS-кода под капотом. Тоже похоже на рекламу, которая трекает своё появление на экране через JS.

  3. Также был стектрейс, который указывал на глобальное окно Гугл-рекламы, которое фреймворк добавляет в приложение и делает невидимым. Зачем? Я не знать! Но тоже чтобы трекать показы, скорее всего.

Проблема в том, что данные были косвенными, я любил параноить на рекламу, а Гугл-реклама в приложении на тот момент была отключена уже как несколько лет. А даже если не отключена, то не было гарантии, что это проблемные стектрейсы, ведь они просто рандомно захватывались в момент просадки. А GADNetwork, JS-код и гугловое окно всегда в фоне что-то делают, такая у них судьба.

Я ещё какое-то время поразмышлял, что это может быть, чтобы не гнать на рекламу, но тут мне начали прилетать похожие новости про Google SDK из соседней компании. Не удержавшись, я решил попробовать погонять тестовую Гугл-рекламу на своём девайсе.

Hell(o), Google!

Включил тестовый конфиг, запустил приложение, зашёл на выдачу, начал скроллить её вниз. И что? Лаги! Дикие лаги, как в первом видео от пользователя. Графики потребления процессора в CPU Usage в это время зашкаливали.

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

Если остановить выполнение приложения во время выполнения или на брейкпоинте, то можно увидеть красивый thread exploding:

Треды плодятся
Треды плодятся

Но Гугл-реклама же отключена несколько лет. Ладно, разберёмся в Слаке. Пишу, жду ответа, и в итоге:

Переписка в Слаке
Переписка в Слаке

И в дополнение, на тестовых сборках её вообще не было в силу технических причин. Кто работал с рекламой знают, что получить её в дебажных сборках — то ещё задание. Поэтому-то проблема была такой неуловимой. А даты проведения теста хорошо коррелировали с датами появления лагов.

А что с технической стороны, в чём там проблема? Когда пользователь открывает выдачу, под капотом в это время:

  1. Загружается выдача со слотами для рекламы.

  2. Загружается реклама от Гугла.

  3. Создаются объекты гугловой рекламы из SDK.

  4. Объекты кладутся в кэш в нашем коде и ждут, когда будет произведен показ данных из них.

  5. После показа они не удаляются и живут в кэше на случай, если пользователь будет скролить выдачу назад.

Шутка в том, что каждый такой объект лезет выполнять JS-код раз в секунду по таймеру и плодит для себя треды. Когда юзер долистывает до 10-15 страницы выдачи (а это частый кейс), то треды и JS-код забивают почти всё процессорное время. Спасибо, Гугл!

На тот момент, конечно, рекламу отключили, и графики просадок из моих нон-фаталов ушли в ноль. Я вздохнул с облегчением.

Нон-фаталы уходят в ноль
Нон-фаталы уходят в ноль

Команда по работе с рекламой связалась с представителями Гугла, чтобы пофиксить SDK. Но ответ был неутешительный — это корневая логика для отслеживания показов баннеров, и пока её не починили (до сих пор).

Что сделали мы? Для бизнеса реклама крайне важна, так как приносит неплохую долю выручки. Отключать её — не вариант, поэтому пришлось искать золотую середину. Мы стали кэшировать максимум 5 последних рекламных блоков, а остальные удалять. Это позволило сильно снять нагрузку с процессора, но, конечно, не полностью. По крайней мере тестирование на iPhone 5 показало себя хорошо.

Но знаете что? Я всё ещё параноил! И именно поэтому пошёл дальше, прямо во тьму.

Alone in the dark

Мало просто пофиксить проблему здесь и сейчас. Если что-то произошло один раз в таком большом проекте как Авито, то оно произойдёт снова. Это проверенная временем аксиома. И мне нужно было найти способ защититься от подобных проблем в будущем, чтобы спать спокойно.

Тут возникает новый челлендж. На что смотреть и как смотреть, чтобы данные были точными? У нас уже были метрики FPS, но они настолько бесполезные, что я давно перестал к ним обращаться.

Метрики FPS
Метрики FPS

FPS — значение динамическое. Как видно из скриншота, с одной стороны значение всегда около 59 кадров в секунду, а с другой — FPS в покое и при скролле очень отличаются. Да и в A/B-тестах сравнивать значения FPS будет сложно, так как всегда будет небольшой дифф. Нужно было что-то другое.

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

Трешхолды я выбрал следующие: 95, 90, 85, 70, 50, 30, 10% от максимально возможного значения FPS на устройстве. То есть на 60 FPS девайсе: 95% = 57 FPS, а 10% = 6 FPS. На верхней границе разбиение более мелкое, чтобы гранулярно детектировать небольшие просадки от максимума. Дальше стоит смотреть только на факт пробития низких трешхолдов, ибо это серьёзная проблема, и гранулярность тут не важна.

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

Сами метрики немного масштабировал. Теперь они отсылаются в Графану, где отображаются в реальном времени и динамике. Так можно понять, в какой версии приложения и в какую дату что-то сломалось.

Метрики пробивания трешхолдов FPS
Метрики пробивания трешхолдов FPS

Также нужно было внедриться в A/B-тесты. Обычно тест раскатывается на небольшую группу пользователей и не сильно изменяет глобальные метрики. Плюс это происходит очень плавно. Ну а если запущено одновременно два A/B, один из которых просаживает FPS, а второй улучшает, то в Графане не будет видно разницы.

По этой причине я продублировал отправку данных в DWH и систему A/B-тестирования. Это позволило в каждом A/B видеть, как он изменяет FPS и сразу понимать, что в конкретном тесте есть проблемы с перформансом. Если A/B проблемный, то продуктовая команда не может его выкатить, пока не исправит ситуацию. 

Итого, мы максимально избавляемся от неочевидных просадок FPS, держим руку на пульсе и спим спокойно. Пока без алертингов, но поддержка тоже не спит.

Метрики FPS в A/B-тестах. Зелёное — стало плохо
Метрики FPS в A/B-тестах. Зелёное — стало плохо

Ну и последнее изменение — краш теперь срабатывает у пользователя только раз в неделю, и то, если тогл включен. С одной стороны, если у юзера спустя неделю ещё есть просадки — мы их увидим, а с другой — не будем крашить апп постоянно.

В общем, хеппи энд, почти.

А ещё у меня есть десерт

Помните про интересные стектрейсы Гугл-рекламы? Если мне не изменяет память, то там вызывается WebKit. Часто и порой долго. Как раз это и приводит к проблемам с FPS, помимо thread exploding. Но как быстро понять, что именно реклама снова начала шалить? Например, чтобы отключить её в случае катастрофы.

К счастью, мы живём в удивительное время, когда iOS SDK написан в большинстве своём на Objective-C и можно засвизлить что угодно. Например, метод WKWebView.evaluateJavaScript(_: completionHandler: ), который дёргает Гугл.

У этого метода есть completion handler, который вызывается на главном потоке. А также он вызывается Гуглом порой по тысяче раз в секунду. Поэтому я собрался его переопределить и трекать три метрики:

  1. Количество вызовов метода за 10 секунд.

  2. Среднее время выполнения кода метода.

  3. Среднее время выполнения комплишена.

А проще говоря: что могу, то и замеряю. Картинка в Графане на этот счёт получается такая:

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

В целом видно, что снижение количества рекламы приводит к снижению количества вызовов JS-кода. На этом и остановимся. Данных хватает, из них можно получить достаточно информации, и на их основе решать проблемы с FPS.

Бесплатный код

Я не стал вставлять код в тело статьи, чтобы не показывать промежуточные решения и не отвлекать читателя от истории. Но это Хабр и, думаю, меня заминусуют, если кода совсем не будет. Поэтому он будет здесь. Весь. Сразу.

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

FpsListener (обёртка над CADisplayLink)
public typealias Frame = (timestamp: TimeInterval, length: TimeInterval)  public final class FpsListener {     public var maximumFps: Int { UIScreen.main.maximumFramesPerSecond }          private var displayLink: CADisplayLink?     private var lastTimestamp: TimeInterval?     private var observerList = ObserverList<(Frame) -> ()>() // Внутренняя реализация обсервера          public init() {}          public func subscribe(_ disposable: AnyObject, observer: @escaping (Frame) -> ()) {         DispatchQueue.main.avitoAsync {             let observersWasEmpty = self.observerList.isEmpty                          self.observerList.addObserver(disposable: disposable, observer: observer)                          if observersWasEmpty {                 self.removeDisplayLink()                 self.forceAddDisplayLink()                 self.suscribeForAppStateUpdates()             }         }     }          public func unsubscribe(_ disposable: AnyObject) {         DispatchQueue.main.avitoAsync {             self.observerList.removeObserver(disposable: disposable)                          if self.observerList.isEmpty {                 self.removeDisplayLink()                 NotificationCenter.default.removeObserver(self)             }         }     }          private func forceAddDisplayLink() {         displayLink?.invalidate()         displayLink = CADisplayLink(target: self, selector: #selector(handleDisplayUpdate))         displayLink?.add(to: .main, forMode: .common)     }          private func removeDisplayLink() {         guard displayLink != nil else { return }          displayLink?.remove(             from: .main,             forMode: .common         )                  displayLink?.invalidate()         displayLink = nil         lastTimestamp = nil     }          private func suscribeForAppStateUpdates() {         NotificationCenter.default.addObserver(             self,             selector: #selector(self.pauseUpdating),             name: UIApplication.willResignActiveNotification,             object: nil         )                  NotificationCenter.default.addObserver(             self,             selector: #selector(self.resumeUpdating),             name: UIApplication.didBecomeActiveNotification,             object: nil         )     }          @objc private func handleDisplayUpdate(_ displayLink: CADisplayLink) {         defer { lastTimestamp = displayLink.timestamp }         guard let lastTimestamp = lastTimestamp else { return }         observerList.forEach { $0((displayLink.timestamp, displayLink.timestamp - lastTimestamp)) }     }          @objc private func pauseUpdating() {         guard observerList.isNotEmpty else { return }         removeDisplayLink()     }          @objc private func resumeUpdating() {         guard displayLink == nil, observerList.isNotEmpty else { return }         forceAddDisplayLink()     } }
FpsDrawdownTracker
final class FpsDrawdownTracker {              private let targetFps: Double     private let fpsThresholds: [FpsThreshold]              private let windowSize: Int // In seconds     private var currentFrames = [Frame]()     private var fpsInWindow = [Double]()     private var onDrawdown: ((FpsDrawdownData) -> ())?          init(         windowSize: Int = 30,         targetFps: Double = Double(UIScreen.main.maximumFramesPerSecond)     ) {         assert(windowSize > 0, "windowSize should be positive value with positive thougths :)")                  self.targetFps = targetFps         self.windowSize = windowSize              self.fpsThresholds = FpsPercent.allCases             .sorted(by: <)             .map { ($0.fps(for: targetFps), $0) }     }              func addFrame(_ frame: Frame) {         guard let onDrawdown = self.onDrawdown else { return }                  currentFrames.append(frame)                  guard             let firstFrameStart = currentFrames.first.flatMap({ $0.timestamp - $0.length }),             let lastFrame = currentFrames.last?.timestamp         else { return }                          guard lastFrame - firstFrameStart >= 1 else { return }                  var nextFrames = [Frame]()                                  while currentFrames.count > 2 && (currentFrames.last?.timestamp ?? 0) - firstFrameStart > 1 {             nextFrames.insert(currentFrames.removeLast(), at: 0)         }                  defer { currentFrames = nextFrames }                          let currentFramesCount = currentFrames.count                  fpsInWindow.append(Double(currentFramesCount))                          guard fpsInWindow.count >= windowSize else { return }                  defer { fpsInWindow.removeAll() }                  let averageFps = ceil(fpsInWindow.reduce(0.0, +) / Double(fpsInWindow.count))                  guard let brokenThreshold = fpsThresholds.first(where: { averageFps <= $0.fps }) else { return }                                  onDrawdown((Double(targetFps), averageFps, brokenThreshold, windowSize))     }              func startTracking(onDrawdown: @escaping ((FpsDrawdownData) -> ())) {         self.onDrawdown = onDrawdown     }          func stopTracking() {         self.onDrawdown = nil     } }  typealias FpsDrawdownData = (target: Double, actual: Double, threshold: FpsThreshold, windowSize: Int)  typealias FpsThreshold = (fps: Double, percent: FpsPercent)  // In percentages because we have 60fps and 120fps devices. All examples for 60fps devices enum FpsPercent: Double, Hashable, CaseIterable, Comparable, Equatable {          case p95 = 95 // 57 fps     case p90 = 90 // 54 fps     case p85 = 85 // 51 fps     case p70 = 70 // 42 fps     case p50 = 50 // 30 fps     case p30 = 30 // 18 fps     case p10 = 10 // _6 fps          static func < (lhs: FpsPercent, rhs: FpsPercent) -> Bool {         return lhs.rawValue < rhs.rawValue     }          func fps(for target: Double) -> Double {         target * rawValue * 0.01     } }
WebViewJSEvaluationTracker
public final class WebViewJSEvaluationTracker {     private static let lock = MultiplatformLock() // По сути любой лок     private static var isStarted = false          public static func startOnce(logger: EventLogger) {         // To avoid using lock if subscriber is already started         guard !isStarted else { return }                  assert(Thread.isMainThread, "This class should be used from main thread only", showAlert: false)                  lock.perform {             guard !isStarted else { return }                          isStarted = true                          var sentEventsCount = 0             var evaluateCount = 0             var evaluateTimings = [Double]()             var completionTimings = [Double]()                          onEvaluateJavaScript = { evaluate in                 evaluateCount += 1                                  let callStart = DispatchTime.now()                                  evaluate {                     let completionEnd = DispatchTime.now()                     let nanoTime = completionEnd.uptimeNanoseconds - callStart.uptimeNanoseconds                     let timeInterval = Double(nanoTime) / 1_000_000_000                     completionTimings.append(timeInterval)                 }                                  let callEnd = DispatchTime.now()                                  let nanoTime = callEnd.uptimeNanoseconds - callStart.uptimeNanoseconds                 let timeInterval = Double(nanoTime) / 1_000_000_000                 evaluateTimings.append(timeInterval)             }                          var timer: Foundation.Timer?                                      timer = Foundation.Timer.scheduledTimer(withTimeInterval: 10, repeats: true) { [weak timer] _ in                 guard sentEventsCount <= 100 else {                     onEvaluateJavaScript = { $0{} }                     timer?.invalidate()                     return                 }                                  guard !evaluateTimings.isEmpty || !completionTimings.isEmpty else { return }                                                  var events = [AppMetricEvent]()                  events += evaluateTimings                     .sorted()                     .suffix(1)                     .map { AppMetricEvent(metrics: [EvaluateJavaScriptCallTimeMetric(timeInterval: $0)]) }                  events += completionTimings                     .sorted()                     .suffix(1)                     .map { AppMetricEvent(metrics: [EvaluateJavaScriptCompletionTimeMetric(timeInterval: $0)]) }                  events += [AppMetricEvent(metrics: [EvaluateJavaScriptCountMetric(count: evaluateCount)])]                  events.forEach { logger.log($0) }                                                  evaluateTimings.removeAll()                 completionTimings.removeAll()                 sentEventsCount += 1                 evaluateCount = 0             }                                      swizzle(                 originalSelector: #selector(WKWebView.evaluateJavaScript(_: completionHandler: )),                 swizzledSelector: #selector(WKWebView.swizzled_evaluateJavaScript(_: completionHandler: ))             )         }     }          private static func swizzle(originalSelector: Selector, swizzledSelector: Selector) {         guard let originalMethod = class_getInstanceMethod(WKWebView.self, originalSelector) else { return }         guard let swizzledMethod = class_getInstanceMethod(WKWebView.self, swizzledSelector) else { return }         method_exchangeImplementations(originalMethod, swizzledMethod)     } }  private var onEvaluateJavaScript: (((@escaping () -> ()) -> ()) -> ())?  private extension WKWebView {     @objc func swizzled_evaluateJavaScript(_ javaScriptString: String, completionHandler: ((Any?, Error?) -> ())?) {         if let onEvaluateJavaScript = onEvaluateJavaScript {             onEvaluateJavaScript { customCompletion in                 swizzled_evaluateJavaScript(javaScriptString) {                     completionHandler?($0, $1)                     customCompletion()                 }             }         } else {             swizzled_evaluateJavaScript(javaScriptString, completionHandler: completionHandler)         }     } }

Подведу черту

На данный момент метрики в A/B уже помогли отловить несколько проблемных тестов с просадками FPS и починить их до выкатки. А глобальные метрики в Графане помогают отследить динамику, если какая-то функциональность катится без A/B-тестов. 

Когда приходят обращения пользователей по поводу лагов скролла или нагрева девайса, то как минимум сразу можно проверить метрики и понять, есть ли проблема. А чтобы отдебажить, где она, — включить тот самый краш при просадке FPS на 50%. Плюс корреляция данных из метрик FPS с данными выполнения JS-кода вебкитом и количеством показов разной рекламы помогает быстро определить, с рекламой ли проблема, и быстро исправить ситуацию.

Ну и главный вывод: как в ушедшем 2021 году многие уже успели убедиться, внешние SDK от крупных компаний не такие милые и пушистые, как может показаться. Вспомним примеры с Facebook и log4j как минимум. Сколько ещё подобных историй случается и проходит мимо внимания комьюнити?

По поводу Facebook у меня есть отдельная история когда пришлось свизлить (только дай посвизлить этому парню!), чтобы они перестали перехватывать все NSExceptions в приложении и слать себе в аналитику. Но это уже совсем другая тема, и кратко с ней можно ознакомиться на Гитхабе

В новом году хочу пожелать всем iOS-разработчикам, чтобы никому не приходилось сталкиваться с колючими внешними библиотеками и их артефактами, а проблемы с перфомансом дебажились быстро и легко. Ну и чтобы не приходилось свизлить.

По всем вопросам непосредственно ко мне можно писать в телеграм @west0r. До середины лета я буду отдыхать и восстанавливать свой личный перформанс, поэтому на Хабре могу не ответить. 


ссылка на оригинал статьи https://habr.com/ru/company/avito/blog/597417/


Комментарии

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *