В предыдущей статье мы узнали о причинах нестабильности unit-тестов и способах борьбы с этим. Теперь мы хотим рассмотреть один из новых инструментов Apple для отладки и профилирования кода. Речь о представленном на WWDC 2018 фреймворке для логирования os_log, который был расширен инструментом для анализа производительности — os_signpost.
В одном из спринтов нам поставили задачу реализовать генерацию pdf-документа на client-side. Мы выполнили задачу и успешно продемонстрировали результаты команде. Но нам захотелось убедиться в эффективности технических нюансов принятого решения. В этом нам помог signpost. С ним нам удалось ускорить отображение документа в несколько раз.
Чтобы узнать побольше о технологии применения os_signpost, посмотреть, где он может вам помочь и как уже помог нам, заходите под кат.
На телефоне пользователя есть много приложений, и все они используют общие ресурсы системы: CPU, RAM, network, battery и т.д. Если ваше приложение выполняет свои задачи и не падает, это еще не значит, что оно работает эффективно и корректно. Ниже опишем кейсы, с которыми потенциально вы можете столкнуться.
Неоптимальный алгоритм может привести к длительной загрузке CPU.
RAM-кейсы:
В спецификациях к телефонам на сайте Apple не указана информация по RAM, но в других источниках приводится следующее распределение памяти по моделям телефонов:
Когда свободной оперативки остается слишком мало, iOS начинает искать память для освобождения, параллельно рассылая memory warning во все запущенные приложения. Этот процесс неявно влияет на CPU и батарею устройства. Если memory warning игнорируется, а выделение памяти продолжается, то система принудительно завершает процесс приложения. Для пользователя это выглядит как crash, при этом в crash report будут отсутствовать backtraces.
Чрезмерное использование сетевых запросов. Это также приводит к уменьшению времени жизни батареи. Дублирование запросов и/или отсутствие отмены лишних запросов дополнительно приводит к неэффективному использованию CPU.
Не стоит забывать и про CoreLocation. Чем чаще и точнее мы запрашиваем местоположение пользователя, тем больше тратится батарея девайса. Чтобы проверить корректность обработки описанных случаев, мы предлагаем воспользоваться os_signpost для профилирования процессов приложения и последующего анализа полученных данных.
На верхнем уровне процесс формирования PDF состоит из трёх шагов:
Допустим, перед нами стоит задача проанализировать асинхронный сетевой запрос. Разметка в коде будет выглядеть следующим образом:
Шаги для использования signpost здесь следующие:
Аналогично на obj-c:
На заметку. Если проект должен запускаться на iOS до 12.0 версии, Xcode предложит обернуть вызовы os_signpost в конструкции if #available. Чтобы не загромождать код, можно вынести эту логику в отдельный класс.
Стоит учесть, что os_signpost требует статический строковый литерал в качестве параметра имени события. Чтобы добавить более строгую типизацию, можно создать enum с типами событий, а в реализации класса сопоставлять их в строковые литералы. Вынесение OSLog в отдельный класс позволит добавить логику его отключения для релизной схемы (для этого есть отдельная команда OSLog).
К маркировке событий можно добавлять значения из любых свойств со следующими type decoders для удобного форматирования:
Теперь при профилировании приложения события от os_signpost будут отправляться в Instruments в виде табличных данных. Для того чтобы перейти в инструменты, воспользуйтесь сочетанием клавиш Cmd+I, затем выберите необходимый для профилирования инструмент. Чтобы увидеть размеченные данные, достаточно включить инструменты os_signpost и Point of Interest в правой части интерфейса инструмента.
По умолчанию события группируются по категориям и отображаются в виде таблицы, где подсчитывается их количество и статистика по времени выполнения. Дополнительно существует графическое отображение на временной шкале, что позволяет легко сопоставить полученные события с результатами в других инструментах. Также существует возможность кастомизации отображения статистики и написания экспертных систем — но эта тема достойна отдельной статьи.
За счет использования os_signpost мы увидели, что для небольших документов (на пару страниц) самым длительным этапом стал последний шаг — отображение документа — а не работа с сетью или графикой. Это привело нас к решению заменить WKWebView на PDFView, что ускорило отображение документа с 1,5 секунды до 30 миллисекунд. На графиках это выглядит следующим образом:
Отображение PDF документа (WKWebView) в Time Profiler
Отображение PDF документа (PDFView) в Time Profiler
Полученные данные можно имплементировать в другие инструменты, которые предоставляет XCode. Как показал инструмент Allocations, выигрыш в скорости загрузки был достигнут за счет увеличения использования RAM.
PDF-документ формируется асинхронно, а для его формирования необходимо выделение значительного объема памяти. В случае недостаточной памяти мы решили добавить возможность остановки асинхронной операции создания документа.
Как известно, при использовании NSOperationQueue метод cancelAllOperation освобождает существующую очередь, но не ос��анавливает уже запущенные операции. Отсюда делаем вывод, что в реализации операции нужно периодически определять её состояние и прекращать работу. Тем самым освобождая ресурсы, если ей выставляется статус Cancelled.
На следующем шаге перед нами асинхронная операция, которую надо проверять на отмену. Но при этом нет ясности, с какой частотой делать данную проверку. У нас было два варианта — построковая проверка и постраничная. os_signpost помог и тут. Как оказалось, добавив проверку на отмену в построчный цикл отрисовки таблицы в документе, мы увеличили время формирования документа (на 150 страниц) в 2 раза. Второй вариант оказался более оптимальным по показателям и фактически не увеличил время создания документа. В итоге при получении события memory warning мы отменяем операцию программно и выводим пользователю экран ошибки.
Чтобы убедиться, что память действительно освобождается, мы можем также использовать os_signpost. В этот раз за счет добавления маркера о начале события в методе didRecieveMemoryWarning и маркера об окончании во viewDidLoad экрана ошибки. Кстати, эмулировать событие недостаточной памяти можно в симуляторе (shift+command+m).
Signpost может оказаться полезным в процессе верстки. Для создания констрейнтов мы используем фреймворк masonry. В документации к фреймворку сказано, что для создания констрейтов рекомендуется использовать метод updateConstraints(). Но Apple категорически не рекомендует так делать, и в этом можно убедиться с помощью разметки signpost.
Согласно документации Apple, updateConstraints стоит использовать только для изменения constraints, если мы не можем сделать это в месте возникновения изменения.
Проанализировав полученные результаты, мы сделали вывод, что в нашем приложении вызов updateConstraints происходит не так часто — примерно при каждом появлении view на экране.
Несмотря на это, во избежание потенциальных дефектов с performance, мы советуем следовать советам компании Apple по данному вопросу.
В 2018 году Apple предоставили разработчикам возможность самостоятельно расширять инструменты профилирования. Конечно, можно использовать другие инструменты отладки: брейкпоинты, вывод в консоль, таймеры, самописные профайлеры. Но они отнимают больше времени на реализацию или не всегда дают полную картину происходящего.
В следующей статье мы рассмотрим, как можно использовать полученную от signpost информацию более эффективно за счет написания собственной экспертной системы (Custom Instruments).
Полезные ссылки
Статью писали вместе с @victoriaqb — Викторией Кашлиной, iOS-разработчиком.
В одном из спринтов нам поставили задачу реализовать генерацию pdf-документа на client-side. Мы выполнили задачу и успешно продемонстрировали результаты команде. Но нам захотелось убедиться в эффективности технических нюансов принятого решения. В этом нам помог signpost. С ним нам удалось ускорить отображение документа в несколько раз.
Чтобы узнать побольше о технологии применения 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 состоит из трёх шагов:
- получение данных по сети;
- формирование документа;
- отображение на экране — мы решили раздробить и логировать этапы генерации документа, начиная с нажатия пользователем кнопки «Сформировать» и заканчивая отображением документа на экране.
Допустим, перед нами стоит задача проанализировать асинхронный сетевой запрос. Разметка в коде будет выглядеть следующим образом:
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_signpost(.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-разработчиком.