Разработчик Игорь Любунчич (Igor Ljubuncic) уже делился с нами ускорением в статье "Snap speed improvements with new compression algorithm", где тестировали алгоритм сжатия LZO. Тестовый стенд приподнёс массу сюрпризов, таких как Fedora 32 Workstation запускает подопытного кролика Chromium в холодном запуске в snap быстрее, чем традиционно из RPM-пакета! Но данная удивительная история началась когда разработчики решили раскрутить проблему с долгим первоначальным стартом в 60 секунд, когда холодный старт занимает 10 секунд.
Предыдущая статья Улучшения скорости snap с новым алгоритмом сжатия из цикла.
Как уже было сказано выше, несложно заметить разницу в 6 раз и дело даже не в 60 сек против 10 сек. В этом плане соотношение 6 секунд против 1 так же интересно анализировать.
Как и в прошлой статье, использовался разработанный скрипт startup-time.sh, позволяющий засечь время запуска браузера Chromium (хотя тестировать можно любой софт). Чтобы моделировать первый холодный старт, достаточно удалять каталог ~/snap/chromium/ и очищать системные кеши. Тогда то впервые и была замечена такая сильная разница в 6 раз.
Сервис snapd предоставляет разработчикам и пользователям ряд инструментов, позволяющие устранять неполадки при запуске и работе программ в snap формате. Одной из возможностей является --trace-exec, позволяющая видеть при старте программы список задач и затраченное на них время. Данный вывод позволяет легко понять на чём нужно сосредоточиться для оптимизации старта.
Но, к сожалению, именно в исследовании с Chromium --trace-exec мало что рассказала.
Slowest 10 exec calls during snap run: 0.220s snap-update-ns 0.345s /usr/libexec/snapd/snap-confine 0.171s /usr/lib/snapd/snap-exec 0.181s /snap/chromium/1328/snap/command-chain/snapcraft-runner 1.830s /snap/chromium/1328/usr/lib/x86_64-linux-gnu/glib-2.0/gio-querymodules 1.887s /snap/chromium/1328/usr/lib/x86_64-linux-gnu/gdk-pixbuf-2.0/gdk-pixbuf-query-loaders 3.431s /snap/chromium/1328/bin/desktop-launch 0.425s /bin/cp 0.247s /usr/bin/snapctl 1.227s /snap/chromium/1328/bin/chromium.launcher Total time: 60.647s
Точно так же не помог и параметр --strace
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ------------------- 42.10 3.315633 3000 1105 86 futex 19.62 1.544763 3814 405 epoll_wait 15.25 1.201121 1814 662 poll 9.94 0.783167 6751 116 51 wait4 2.68 0.210840 149 1410 2 read 2.18 0.171819 14 12079 10122 openat 2.00 0.157887 22 6934 6600 access 1.39 0.109535 2960 37 execve 0.96 0.075822 15 4749 3388 stat
Информация интересная, но без конкретики. Показателен тот факт, что время, записанное в журнале strace, не совпадало со временем, потраченным на запуск. Как правило, такое несоответствие между общим временем выполнения и суммой его подзадач (и системных вызовов) указывает на вычисления (время когда ЦПУ перемалывал цифры).
Прежде чем начали смотреть счётчики ЦПУ, решили более подробно изучить содержимое каталога ~/snap/chromium/
Условно snap можно представить из 2 частей:
1) монтируемая файловая система (образ squashfs) только-для-чтения в каталог /snap/имя_snap_пакета/
2) доступная на запись ~/snap/имя_snap_пакета/
В каталоге ~/snap/имя_snap_пакета/ часто можно найти подкаталог common, который хранит конфигурации, которые сохраняются между атомарными обновлениями программы.
Например, в случае с браузером Chromium там можно ожидать увидеть профиль пользователя, а также любые кеши, такие как кеши шрифтов и шейдеров, и другую информацию, необходимую браузеру для поддержания согласованности и пользовательских данных при нескольких запусках.
Анализируя дату/время у каталогов и файлов была найдена подсказка. Между созданием подкаталога BrowserMetrics и символической ссылкой SingletonSocket был промежуток времени в ~50 секунд.
drwx------. 2 igor igor 4096 2020-10-26 12:15:56.952907984 +0000 BrowserMetrics lrwxrwxrwx. 1 igor igor 50 2020-10-26 12:16:47.236109348 +0000 SingletonSocket -> /tmp/.org.chromium.Chromium.zrTDlA/SingletonSocket
На этом этапе стало ясно, нужно разобраться что в данный момент делал Chromium.
Perf - мощный инструмент профилирования системы, использующий perf_events интерфейс в ядре Linux. Perf можно использовать по-разному, но если вы хотите просто и быстро получить отчёт об активности процессора, можно использовать команду record. Вы не будете отслеживать какое-либо конкретное приложение, но всё же сможете понять какие вычисления проводит данное ПО на простаивающем хосте.
Был запущен Perf в фоновом режиме и обнаружено масса интересных мест. В частности, из ~33000 событий - 6800 были вызваны Chromium, что составило 80,3% ЦПУ. Из этой части 91,8% приходилось на libfreetype.so.6.15.0 и libfontconfig.so.1.10.1.
Небольшая подборка показана ниже:
7.42% swapper [kernel.kallsyms] [k] mwait_idle_with_hints.constprop.0 4.40% chrome libfreetype.so.6.15.0 [.] 0x00000000000378fa 2.39% chrome libc-2.27.so [.] 0x000000000018f19d 1.95% chrome libfreetype.so.6.15.0 [.] FT_DivFix 1.05% chrome libfreetype.so.6.15.0 [.] 0x0000000000039645 0.86% chrome libfreetype.so.6.15.0 [.] FT_Outline_Get_CBox 0.85% chrome libfreetype.so.6.15.0 [.] 0x0000000000039233 0.69% chrome [kernel.kallsyms] [k] lzo1x_decompress_safe 0.67% chrome libfreetype.so.6.15.0 [.] 0x00000000000349b8 0.62% chrome libfreetype.so.6.15.0 [.] 0x000000000003a150 ...
Это указывает на возможную проблему с созданием кеша шрифтов, которая раньше влияла на первый старт программ в snap, но в значительной степени данная проблема решена. Тем не менее, какая-то похожая проблема затрагивает Chromium. Пришлось более подробно изучить кеши fontconfig.
Кеши сохраняются в ~/snap/имя_snap_пакета/common/.cache/. Там сохраняются различные типы кешей: fontconfig, GDK-PixBuf Loaders, модулей GIO, immodules, шейдеров MESA и другие.
Поскольку perf указывал на проблему с кешем шрифтов, то было относительно просто выяснить - основная ли это причина? Удаление всех кешей и сохранение каталога ~/snap/имя_snap_пакета/common/.cache/fontconfig/ привело к тому, что время первого запуска стало почти идентично времени холодного старта. Но всё равно нужно было определить - почему создание кеша шрифтов было таким медленным?
... -rw-rw-r--. 1 igor igor 104 2020-10-27 16:41:14.683992076 +0000 4c599c202bc5c08e2d34565a40eac3b2-le64.cache-7 -rw-rw-r--. 1 igor igor 176 2020-10-27 16:41:14.691992107 +0000 9dc4195ac9420d9178822dc735425b39-le64.cache-7 -rw-rw-r--. 1 igor igor 4928 2020-10-27 16:41:14.745992316 +0000 b3043b29744cf0a429678d296f5e4026-le64.cache-7 ...
По отметкам времени было обнаружено что большую часть времени заняло создание одного конкретного шрифта. Из 50 шрифтов - создание кеша 49 шрифтов заняло ~500 мс и этот один шрифт - вынудил создавать кеш 45 секунд!
Кеши - это двоичные файлы, но можно воспользоваться инструментом strings или текстовым редактором, чтобы увидеть внутри имя шрифта, для которого, собственно, и создавался кеш. Быстро было выяснено что имя проблемного шрифта - google-noto. Временное перемещение шрифта из папки /usr/share/fonts/ привело к тому, что время первого запуска стало равно холодному старту.
Естественно, цикл разработки и выпуска snap включает в себя ряд автоматических тестов, предназначенных для обнаружения возможных ошибок и регрессий, как в процессе сборки, так и во время выполнения приложения. Этот вопрос более подробно будет обсуждён в следующих статьях. Здесь же стоит упомянуть, что проблема, с которой столкнулись, была новой и специфичной для браузера Chromium.
Более того, в генерации шрифтов не было ничего явно неправильного. Поскольку в системе может быть огромное количество шрифтов, то создание их кешей может занять много времени. Вот почему данное исследование было увлекательной историей.
Конечно, удаление шрифтов не решение проблемы.
В ходе исследования, было определёно несколько моментов. Во-первых, snap пакет Chromium не использовал несколько полезных возможностей, которые дают расширения snapcraft (extensions). Благодаря им, уменьшается размер snap и программа быстрее стартует за счёт уже предзагруженных в память общих ресурсов.
Самый простой пример - посмотреть на что-то вроде gnome-calculator
... apps: gnome-calculator: command: usr/bin/gnome-calculator extensions: [gnome-3-34] plugs: - gsettings - network ...
Если рассмотреть snapcraft.yaml у пакета snap gnome-calculator, то можно увидеть:
plugs: gnome-3-34-1804: default-provider: gnome-3-34-1804 interface: content target: $SNAP/gnome-platform
Такой подход помогает разработчикам программы с её лучшей интеграцией в среду рабочего стола пользователя и уменьшить итоговый размер snap пакета. Как отдельный пример, стоит напомнить ситуацию с KDE Kcalc, который весит около 1 мегабайта, так как использует (connect) к content snap с KDE Framework. В противном случае, типичный размер составил бы около 100 Мб.
Что касается разработки, Snapcraft 4.4 даст одну изящную оптимизацию - новый механизм предварительного создания кеша шрифтов. Итоговое время запуска программы snap станет ещё меньше. Разработчику программы нужно прочесть Desktop Extensions Font Hook и перестроить пакет новой версией snapcraft.
Всё что описано в статье было опробовано на подопытном кролике Chromium. Последняя стабильная сборка (на дату написания статьи 86.0.4240.183) использует расширение gnome-3-28 и доступно для тестирования на канале candidate.
snap refresh chromium --channel=candidate/gnome-3-28-extension
Данный snap пакет собран snapcraft 4.4, что даёт преимущества нового механизма предварительного создания кешей шрифтов для более быстрого старта. Общие библиотеки теперь "получены" от content snap, что уменьшило сам snap пакет программы. 122 Мб против старой версии 250 Мб, которая не использовала gnome-3-28-1804 snap.
Проблемы с программным обеспечением никогда не доставляют удовольствие, но они могу стать поворотным моментом и возможностью элегантно решить её. Пользовательский опыт (UX) является важной частью экосистемы snap и разработчики прилагают массу усилий, чтобы пользователи могли быстро, плавно и весело запускать свои приложения.
С Chromium пользователи теперь получили быстрый старт из-за нового сжатия LZO, использования хука шрифтов, улучшенную интеграцию с системой и меньше занятое место.
Оригинал The Hunt for Rogue Time – How we investigated and solved the Chromium snap slow startup problem
Дата последней правки: 2020-11-11 10:50:06