Логи в iOS, эпизод 2: os_signpost

e7b7a0a46cfa8247f76c94045184eee6.png

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

Сегодня расскажу, как Apple предлагает решать эту проблему с помощью логов.

В прошлой статье мы научились логировать в Console.app, чтобы удобно ориентироваться в логах. Но туда мы складывали обычные текстовые сообщения. Да, они идут в хронологическом порядке. Да, в них есть вся необходимая информация. Но вот есть у нас сетевой слой, и в нём, например, стоит ограничение — не более 5 параллельных запросов одновременно. А в логах мы видим просто пачку сообщений Start: Request и End: Request, где напротив каждого End стоит длительность выполнения запроса:

ed3ac2252d0686b0a7bf3e68ad8c44de.png

По таким логам сложно понять, что началось вместе с чем и когда оно закончилось, потому что конечные логи визуально никак не связаны с начальными. Давайте свяжем. Но для этого придётся os_log и Console.app заменить другими инструментам.

Time Profiler

Apple предлагает смотреть замеры в специальном инструменте — Time Profiler, он поставляется вместе с Xcode.

Для запуска нужно в своём проекте нажать Product → Profile. Появится окно с целым набором инструментов:

85bcdc4b265eaee8a0b6ea34673d1f94.png

Среди них надо выбрать именно Time Profiler. В открывшемся окне слева сверху жмём на кнопку записи. В инструменте сразу начинают рисоваться какие-то графики:

dc0671e90abf2bc4c9d8499b6e81b22c.png

Конечно, здесь видно какую-то статистику внутри приложения, но сказать что-то однозначно по ней — сложно. Это потому что 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. Добавляем его двойным кликом или перетаскиваем в список слева:

bd48bf547dce5521d20a3eebaf4e259a.png

Снова запускаем запись. Приложение запускается и все наши замеры отображаются внутри os_signpost:

ed0b29c0900ab885b9099bb07de718f8.png

Названия замеров

Каждый замер отображается отдельной синей полоской. Сейчас у нас целый набор из таких замеров, и что какой отображает — не ясно. Как отличать, где какая функция рисуется на графике? Time Profiler умеет подписывать названия замеров, если увеличить по высоте наш таймлайн. Для этого наведём курсор на нижнюю границу таймлайна в левой панельке (выделен синим на скрине) и растянем его:

9bd02a9d47e3c265f4b6038420aae0a7.png

Но ориентироваться в такой пачке замеров сложно.

Источник лога

На самом деле, в 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 все замеры аккуратно рассортированы по модулям, файлам и функциям:

В панельке слева появились модули Auth, Network. Newsfeed. В модуле LogsDemo лежат замеры из основного приложения.В панельке слева появились модули Auth, Network. Newsfeed. В модуле LogsDemo лежат замеры из основного приложения.

Можно развернуть каждый модуль и увидеть конкретные файлы:

В модуле Newsfeed есть замеры из 3 файлов: Newsfeed, NewsfeedParser и Storage.В модуле Newsfeed есть замеры из 3 файлов: Newsfeed, NewsfeedParser и Storage.

Улучшенные названия замеров

Теперь все замеры сгруппированы по модулям и файлам, а так же напротив каждого подписано его имя. Но у нас в сетевом модуле все замеры названы одинаково. Чтобы научиться их различать, добавляем URL запроса в сообщение окончания замера.

let message = "End: \(url)"

И вот уже замеры стали гораздо полезнее:

Каждый замер сетевого запроса говорит, на какой URL он шёл.Каждый замер сетевого запроса говорит, на какой 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)

Рисует он такое обычными точками на таймлайне. Если навести курсор на точку, то можно узнать что именно в тот момент произошло:

822e4483808ef02b2a5d2ec7dde40854.png

Заключение

Связка os_signpost и Time Profiler — мощный инструмент. Вы можете замерить сколько времени у вас выполнялась те или иные расчёты, сколько раз вы сходили в сеть, а также узнать, какая модель данных дольше всего парсилась.

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

Подписывайтесь на телеграм-канал Dodo Mobile, чтобы узнать больше о мобильной разработке в Dodo Engineering в коротком формате.

© Habrahabr.ru