В октябре 2020 года в техническую поддержку Авито стали обращаться пользователи с проблемами нагрева девайса и просадками FPS вплоть до полного фриза iOS-приложения. Проблема, как казалось, была глобальной. Она не относилась к какой-то конкретной функциональности приложения и поэтому не подходила в бэклоги продуктовых команд. Выход был один: засучить рукава и самому разобраться, что пошло не так. Не даром же я performance engineer.
В статье я расскажу, как происходило погружение во тьму, выход из неё и к каким выводам это путешествие меня привело.
Сигналы из космоса
Жалобы на лаги в основном были связаны с экранами выдачи и карточки объявления. Это два самых популярных экрана в приложении. По статистике, если что-то происходит на них, то это происходит во всем приложении глобально. Неудивительно, что счётчик обращений быстро рос.
От одного из пользователей поддержка получила такое видео:
В глобальности крылась основная проблема лично для меня. Если всё так, то где искать баг в огромном приложении Авито? У нас больше 200 экранов, куча демонов, фоновых процессов, БД для мессенджера, логирование аналитики и это ещё не конец. Произойти могло что угодно и где угодно. Например, какой-то не удалившийся вовремя из памяти экран мог начать потреблять ресурсы процессора. Или что-то начинало бесконечно перерисовываться.
Вариантов рождалось бесконечное количество. Загвоздка в том, что воспроизвести проблему не получалось ни у меня, ни у коллег. В один момент мы даже пригласили в офис пользователя, чтобы воспроизвести и отбежать лаги на его девайсе. Но из этой идеи ничего не вышло. Когда юзер оказался в офисе, всё работало как часы. Ha-ha, classic!
Я проверил все варианты, которые мог, чтобы воспроизвести проблему. Зависимости от типа девайса, сети, геолокации, версии оси и других факторов не было. При этом даже эпловые метрики main thread hang time от MetricKit, которые мы собираем в Графану, показывали неладное:
Что сделает перформанс-инженер в данном случае?
Просадка есть, а если найду?
Мне пришла в голову следующая идея. Команда перфоманса собирает множество различных метрик производительности приложения с продакшена, а также в Авито очень любят A/B-тесты и смотреть на метрики. Я решил воспользоваться протоптанной дорожкой и собрать ещё больше метрик для бога метрик. Вообще, у меня давно выработалось правило: что-то не понял — собери больше метрик! Когда собрал, можно проанализировать данные, понять, чего не хватает, и собрать ещё метрик. Перемешать и повторить.
В итоге план был такой:
-
Быстро на коленке собрать метрики о том, как часто происходят просадки.
-
Проверить, насколько много метрик набралось и как много просадок.
-
Подумать, как выйти на причину проблемы и собрать детальные метрики.
-
Повторять пункт 3, пока не появится ясность или мне не станет плохо.
Но как собрать нужные метрики? Как понять, что приложению стало плохо? Измерять загрузку CPU, следить за нагревом девайса, сделать вотчдог на мейн тред? В какую сторону бежать в первую очередь?
Ну, если проблема с FPS, то туда и стоит бежать, подумал я. Встроил в приложение демона — FpsDrawdownTracker, работающего поверх DisplayLink. Он собирает статистику кадров за последние 30 секунд и, если FPS просаживается больше, чем на половину, генерирует событие, что FPS просажен.
Трешхолд в половину выбирался рандомно, исходя из понимания, что он не должен быть слишком высоким, чтобы не создавать шума, и слишком низким, чтобы хоть что-то детектировать. Половина показалась здравым решением, ведь в нормальной жизни FPS не просаживается на 30 секунд так сильно. Как оказалось, этот выбор был удачным.
Если можешь взять что-то рандомно и не грузить — сделай так. Потом проанализируешь данные и разберёшься.
Так говорил во мне внутренний аналитик.
Важная особенность в реализации FpsDrawdownTracker — он должен сбрасывать статистику, когда приложение переходит в неактивное состояние, и начинать собирать её снова, когда оно становится активным. Иначе я бы намерял ложных просадок в неактивном состоянии и потом не мог бы их отфильтровать.
Ещё одна важная особенность — за один запуск приложения может произойти разное количество просадок или одна, но по длительности в несколько 30-секундных окон. Поэтому я логирую только первый факт просадки за сессию, а остальные игнорирую.
Логика подсчёта получилась такая:
-
FpsDrawdownTrackerнакапливает длины и тайминги кадров в течение секунды. -
Получает FPS из накопленных кадров и кладёт результат в отдельный массив.
-
При накоплении 30 результатов измерения FPS (иначе 30 секунд) вычисляет среднее значение из них.
-
Проверяет, больше ли полученное среднее, чем трешхолд — 30 FPS на девайсах c 60 FPS.
-
Если значение не больше трешхолда, генерирует нон-фатал в Crashlytics.
Сделал, запушил, раскатил, включил тоггл на логирование.
За первую неделю раскатки нон-фаталы вышли на пик в 50 000 событий за сутки. Цифра внушительная даже для Авито. Для примера, топовый краш в приложении происходит примерно в 20 раз реже. А этот результат означал только одно: проблема точно есть, она глобальна, распространена, и нужно докопаться до её корней. Ну и плюс у меня был индикатор проблемности.
Здесь начинается безумие
Как понять, что именно приводит к просадке, если воспроизвести её никак не удаётся? Мой ответ вы уже знаете — добавить данных в метрики.
Мне до сих пор было непонятно, куда копать, поэтому я обложился всем, чем смог и начал слать в нон-фатал следующие данные в качестве кастомных ключей и значений:
-
Текущий FPS.
-
Пробитый трешхолд.
-
Дефолтный — максимальный — FPS для девайса.
-
Загрузку процессора в момент просадки.
-
Количество тредов в приложении.
-
Информацию о исполняемых тредах.
Выглядело это так:
Как ни печально, эти данные мне ничего не дали. Ни один из параметров не указывал на потенциальные проблемы. И тут я понял, в них не было самого важного — стектрейса главного потока! Ведь интересней всего именно причина, почему он загружен и не может отрисовывать интерфейс, а всё остальное — бездушные цифры.
К сожалению, в нон-фаталах нет стектрейса потоков, только трейс вызова самого нон-фатала. Это явно не то, что мне нужно. Как получить все стекстрейсы? Можно заморочиться по-разному и долго мучаться, чтобы эти трейсы собрать, а потом ещё и символизировать. Но зачем, если Crashlytics всё это умеет? Нужно лишь... крашить приложение, когда произошла просадка! Отчаянная мера, но тот, кто не рискует... Ну и я всегда мечтал крашить приложение по своей воле. Какая беспредельная власть!
Я сделал логику, которая помимо нон-фатала в Crashlytics генерировала NSException со всеми теми же полями, но с несколькими важными отличиями. Краш происходил только один раз для установки приложения, проверяя ключ в UserDefaults, и эксепшен выкидывался на фоновом потоке. Если бы он отрабатывал на главном, то в стектрейсе главного потока я бы видел одно и то же — трейс выкидывания NSException. А мне нужно видеть, чем главный поток может быть занят в текущий момент.
Также краш помещён под тоггл, управляемый с бэкенда, чтобы можно было его аккуратно регулировать. Изначально тогл выключен у всех пользователей и включается на процент при необходимости.
Когда я включил тогл на 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, но найти его при написании статьи я уже не смог.
На этом месте стоит оговориться, что когда-то в Авито я работал в команде монетизации и занимался интеграцией рекламных сетей в приложение. Успев столкнуться с разными интересными багами, я по привычке сразу паранойю, что любая непонятная проблема — это реклама. Поэтому тут я тоже стал думать в сторону рекламы. На это у меня было несколько причин:
-
GADNetwork— это гугловая реклама. -
18 строка стектрейса — выполнение JS-кода под капотом. Тоже похоже на рекламу, которая трекает своё появление на экране через JS.
-
Также был стектрейс, который указывал на глобальное окно Гугл-рекламы, которое фреймворк добавляет в приложение и делает невидимым. Зачем? Я не знать! Но тоже чтобы трекать показы, скорее всего.
Проблема в том, что данные были косвенными, я любил параноить на рекламу, а Гугл-реклама в приложении на тот момент была отключена уже как несколько лет. А даже если не отключена, то не было гарантии, что это проблемные стектрейсы, ведь они просто рандомно захватывались в момент просадки. А GADNetwork, JS-код и гугловое окно всегда в фоне что-то делают, такая у них судьба.
Я ещё какое-то время поразмышлял, что это может быть, чтобы не гнать на рекламу, но тут мне начали прилетать похожие новости про Google SDK из соседней компании. Не удержавшись, я решил попробовать погонять тестовую Гугл-рекламу на своём девайсе.
Hell(o), Google!
Включил тестовый конфиг, запустил приложение, зашёл на выдачу, начал скроллить её вниз. И что? Лаги! Дикие лаги, как в первом видео от пользователя. Графики потребления процессора в CPU Usage в это время зашкаливали.
Я не поверил, что это правда. Выключил рекламу и сделал всё то же самое — лагов нет. Включил — есть. Так несколько раз, чтобы убедиться, что это не моя паранойя. Удивительно, но спустя несколько месяцев сбора статистики виновник был найден!
Если остановить выполнение приложения во время выполнения или на брейкпоинте, то можно увидеть красивый thread exploding:
Но Гугл-реклама же отключена несколько лет. Ладно, разберёмся в Слаке. Пишу, жду ответа, и в итоге:
И в дополнение, на тестовых сборках её вообще не было в силу технических причин. Кто работал с рекламой знают, что получить её в дебажных сборках — то ещё задание. Поэтому-то проблема была такой неуловимой. А даты проведения теста хорошо коррелировали с датами появления лагов.
А что с технической стороны, в чём там проблема? Когда пользователь открывает выдачу, под капотом в это время:
-
Загружается выдача со слотами для рекламы.
-
Загружается реклама от Гугла.
-
Создаются объекты гугловой рекламы из SDK.
-
Объекты кладутся в кэш в нашем коде и ждут, когда будет произведен показ данных из них.
-
После показа они не удаляются и живут в кэше на случай, если пользователь будет скролить выдачу назад.
Шутка в том, что каждый такой объект лезет выполнять JS-код раз в секунду по таймеру и плодит для себя треды. Когда юзер долистывает до 10-15 страницы выдачи (а это частый кейс), то треды и JS-код забивают почти всё процессорное время. Спасибо, Гугл!
На тот момент, конечно, рекламу отключили, и графики просадок из моих нон-фаталов ушли в ноль. Я вздохнул с облегчением.
Команда по работе с рекламой связалась с представителями Гугла, чтобы пофиксить SDK. Но ответ был неутешительный — это корневая логика для отслеживания показов баннеров, и пока её не починили (до сих пор).
Что сделали мы? Для бизнеса реклама крайне важна, так как приносит неплохую долю выручки. Отключать её — не вариант, поэтому пришлось искать золотую середину. Мы стали кэшировать максимум 5 последних рекламных блоков, а остальные удалять. Это позволило сильно снять нагрузку с процессора, но, конечно, не полностью. По крайней мере тестирование на iPhone 5 показало себя хорошо.
Но знаете что? Я всё ещё параноил! И именно поэтому пошёл дальше, прямо во тьму.
Alone in the dark
Мало просто пофиксить проблему здесь и сейчас. Если что-то произошло один раз в таком большом проекте как Авито, то оно произойдёт снова. Это проверенная временем аксиома. И мне нужно было найти способ защититься от подобных проблем в будущем, чтобы спать спокойно.
Тут возникает новый челлендж. На что смотреть и как смотреть, чтобы данные были точными? У нас уже были метрики 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 и более секунд — это очень серьёзно, если меньше, то в метриках может быть много флуктуаций.
Сами метрики немного масштабировал. Теперь они отсылаются в Графану, где отображаются в реальном времени и динамике. Так можно понять, в какой версии приложения и в какую дату что-то сломалось.
Также нужно было внедриться в A/B-тесты. Обычно тест раскатывается на небольшую группу пользователей и не сильно изменяет глобальные метрики. Плюс это происходит очень плавно. Ну а если запущено одновременно два A/B, один из которых просаживает FPS, а второй улучшает, то в Графане не будет видно разницы.
По этой причине я продублировал отправку данных в DWH и систему A/B-тестирования. Это позволило в каждом A/B видеть, как он изменяет FPS и сразу понимать, что в конкретном тесте есть проблемы с перформансом. Если A/B проблемный, то продуктовая команда не может его выкатить, пока не исправит ситуацию.
Итого, мы максимально избавляемся от неочевидных просадок FPS, держим руку на пульсе и спим спокойно. Пока без алертингов, но поддержка тоже не спит.
Ну и последнее изменение — краш теперь срабатывает у пользователя только раз в неделю, и то, если тогл включен. С одной стороны, если у юзера спустя неделю ещё есть просадки — мы их увидим, а с другой — не будем крашить апп постоянно.
В общем, хеппи энд, почти.
А ещё у меня есть десерт
Помните про интересные стектрейсы Гугл-рекламы? Если мне не изменяет память, то там вызывается WebKit. Часто и порой долго. Как раз это и приводит к проблемам с FPS, помимо thread exploding. Но как быстро понять, что именно реклама снова начала шалить? Например, чтобы отключить её в случае катастрофы.
К счастью, мы живём в удивительное время, когда iOS SDK написан в большинстве своём на Objective-C и можно засвизлить что угодно. Например, метод WKWebView.evaluateJavaScript(_: completionHandler: ), который дёргает Гугл.
У этого метода есть completion handler, который вызывается на главном потоке. А также он вызывается Гуглом порой по тысяче раз в секунду. Поэтому я собрался его переопределить и трекать три метрики:
-
Количество вызовов метода за 10 секунд.
-
Среднее время выполнения кода метода.
-
Среднее время выполнения комплишена.
А проще говоря: что могу, то и замеряю. Картинка в Графане на этот счёт получается такая:
Чтобы сопоставить эти данные с данными загрузки рекламы, нужно дополнительно отправлять метрики количества показов рекламы разных рекламных сетей. Это выглядит так:
В целом видно, что снижение количества рекламы приводит к снижению количества вызовов 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. До середины лета я буду отдыхать и восстанавливать свой личный перформанс, поэтому на Хабре могу не ответить.
Автор: Алексей Кудрявцев
