В какой-то момент разработки приложения вы получаете обратную связь от пользователей: например, при нажатии на кнопку «Выбрать адрес» приложение сначала на пару секунд подвисает, а уже только потом показывает экран со списком адресов. Специально никто медленный код не писал, но он откуда-то где-то возник.
Сегодня расскажу, как Apple предлагает решать эту проблему с помощью логов.
В прошлой статье мы научились логировать в Console.app, чтобы удобно ориентироваться в логах. Но туда мы складывали обычные текстовые сообщения. Да, они идут в хронологическом порядке. Да, в них есть вся необходимая информация. Но вот есть у нас сетевой слой, и в нём, например, стоит ограничение — не более 5 параллельных запросов одновременно. А в логах мы видим просто пачку сообщений Start: Request и End: Request, где напротив каждого End стоит длительность выполнения запроса:
По таким логам сложно понять, что началось вместе с чем и когда оно закончилось, потому что конечные логи визуально никак не связаны с начальными. Давайте свяжем. Но для этого придётся os_log и Console.app заменить другими инструментам.
Time Profiler
Apple предлагает смотреть замеры в специальном инструменте — Time Profiler, он поставляется вместе с Xcode.
Для запуска нужно в своём проекте нажать Product → Profile. Появится окно с целым набором инструментов:
Среди них надо выбрать именно Time Profiler. В открывшемся окне слева сверху жмём на кнопку записи. В инструменте сразу начинают рисоваться какие-то графики:
Конечно, здесь видно какую-то статистику внутри приложения, но сказать что-то однозначно по ней — сложно. Это потому что Time Profiler пытается показать, где мы сильно нагрузили CPU, а мы этого и не делали: сходить в сеть долго, но совсем не тяжело.
Чтобы увидеть долгие, но при этом не тяжелые операции, нужно в приложении залогировать их с помощью os_signpost:
// вызов os_signpost требует инстанс OSLog
let osLog = OSLog(subsystem: "LogsDemo", category: "")
// генерируем рандомный ID
// по этому ID мы свяжем начало и конец замера
let signpostID: UInt64 = .random
// логируем начало замера
let startMessage = "Start: Request"
os_signpost(.begin,
log: osLog,
name: name,
signpostID: signpostID,
"%{public}@", startMessage)
// выполняем код, который хотим замерить
let request = SomeNetworkRequest()
let data = networkService.getData(for: request)
// логируем конец замера
let endMessage = "End: Request"
os_signpost(.end,
log: osLog,
name: "",
signpostID: signpostID,
"%{public}@", endMessage)Перезапускаем запись в Time Profiler, а там наших логов нет. Дело в том, что Time Profiler не показывает сайнпосты, если его принудительно не попросить. Давайте попросим: справа сверху жмём на плюсик и находим в списке os_signpost. Добавляем его двойным кликом или перетаскиваем в список слева:
Снова запускаем запись. Приложение запускается и все наши замеры отображаются внутри os_signpost:
Названия замеров
Каждый замер отображается отдельной синей полоской. Сейчас у нас целый набор из таких замеров, и что какой отображает — не ясно. Как отличать, где какая функция рисуется на графике? Time Profiler умеет подписывать названия замеров, если увеличить по высоте наш таймлайн. Для этого наведём курсор на нижнюю границу таймлайна в левой панельке (выделен синим на скрине) и растянем его:
Но ориентироваться в такой пачке замеров сложно.
Источник лога
На самом деле, в Time Profiler можно подать источник лога, и тогда он сгруппирует всё по нему.
Для этого надо в OSLog передать название текущего модуля и файла:
let osLog = OSLog(subsystem: module, category: filename)А в os_signpost — имя нашей функции:
os_signpost(.begin,
log: osLog,
name: function,
signpostID: signpostID,
"%{public}@", endMessage)Если вы не понимаете, откуда взялось название модуля, файла и функции — прочитайте предыдущую статью, я там рассказываю.
Теперь в Time Profiler все замеры аккуратно рассортированы по модулям, файлам и функциям:
Можно развернуть каждый модуль и увидеть конкретные файлы:
Улучшенные названия замеров
Теперь все замеры сгруппированы по модулям и файлам, а так же напротив каждого подписано его имя. Но у нас в сетевом модуле все замеры названы одинаково. Чтобы научиться их различать, добавляем URL запроса в сообщение окончания замера.
let message = "End: \(url)"И вот уже замеры стали гораздо полезнее:
Статистика
На скрине выше в нижней панельке можно увидеть, сколько раз вызвался каждый замер, сколько он занял в среднем, а также минимальные и максимальные значения. Можно, например, замерить, как долго идёт парсинг ответов от API в модели данных. Это можно посмотреть как для конкретного файла, так и для модуля целиком — смотря что вы выберите в левой панельке в Time Profiler.
Группировка статистики идёт в том числе и по сообщениям в замерах. В моём примере для всех сетевых запросов начальные сообщения одинаковые — Start: Request. А вот конечное сообщение у каждого URL своё. Это позволяет смотреть статистику в удобном виде как по всем запросам сразу, так и по каждому по отдельности.
А что ещё можно?
Time Profiler умеет показывать не только замеры, но и просто одномоментные события: логи с обычными текстовыми сообщениями или с ошибками.
Чтобы такое получилось и у вас, надо в os_signpost передать тип события .event:
let message = "Did save response"
os_signpost(.event,
log: osLog,
name: name,
signpostID: signpostID,
"%{public}@", message)
Рисует он такое обычными точками на таймлайне. Если навести курсор на точку, то можно узнать что именно в тот момент произошло:
Заключение
Связка os_signpost и Time Profiler — мощный инструмент. Вы можете замерить сколько времени у вас выполнялась те или иные расчёты, сколько раз вы сходили в сеть, а также узнать, какая модель данных дольше всего парсилась.
Но для его использования приходится писать много сопроводительного кода. Надо и замеры выполнения функций форматировать, обычные сообщения правильно показывать, и ошибки как-то ещё припихнуть. Как этого избежать — расскажу в следующей статье.
Подписывайтесь на телеграм-канал Dodo Mobile, чтобы узнать больше о мобильной разработке в Dodo Engineering в коротком формате.