[Перевод] Расставляем сообщения Android Logcat на шкале времени VTune Amplifier
Известная пословица гласит: «Один ум хорошо, а два лучше». Она справедлива не только для житейских ситуаций, но и в делах отладки приложений. Объединяя «умы» различных программных средств, можно получить не только количественные, но и качественные преимущества. Например, союз Android Logcat и VTune Amplifier — это как раз такой случай.
Android Logcat — это мощный отладочный инструмент. С его помощью можно получить массу полезной информации о системе или о приложениях с привязкой к временным меткам. Android предоставляет разработчикам стандартные API для логирования данных. Этими API удобно пользоваться при разработке и отладке приложений: достаточно добавить вызовы соответствующих команд в нужные места программного кода. Команды выводят сообщения в Logcat, где их можно просмотреть.
VTune Amplifier для специализированных систем — это программный комплекс для профилирования. С его помощью можно анализировать и оптимизировать производительность операционных систем и приложений. VTune Amplifier имеет весьма полезное средство — панель шкалы времени. Оно позволяет разработчику просматривать сведения о производительности, привязанные ко времени.
Как сопоставить сообщения из Logcat с временной шкалой VTune Amplifier? Это даст разработчикам возможность видеть сообщения из Logcat совместно со сведениями о производительности из временной шкалы VTune Amplifier. Как результат — можно будет узнать, что именно произошло в конкретное время и тут же понять, какую нагрузку на систему оказало то или иное событие, как оно повлияло на производительность.
Intel VTune Amplifier способен обрабатывать и интегрировать в собственные наборы данных, полученные с помощью его встроенных инструментов, дополнительные сведения о производительности. Они могут быть получены с помощью внешних сборщиков данных или средствами тестируемого приложения. Для того чтобы добавить в VTune Amplifier внешние данные, нужен CSV-файл, обладающий определенной структурой, в котором находятся собранные сведения. Этот файл, для дальнейшей работы с ним, надо загрузить в VTune Amplifier.
Подробности о создании собственных CSV-файлов с данными можно найти в руководстве пользователя VTune Amplifier. В частности, в разделе VTune Amplifier > User«s Guide > External Data Import есть сведения о том, как создавать такие файлы. Имеются там и примеры их внутренней структуры. Для того чтобы сообщения из Logcat оказались на временной шкале VTune, нужно, следуя руководству, преобразовать их в CSV-файл и загрузить полученный файл в VTune Amplifier.
Пример
Рассмотрим пример. Имеется приложение «com.example.Thread1». В нём есть функция, в которой выполняются тяжёлые вычисления. Вот как она, в общих чертах, выглядит:
void myfunction ()
{
Log.v("MYTEST", "start block 1");
{
...//вычислительный блок 1
}
Log.v("MYTEST", "start block 2");
{
...//вычислительный блок 2
}
Log.v("MYTEST", "my computation finished");
}
Обратите внимание на то, что перед профилированием Android-приложения с помощью VTune Amplifier, приложение нужно подготовить. А именно, в его файле AndroidManifest.xml, в разделе
Установить debug-версию приложения на Android-устройство можно, например, с помощью стандартных средств Android Studio. А после установки приложения Android Studio нужно будет закрыть, иначе VTune Amplifier не сможет собрать данные. Для того чтобы совместить сбор Logcat-сообщений и профилирование в VTune Amplifier, Logcat понадобится запустить из командной строки. Универсальное средство, подходящее и тем, кто работает в Windows, и тем — кто пользуется Linux — это оболочка bash.
В Linux-системах bash присутствует по умолчанию. А вот если ваша хост-система — Windows, вам потребуется дополнительное ПО. Мы рекомендуем Cygwin. Это приложение позволяет пользоваться bash-окружением в Windows. Подробности о работе с Logcat из командной строки можно узнать здесь.
По умолчанию, если мы, например, запустим Logcat командой »$ adb logcat -v threadtime», данные будут выводиться на экран. Гораздо удобнее перенаправить вывод во внешний файл. Делается это такой командой:
$ adb logcat -v threadtime > log.txt
Мы перенаправляем вывод от Logcat в файл log.txt, который будет помещен в текущей директории.
Начинать сбор Logcat-данных нужно до запуска профилирования в VTune Amplifier, а останавливать (Ctrl + C в командной строке) — после.
Вернемся к нашему примеру. Судя по временной шкале VTune Amplifier, которая показана ниже, функция была выполнена 6 раз. ID главного потока приложения — 12271. Коричневые столбцы — это сведения о производительности (процессорное время), которые были собраны в ходе профилирования с помощью VTune Amplifier.
Просмотр результатов анализа приложения на шкале времени VTune Amplifier
При каждом выполнении функции, если собирать Logcat-сообщения командой вида «logcat -v threadtime», мы получим набор данных, показанный ниже.
01-12 11:13:19.090 2174 2174 V MYTEST : start block 1
01-12 11:13:19.260 2174 2174 V MYTEST : start block 2
01-12 11:13:19.500 2174 2174 V MYTEST : my computation finished
Получив эти данные, мы можем конвертировать их в CSV-файл подходящего формата, который подходит для загрузки в VTune Amplifier. В соответствии с документацией к VTune Amplifier, нужный нам CSV-файл может выглядеть так:
name,start_tsc.UTC,end_tsc,pid,tid
V/MYTEST : start block 1,2015-01-12 03:13:19.090,2015-01-12 03:13:19.090,2174,2174
V/MYTEST : start block 2,2015-01-12 03:13:19.260,2015-01-12 03:13:19.260,2174,2174
V/MYTEST:my computation finished,2015-01-12 03:13:19.500, 2015-01-12 03:13:19.500, 2174, 2174
Здесь, в качестве столбца данных «name», используется тег, который применялся при логировании, и строка сообщения. Время сообщения попадает в столбцы start_tsc.UTC и end_tsc. ID процесса и ID потока представлены в CSV-файле, соответственно, как pid и tid. Поля разделены запятыми.
Теперь нужно перейти в VTune Amplifier и выполнить команду Analysis Type > Import from CSV, выбрав для импорта только что созданный файл с данными. Приложение загрузит данные и отобразит сообщения из Logcat на временной шкале со сведениями о производительности. На рисунке ниже показано, как перемещение мыши к маленькому жёлтому треугольнику, который указывает на точку расположения сообщения, выводит всплывающее окно с данными из Logcat, которые были сгенерированы нашим приложением.
Просмотр сообщений из Logcat на шкале времени VTune Amplifier
Вот несколько советов, которые касаются создания CSV-файлов.
- Те отметки времени, которые отображаются в Logcat, берутся из Android OS. Они привязаны к часовому поясу, который выставлен на устройстве. Их, при создании CSV-файла, нужно поменять на отметки времени в стандарте UTC. Именно они нужны для успешного импорта данных в VTune Amplifier.
- В имени CSV-файла должно быть указано имя хоста (hostname), на котором осуществляется сбор данных с помощью стороннего приложения. Например, имя файла может иметь такую структуру: [user-defined]-hostname-
.csv. Для целевых устройств, работающих под управлением Android, имя хоста есть в файле /proc/sys/kernel/hostname. Просмотреть его можно с помощью оболочки ADB. - Строковые данные, которые располагаются в столбце «name», можно настроить в соответствии с потребностями разработчика. В примере, рассмотренном выше, мы обошлись без изысков: в столбец «name» было помещено всё Logcat-сообщение. Обратите внимание на то, что в строковых данных, которые предназначены для столбца «name», не должно быть запятых. Знак запятой — это зарезервированный символ-разделитель, который не должен появляться в строках.
- В формат CSV можно сконвертировать и сообщения ядра системы (например, от «dmesg»), импортировать в VTune Amplifier и просмотреть на временной шкале. Эта возможность весьма полезна для системных программистов, например, для тех, кто разрабатывает модули ядра или драйверы устройств. У сообщений из ядра системы ID процесса и потока должны быть установлены в 0. Обратите внимание и на то, что отсчёт отметок времени системных сообщений (например, от того же «dmesg») начинается с момента загрузки системы. Их нужно преобразовать так, чтобы они указывали на UTC-время вывода сообщений. Например, можно воспользоваться такой формулой расчёта временных меток сообщений: «Время сообщения» = «текущее время» — «время с начала работы системы» + «отметка времени сообщения». Под «текущим временем» здесь понимается текущее системное время. Его можно получить, воспользовавшись командой «date» в оболочке ADB. «Время с начала работы системы» — это время, которое прошло с начала загрузки ОС. Его можно найти в файле »/proc/uptime».
Вспомогательный скрипт
Мы создали экспериментальный bash-скрипт (logcat2vtune.sh), который позволяет упростить вышеописанные действия. Вы можете воспользоваться им для того, чтобы автоматизировать сбор Logcat-данных и создание CSV-файла. Скрипт может собирать сообщения, которые выводят в Logcat приложения, а так же — сообщения от ядра системы. Кроме того, он считывает сведения о целевой системе, разбирает результаты логирования и автоматически генерирует CSV-файлы.
Для того чтобы воспользоваться этим скриптом, вам понадобится bash-окружение. Как было сказано выше, в Linux-системах это стандартная рабочая среда, а в Windows можно воспользоваться, например, Cygwin.
Для того чтобы получить CSV-файл с данными в ходе профилирования с помощью VTune Amplifier, нужно сделать следующее:
- Проверьте, доступен ли «adb» из командной строки. После этого запустите скрипт logcat2vtune.sh, указав необходимые ключи. Например, так: > ./logcat2vtune.sh -c logcat -g MYTEST
- Запустите сбор данных о производительности в VTune Amplifier. Это можно сделать как из окна приложения, так и через командную строку.
- Остановите сбор данных в VTune Amplifier.
- Нажмите любую кнопку в окне командной строки, где работает logcat2vtune.sh, тем самым остановив сбор данных. Скрипт прочитает собранные данные логирования, разберет их с использованием регулярных выражений bash и сконвертирует в CSV-файл. Этот файл можно найти в текущей папке, с которой вы работаете из командной строки.
- Загрузите полученный CSV-файл в VTune Amplifier. Теперь сообщения из Logcat можно просмотреть на временной шкале.
Вот несколько типичных примеров использования скрипта.
$logcat2vtune.sh -c logcat -g MYTEST
Эта команда позволяет собрать данные Logcat, отобрать сообщения со строкой «MYTEST» и сгенерировать CSV-файл. Данные Logcat скрипт собирает с помощью следующей команды:
$adb shell logcat -v threadtime
«MYTEST» — это строка, по которой осуществляется фильтрация сообщений из Logcat. Мы настоятельно рекомендуем пользоваться фильтрами, так как Logcat может выводить весьма длинные списки сообщений, в то время как разработчиков обычно интересуют лишь сообщения от их процесса. В качестве фильтра можно использовать имя тега Logcat-сообщений, ID процесса, ID потока или любую другую строку. Здесь можно использовать запятые, можно указывать несколько строк. Сообщения, в которых найдено совпадение с любой строкой, указанной при запуске скрипта с ключом »-g», будут отобраны и организованы в виде CSV-файла.
$logcat2vtune.sh -c dmesg -g MYDRIVER
С помощью такой команды можно собрать сообщения от «dmesg», отфильтровать их по строке «MYDRIVER» и создать CSV-файл.
$logcat2vtune.sh -c logcatk -g MYTEST,MYDRIVER
Эта команда позволяет собрать и обычные сообщения из Logcat, и сообщения от ядра, отфильтровать их по строкам «MYTEST» или «MYDRIVER» и создать CSV-файл. В результате на временной шкале VTune Amplifier можно будет просмотреть сообщения от обычных приложений пользовательского уровня и сообщения ядра от «dmesg». Эти данные скрипт собирает с помощью следующей команды:
>adb shell logcat -v threadtime -f /dev/kmsg | adb shell cat /proc/kmsg
В данном случае на шкале времени можно будет видеть сообщения от vmlinux с TID 0 и логи пользовательского уровня из Logcat с TID 1922.
Просмотр Logcat-сообщений, полученных из различных потоков, на шкале времени VTune Amplifier
Для того чтобы узнать подробности о работе со скриптом, воспользуйтесь следующей командой: «logcat2vtune.sh –h».
При желании, вы можете настроить скрипт под собственные нужды. Пожалуйста, учитывайте, что «logcat2vtune.sh» — это экспериментальный проект, он не прошёл всеобъемлющего тестирования. Если при работе с ним обнаружатся какие-либо проблемы — вы можете сообщить нам об этом.
Выводы
То, о чём мы здесь рассказали, применимо к продуктам Intel System Studio 2015 и Intel System Studio 2016. В материале освещена работа с хост-системами Windows (IA-32, Intel 64) и Linux (IA32, Intel 64). В качестве целевой системы рассмотрена ОС Android.
Воспользовавшись инструментами и приёмами работы, описанными выше, вы можете вывести профилирование и отладку Android-приложений на более высокий уровень, совместив информацию из Android Logcat с данными о производительности из VTune Amplifier. Надеемся, это поможет вашим приложениям покорить новые вершины производительности и экономичности.
