Как мы написали поверх Sentry кастомную систему профилирования приложения на проде

Привет, Хабр! В эфире Дмитрий Зайцев из Купера. Я отвечаю за Supply&Demand в команде разработки Shopper — мобильного приложения для сборщиков и курьеров. Сегодня я расскажу о том, что можно сделать, если пользователи постоянно жалуются, что ваше приложение тормозит, а вы не знаете, почему.

Откуда у кейса ноги растут?

У нас было 0 запрещенных веществ, приложение на React Native с тысячью транзакций и куча негативных отзывов. Приложение тормозило, несмотря на регулярную оптимизацию.

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

Где подобные метрики обитают? Ну, например, в Sentry. Мы пользуемся этим инструментом с самого рождения приложения, поэтому придумывать что-то новое было избыточно.

Глоссарий Sentry

Здесь потребуется лирическое отступление, чтобы все понимали дальнейший ход мысли. Ага, в чат вошел вольный пересказ документации сервиса :)

Самая мелкая единица — интервал (спан). Это именованная операция, часть рабочего процесса приложения: http-запрос, вызов какой-то функции, обновление компонента и т. д. Спан имеет начало и конец и может включать в себя другие интервалы, которые начались после его начала и закончились до его завершения. Например, у нас есть функция fetch, которая отправляет запрос, перезаписывает данные в store и обновляет компонент. В нее могут входить интервалы http-запроса и обновления (перерисовки) компонента.

Интервалы можно собирать в дерево, где каждый следующий спан будет ребенком предыдущего. Чтобы как-то это все систематизировать, вводится понятие «транзакция».

Транзакция — тот же спан, только корневой. Это интервал, который считается единичным экземпляром активности, которую надо измерить или отследить. Активность может состоять из одного спана (который и будет транзакцией), а может иметь древовидную структуру. Здесь примером тоже может служить функция fetch, но мы смотрим на нее не как на три атомарных операции, а как на интервальную совокупность, которая монолитно влияет на пользовательский опыт.

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

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

Итак, пошли в Sentry

В нашем случае (Sentry + React Native) инструменты профилирования уже были синхронизированы с библиотекой, используемой для навигации. Для старта нужно было только включить Profile Monitoring.

Включаем и видим, что — о ужас! — приложение на проде работает еще медленнее, чем представляли себе разработчики: главная страница загружается в среднем 7 секунд; если брать таргет в 95-й перцентиль — вообще 20+ секунд. Можете также представить наши лица, когда Sentry сообщил, что экран настроек с парой кнопок отрисовывается 3 минуты.

Уже при поверхностном анализе мы выяснили:

• некоторые транзакции начинались не вместе с загрузкой экрана, а во время холодного старта приложения;

• часть транзакций продолжалась после того, как отрисовка была завершена и пользователь, очевидно, уже пошел дальше.

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

В общем, стало очевидно, что нельзя полностью доверять данным Sentry. Так у нас появилась развилка:

1. Найти и внедрить другой инструмент.

2. Разобраться, что происходит в «голове» у Sentry и попытаться подчинить эти алгоритмы своим целям (то есть, скорее всего, написать свой инструмент на их основе).

3. Сразу написать что-то свое поверх Sentry и не тратить время на разбирательства.

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

И пошла жара!

Команда решила прежде всего определить Time to Interactive для наших экранов. Проще говоря — понять, как быстро они загружаются.

Как отследить это время в React-коде?

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

Завершить транзакцию хочется в момент, когда все данные уже получены и отрисованы. В React, когда дерево компонентов отрисовано, сразу запускается useEffect. Соответственно, мы можем определить условие, при котором считаем, что экран готов к использованию. Например, данные загрузились, переменная isLoading стала равна false. Ставим это условие в useEffect и считываем окончание.

В Sentry есть три способа начать и закончить спан.

Документация сервиса говорит, что самый простой и отвечающий большинству задач способ выглядит так:

То есть мы используем функцию startSpan, которая принимает два аргумента: объект с опциями спана и функцию, которую надо «заспанить» (она не обязательно должна быть асинхронной). Sentry начнет спан с запуском функции и автоматически завершит его сразу после того, как она что-то вернет. В переменную result попадет результат вызова функции, переданной вторым аргументом.

Нам это не подходит. Даже если передать компонент в качестве второго аргумента, return еще не означает, что он отрисовался. К тому же мы хотим контролировать завершение транзакции, а здесь этого не дано.

Другой способ сформировать спан — старт интервала с ручной остановкой:

Эта функция работает аналогично предыдущей, однако она никогда не завершит интервал самостоятельно. Вместо этого в функцию, которая идет вторым аргументом, передается спан, у которого есть соответствующий метод остановки. Запускаем этот метод перед завершением функции или в любом другом месте, где считаем нужным. Можно взять на вооружение, согласитесь?

Но есть еще третий вариант формирования транзакции — создание некого независимого спана:

Документация Sentry предполагает, что такой спан можно формировать, чтобы создать некий интервал, который не хочется включать в активный спан. Функция запуска принимает только опции и возвращает конкретно этот спан. Мы вольны остановить его в любой момент. Выглядит красиво и как будто подходит нам так же, как предыдущий вариант? Однако такая транзакция всегда запускается изолированно от других интервалов, созданных Sentry. А у нас есть, например, автоматическая запись http-запросов в интервалы. Поэтому остановились на втором варианте.

Чтобы измерять Time to Interactive, сделаем хук, который можно добавить в компонент с минимальными данными, не занимая слишком много места:

Хук — useTimeToReady. Он будет принимать имя спана, установку, корневой ли это спан, и условие, когда считается, что экран готов.

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

Поскольку мы хотим измерять только время первого отображения, будем стартовать спан только при маунте компонента, а значит — обернем в useMemo. Также важно, чтобы экран был в фокусе.

Если это корневой спан, который хорошо бы видеть на дашбордах, для названия берем имя роута. Пока не будет удален автоматический инструментарий по созданию транзакций навигации, добавляем суффикс custom. Для любого некорневого спана задаем имя напрямую.

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

Вторым аргументом следует передать функцию, которая принимает начатый спан. Результат работы этой функции = результат запуска спана. Пусть useMemo вернет спан, который мы в нужный момент сможем завершить. Окончание запускаем в useEffect, когда условие isReady выполнено и спан существует (Sentry отдает его как Span или undefined).

Не забываем, что экран может демонтироваться до isReady, поэтому защищаем себя еще одним useEffect, в котором будем вызывать завершение спана на unmount.

Здесь хочу предупредить, что в useMemo лучше возвращать именно целиком спан, а не только функцию его завершения. Методы работы со спаном, в том числе функция end, имеют внутри себя ссылку на this — этот контекст важно сохранить.

Наконец выявляем проблему

Собственно то, ради чего мы тут собрались.

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

Получается график:

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

Мы посмотрели на все это и пришли к выводу, что, например, функционал, связанный с кошельком (его запросы выделены синим на графике выше), находится в той части экрана, которая пользователю не видна сразу и не так востребована. Поэтому виджету кошелька сделали скелетон: отображение остальных данных от него уже не зависит, и взаимодействовать с остальной частью страницы можно раньше, чем придет ответ от сервиса кошелька.

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

Вот и сказочке конец? Нет!

Видеть Time to Interactive экранов, где есть какие-то условия, запросы или сложные вычисления, — класс. А вот трекать экраны, где данные для отрисовки уже доступны в момент перехода, нам не очень хотелось. Казалось бы, зачем исследовать, как React рисует список товаров?

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

Мы сопротивлялись, но героически взяли на себя и эту ношу.

Скажем, перед сборщиком список товаров. Он что-то выбирает и нажимает кнопку «Отсканировать штрихкод». Сканер открывается, штрихкод распознается, отправляется некоторое количество запросов. Далее пользователь автоматом переходит обратно на список товаров, где, после лоадера, только что отсканированный товар попадает в категорию «Собрано». Что тормозит этот процесс?

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

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

Как будем начинать спан? Добавляем к классу логгера функцию, которая стартанет спан по переданным в нее параметрам и вернет его. По ключу имени записываем спан в приватную переменную логгера:

Передавать в эту функцию будем имя спана, информацию о том, является ли он корневым (isRoot), а еще op и id.

Op — стандартизированное определение операции, чтобы было легче идентифицировать спан в интерфейсе Sentry и делать по нему графики. У нас используются такие значения, как ui.screen, ui.component, http.client, function, dispatch.

Id нужен на случай, когда мы отображаем некий список и хотим увидеть элементы этого списка в транзакции. Тогда в компоненте запускаем спан с именем карточки; карточек много, и id нужен, чтобы они не смешивались.

Функция завершения: как выглядит и что дает

Для завершения спана также пишем функцию в логгере. Она берет имя из приватной переменной со спаном, вызывая функцию завершения, и удаляет спан оттуда, чтобы не засорять объект.

Зачем это нужно?

Во-первых, у нас есть места, где в одной точке по одному условию хотелось бы завершать разные транзакции. У сборщиков есть разные сценарии: работа с упакованными товарами, весовыми товарами и товарами, где есть маркировка; сборка через сканнер и без него, вручную. Конец этих флоу должен быть на итоговом экране списка товаров после сборки. Чтобы не городить строчки кода с завершением разных спанов, мы сделали так, что функция завершения первым параметром принимает либо имя спана, либо их массив. В случае, если передается массив, завершаются (и удаляются) все спаны.

Во-вторых, есть места, где можно начать несколько флоу из одной точки. Лишь после определенного ответа от бэкенда понятно, какой флоу «победил» в этот раз. Поэтому запускаем транзакцию с каким-то общим именем, а завершаем — с персонализированным.

В-третьих, на пути стоят http-запросы, которые не всегда отдают то, что нужно. В случае ошибки пользователь может не завершить транзакцию или завершить ее слишком быстро (так как вернется на экран, где она завершается не через флоу, а сразу). Можно вызвать завершение спана, но, передав в опции параметр isDelete, не отправить транзакцию в Sentry. Она удалится и не сможет быть отправлена позже.

На картинке пример одного флоу, который мы обвязали этим инструментом:

Здесь список из 8 товаров. Собран только 1 товар, однако при переходе на список товаров (см. 2–8 items) перерендерились все 8 карточек. Вдобавок они по какой-то причине перерендерились и немного раньше (см. 1–8 items). Также на графике можно заметить пустую область между ререндерами: там обновлялись экраны, находящиеся в стеке, + работали их хуки, что не добавляло производительности.

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

Ререндерится 1 элемент. В результате проделанной работы мы получили прохождение флоу за 1,1 секунды вместо 2,8 секунды, которые были в среднем до оптимизированной версии.

Плюсы нашего подхода

Отказ от стандартных инструментов, когда Sentry фиксирует все переходы в транзакции, принес гораздо больший эффект, чем ожидалось. Мы не просто уменьшили шум в интерфейсе, а настроили гладкий сбор метрик, которые помогают видеть пробелы в разработке.

У нас есть rate-лимит в Sentry. Отправляя большое количество стандартных транзакций, которые нам не особо интересны, мы режем количество важных для нас транзакций. С новым кодом создаются только нужные корневые спаны, а таблицы и графики наполняются реально полезными, достоверными данными.

Теперь можно отслеживать динамику изменений. Вот у нас есть медленный экран. Мы его оптимизировали — насколько это помогло? Стали ли пользователи быстрее работать в этом флоу?

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

Все это почти ничего не стоит с точки зрения производительности. Sentry уверяет, что автоматический мониторинг добавляет менее 3% накладных расходов и что юзеры этого не замечают. Ну а наш подход сравним по влиянию с автоматическим.

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

 

А минусы будут?

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

Желаю всем высокой производительности приложений и самых лояльных юзеров!