В предыдущей статье мы узнали о причинах нестабильности unit-тестов и способах борьбы с этим. Теперь мы хотим рассмотреть один из новых инструментов Apple для отладки и профилирования кода. Речь о представленном на WWDC 2018 фреймворке для логирования os_log, который был расширен инструментом для анализа производительности — os_signpost.



В одном из спринтов нам поставили задачу реализовать генерацию pdf-документа на client-side. Мы выполнили задачу и успешно продемонстрировали результаты команде. Но нам захотелось убедиться в эффективности технических нюансов принятого решения. В этом нам помог signpos. С ним нам удалось ускорить отображение документа в несколько раз.

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

Глубже в проблематику

На телефоне пользователя есть много приложений, и все они используют общие ресурсы системы: CPU, RAM, network, battery и т.д. Если ваше приложение выполняет свои задачи и не падает, это еще не значит, что оно работает эффективно и корректно. Ниже опишем кейсы, с которыми потенциально вы можете столкнуться.

Неоптимальный алгоритм может привести к длительной загрузке CPU.

• На старте приложения, после 20 секунд ожидания, система завершит работу приложения, а пользователь не увидит даже первый экран. При этом система выставит crash report, отличительной особенностью которого будет exception type — EXC_CRASH (SIGKILL) с типом 0x8badf00d.
  
• Ресурсоемкие процессы в background-потоке могут отразиться на отзывчивости UI, повысить потребление батареи и принудительно завершить приложение системой (в случае длительного перегрева CPU).
  

RAM-кейсы:

В спецификациях к телефонам на сайте Apple не указана информация по RAM, но в других источниках приводится следующее распределение памяти по моделям телефонов:

Type	4S	5	5C	5S	6	6P	6S	6SP
RAM, ГБ	0.5	1	1	1	1	1	2	2

Type	SE	X	7	7P	8	8P	XS	XSM	XR
RAM, ГБ	2	3	2	3	2	3	4	4	3

Когда свободной оперативки остается слишком мало, iOS начинает искать память для освобождения, параллельно рассылая memory warning во все запущенные приложения. Этот процесс неявно влияет на CPU и батарею устройства. Если memory warning игнорируется, а выделение памяти продолжается, то система принудительно завершает процесс приложения. Для пользователя это выглядит как crash, при этом в crash report будут отсутствовать backtraces.

Чрезмерное использование сетевых запросов. Это также приводит к уменьшению времени жизни батареи. Дублирование запросов и/или отсутствие отмены лишних запросов дополнительно приводит к неэффективному использованию CPU.

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

Интеграция инструмента в проект

На верхнем уровне процесс формирования PDF состоит из трёх шагов:

1. получение данных по сети;
2. формирование документа;
3. отображение на экране — мы решили раздробить и логировать этапы генерации документа, начиная с нажатия пользователем кнопки «Сформировать» и заканчивая отображением документа на экране.

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

import os.signpost

let pointsOfInterestLog = OSLog(subsystem: "com.example.your-app", category: . pointsOfInterest)
let networkLog = OSLog(subsystem: "com.example.your-app", category: "NetworkOperations")

os_signpost(.event, log: pointsOfInterestLog, name: "Start work")
os_signpost(.begin, log: networkLog, name: "Overall work")

for element in elements {
    os_signpost(.begin, log: networkLog, name: "Element work")
    makeWork(for: element)
    os_signpost(.end, log: networkLog, name: "Element work")
}

os_sginpost(.end, log: networkLog, name: "Overall work")

Шаги для использования signpost здесь следующие:

• Импортировать фреймворк os.signpost.
  
• Создать экземпляр OSLog. Стоит учитывать, что есть несколько типов событий: для интервальных событий (например, сетевой запрос) можно использовать произвольную категорию, а для одномоментных событий (например, нажатие по кнопке) предопределенную категорию pointsOfInterest / OS_LOG_CATEGORY_POINTS_OF_INTEREST.
  
• Для интервальных событий вызвать функцию os_signpost c типом .begin и .end в начале и в конце исследуемого этапа. Для одномоментных событий использовать тип .event.
  
• Если исследуемый код может выполняться асинхронно, то добавить Signpost ID, что позволит разделить интервалы однотипных операций с разными объектами.
  
• Опционально можно добавить дополнительные данные (metadata) к отправляемым событиям. Например, размер загруженных по сети изображений или номер генерируемой PDF-страницы. Такая информация поможет понять, что конкретно происходит в исследуемой стадии исполнения кода.
  

Аналогично на obj-c:

@import os.signpost;

os_log_t pointsOfInterestLog = os_log_create("com.example.your-app",   OS_LOG_CATEGORY_POINTS_OF_INTEREST);
os_log_t networkLog = os_log_create("com.example.your-app",   "NetworkOperations");
os_signpost_id_t operationIdentifier = os_signpost_id_generate(networkLog);

os_signpost_event_emit(pointsOfInterestLog, operationIdentifier, "Start work");
os_signpost_interval_begin(networkLog, operationIdentifier, "Overall work");

for element in elements {	
    os_signpost_id_t elementIdentifier = os_signpost_id_make_with_pointer(networkLog, element);
    os_signpost_interval_begin(networkLog, elementIdentifier, "Element work");
    [element makeWork];
    os_signpost_interval_end(networkLog, elementIdentifier, "Element work");
}

os_signpost_interval_end(networkLog, operationIdentifier, "Overall work");

На заметку. Если проект должен запускаться на iOS до 12.0 версии, Xcode предложит обернуть вызовы os_signpost в конструкции if #available. Чтобы не загромождать код, можно вынести эту логику в отдельный класс.

Стоит учесть, что os_signpost требует статический строковый литерал в качестве параметра имени события. Чтобы добавить более строгую типизацию, можно создать enum с типами событий, а в реализации класса сопоставлять их в строковые литералы. Вынесение OSLog в отдельный класс позволит добавить логику его отключения для релизной схемы (для этого есть отдельная команда OSLog).

import os.signpost

let networkLog: OSLog

if ProcessInfo.processInfo.environment.keys.contains("SIGNPOSTS_FOR_NETWORK") {
    networkLog = OSLog(subsystem: "com.example.your-app", category: "NetworkOperations"
} else {	
    networkLog = .disabled
}

К маркировке событий можно добавлять значения из любых свойств со следующими type decoders для удобного форматирования:

Value type	Custom specifier	Example output
time_t	%{time_t}d	2016-01-12 19:41:37
timeval	%{timeval}.*P	2016-01-12 19:41:37.774236
timespec	%{timespec}.*P	2016-01-12 19:41:37.2382382823
errno	%{errno}d	Broken pipe
iec-bytes	%{iec-bytes}d	2.64 MiB
bitrate	%{bitrate}d	123 kbps
iec-bitrate	%{iec-bitrate}d	118 Kibps
uuid_t	%{uuid_t}.*16P %{uuid_t}.*P	10742E39-0657-41F8-AB99-878C5EC2DCAA

Теперь при профилировании приложения события от os_signpost будут отправляться в Instruments в виде табличных данных. Для того чтобы перейти в инструменты, воспользуйтесь сочетанием клавиш Cmd+I, затем выберите необходимый для профилирования инструмент. Чтобы увидеть размеченные данные, достаточно включить инструменты os_signpost и Point of Interest в правой части интерфейса инструмента.



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

Примеры использования

Кейс №1. PDFKit vs WKWebView

За счет использования os_signpost мы добились того, что для небольших документов (на пару страниц) самым длительным этапом стал последний шаг — отображение документа — а не работа с сетью или графикой. Это привело нас к решению заменить WKWebView на PDFView, что ускорило отображение документа с 1,5 секунды до 30 миллисекунд. На графиках это выглядит следующим образом:


Отображение PDF документа (WKWebView) в Time Profiler


Отображение PDF документа (PDFView) в Time Profiler

Полученные данные можно имплементировать в другие инструменты, которые предоставляет XCode. Как показал инструмент Allocations, выигрыш в скорости загрузки был достигнут за счет увеличения использования RAM.

Кейс №2. LowMemory Warning

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

Как известно, при использовании NSOperationQueue метод cancelAllOperation освобождает существующую очередь, но не останавливает уже запущенные операции. Отсюда делаем вывод, что в реализации операции нужно периодически определять её состояние и прекращать работу. Тем самым освобождая ресурсы, если ей выставляется статус Cancelled.

На следующем шаге перед нами асинхронная операция, которую надо проверять на отмену. Но при этом нет ясности, с какой частотой делать данную проверку. У нас было два варианта — построковая проверка и постраничная. os_signpost помог и тут. Как оказалось, добавив проверку на отмену в построчный цикл отрисовки таблицы в документе, мы увеличили время формирования документа (на 150 страниц) в 2 раза. Второй вариант оказался более оптимальным по показателям и фактически не увеличил время создания документа. В итоге при получении события memory warning мы отменяем операцию программно и выводим пользователю экран ошибки.

Чтобы убедиться, что память действительно освобождается, мы можем также использовать os_signpost. В этот раз за счет добавления маркера о начале события в методе didRecieveMemoryWarning и маркера об окончании во viewDidLoad экрана ошибки. Кстати, эмулировать событие недостаточной памяти можно в симуляторе (shift+command+m).

Кейс №3. Update Constraints

Signpost может оказаться полезным в процессе верстки. Для создания констрейнтов мы используем фреймворк masonry. В документации к фреймворку сказано, что для создания констрейтов рекомендуется использовать метод updateConstraints(). Но Apple категорически не рекомендует так делать, и в этом можно убедиться с помощью разметки signpost.



Согласно документации Apple, updateConstraints стоит использовать только для изменения constraints, если мы не можем сделать это в месте возникновения изменения.



Проанализировав полученные результаты, мы сделали вывод, что в нашем приложении вызов updateConstraints происходит не так часто — примерно при каждом появлении view на экране.
Несмотря на это, во избежание потенциальных дефектов с performance, мы советуем следовать советам компании Apple по данному вопросу.

Выводы

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

В следующей статье мы рассмотрим, как можно использовать полученную от signpost информацию более эффективно за счет написания собственной экспертной системы (Custom Instruments).

---

Полезные ссылки

• Measuring Performance Using Logging (WWDC)
  
• Creating Custom Instruments (WWDC)
  
• What’s New in Energy Debugging (WWDC)
  
• iOS Memory Deep Dive (WWDC)
  
• Practical Approaches to Great App Performance (WWDC)
  
• High Performance Auto Layout (WWDC)
  
• Understanding and Analyzing Application Crash Reports
  
• Logging
  
• List of iOS devices
  
• Using Signposts for Performance Tuning on iOS
  
• Getting started with signposts
  
• os_signpost API ??
  

Статью писали вместе с @victoriaqb — Викторией Кашлиной, iOS-разработчиком.