Охота за украденным временем.

Разработчик Игорь Любунчич (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 пакета 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/имя_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.

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

Исправление ситуации. Расширения snapcraft и хуки шрифтов.

Конечно, удаление шрифтов не решение проблемы.

В ходе исследования, было определёно несколько моментов. Во-первых, 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, включая в себя такой тип snap пакетов как content с именем GNOME 3.34. В данном пакете собраны все ресурсы, необходимые приложениям GNOME/GTK3. Такое решение уменьшает итоговой размер приложения в snap.
  

  plugs:
    gnome-3-34-1804:
      default-provider: gnome-3-34-1804
      interface: content
      target: $SNAP/gnome-platform
  

• Длинный список переменных окружения для сборки, в том числе: XDG_DATA_DIRS, GETTEXTDATADIRS, GDK_PIXBUF_MODULE_FILE и другие.
• Темы GTK3, темы значков, звуковые темы и другие.

Такой подход помогает разработчикам программы с её лучшей интеграцией в среду рабочего стола пользователя и уменьшить итоговый размер 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