NixOS широко использует виртуальные машины на базе QEMU для запуска своего набора тестов. Чтобы не генерировать образ диска для каждого теста, тестовый драйвер обычно загружается с помощью ресурса Plan 9 File Protocol (9p) (сервер, реализованный QEMU) для Nix Store, который содержит все программы и конфиги, необходимые для теста.

Я работал над тестом VM, который копировал довольно большой объем данных (~278 тыс. файлов общим объемом ~5,3 Гбайт) из Nix Store на 9p, и был потрясен тем, сколько времени заняло копирование этих данных. На NVMe-устройствах я ожидал бы, что это займет несколько секунд или минут, но в итоге тест занял более 2 часов, большая часть которых ушла на копирование файлов с 9p. Поскольку для инкрементальной работы это непозволительно долго, я решил немного покопаться в этом вопросе и смог сократить продолжительность теста до всего 7 минут. В этой статье я опишу это небольшое приключение.

Профилирование QEMU

В качестве предисловия: У меня не так много опыта в отладке проблем с производительностью! Большинство из того, что я использовал, было для меня в новинку. Первое, что я хотел сделать, это выяснить, на что тратится так много времени. Я предположил, что это происходит в QEMU, а не в госте, и то, что это предположение оказалось верным, было вопросом чистого везения. Этот вопрос в stack overflow описывал проблему похожую на мою (но, к моему сожалению, не полностью). Это привело меня к тому, что я попытался использовать профилировщик для бедных — небольшой хак, состоящий из gdb, немного shell и awk.

Истории о неожиданностях и неудачах: профилировщик для бедных

Решив попробовать этот подход, я сразу же столкнулся с небольшим препятствием. gdb сказал:

warning: Target and debugger are in different PID namespaces;
thread lists and other data are likely unreliable.
Connect to gdbserver inside the container.
(предупреждение: Таргет и отладчик находятся в разных пространствах имен PID;
Списки потоков и другие данные, скорее всего, ненадежны.
Подключитесь к gdbserver внутри контейнера.)

Nix использует пространства имен Linux для обеспечения некоторой степени изоляции сборок от системы, на которой выполняется сборка, чтобы уменьшить влияние окружения конкретной машины на результат сборки ("чистота"). Сюда относятся и пространства имен PID, которые не позволяют процессам внутри пространства имен касаться процессов вне этого пространства имен. gdb был недоволен тем, что находится в пространстве имен PID, отличном от пространства имен процесса, на который он нацелился! Сначала я попытался запустить свой gdb в песочнице с помощью nsenter. Первый сюрприз, с которым я столкнулся, заключался в том, что вход в пространство имен PID не заставляет утилиты из procps, такие как ps, pgrep и top, сообщать только о процессах внутри нового пространства имен:

[root@oak:~]# pgrep -a qemu
1678991 /nix/store/6shk4z9ip57p6vffm5n9imnkwiks9fsa-qemu-host-cpu-only-for-vm-tests-7.0.0/bin/qemu-kvm [...]

[root@oak:~]# nsenter --target=1678991 --pid

???? Это породило новый shell в пространстве имен PID сборки
[root@oak:~]# ps -f 1
UID          PID    PPID  C STIME TTY      STAT   TIME CMD
root           1       0  0 Sep02 ?        Ss     1:24 /run/current-system/systemd/lib/systemd/systemd

Что!? Это не тот PID1, которого я ожидал! И я точно не запускаю эту сборку со 2 сентября.

Не буду описывать подробности последовавшего часа разочарования, но оказалось, что /proc, из которого читали ps и сотоварищи, все еще принадлежал корневому пространству имен PID — даже если они больше не выполнялись в нем! Это может привести к забавному неожиданному поведению при использовании таких инструментов, как pkill... Но это уже совсем другая проблема.

Благодаря моим новоприобретенным знаниям я смог обойти эту проблему, создав новое пространство имен файловой системы (mount) и смонтировав нужную файловую систему proc поверх /proc, которую мы унаследовали от корневого пространства имен.

[root@oak:~]# nsenter -t 1684606 -p -- unshare -m

???? Теперь внутри пространства имен PID сборки (через nsenter) и нового пространства имен файловой системы (созданного с помощью unshare)
[root@oak:~]# ps -f 1
UID          PID    PPID  C STIME TTY      STAT   TIME CMD
root           1       0  0 Sep02 ?        Ss     1:24 /run/current-system/systemd/lib/systemd/systemd
[root@oak:~]# mount -t proc proc /proc
[root@oak:~]# ps -f 1
UID          PID    PPID  C STIME TTY      STAT   TIME CMD
nixbld1        1       0  0 12:27 ?        Ss     0:00 bash -e /nix/store/9krlzvny65gdc8s7kpb6lkx8cd02c25b-default-builder.sh
[root@oak:~]# ps -ef
UID          PID    PPID  C STIME TTY          TIME CMD
nixbld1        1       0  0 12:27 ?        00:00:00 bash -e /nix/store/9krlzvny65gdc8s7kpb6lkx8cd02c25b-default-builder.sh
nixbld1        6       1  0 12:27 ?        00:00:00 /nix/store/pn7863n7s2p66b0gazcylm6cccdwpzaf-python3-3.9.13/bin/python3.9 /nix/store/kdi82vgfixayxaql77j3nj7
nixbld1        7       6 99 12:27 ?        00:04:00 /nix/store/6shk4z9ip57p6vffm5n9imnkwiks9fsa-qemu-host-cpu-only-for-vm-tests-7.0.0/bin/qemu-kvm -cpu max -na
root          46       0  0 12:29 pts/5    00:00:00 -bash
root          79      46  0 12:30 pts/5    00:00:00 ps -ef
???? Так-то лучше!

[root@oak:~]# pid=7 ./pprof
   1500 __futex_abstimed_wait_common,__new_sem_wait_slow64.constprop.1,qemu_sem_timedwait,worker_thread,qemu_thread_start,start_thread,clone3
    743 __lll_lock_wait,pthread_mutex_lock@@GLIBC_2.2.5,qemu_mutex_lock_impl,qemu_mutex_lock_iothread_impl,flatview_read_continue,flatview_read,address_space_rw,kvm_cpu_exec,kvm_vcpu_thread_fn,qemu_thread_start,start_thread,clone3
    100 syscall,qemu_event_wait,call_rcu_thread,qemu_thread_start,start_thread,clone3
     53 ioctl,kvm_vcpu_ioctl,kvm_cpu_exec,kvm_vcpu_thread_fn,qemu_thread_start,start_thread,clone3
     45 get_fid,v9fs_read,coroutine_trampoline,__correctly_grouped_prefixwc,??
     15 get_fid,v9fs_walk,coroutine_trampoline,__correctly_grouped_prefixwc,??
     11 alloc_fid,v9fs_walk,coroutine_trampoline,__correctly_grouped_prefixwc,??
      8 get_fid,v9fs_getattr,coroutine_trampoline,__correctly_grouped_prefixwc,??
      5 clunk_fid,v9fs_xattrwalk,coroutine_trampoline,__correctly_grouped_prefixwc,??
      5 alloc_fid,v9fs_xattrwalk,coroutine_trampoline,__correctly_grouped_prefixwc,??
      4 __lll_lock_wait,pthread_mutex_lock@@GLIBC_2.2.5,qemu_mutex_lock_impl,qemu_mutex_lock_iothread_impl,flatview_write_continue,flatview_write,address_space_rw,kvm_cpu_exec,kvm_vcpu_thread_fn,qemu_thread_start,start_thread,clone3
      3 get_fid,v9fs_xattrwalk,coroutine_trampoline,__correctly_grouped_prefixwc,??
      3 get_fid,v9fs_open,coroutine_trampoline,__correctly_grouped_prefixwc,??
      2 clunk_fid,v9fs_clunk,coroutine_trampoline,__correctly_grouped_prefixwc,??
      1 get_fid,v9fs_readlink,coroutine_trampoline,__correctly_grouped_prefixwc,??
      1 get_fid,v9fs_readdir,coroutine_trampoline,__correctly_grouped_prefixwc,??
      1 address_space_translate_internal,flatview_do_translate.isra,address_space_map,virtqueue_map_desc,virtqueue_split_pop,virtio_blk_handle_vq,virtio_queue_notify_vq.part,aio_dispatch_handler,aio_dispatch,aio_ctx_dispatch,g_main_context_dispatch,main_loop_wait,qemu_main_loop,main
      1

• Блокировка ресурсов, в 1500 и 743 выборках потоков. Поскольку самый высокий результат был получен на рабочих потоках, я предположил, что это неинтересно и они просто ждут, когда появится работа.

• Ожидание событий внутри VM в 100 и 53 выборках потоков. Однако это не выглядит такой уж существенной проблемой — ожидается, что монитор VM большую часть времени будет ждать, пока гостю что-то понадобится.

Остальные числа были настолько малы, что я (ошибочно!) счел их тоже неинтересными. В этот момент я настолько разочаровался в этом направлении своего исследования, что отказался от него.

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

Флеймграфы и perf

И это оказалось именно то, что привело меня к хоть какому-нибудь успеху. Записав данные о производительности с помощью команды perf record -F max -a -g -- sleep 20 во время выполнения сборки, я смог сгенерировать флеймграф, который сделал источник проблем с производительностью вполне очевидным. Эта команда:

perf script | stackcollapse-perf.pl |  # Взято со страницы флеймграфа, ссылка на которую приведена выше
  grep ^qemu | # Нас интересует только процесс qemu
  awk '/unknown/ { gsub("(\\[unknown];){1,}", "[unknown...];", $0) } { print }' | # Делает график менее высоким, свернув несколько последовательных неизвестных фреймов стека вместе
  flamegraph.pl > flamegraph.svg # Генерирует флеймграф

создала этот интересный интерактивный SVG-график:

Преобладание функций, связанных с "fid", на этом графике вполне очевидно. Поэтому я залез в документацию по 9p и исходный код QEMU, чтобы выяснить, что fid — это числа, которые соответствуют открытым файлам в 9p соединении, аналогично дескрипторам файлов в POSIX API, поэтому для каждого файла, открытого гостем, будет существовать соответствующий fid.

Давайте рассмотрим предыдущую реализацию get_fid, которая используется сервером QEMU 9p в реализациях stat (получение метаданных файла), open (открытие файла), read (чтение данных из открытого файла) и других:

static V9fsFidState *coroutine_fn get_fid(V9fsPDU *pdu, int32_t fid)
{
    int err;
    V9fsFidState *f;
    V9fsState *s = pdu->s;

    // Примечание к статье: я опустил некоторые части, которые не имеют отношения к производительности.
    QSIMPLEQ_FOREACH(f, &s->fid_list, next) {
        if (f->fid == fid) {
            return f;
        }
    }
    return NULL;
}

QEMU перебирает список fid_list, чтобы найти нужные fid-данные. Поиск элемента в списке путем итерации имеет временную сложность O(n), где n — размер списка, в данном случае списка всех файлов, открытых гостем, так что это достаточно дорого! Более того, при осмотре QSIMPLEQ (простой очереди QEMU) выясняется, что она реализована в виде связанного списка — структуры данных, которая склонна демонстрировать плохую локальность кэша.

Поскольку мой тест копирует много файлов из файловой системы 9p, а также загружается с нее, этот поиск происходит очень часто:

• Один stat для получения метаданных файла (в частности, разрешений)

• Один open, чтобы получить доступ к файлу

• Один read для маленьких файлов или много для больших файлов, чтобы получить их содержимое

Таким образом, для каждого из 278000 файлов выполняется как минимум 3 операции поиска, что выводит неэффективный поиск в hot code path. В этом и заключалась причина такой медлительности.

Исправление

Что нам нужно, так это структура, в которой мы могли бы искать записи по fid более дешево. Мы не можем просто использовать вектор на основе массива, который бы постоянно давал нам O(1) поиск, потому что fid’ы выбираются клиентом: мы не можем полагаться на то, что каждый вновь выделенный fid будет наименьшим незанятым, и должны поддерживать произвольные 32-битные целые числа. Я выбрал хэш-таблицу, удобно реализованную в glib, от которого QEMU уже зависит. Это обеспечивает нам сложность O(1) в лучшем случае, а в худшем — O(n). Точные характеристики производительности в реальном мире значительно сложнее, чем у связанного списка, и, возможно, существуют более подходящие структуры данных (или реализации хэш-таблиц), но мы ищем скорее большую легкую победу, а не микрооптимизацию.

Переписывание соответствующего кода оказалось на удивление простым и необременительным, настолько, что после компиляции он сразу же заработал (не уверен, что когда-либо раньше сталкивался с таким в C!). Результаты были впечатляющими: мой тест, который ранее занимал более 2 часов, был завершен за 7 минут. Он также сокращает время сборки образа ZFS AWS для NixOS с 19 минут до 1. Для меня было совершенно очевидно, что этим решением следовало поделиться с остальными.

Контрибьют исправления

В QEMU принят рабочий процесс на основе электронной почты, когда патчи отправляются в виде писем в список рассылки, на который подписаны мейнтейнеры. Я не делал этого раньше, и все шло несколько хаотично, как вы можете видеть, взглянув на потоки (v1 v3 v1a v5 v6) в архивных списках. При отправке патчей по электронной почте достаточно пространства для ошибок, и я не смог не совершить пару штук:

• Можно забыть сделать reply-all на комментарии к рецензии, чтобы ответ был виден всем заинтересованным, а не только рецензенту

• Отсутствие тега версии при повторном сабмите (в моем случае это произошло из-за вводящей в заблуждение документации)

• Отправка повторного сабмита в качестве ответа на предыдущую тему (это я просто не дочитал документацию)

• Потеря кучи документации к патчу при использовании git-publish из-за сбоя git send-email (nixpkgs не включает почтовую функциональность Git в пакет по умолчанию, а git-publish безоговорочно удаляет рабочие файлы после выполнения команды send).

Но рецензенты, особенно Кристиан Шенебек (Christian Schoenebeck - огромное спасибо!), были очень полезны и терпеливы, и в конце концов патч получился (хотя была обнаружена явно несвязанная с ним ошибка) и скоро окажется в ближайшей к вам версии QEMU! Если вы не можете ждать и используете Nix, вы можете установить патч с помощью этого оверлея:

final: prev: {
  qemu = prev.qemu.overrideAttrs (o: {
    patches = o.patches ++ [ (prev.fetchpatch {
      name = "qemu-9p-performance-fix.patch";
      url = "https://gitlab.com/lheckemann/qemu/-/commit/ca8c4a95a320dba9854c3fd4159ff4f52613311f.patch";
      sha256 = "sha256-9jYpGmD28yJGZU4zlae9BL4uU3iukWdPWpSkgHHvOxI=";
    }) ];
  });
}

Итоги

Хотя суть того, что я изменил, не была очень сложной, это приключение имело для меня множество побочных (положительных!) результатов:

• Я написал пакеты Nix для quickstack (включая PR-дополнение, которое делает сборку более универсальной) и git-publish.

• Я впервые использовал perf для работы над проблемами производительности, изучив его полезность и основы использования.

• Я узнал, что разные методы профилирования могут давать совершенно разные результаты — результаты, полученные с помощью perf, сильно отличаются от результатов профилировщика для бедных; я пока не понимаю, почему, но скоро потрачу еще немного времени на их изучение.

• Я отправил свой первый патч в QEMU, немного познакомившись с кодом в процессе.

• Я отправил свой второй патч в QEMU (попутно пытаясь немного улучшить документацию по сабминут патчей).

• Я узнал, как отправлять патчи по электронной почте и каких ошибок следует избегать.

• Я узнал больше о протоколе 9p.

• Теперь мои тесты выполняются гораздо быстрее!

• И у меня появилось то теплое чувство, что я внес ценный вклад.

Что я вынес из этого? Копаться в сложной проблеме — даже если я совершенно не знаком с кодом и технологией, которую использую, — может быть очень полезно!

Я не только сделал свою собственную работу над тестами намного приятнее, сократив время выполнения, но это будет доступно всем пользователям QEMU и значительно снизит нагрузку, создаваемую тестами инсталлятора на ферму сборки NixOS. Вот что мне нравится в работе над открытым программным обеспечением: если что-то не так, у меня есть средства, чтобы пойти и исправить это, и я могу поделиться полученными преимуществами со всеми остальными, кто использует это ПО.

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

В заключение статьи приглашаем всех желающих на открытый урок «Unicode в С». На нем подробнее познакомимся с Unicode и низкоуровневым устройством его кодировок, а также развеем несколько популярных мифов в области кодировок и посмотрим на инструменты языка C для работы с юникодом. Занятие будет полезно всем программистам, практикующим написание кода на C и C++. Урок пройдет сегодня вечером, успевайте записаться по ссылке.