Я потратил месяц на создание веб-сайта в Docker и теперь готов поделиться ужасными историями.

У меня есть проблема.

Мой веб-сайт (на котором была опубликована эта статья) в основном обслуживается одним двоичным файлом Rust. Он стал слишком длинным. Каждый раз, когда мне нужно внести изменение, я должен:

1. Собрать новую статически компонуемую библиотеку (с --target=x86_64-unknown-linux-musl)

2. Скопировать её на сервер

3. Перезапустить веб-сайт

Ситуация, мягко говоря, неидеальная.

Поэтому мне бы хотелось перейти к развёртыванию веб-сайта при помощи контейнеров (будь то Docker, Kubernetes или что-то иное), в духе подавляющего большинства ПО, разворачиваемого в последний десяток лет.

Единственная проблема заключается в том, что реализовать быстрые сборки Rust с Docker не так уж просто.

Основы: Rust в Docker

Rust в Docker: простой способ

Чтобы поместить программу на Rust в контейнер, обычно используют примерно такую методику:

FROM rust:1.87-alpine3.22 AS builder

RUN apk add musl-dev

WORKDIR /workdir
COPY . .

# "package" для моего веб-сайта - это "web-http-server".
RUN cargo build --package web-http-server --target=x86_64-unknown-linux-musl

# включаем в финальный образ только двоичный файл
FROM alpine:3.20
COPY --from=builder /workdir/target/x86_64-unknown-linux-musl/release/web-http-server /usr/bin/web-http-server

ENTRYPOINT ["/usr/bin/web-http-server"]

К сожалению, в случае любых изменений придётся заново пересобирать всё с нуля.

В моём случае, сборка с нуля занимает примерно 4 минуты (включая 10 секунд на скачивание каждый раз крейтов).

$ cargo build --release --target=x86_64-unknown-linux-musl --package web-http-server
    Updating crates.io index
 Downloading crates ...
  Downloaded anstream v0.6.18
  Downloaded http-body v1.0.1

... ещё много строк ...

   Compiling web-http-server v0.1.0 (/workdir/web-http-server)
    Finished `release` profile [optimized + debuginfo] target(s) in 3m 51s

Да, могло быть и хуже. Но я-то привык к быстрым локальным сборкам, возможным благодаря инкрементной компиляции. Я не хочу ждать так долго при внесении малейших изменений!

Rust в Docker с улучшенным кэшированием

К счастью, есть инструмент, который может нам в этом помочь!

cargo-chef Луки Палмиери упрощает предварительную сборку всех зависимостей как отдельного слоя в кэше сборки Docker, чтобы изменения в вашей кодовой базе приводили к перекомпиляции только этой кодовой базы (но не зависимостей).

Подробности можно изучить в посте Луки, но если вкратце, то cargo-chef создаёт упрощённый файл «рецепта» из текущего рабочего пространства, который можно «испечь», чтобы кэшировать зависимости так, чтобы изменения в рабочем пространстве не сделали их невалидными.

Мой веб-сайт подтягивает несколько сотен зависимостей, так что это должно помочь!

...

FROM ... AS planner
COPY . .
RUN cargo chef prepare --recipe-path=/workdir/recipe.json

FROM ... AS cooker
# ПРИМЕЧАНИЕ: изменения в проекте могут привести к созданию того же "рецепта",
# что позволяет кэшировать этот этап сборки.
COPY --from=planner /workdir/recipe.json recipe.json
RUN cargo chef cook --release --recipe-path=/workdir/recipe.json \
    --target=x86_64-unknown-linux-musl

# Если recipe.json не поменялся, то 'cooker' будет кэширован.
# Останется лишь скомпилировать финальный двоичный файл.
FROM cooker AS builder
COPY . .
RUN cargo build --release --package web-http-server \
    --target=x86_64-unknown-linux-musl

К сожалению, рост скорости оказался не таким, как мы ожидали — основная часть времени всё равно тратится на финальный двоичный файл:

$ # Пересборка зависимостей
$ cargo chef cook --release ...
    Updating crates.io index
 Downloading crates ...
 ...
   Compiling web-http-server v0.0.1 (/workdir/web-http-server)
    Finished `release` profile [optimized + debuginfo] target(s) in 1m 07s

$ # Собираем финальный двоичный файл, используя кэшированные зависимости
$ cargo build --release ...
   Compiling web-http-server v0.1.0 (/workdir/web-http-server)
    Finished `release` profile [optimized + debuginfo] target(s) in 2m 50s

Как ни странно, на зависимости тратится всего 25% времени! Насколько я понимаю, мой код не делает ничего фундаментально неправильного. Он состоит примерно из семи тысяч строк клея, объединяющего различные крупные зависимости (например, axum, reqwest и tokio-postgres).

(Чтобы ещё раз всё проверить, я попробовал запустить cargo build с --verbose. Почти 3 минуты действительно тратится на единственный вызов rustc!)

Что rustc делает всё это время?

Воспользовавшись информацией из замечательного поста fasterthanlime, я сначала попробовал выполнить cargo --timings, чтобы получить больше информации:

$ cargo build --release --timings ...
   Compiling web-http-server v0.1.0 (/workdir/web-http-server)
      Timing report saved to /workdir/target/cargo-timings/cargo-timing-20250607T192029.207407545Z.html
    Finished `release` profile [optimized + debuginfo] target(s) in 2m 54s

Наряду с файлом cargo-timing-<timestamp>.html есть и файл cargo-timing.html. Мы просто скопируем каноничную версию:

...

FROM cooker AS builder
COPY . .
RUN cargo build --timings --release --target=x86_64-unknown-linux-musl --package web-http-server
# НОВОЕ: перемещаем тайминги cargo в известное местоположение
RUN mv target/cargo-timings/cargo-timing-*.html cargo-timing.html

FROM alpine:3.22
COPY --from=builder /workdir/target/x86_64-unknown-linux-musl/release/web-http-server /usr/bin/web-http-server
# НОВОЕ: включаем это в финальный образ
COPY --from=builder /workdir/cargo-timing.html cargo-timing.html

И немного повозившись с контейнером...

id="$(docker container create <IMAGE>)"
docker cp "$id:/cargo-timing.html" cargo-timing.html
docker container rm -f "$id"

... мы сможем понять, что же происходит! Давайте посмотрим:

Ой. Не так уж много информации!

Что здесь происходит?

cargo build --timings показывает информацию о том, сколько времени тратится на компиляцию каждого крейта. Но нас волнует только время компиляции финального крейта!

Впрочем, это всё равно поможет нам получить более точные тайминги. Выполнив измерения снаружи компилятора, мы добавили бы дополнительные аспекты, или нам бы понадобилось искать вывод cargo build, поэтому собственные тайминги cargo позже немного упростит нам точный анализ.

Проверим: в отчёте указано значение 174,1 с, что примерно соответствует 2 минутам 54 секундам, которые мы видели в выводе cargo build.

Теперь спросим сам rustc

В посте fasterthanlime есть ещё один совет, который мы можем использовать — применение фичи самопрофилирования rustc при помощи флага -Zself-profile.

В обычным случае мы сделали бы примерно так:

RUSTC_BOOTSTRAP=1 cargo rustc --release -- -Z self-profile

(Примечание: здесь cargo rustc используется для передачи rustc дополнительных флагов с RUSTC_BOOTSTRAP=1, чтобы позволить использовать нестабильные флаги -Z для стабильного компилятора.)

К сожалению, здесь это не сработает — изменение в аргументах инвалидирует кэшированные зависимости из cargo chef cook, а эквивалентный способ передачи дополнительных флагов rustc через cargo-chef отсутствует.

Вместо этого можно передать всё через переменную окружения RUSTFLAGS:

# cargo chef:
RUSTC_BOOTSTRAP=1 RUSTFLAGS='-Zself-profile' cargo chef cook --release ...

# финальная сборка:
RUSTC_BOOTSTRAP=1 RUSTFLAGS='-Zself-profile' cargo build --release ...

Так мы получим файлы вида web_http_server-<random-number>.mm_profdata, которые можно будет перемещать и извлекать из образа так же, как мы делали для cargo-timing.html.

(Примечание: выполнить автоматизацию гораздо проще, если перед финальной сборкой мы удалим данные профилирования, добавленные из cargo chef cook. Я не стал указывать этого для экономии времени).

Используем profdata

Разработчики Rust поддерживают набор инструментов для исследования вывода самопрофилирования rustc; этот набор можно найти по адресу https://github.com/rust-lang/measureme.

Основные инструменты:

• summary — создаёт текстовый вывод с краткой сводкой данных профилирования

• flamegraph — создаёт SVG с flame-графиком

• crox — создаёт трассировку в формате трассировки Chrome, совместимую с chrome://tracing (в браузерах на основе Chromium)

Давайте установим пару инструментов, чтобы разобраться, что у нас есть:

cargo install --git https://github.com/rust-lang/measureme flamegraph summarize

Лично я пользуюсь Firefox, поэтому мы пока не будем касаться трассировки Chrome.

Для начала рассмотрим summarize (у которого есть подкоманды summarize и diff):

$ summarize summarize web_http_server.mm_profdata | wc -l
945
$ summarize summarize web_http_server.mm_profdata | head
+-------------------------------+-----------+-----------------+----------+------------+
| Item                          | Self time | % of total time | Time     | Item count |
+-------------------------------+-----------+-----------------+----------+------------+
| LLVM_lto_optimize             | 851.95s   | 33.389          | 851.95s  | 1137       |
+-------------------------------+-----------+-----------------+----------+------------+
| LLVM_module_codegen_emit_obj  | 674.94s   | 26.452          | 674.94s  | 1137       |
+-------------------------------+-----------+-----------------+----------+------------+
| LLVM_thin_lto_import          | 317.75s   | 12.453          | 317.75s  | 1137       |
+-------------------------------+-----------+-----------------+----------+------------+
| LLVM_module_optimize          | 189.00s   | 7.407           | 189.00s  | 17         |

thread 'main' panicked at library/std/src/io/stdio.rs:1165:9:
failed printing to stdout: Broken pipe (os error 32)
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

(Ой! Классический пограничный случай CLI. Впрочем, проблему легко решить.)

На высоком уровне два самых важных аспекта — это оптимизация времени компоновки (link-time optimization, LTO) и LLVM_module_codegen_emit_obj, что бы это ни было.

Давайте посмотрим, сможем ли мы получить больше информации с помощью flame-графика:

$ flamegraph web_http_server.mm_profdata
$ # ... вывода нет. Давайте посмотрим, что добавилось ...
$ find . -cmin 1 -type f # ищем файлы, созданные меньше минуты назад
./rustc.svg

Отлично, у нас есть SVG!

(Он интерактивный! Если вам любопытно, можете понажимать на него и поэкспериментировать самостоятельно.)

Похоже, кодогенерация и LTO смешались: codegen_module_perform_lto относится и к LLVM_lto_optimize/LLVM_thin_lto_import, и к LLVM_module_codegen.

Но, как бы то ни было, проблема заключается в LTO: codegen_module_perform_lto занимает около 80% общего времени.

Настало время поговорить об LTO

Компилятор Rust разбивает крейты на блоки кодогенерации, передавая каждый LLVM как отдельный модуль для компиляции. В общем случае оптимизации выполняются внутри каждого блока кодогенерации, а в конце они компонуются вместе.

LTO управляет набором оптимизаций, вносимых LLVM на этапе компоновки, например, встраиванием или оптимизацией между блоками кодогенерации.

Cargo (через rustc) раскрывает несколько опций LTO:

• Off — все LTO отключены

• «Тонкие» LTO — теоретически, выигрыш в производительности схож с опцией «толстых» LTO, но эта опция менее затратна при выполнении

• «Толстые» LTO — максимальный объём LTO среди всех крейтов одновременно

А если опция LTO не указана, то rustc использует «тонкие локальные LTO», ограничивающие «тонкие» LTO лишь одним крейтом за раз.

Какие настройки используются

Оказалось, что несколько лет назад я указал в Cargo.toml опцию lto = "thin":

[profile.release]
lto = "thin"
debug = "full"

Кстати, debug = "full" включает все отладочные символы (которые по умолчанию исключаются для профиля release). Возможно, стоит присмотреться и к этому тоже.

Изменение (обычных) настроек

Давайте взглянем на время компиляции и размеры двоичных файлов для разных настроек lto и debug (снова воспользовавшись, как и раньше, cargo build --timings для более точных таймингов).

Опишем ситуацию в общем: похоже, наихудшие случаи — это когда используются все отладочные символы, что добавляет 30-50% ко времени компиляции, и толстые LTO, занимающие примерно в четыре раза больше времени, чем при полностью отключенных LTO.

Это практически соответствует тому, что написано в документации — да, толстые LTO выполняются дольше. Но если всё отключить, то финальный двоичный файл всё равно скомпилируется за 50 секунд!

Небольшое примечание: на самом деле, 50 секунд — это неплохо!

50 секунд — это уже приличный скачок скорости, и для него нужно отключить LTO и отладочные символы... а ведь нагрузка у моего веб-сайта почти нулевая. Меня это вполне устроит.

Нет никаких практических причин ковыряться дальше.

Но разве не весело будет разобраться поглубже? Мы ведь всё ещё можем улучшить ситуацию?

Ещё одно краткое примечание: разве нельзя просто использовать инкрементную компиляцию?

Это будет чуть сложнее, но да, вполне возможно; по крайней мере, для локальной разработки. Согласованная загрузка кэша сборок — не такая уж простая задача, но вам понадобиться сделать доступной папку /target при помощи cache mount в dockerfile и сохранять эту папку между сборками.

Тем не менее, я ценю то, что docker build может обеспечивать каждый раз чистое окружение, и считаю, что стоит воспользоваться собственной системой кэширования docker, ведь именно поэтому я и использую cargo-chef.

Копаем глубже: и ты тоже, LLVM_module_optimize?

Если мы отключим LTO и отладочные символы, то на компиляцию финального двоичного файла потребуется 50 секунд, в которые происходит... что-то.

Давайте заново запустим самопрофилирование, чтобы разобраться, что происходит.

Примерно 70% тратится на один LLVM_module_optimize, то есть на то, где LLVM оптимизирует код. Прежде, чем приступать к самому LLVM, давайте посмотрим, нет ли более простых способов.

Настройка оптимизации

Профиль release по умолчанию использует opt-level = 3; возможно, если снизить уровень оптимизации, на неё будет тратиться меньше времени.

На самом деле, можно сделать кое-что получше — так как наши зависимости кэшированы и нас волнует только финальный двоичный файл, можно сохранить большинство преимуществ, ограничив оптимизации только в финальном бинарнике:

[profile.release]
lto = "off"
debug = "none"
opt-level = 0 # Отключаем оптимизации в финальном двоичном файле

# ... Но используем более высокий уровень оптимизации для всех зависимостей
# Подробнее см. здесь:
# https://doc.rust-lang.org/cargo/reference/profiles.html#overrides
[profile.release.package."*"]
opt-level = 3

Как и в случае предыдущих опций, существует несколько opt-level:

• 0 отключает оптимизации

• 1, 2 и 3 включают разные уровни оптимизаций

• "s" и "z" — это разные способы изменения приоритета размера двоичного файла

Снова попробуем несколько комбинаций:

По сути:

• Отправная точка измерений для любого уровня оптимизаций финального двоичного файла — примерно 50 секунд;

• Если отключить все оптимизации, то компиляция будет довольно быстрой: всего около 15 с.

Что за дела с LLVM?

Rust достаточно сильно зависит от оптимизаций, и хотя вполне можно полностью отключить их для финального двоичного файла, было бы здорово сохранить хотя бы некоторые из них!

Давайте разберёмся, на что уходит так много времени. Однако здесь нам больше не поможет функция самопрофилирования rustc, поэтому мы будем получать данные от LLVM.

Есть ещё пара полезных флагов rustc:

• -Z time-llvm-passes — выводит информацию о профилировании LLVM в текстовом виде

• -Z llvm-time-trace — выводит информацию о профилировании LLVM в формате трассировки Chrome

Профилирование LLVM с rustc — текстовый вид

Давайте, как и раньше, пока отложим формат трассировки Chrome и посмотрим, что можно узнать из текста.

# cargo chef:
RUSTC_BOOTSTRAP=1 RUSTFLAGS='-Ztime-llvm-passes' cargo chef cook --release ...

# финальная сборка:
RUSTC_BOOTSTRAP=1 RUSTFLAGS='-Ztime-llvm-passes' cargo build --release ...

... К сожалению, если попробовать снова выполнить docker build, то мы сразу же получим что-то подобное:

[output clipped, log limit 2MiB reached]

Причина в том, что у BuildKit (мы используем довольно свежую версию Docker в Linux) стандартные ограничения вывода довольно малы.

BUILDKIT_STEP_LOG_MAX_SIZE=-1 BUILDKIT_STEP_LOG_MAX_SPEED=-1 docker build ...

$ systemctl edit --drop-in=buildkit-env.conf docker.service

[Service]
Environment="BUILDKIT_STEP_LOG_MAX_SIZE=-1"
Environment="BUILDKIT_STEP_LOG_MAX_SPEED=-1"

$ systemctl restart docker.service

$ pgrep dockerd
1234567
$ cat /proc/1234567/environ | tr '\0' '\n' | grep -i 'buildkit'
BUILDKIT_STEP_LOG_MAX_SIZE=-1
BUILDKIT_STEP_LOG_MAX_SPEED=-1

Настроив неограниченный вывод docker build в терминал, мы получим около 200 тысяч строк текста; наверно, вам не захочется копировать их все из терминала.

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

===-------------------------------------------------------------------------===
                          Pass execution timing report
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0428 seconds (0.0433 wall clock)

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  — Name ---
   0.0072 ( 19.2%)   0.0015 ( 27.4%)   0.0086 ( 20.2%)   0.0087 ( 20.0%)  InstCombinePass
   0.0040 ( 10.8%)   0.0006 ( 10.8%)   0.0046 ( 10.8%)   0.0047 ( 10.8%)  InlinerPass
   0.0024 (  6.4%)   0.0010 ( 18.0%)   0.0034 (  7.9%)   0.0034 (  7.8%)  SimplifyCFGPass
   0.0022 (  5.9%)   0.0002 (  4.5%)   0.0025 (  5.7%)   0.0024 (  5.6%)  EarlyCSEPass
   0.0021 (  5.5%)   0.0001 (  1.5%)   0.0021 (  5.0%)   0.0022 (  5.0%)  GVNPass
   0.0015 (  4.0%)   0.0001 (  2.2%)   0.0016 (  3.8%)   0.0018 (  4.2%)  ArgumentPromotionPass

   ... здесь продолжаются записи, ниже идёт много проходов, сотни тысяч строк ...

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

Давайте посмотрим, можно ли получить качественные данные как-то иначе.

Профилирование LLVM с rustc — теперь настоящая трассировка

Ранее мы пропустили -Z llvm-time-trace, потому что он генерирует формат трассировки Chrome.

Давайте вернёмся к нему:

# cargo chef:
RUSTC_BOOTSTRAP=1 RUSTFLAGS='-Zllvm-time-trace' cargo chef cook --release ...

# финальная сборка:
RUSTC_BOOTSTRAP=1 RUSTFLAGS='-Zllvm-time-trace' cargo build --release ...

Он генерирует набор файлов $package-$hash.llvm_timings.json, а также обычные артефакты компиляции:

$ ls -lAh target/x86_64-unknown-linux-musl/release/deps | head
total 5G
-rw-r--r--    1 root     root       11.8K Jun  9 23:11 aho_corasick-ff268aeac1b7a243.d
-rw-r--r--    1 root     root       69.4M Jun  9 23:11 aho_corasick-ff268aeac1b7a243.llvm_timings.json
-rw-r--r--    1 root     root        6.6K Jun  9 23:11 allocator_api2-28ed2e0fa8ab7b44.d
-rw-r--r--    1 root     root      373.1K Jun  9 23:11 allocator_api2-28ed2e0fa8ab7b44.llvm_timings.json
-rw-r--r--    1 root     root        4.0K Jun  9 23:11 anstream-cf9519a72988d4c1.d
-rw-r--r--    1 root     root        4.4M Jun  9 23:11 anstream-cf9519a72988d4c1.llvm_timings.json
-rw-r--r--    1 root     root        2.4K Jun  9 23:11 anstyle-76a77f68346b4238.d
-rw-r--r--    1 root     root      885.3K Jun  9 23:11 anstyle-76a77f68346b4238.llvm_timings.json
-rw-r--r--    1 root     root        2.2K Jun  9 23:11 anstyle_parse-702e2f8f76fe1827.d

(Почему root? Мне не удалось заставить работать docker без root несколько лет назад, поэтому с тех пор я не заморачивался)

Итак, удалив *.llvm_timings.json между cargo-chef и финальной сборкой, мы можем извлечь в web_http_server.llvm_timings.json единый профиль для финального двоичного файла.

Но есть одна небольшая проблема:

$ du -sh web_http_server.llvm_timings.json
1.4G	web_http_server.llvm_timings.json

Файл получился гигантский. К тому же это одна длинная строка!

Однако, теоретически, его может обработать множество разных инструментов:

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

Я пользуюсь Firefox, так почему бы не применить Firefox Profiler? Он должен справиться с файлом:

Firefox Profiler может также импортировать профили из других профилировщиков, например Linux perf, Android SimplePerf, панели производительности Chrome, Android Studio или любой файл в формате dhat или Google Trace Event.

К сожалению, это не сработало:

Заглянув в консоль, мы поймём, почему – кончилась память:

perfetto.dev в Firefox

Поискав способы отображения этих трассировок формата Chrome, я нашёл perfetto.dev. Его мейнтейнингом тоже занимается Google.

Я впервые попробовал его на более длинной трассировке более долгой компиляции, и у него тоже закончилась память:

Я решил использовать локально обработчик WASM, столкнувшись с багом Firefox.

На этом этапе я сдался и воспользовался Chromium, но в процессе написания поста повторил попытку. С трассировкой меньшего размера Perfetto заработал:

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

chrome://tracing в Chromium

Стоило бы ожидать, что этот способ сработает лучше всего, но, к сожалению, я тоже потерпел неудачу, хотя и более удивительную, чем раньше:

Ни один из вариантов у меня не сработал, но ведь это просто большой файл JSON с известным форматом, так что, наверно, в этом не должно быть ничего сложного?

Оказалось, что JSON на 1,4 ГиБ в одну строку заставляет жаловаться все обычные инструменты:

• Если попробовать открыть его с помощью less, то скроллинг блокируется при обработке всего файла.

• Если попробовать jq, то придётся загружать все 1,4 ГиБ во внутренний формат jq (который, разумеется, занимает гораздо больше места, чем исходные 1,4 ГиБ).

• Vim при попытке открытия зависает.

• И, вероятно, вы не захотите просто запускать cat в терминале — повторюсь: это файл на 1,4 ГиБ!

Поэтому вместо этого мы можем просто посмотреть на несколько сотен символов в начале и конце файла:

$ head -c300 web_http_server.llvm_timings.json
{"traceEvents":[{"pid":25,"tid":30,"ts":8291351,"ph":"X","dur":6827,"name":"RunPass","args":{"detail":"Expand large div/rem"}},{"pid":25,"tid":30,"ts":8298181,"ph":"X","dur":2,"name":"RunPass","args":{"detail":"Expand large fp convert"}},{"pid":25,"tid":30,"ts":8298183,"ph":"X","dur":8,"name":"RunPa
$ tail -c300 web_http_server.llvm_timings.json
me":""}},{"cat":"","pid":25,"tid":43,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}},{"cat":"","pid":25,"tid":44,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}},{"cat":"","pid":25,"tid":29,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}}],"beginningOfTime":1749510885820760}

Сопоставив их с JSON Object Format из спецификации трассировки Chrome, можно прийти к выводу, что это единый объект JSON такого вида:

{
  "traceEvents": [
    {"pid":25,"tid":30,"ts":8291351,"ph":"X","dur":6827,"name":"RunPass","args":{"detail":"Expand large div/rem"}},
    {"pid":25,"tid":30,"ts":8298181,"ph":"X","dur":2,"name":"RunPass","args":{"detail":"Expand large fp convert"}},
    ...
  ],
  "beginningOfTime": 1749510885820760
}

Мы бы смогли обработать его обычными инструментами, если бы разбили все события на отдельные объекты. Можно было бы сделать примерно так:

cat web_http_server.llvm_timings.json \
    | sed -E 's/},/}\n/g;s/^\{"traceEvents":\[//g;s/\],"beginningOfTime":[0-9]+}$//g' \
    > web-http-server.llvm_timings.jsonl

(то есть превращаем "}," в символ новой строки, вырезаем начало объекта, вырезаем конец объекта)

Вот теперь мы можем это обработать.

$ wc -l web_http_server.llvm_timings.jsonl
7301865 web_http_server.llvm_timings.jsonl

$ head web_http_server.llvm_timings.jsonl
{"pid":25,"tid":30,"ts":8291351,"ph":"X","dur":6827,"name":"RunPass","args":{"detail":"Expand large div/rem"}}
{"pid":25,"tid":30,"ts":8298181,"ph":"X","dur":2,"name":"RunPass","args":{"detail":"Expand large fp convert"}}
{"pid":25,"tid":30,"ts":8298183,"ph":"X","dur":8,"name":"RunPass","args":{"detail":"Expand Atomic instructions"}}
{"pid":25,"tid":30,"ts":8298192,"ph":"X","dur":0,"name":"RunPass","args":{"detail":"Lower AMX intrinsics"}}
{"pid":25,"tid":30,"ts":8298193,"ph":"X","dur":0,"name":"RunPass","args":{"detail":"Lower AMX type for load/store"}}
{"pid":25,"tid":30,"ts":8298195,"ph":"X","dur":1,"name":"RunPass","args":{"detail":"Lower Garbage Collection Instructions"}}
{"pid":25,"tid":30,"ts":8298196,"ph":"X","dur":1,"name":"RunPass","args":{"detail":"Shadow Stack GC Lowering"}}
{"pid":25,"tid":30,"ts":8298197,"ph":"X","dur":1164,"name":"RunPass","args":{"detail":"Remove unreachable blocks from the CFG"}}
{"pid":25,"tid":30,"ts":8299362,"ph":"X","dur":1,"name":"RunPass","args":{"detail":"Instrument function entry/exit with calls to e.g. mcount() (post inlining)"}}
{"pid":25,"tid":30,"ts":8299363,"ph":"X","dur":5,"name":"RunPass","args":{"detail":"Scalarize Masked Memory Intrinsics"}}

Что находится в событиях трассировки LLVM?

Похоже, во всех этих событиях есть "ph":"X".

Согласно спецификации, поле ph задаёт тип события, а X обозначает «полные» события, записывая, сколько заняло выполнение конкретной задачи в заданном потоке (tid). Длительность в микросекундах задаётся значением dur.

Кроме того, бывают события M:

$ cat web_http_server.llvm_timings.jsonl | jq -c 'select(.ph != "X")' | head
{"cat":"","pid":25,"tid":27,"ts":0,"ph":"M","name":"process_name","args":{"name":"rustc"}}
{"cat":"","pid":25,"tid":27,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}}
{"cat":"","pid":25,"tid":30,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}}
{"cat":"","pid":25,"tid":35,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}}
{"cat":"","pid":25,"tid":32,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}}
{"cat":"","pid":25,"tid":33,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}}
{"cat":"","pid":25,"tid":34,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}}
{"cat":"","pid":25,"tid":39,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}}
{"cat":"","pid":25,"tid":40,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}}
{"cat":"","pid":25,"tid":36,"ts":0,"ph":"M","name":"thread_name","args":{"name":""}}

Это события «метаданных» — в нашем случае это не такая полезная информация.

А кроме них больше нет ничего:

$ cat web_http_server.llvm_timings.jsonl | jq -c 'select(.ph != "X" and .ph != "M")'
<nothing>

Вернёмся к событиям X: у многих из них есть "name":"RunPass". А что ещё там есть?

$ cat web_http_server.llvm_timings.jsonl | jq -c 'select(.ph == "X" and .name != "RunPass")' | head
{"pid":25,"tid":30,"ts":8291349,"ph":"X","dur":32009,"name":"OptFunction","args":{"detail":"_RNvCscSpY9Juk0HT_7___rustc12___rust_alloc"}}
{"pid":25,"tid":30,"ts":8323394,"ph":"X","dur":283,"name":"OptFunction","args":{"detail":"_RNvCscSpY9Juk0HT_7___rustc14___rust_dealloc"}}
{"pid":25,"tid":30,"ts":8323678,"ph":"X","dur":216,"name":"OptFunction","args":{"detail":"_RNvCscSpY9Juk0HT_7___rustc14___rust_realloc"}}
{"pid":25,"tid":30,"ts":8323895,"ph":"X","dur":179,"name":"OptFunction","args":{"detail":"_RNvCscSpY9Juk0HT_7___rustc19___rust_alloc_zeroed"}}
{"pid":25,"tid":30,"ts":8324075,"ph":"X","dur":155,"name":"OptFunction","args":{"detail":"_RNvCscSpY9Juk0HT_7___rustc26___rust_alloc_error_handler"}}
{"pid":25,"tid":30,"ts":8288691,"ph":"X","dur":35693,"name":"OptModule","args":{"detail":"5z12fn0vr5uv0i2pfsngwe5em"}}
{"pid":25,"tid":35,"ts":9730144,"ph":"X","dur":16,"name":"Annotation2MetadataPass","args":{"detail":"[module]"}}
{"pid":25,"tid":35,"ts":9730214,"ph":"X","dur":10,"name":"ForceFunctionAttrsPass","args":{"detail":"[module]"}}
{"pid":25,"tid":35,"ts":9730346,"ph":"X","dur":11,"name":"InnerAnalysisManagerProxy<llvm::AnalysisManager<llvm::Function>, llvm::Module>","args":{"detail":"[module]"}}
{"pid":25,"tid":35,"ts":9730416,"ph":"X","dur":17,"name":"TargetLibraryAnalysis","args":{"detail":"llvm.expect.i1"}}

Здорово! Похоже, мы можем раздекорировать (demangle) часть символов, чтобы получить тайминги отдельных функций.

Если отследить, что запускается и сколько на это требуется времени, мы лучше поймём, почему компиляция такая долгая.

Ниже идёт агрегированная информация для определённых типов событий, например Total OptFunction. Она эквивалентна сумме длительностей для этого типа события (в данном случае OptFunction). Давайте посмотрим, какие операции занимают больше всего времени:

$ cat web_http_server.llvm_timings.jsonl | jq -r 'select(.name | startswith("Total ")) | "\(.dur / 1e6) \(.name)"' | sort -rn | head
665.369662 Total ModuleInlinerWrapperPass
656.465446 Total ModuleToPostOrderCGSCCPassAdaptor
632.441396 Total DevirtSCCRepeatedPass
627.236893 Total PassManager<llvm::LazyCallGraph::SCC, llvm::AnalysisManager<llvm::LazyCallGraph::SCC, llvm::LazyCallGraph&>, llvm::LazyCallGraph&, llvm::CGSCCUpdateResult&>
536.738589 Total PassManager<llvm::Function>
372.768547 Total CGSCCToFunctionPassAdaptor
193.914869 Total ModuleToFunctionPassAdaptor
190.924012 Total OptModule
189.621119 Total OptFunction
182.250077 Total InlinerPass

На этот конкретный прогон потребовалось примерно 110 секунд на машине с 16 ядрами, поэтому очевидно, что некоторые проходы подсчитаны дважды (что логично — мы встречаем и ModuleInlinerWrapperPass, и InlinerPass, а OptModule, похоже, просто вызывает OptFunction).

Но если в целом, кажется, основную часть времени занимают оптимизация (OptFunction) и встраивание (InlinerPass). Давайте посмотрим, можно ли с этим что-то сделать.

Можно ли ускорить InlinerPass?

Надеюсь, что да!

У LLVM есть множество настраиваемых аргументов, которые rustc раскрывает при помощи флага -C llvm-args. На момент написания статьи (июнь 2025 года), существует примерно сто опций, связанных со встраиванием (rustc -C llvm-args='--help-list-hidden'). В частности, куча соответствующих опций есть в файле, управляющем анализом затрат.

Буду откровенным: я очень мало знаю о встраивании LLVM. Большинство опций связано с «затратами» на встраивание или со встраиванием функций и так далее. В этом я почти не разбираюсь. Но есть аргументы, которые вроде бы подходят для настройки:

• --inlinedefault-threshold=225 — «объём встраивания, выполняемый по умолчанию»

• --inline-threshold=225 — «управление объёмом выполняемого встраивания»

• --inlinehint-threshold=325 — «пороговое значение для встраивания функций с хинтом inline»

Во всех этих опциях «threshold» приблизительно означает следующее: «позволять встраивание с затратами ниже этого порогового значения», то есть чем выше threshold, тем больше встраивания.

То есть если мы присвоим этим опциям какое-то значение (например, 50), то встраивания будет меньше, а значит, снизится время компиляции.

Примерно так:

RUSTFLAGS="-Cllvm-args=-inline-threshold=50 -Cllvm-args=-inlinedefault-threshold=50 -Cllvm-args=-inlinehint-threshold=50" ...

Как бы то ни было, снижение threshold до 50 действительно ускоряет компиляцию! С 48,8 с до 42,2 с.

Вот, как это выглядит для разных значений:

(Примечание: наименьшее значение — это 1, а не 0. Почему 1? Иногда 0 означает особое поведение, поэтому безопаснее будет выбрать 1.)

По этому графику сложно выбрать наилучшее значение, но в моём сценарии использования (вспомним, что у моего веб-сайта почти нулевая нагрузка!), многообещающе выглядит 10. Впрочем, пока не будем торопиться.

Можно ли ускорить OptFunction?

Ещё одной затратной задачей оказалась оптимизация функций.

В этой теме я ориентируюсь гораздо лучше (у нас выбран opt-level = 1, а opt-level = 0 полностью отключает оптимизации). Давайте же разберёмся, на что тратится так много времени.

Для начала вкратце рассмотрим формат событий:

$ cat web_http_server.llvm_timings.jsonl | jq -c 'select(.name == "OptFunction")' | head
{"pid":25,"tid":30,"ts":7995006,"ph":"X","dur":32052,"name":"OptFunction","args":{"detail":"_RNvCscSpY9Juk0HT_7___rustc12___rust_alloc"}}
{"pid":25,"tid":30,"ts":8027059,"ph":"X","dur":242,"name":"OptFunction","args":{"detail":"_RNvCscSpY9Juk0HT_7___rustc14___rust_dealloc"}}
{"pid":25,"tid":30,"ts":8027302,"ph":"X","dur":158,"name":"OptFunction","args":{"detail":"_RNvCscSpY9Juk0HT_7___rustc14___rust_realloc"}}
{"pid":25,"tid":30,"ts":8027461,"ph":"X","dur":126,"name":"OptFunction","args":{"detail":"_RNvCscSpY9Juk0HT_7___rustc19___rust_alloc_zeroed"}}
{"pid":25,"tid":30,"ts":8027589,"ph":"X","dur":150,"name":"OptFunction","args":{"detail":"_RNvCscSpY9Juk0HT_7___rustc26___rust_alloc_error_handler"}}
{"pid":25,"tid":35,"ts":31457262,"ph":"X","dur":24576,"name":"OptFunction","args":{"detail":"_ZN10serde_json5value8to_value17h0315c73febebe85cE"}}
{"pid":25,"tid":35,"ts":31481850,"ph":"X","dur":11862,"name":"OptFunction","args":{"detail":"_ZN10serde_json5value8to_value17h0516143613516496E"}}
{"pid":25,"tid":35,"ts":31493764,"ph":"X","dur":15830,"name":"OptFunction","args":{"detail":"_ZN10serde_json5value8to_value17h0bdb4ac12d8ad59bE"}}
{"pid":25,"tid":35,"ts":31509615,"ph":"X","dur":8221,"name":"OptFunction","args":{"detail":"_ZN10serde_json5value8to_value17h0c630b789ee318c2E"}}
{"pid":25,"tid":35,"ts":31517858,"ph":"X","dur":8670,"name":"OptFunction","args":{"detail":"_ZN10serde_json5value8to_value17h12ba815471bb2bc8E"}}

В этом сыром виде поле .args.detail каждого из событий содержит декорированный символ оптимизируемой функции. Можно «раздекорировать» их обратно в исходные символы Rust при помощи rustfilt. Например:

$ cargo install rustfilt

$ rustfilt '_RNvCscSpY9Juk0HT_7___rustc12___rust_alloc'
__rustc::__rust_alloc
$ rustfilt '_ZN10serde_json5value8to_value17h0315c73febebe85cE'
serde_json::value::to_value

Стоит отметить, что хотя в показанном выше списке есть множество элементов serde_json::value::to_value, на самом деле они имеют уникальные хэши:

$ rustfilt -h '_ZN10serde_json5value8to_value17h0315c73febebe85cE'
serde_json::value::to_value::h0315c73febebe85c
$ rustfilt -h '_ZN10serde_json5value8to_value17h0516143613516496E'
serde_json::value::to_value::h0516143613516496
$ rustfilt -h '_ZN10serde_json5value8to_value17h0bdb4ac12d8ad59bE'
serde_json::value::to_value::h0bdb4ac12d8ad59b
$ rustfilt -h '_ZN10serde_json5value8to_value17h0c630b789ee318c2E'
serde_json::value::to_value::h0c630b789ee318c2
$ rustfilt -h '_ZN10serde_json5value8to_value17h12ba815471bb2bc8E'
serde_json::value::to_value::h12ba815471bb2bc8

... что логично, учитывая, что serde_json::value::to_value — это дженерик-функция; может быть так, что она оптимизируется с разными дженерик-параметрами («мономорфизациями»).

Постойте, а почему мы оптимизируем функции из других крейтов?

Если вкратце, то оптимизация выполняется в контексте того крейта, где была мономорфизирована функция. То есть если мы определим тип Foo, а затем вызовем методы для Option<Foo>, то эти методы с этими типами будут сначала существовать в контексте нашего крейта. Это значит, что он будет компилироваться и оптимизироваться с той же конфигурацией, что и наш крейт.

Если немного знать, как устроена внутренняя работа компилятора, то это будет довольно логично, но снаружи это наверняка покажется немного странным!

На что же тратится столько времени?

Теперь, когда мы знаем, что изучаем, пришла пора провести анализ. Например, найдя отдельные функции, на оптимизацию которых тратится больше всего времени:

$ cat web_http_server.llvm_timings.jsonl \
    | jq -c 'select(.name == "OptFunction")' \
    | jq -sc 'sort_by(-.dur) | .[] | { dur: (.dur / 1e6), detail: .args.detail }' \
    | head
{"dur":1.875744,"detail":"_ZN15web_http_server6photos11PhotosState3new28_$u7b$$u7b$closure$u7d$$u7d$17ha4de409b0951d78bE"}
{"dur":1.44252,"detail":"_ZN14tokio_postgres6client6Client5query28_$u7b$$u7b$closure$u7d$$u7d$17h18fb9179bb73bfa4E"}
{"dur":1.440186,"detail":"_ZN15web_http_server3run28_$u7b$$u7b$closure$u7d$$u7d$17h426fe76bd1b089abE"}
{"dur":1.397705,"detail":"_ZN15web_http_server6photos11PhotosState3new28_$u7b$$u7b$closure$u7d$$u7d$17ha4de409b0951d78bE"}
{"dur":1.170948,"detail":"_ZN14tokio_postgres11connect_raw11connect_raw28_$u7b$$u7b$closure$u7d$$u7d$17h0dfcfa0a648a93f8E"}
{"dur":1.158111,"detail":"_ZN14pulldown_cmark5parse15Parser$LT$F$GT$19handle_inline_pass117hc91a3dc90e0e9e0cE"}
{"dur":1.131707,"detail":"_ZN129_$LT$axum..boxed..MakeErasedHandler$LT$H$C$S$GT$$u20$as$u20$axum..boxed..ErasedIntoRoute$LT$S$C$core..convert..Infallible$GT$$GT$9clone_box17he7f38a2ccd053fbbE"}
{"dur":1.062162,"detail":"_ZN4core3ptr49drop_in_place$LT$http..extensions..Extensions$GT$17h89b138bb6c1aa101E"}
{"dur":1.026656,"detail":"_ZN15web_http_server3run28_$u7b$$u7b$closure$u7d$$u7d$17h426fe76bd1b089abE"}
{"dur":1.009844,"detail":"_ZN4core3ptr252drop_in_place$LT$$LT$alloc..vec..drain..Drain$LT$T$C$A$GT$$u20$as$u20$core..ops..drop..Drop$GT$..drop..DropGuard$LT$lol_html..selectors_vm..stack..StackItem$LT$lol_html..rewriter..rewrite_controller..ElementDescriptor$GT$$C$alloc..alloc..Global$GT$$GT$17h62ca0c07fce3ede0E"}

(Зачем нужны два отдельных вызова jq? Если бы мы выполнили всего один, то вызов -s/--slurp перед обработкой загрузил бы весь файл в один массив, а это одна из основных операций, которых мы хотим избежать)

На отдельные функции тратится неожиданно много времени! Профилирование приблизительно удваивает общее время компиляции, но даже 1 секунда на оптимизацию функции — это много!

Но давайте изучим всё подробнее. У нас есть:

• web_http_server::photos::PhotosState::new::{{closure}} — это некое замыкание внутри огромной async-функции на четыреста строк, выполняющей подготовку для https://sharnoff.io/photos

• web_http_server::run::{{closure}} — это замыкание внутри основной точки входа (тоже async), но все замыкания выполняют небольшую обработку ошибок, например .wrap_err_with(|| format!("failed to bind address {addr:?}"))

  • Возможно, здесь происходит что-то странное!

... и куча зависимостей, на которые тоже тратится приличное время:

• pulldown_cmark содержит функцию в пятьсот строк

• tokio_postgres::connect_raw — это простое замыкание внутри async-функции нормального размера. Возможно, оно нужно для того же, что и замыкание в web_http_server::run?

• Drop-реализация http::extensions::Extensions выглядит так, как будто должна быть простой (у неё нет явного деструктора), но внутри неё Option<Box<HashMap<TypeId, Box<dyn ...>, BuildDefaultHasher<..>>>>. Возможно, здесь большая сложность возникла из-за встраивания?

• И vec::Drain<T> с серией вложенных типов lol_html тоже вызывают жалобы; возможно, по тем же причинам.

Или же мы можем выполнить разбивку по самому внешнему крейту:

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' \
    | xargs -l bash -c 'echo "{\"dur\":$0,\"root\":\"$(rustfilt "$1" | sed -E "s/^([a-z_-]+)::.*/\1/g")\"}"' \
    | jq -s -r 'group_by(.root) | map({ root: .[0].root, dur: (map(.dur) | add) }) | sort_by(-.dur) | .[] | "\(.dur / 1e6) \(.root)"' \
    | head 
61.534452 core
13.750173 web_http_server
11.237289 tokio
7.890088 tokio_postgres
6.851621 lol_html
4.470053 alloc
4.177471 feed_rs
3.269217 std
3.067573 hashbrown
3.063146 eyre

Разумеется, это очень неточная метрика: самый внешний крейт не всегда больше всего связан со временем компиляции, и при этой простой фильтрации мы упускаем множество элементов наподобие <Foo as Bar>::baz. Но если закрыть на всё это глаза, то удивительно, насколько большой вклад вносит core!

Если покопаться глубже, выясниться, что 84% этого времени — это просто параметризации core::ptr::drop_in_place!

Исследуем глубже замыкания с декорированием v0

Длительное время компиляции замыканий кажется очень подозрительным; возможно, стоит исследовать его подробнее. Есть лишь одна проблема: все символы заканчиваются на {{closure}}, не сообщая, какое из них занимает всё время.

Как оказалось, это легко можно исправить! На июнь 2025 года rustc по умолчанию использует «легаси»-формат декорирования символов, но есть и более новая опция с дополнительной информацией: формат v0.

Мы можем включить его, добавив к уже имеющимся флагам RUSTFLAGS="-C symbol-mangling-version=v0". Выглядеть это будет примерно так:

RUSTC_BOOTSTRAP=1 RUSTFLAGS="-Csymbol-mangling-version=v0 -Zllvm-time-trace" cargo build --timings ...

(Примечание: issue этой фичи был открыт в течение шести лет, почему её до сих пор не смерджили? Оказывается, чтобы добавить её поддержку в популярные инструменты наподобие gdb и perf, требуется много апстрим-работы. Большая её часть уже была проделана, но готово ещё не всё).

В результате этого в трассировке LLVM будут отображаться гораздо более качественные символы. Например, вот, как выглядят теперь эти символы serde_json::value::to_value:

$ cat web_http_server.llvm_timings.jsonl | jq -c 'select(.name == "OptFunction")' | grep -E 'serde_json.+value.+to_value' | head
{"pid":25,"tid":35,"ts":34400185,"ph":"X","dur":7336,"name":"OptFunction","args":{"detail":"_RINvNtCs9KWWFfvvCPd_10serde_json5value8to_valueINtNCNvCs5etrU9lJXb7_15web_http_server5index012IndexContextNtNtNtNtBQ_4blog6handle7context9RootIndexNtNtNtNtBQ_6photos6handle7context9RootIndexEEBQ_"}}
{"pid":25,"tid":35,"ts":34407530,"ph":"X","dur":13226,"name":"OptFunction","args":{"detail":"_RINvNtCs9KWWFfvvCPd_10serde_json5value8to_valueNtNtNtNtCs5etrU9lJXb7_15web_http_server4blog6handle7context4PostEBR_"}}
{"pid":25,"tid":35,"ts":34420761,"ph":"X","dur":10344,"name":"OptFunction","args":{"detail":"_RINvNtCs9KWWFfvvCPd_10serde_json5value8to_valueNtNtNtNtCs5etrU9lJXb7_15web_http_server4blog6handle7context5IndexEBR_"}}
{"pid":25,"tid":35,"ts":34431114,"ph":"X","dur":11100,"name":"OptFunction","args":{"detail":"_RINvNtCs9KWWFfvvCPd_10serde_json5value8to_valueNtNtNtNtCs5etrU9lJXb7_15web_http_server6photos6handle7context11AlbumsIndexEBR_"}}

$ rustfilt '_RINvNtCs9KWWFfvvCPd_10serde_json5value8to_valueINtNCNvCs5etrU9lJXb7_15web_http_server5index012IndexContextNtNtNtNtBQ_4blog6handle7context9RootIndexNtNtNtNtBQ_6photos6handle7context9RootIndexEEBQ_'
serde_json::value::to_value::<web_http_server::index::{closure#0}::IndexContext<web_http_server::blog::handle::context::RootIndex, web_http_server::photos::handle::context::RootIndex>>
$ rustfilt '_RINvNtCs9KWWFfvvCPd_10serde_json5value8to_valueNtNtNtNtCs5etrU9lJXb7_15web_http_server4blog6handle7context4PostEBR_'
serde_json::value::to_value::<web_http_server::blog::handle::context::Post>
$ rustfilt '_RINvNtCs9KWWFfvvCPd_10serde_json5value8to_valueNtNtNtNtCs5etrU9lJXb7_15web_http_server4blog6handle7context5IndexEBR_'
serde_json::value::to_value::<web_http_server::blog::handle::context::Index>
$ rustfilt '_RINvNtCs9KWWFfvvCPd_10serde_json5value8to_valueNtNtNtNtCs5etrU9lJXb7_15web_http_server6photos6handle7context11AlbumsIndexEBR_'
serde_json::value::to_value::<web_http_server::photos::handle::context::AlbumsIndex>

То есть мы получаем не только более качественную разметку замыканий (см., например, {closure#0}), но и полные дженерики для всего!

Теперь нам должно уже стать намного понятнее, на что же тратится столько времени:

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' \
    | xargs -l bash -c 'echo "{\"dur\":$0,\"fn\":\"$(rustfilt "$1")\"}"' \
    | jq -sr 'sort_by(-.dur) | .[] | "\(.dur / 1e4 | round | . / 1e2)s \(.fn)"' \
    | head -n5
1.99s <web_http_server::photos::PhotosState>::new::{closure#0}
1.56s web_http_server::run::{closure#0}
1.41s <web_http_server::photos::PhotosState>::new::{closure#0}
1.22s core::ptr::drop_in_place::<axum::routing::Endpoint<web_http_server::AppState>>
1.15s core::ptr::drop_in_place::<axum::routing::method_routing::MethodEndpoint<web_http_server::AppState, core::convert::Infallible>>

... но эти первые несколько замыканий крошечные:

let is_jpg = |path: &Path| path.extension().and_then(|s| s.to_str()) == Some("jpg");

и

let app = axum::Router::new()
    /* .route(...) для многих других */
    .route("/feed.xml", axum::routing::get(move || async move { feed }))
    //                         вот это:   ^^^^^^^^^^^^^^^^^^^^^^^^^^^

И если мы удалим эти замыкания, по возможности заменив их на отдельно определяемые функции, LLVM всё равно сообщит, что на оптимизацию {closure#0} во внешней функции требуется много времени.

Так откуда берутся эти замыкания?

Сдампив LLVM IR с помощью RUSTFLAGS="--emit=llvm-ir" (который помещает его в target/.../deps/*.ll) и выполнив поиск по сгенерированным функциям, я нашёл следующую строку:

; core::ptr::drop_in_place::<<web_http_server::photos::PhotosState>::new::{closure#0}::process_photo::{closure#0}>

Эта функцияprocess_photo была вложенной async-функцией, определённой непосредственно внутри PhotosState::new. Так почему же символ говорит, что она определена внутри замыкания?

Потому что внутри rustc async-функции/блоки представлены в виде вложенного замыкания. То есть во всех этих местах async-функций, где компиляция closure#0 занимала много времени, на самом деле имелись в виду сами функции!

Поискав по github (is:issue state:open async fn closure mangle), я выяснил, что по этому поводу уже есть открытое issue!

Большие async-функции считаются вредными?

Вернёмся к приведённому выше списку: в тех async-функциях, в которых LLVM тратит много времени на оптимизацию closure#0, на самом деле время тратится в теле самой функции. Логично, что большие функции оптимизировать сложно, а async-функции — вдвое сложнее.

Можно достаточно просто обнаружить внутри основного крейта все функции, занимающие много времени:

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' \
    | xargs -l bash -c 'echo "{\"dur\":$0,\"fn\":\"$(rustfilt "$1")\"}"' \
    | jq -sc 'group_by(.fn) | map({ fn: .[0].fn, dur: (map(.dur) | add) }) | sort_by(-.dur) | .[]' \
    | jq -r 'select(.fn | test("^(core::ptr::drop_in_place::<)?<*web_http_server")) | "\(.dur / 1e4 | round | . / 1e2)s \(.fn)"' \
    | head -n10
4.11s <web_http_server::photos::PhotosState>::new::{closure#0}
3.05s web_http_server::run::{closure#0}
1.44s core::ptr::drop_in_place::<web_http_server::run::{closure#0}>
0.6s <web_http_server::reading_list::handle::post_login as axum::handler::Handler<(axum_core::extract::private::ViaRequest, axum::extract::state::State<&web_http_server::reading_list::ReadingListState>, axum::extract::state::State<&tera::tera::Tera>, axum_extra::extract::cookie::CookieJar, axum::form::Form<web_http_server::reading_list::handle::LoginForm>), web_http_server::AppState>>::call::{closure#0}
0.57s web_http_server::reading_list::fetch_posts_data::{closure#0}
0.51s <web_http_server::reading_list::ReadingListState>::make_pool::{closure#0}
0.44s <web_http_server::reading_list::ReadingListState>::refresh_single::{closure#0}
0.38s <web_http_server::photos::PhotosState>::process_photo::{closure#0}
0.38s <web_http_server::html::WriteState>::process_event
0.33s core::ptr::drop_in_place::<<web_http_server::reading_list::ReadingListState>::run_refresh::{closure#0}::{closure#0}>

Часть самых затратных функций находится в области подготовки.

Давайте попробуем разбить на части одну функцию, чтобы проверить, поможет ли это. Начнём с PhotosState::new.

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' \
    | xargs -l bash -c 'echo "{\"dur\":$0,\"fn\":\"$(rustfilt "$1")\"}"' \
    | jq -sc 'group_by(.fn) | map({ fn: .[0].fn, dur: (map(.dur) | add) }) | sort_by(-.dur) | .[]' \
    | jq 'select(.fn | test("^(core::ptr::drop_in_place::<)?<web_http_server::photos::PhotosState>::new")) | .dur' \
    | jq -sr 'add | . / 1e4 | round | . / 1e2 | "\(.)s"'
5.3s

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' \
    | xargs -l bash -c 'echo "{\"dur\":$0,\"fn\":\"$(rustfilt "$1")\"}"' \
    | jq -sc 'group_by(.fn) | map({ fn: .[0].fn, dur: (map(.dur) | add) }) | sort_by(-.dur) | .[]' \
    | jq -r 'select(.fn | test("^(core::ptr::drop_in_place::<)?<web_http_server::photos::PhotosState>::new")) | "\(.dur / 1e4 | round | . / 1e2)s \(.fn)"'
4.11s <web_http_server::photos::PhotosState>::new::{closure#0}
0.27s core::ptr::drop_in_place::<<web_http_server::photos::PhotosState>::new::{closure#0}>
0.24s core::ptr::drop_in_place::<<web_http_server::photos::PhotosState>::new::{closure#0}::{closure#2}::{closure#0}>
0.23s core::ptr::drop_in_place::<<web_http_server::photos::PhotosState>::new::{closure#0}::{closure#2}>
0.19s core::ptr::drop_in_place::<<web_http_server::photos::PhotosState>::new::{closure#0}::{closure#6}::{closure#0}>
0.11s core::ptr::drop_in_place::<<web_http_server::photos::PhotosState>::new::{closure#0}::{closure#7}::{closure#0}>
0.03s <web_http_server::photos::PhotosState>::new::{closure#0}::{closure#6}::{closure#0}
0.02s <web_http_server::photos::PhotosState>::new::{closure#0}::{closure#3}
0.02s <web_http_server::photos::PhotosState>::new::{closure#0}::{closure#11}
0.02s <web_http_server::photos::PhotosState>::new::{closure#0}::{closure#4}
0.02s <web_http_server::photos::PhotosState>::new::{closure#0}::{closure#5}
0.01s <web_http_server::photos::PhotosState>::new::{closure#0}::{closure#2}
0.01s <web_http_server::photos::PhotosState>::new::{closure#0}::{closure#7}::{closure#0}
0.01s <web_http_server::photos::PhotosState>::new::{closure#0}::{closure#2}::{closure#0}
0.01s <web_http_server::photos::PhotosState>::new::{closure#0}::{closure#1}::{closure#1}

В своей первой попытке я попытался разбить её на части, параллельно стремясь сохранить количество .await, надеясь изолировать тот тип сложности, который вызывает проблемы.

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' 
    | xargs -l bash -c 'echo "{\"dur\":$0,\"fn\":\"$(rustfilt "$1")\"}"' \
    | jq -sc 'group_by(.fn) | map({ fn: .[0].fn, dur: (map(.dur) | add) }) | sort_by(-.dur) | .[]' \
    | jq 'select(.fn | test("^(core::ptr::drop_in_place::<)?<*web_http_server::photos::(init|PhotosState>::new)")) | .dur' \
    | jq -sr 'add | . / 1e4 | round | . / 1e2 | "\(.)s"'
4.66s

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' \
    | xargs -l bash -c 'echo "{\"dur\":$0,\"fn\":\"$(rustfilt "$1")\"}"' \
    | jq -sc 'group_by(.fn) | map({ fn: .[0].fn, dur: (map(.dur) | add) }) | sort_by(-.dur) | .[]' \
    | jq -r 'select(.fn | test("^(core::ptr::drop_in_place::<)?<*web_http_server::photos::(init|PhotosState>::new)")) | "\(.dur / 1e4 | round | . / 1e2)s \(.fn)"'
3.37s web_http_server::photos::init::make_state::{closure#0}
0.24s core::ptr::drop_in_place::<web_http_server::photos::init::image_process_futs::{closure#0}::{closure#0}>
0.21s core::ptr::drop_in_place::<web_http_server::photos::init::album_process_futs::{closure#0}>
0.21s core::ptr::drop_in_place::<web_http_server::photos::init::make_state::{closure#0}>
0.16s core::ptr::drop_in_place::<web_http_server::photos::init::image_process_futs::{closure#0}>
0.12s core::ptr::drop_in_place::<web_http_server::photos::init::album_process_futs::{closure#1}>
0.06s web_http_server::photos::init::album_process_futs::{closure#0}
0.04s web_http_server::photos::init::image_process_futs::{closure#0}
0.03s web_http_server::photos::init::album_process_futs::{closure#1}
0.03s web_http_server::photos::init::album_process_futs
0.02s core::ptr::drop_in_place::<web_http_server::photos::init::get_img_candidates::{closure#0}>
0.02s web_http_server::photos::init::make_album_membership
0.02s web_http_server::photos::init::make_state::{closure#0}::{closure#1}
0.02s web_http_server::photos::init::make_albums_in_order
0.02s web_http_server::photos::init::image_process_futs
0.02s web_http_server::photos::init::make_state::{closure#0}::{closure#3}
0.02s web_http_server::photos::init::make_state::{closure#0}::{closure#2}
0.02s web_http_server::photos::init::image_process_futs::{closure#0}::{closure#0}
0.02s web_http_server::photos::init::make_state::{closure#0}::{closure#7}
0.01s web_http_server::photos::init::make_all_album
0.01s web_http_server::photos::init::make_recently_published_albums
0.01s web_http_server::photos::init::make_images_by_time
0s web_http_server::photos::init::get_img_candidates::{closure#0}::{closure#1}::{closure#1}

Любопытно, что это почти не помогло, общее время снизилось с 5,3 с до 4,7 с.

Так что затем я попытался объединить несколько соседних .await в их собственные функции, снизив общее количество с 10 до 3.

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' 
    | xargs -l bash -c 'echo "{\"dur\":$0,\"fn\":\"$(rustfilt "$1")\"}"' \
    | jq -sc 'group_by(.fn) | map({ fn: .[0].fn, dur: (map(.dur) | add) }) | sort_by(-.dur) | .[]' \
    | jq 'select(.fn | test("^(core::ptr::drop_in_place::<)?<*web_http_server::photos::(init|PhotosState>::new)")) | .dur' \
    | jq -sr 'add | . / 1e4 | round | . / 1e2 | "\(.)s"'
6.24s

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' \
    | xargs -l bash -c 'echo "{\"dur\":$0,\"fn\":\"$(rustfilt "$1")\"}"' \
    | jq -sc 'group_by(.fn) | map({ fn: .[0].fn, dur: (map(.dur) | add) }) | sort_by(-.dur) | .[]' \
    | jq -r 'select(.fn | test("^(core::ptr::drop_in_place::<)?<*web_http_server::photos::(init|PhotosState>::new)")) | "\(.dur / 1e4 | round | . / 1e2)s \(.fn)"'
2.7s web_http_server::photos::init::process_all_images::{closure#0}
1.93s web_http_server::photos::init::make_state::{closure#0}
0.25s core::ptr::drop_in_place::<web_http_server::photos::init::image_process_futs::{closure#0}::{closure#0}>
0.25s core::ptr::drop_in_place::<web_http_server::photos::init::album_process_futs::{closure#0}>
0.18s core::ptr::drop_in_place::<web_http_server::photos::init::image_process_futs::{closure#0}>
0.14s core::ptr::drop_in_place::<web_http_server::photos::init::album_process_futs::{closure#1}>
0.09s core::ptr::drop_in_place::<web_http_server::photos::init::process_all_images::{closure#0}>
0.08s core::ptr::drop_in_place::<web_http_server::photos::init::join_image_futs<web_http_server::photos::init::image_process_futs::{closure#0}>::{closure#0}>
0.07s core::ptr::drop_in_place::<web_http_server::photos::init::make_state::{closure#0}>
0.07s web_http_server::photos::init::album_process_futs::{closure#0}
0.06s core::ptr::drop_in_place::<web_http_server::photos::init::parse::{closure#0}>
0.04s core::ptr::drop_in_place::<web_http_server::photos::init::join_album_futs::{closure#0}>
0.04s web_http_server::photos::init::image_process_futs::{closure#0}
0.03s web_http_server::photos::init::album_process_futs
0.03s web_http_server::photos::init::make_album_membership
0.03s core::ptr::drop_in_place::<web_http_server::photos::init::get_img_candidates::{closure#0}>
0.03s web_http_server::photos::init::album_process_futs::{closure#1}
0.03s web_http_server::photos::init::make_albums_in_order
0.03s web_http_server::photos::init::image_process_futs
0.02s web_http_server::photos::init::process_all_images::{closure#0}::{closure#1}
0.02s web_http_server::photos::init::make_state::{closure#0}::{closure#0}
0.02s web_http_server::photos::init::make_state::{closure#0}::{closure#1}
0.02s web_http_server::photos::init::process_all_images::{closure#0}::{closure#2}
0.02s web_http_server::photos::init::image_process_futs::{closure#0}::{closure#0}
0.02s web_http_server::photos::init::make_all_album
0.01s web_http_server::photos::init::make_images_by_time
0.01s web_http_server::photos::init::make_recently_published_albums
0s web_http_server::photos::init::get_img_candidates::{closure#0}::{closure#1}::{closure#1}

Но всё стало существенно медленнее! Время увеличилось с 4,66 с до 6,24 с!

Начало казаться, что с async-функциями происходит что-то странное. Иначе почему бы разбиение на большее количество функций ухудшало ситуацию?

Внутри async-функции избавляются от сахара, превращаясь в сложный конечный автомат. Возможно, там происходит что-то непонятное, поэтому если мы хотим упростить ситуацию на вызывающей стороне, можно превратить Future в объект трейта, чтобы скрыть реализацию за ним (обычно Pin<Box<dyn Future>>).

Так что на этот раз давайте добавим такую новую функцию:

fn erase<'a, T>(
    fut: impl 'a + Send + Future<Output = T>,
) -> Pin<Box<dyn 'a + Send + Future<Output = T>>> {
    Box::pin(fut)
}

и используем её везде, где применяется .await. Например:

// старое:
let candidates = get_img_candidates().await?;

// новое:
let candidates = erase(get_img_candidates()).await?;

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' 
    | xargs -l bash -c 'echo "{\"dur\":$0,\"fn\":\"$(rustfilt "$1")\"}"' \
    | jq -sc 'group_by(.fn) | map({ fn: .[0].fn, dur: (map(.dur) | add) }) | sort_by(-.dur) | .[]' \
    | jq 'select(.fn | test("^(core::ptr::drop_in_place::<)?<*web_http_server::photos::(init|PhotosState>::new)")) | .dur' \
    | jq -sr 'add | . / 1e4 | round | . / 1e2 | "\(.)s"'
2.14s

$ cat web_http_server.llvm_timings.jsonl \
    | jq -r 'select(.name == "OptFunction") | "\(.dur) \(.args.detail)"' \
    | xargs -l bash -c 'echo "{\"dur\":$0,\"fn\":\"$(rustfilt "$1")\"}"' \
    | jq -sc 'group_by(.fn) | map({ fn: .[0].fn, dur: (map(.dur) | add) }) | sort_by(-.dur) | .[]' \
    | jq -r 'select(.fn | test("^(core::ptr::drop_in_place::<)?<*web_http_server::photos::(init|PhotosState>::new)")) | "\(.dur / 1e4 | round | . / 1e2)s \(.fn)"'
0.25s web_http_server::photos::init::process_all_images::{closure#0}
0.21s core::ptr::drop_in_place::<web_http_server::photos::init::image_process_futs::{closure#0}::{closure#0}>
0.2s core::ptr::drop_in_place::<web_http_server::photos::init::image_process_futs::{closure#0}>
0.2s web_http_server::photos::init::join_image_futs::<web_http_server::photos::init::image_process_futs::{closure#0}>::{closure#0}
0.19s core::ptr::drop_in_place::<web_http_server::photos::init::album_process_futs::{closure#0}>
0.13s web_http_server::photos::init::parse::{closure#0}
0.11s core::ptr::drop_in_place::<web_http_server::photos::init::album_process_futs::{closure#1}>
0.1s web_http_server::photos::init::get_img_candidates::{closure#0}
0.1s core::ptr::drop_in_place::<web_http_server::photos::init::make_state::{closure#0}>
0.06s core::ptr::drop_in_place::<web_http_server::photos::init::process_all_images::{closure#0}>
0.06s web_http_server::photos::init::album_process_futs::{closure#0}
0.06s web_http_server::photos::init::album_process_futs
0.05s web_http_server::photos::init::join_album_futs::{closure#0}
0.05s web_http_server::photos::init::make_albums_in_order
0.05s core::ptr::drop_in_place::<web_http_server::photos::init::join_image_futs<web_http_server::photos::init::image_process_futs::{closure#0}>::{closure#0}>
0.04s core::ptr::drop_in_place::<web_http_server::photos::init::parse::{closure#0}>
0.03s web_http_server::photos::init::image_process_futs::{closure#0}
0.03s web_http_server::photos::init::make_all_album
0.03s web_http_server::photos::init::album_process_futs::{closure#1}
0.02s core::ptr::drop_in_place::<web_http_server::photos::init::join_album_futs::{closure#0}>
0.02s core::ptr::drop_in_place::<web_http_server::photos::init::get_img_candidates::{closure#0}>
0.02s web_http_server::photos::init::make_state::{closure#0}::{closure#1}
0.02s web_http_server::photos::init::make_state::{closure#0}::{closure#0}
0.02s web_http_server::photos::init::make_recently_published_albums
0.02s web_http_server::photos::init::image_process_futs::{closure#0}::{closure#0}
0.01s web_http_server::photos::init::make_images_by_time
0.01s web_http_server::photos::init::erase::<core::result::Result<std::collections::hash::map::HashMap<alloc::string::String, &web_http_server::photos::Album>, eyre::Report>, web_http_server::photos::init::join_album_futs::{closure#0}>
0.01s web_http_server::photos::init::erase::<core::result::Result<web_http_server::photos::init::ProcessedImages, eyre::Report>, web_http_server::photos::init::process_all_images::{closure#0}>
0.01s web_http_server::photos::init::erase::<core::result::Result<(web_http_server::photos::MapSettings, web_http_server::photos::FlexGridSettings, web_http_server::photos::parsed::HiddenAlbumsAndPhotos, web_http_server::photos::parsed::Albums), eyre::Report>, web_http_server::photos::init::parse::{closure#0}>
0.01s web_http_server::photos::init::process_all_images::{closure#0}::{closure#1}
0.01s web_http_server::photos::init::process_all_images::{closure#0}::{closure#2}
0.01s web_http_server::photos::init::make_state
0.01s web_http_server::photos::init::get_img_candidates::{closure#0}::{closure#1}::{closure#1}

Это решение сработало — время снизилось до 2,14 с.

То есть мы перешли от 5,3 с до 2,14 с — приличный прогресс, хоть и потребовавший кучи усилий. (Также должен сказать, что когда я обёртывал future в Box::pin вместо новой функции, время это никак не поменяло).

Заново запустив сборку без профилирования, мы получили общее снижение времени с 48,8 с до 46,8 с. Довольно мало, но мы ведь изменили всего одну функцию!

(Примечание: а как насчёт #[inline(never)]? Я пробовал с ним и без него – после box время компиляции с отключенным для этих функций встраиванием не становились лучше, но это всё равно полезно, чтобы лучше разбираться, от чего зависят тайминги LLVM.)

(Примечание: а как насчёт отключения встраивания для poll-функций? Я пробовал обернуть async-функции в реализацию Future, указав #[inline(never)] для её poll-функции. Это немного помогло, но не так сильно, как box).

Соединяем всё вместе

У нас есть множество возможных подходов. Давайте попробуем:

1. Заменить встраивание аргументами LLVM;

2. Разбивать затратные функции в основном крейте;

3. Удалить дженерики из зависимостей, чтобы их не нужно было компилировать в основном крейте

Изменим финальные команды Dockerfile следующим образом:

RUN RUSTFLAGS='-Cllvm-args=-inline-threshold=10 -Cllvm-args=-inlinedefault-threshold=10 -Cllvm-args=-inlinehint-threshold=10' \
        cargo chef cook --release --target=x86_64-unknown-linux-musl --recipe-path=/workdir/recipe.json

...

RUN RUSTFLAGS='-Cllvm-args=-inline-threshold=10 -Cllvm-args=-inlinedefault-threshold=10 -Cllvm-args=-inlinehint-threshold=10' \
        cargo build --timings --release --target=x86_64-unknown-linux-musl --package web-http-server

... и внесём множество более мелких изменений в основной крейт:

$ git diff --stat base..HEAD -- web-http-server
...
 10 files changed, 898 insertions(+), 657 deletions(-)

... а также изменения в крупные зависимости:

• Сделаем дженерик-функцию не дженериком: https://github.com/pulldown-cmark/pulldown-cmark/pull/1045

• Соберём отдельный крейт с не дженериками: изменения в cargo-chef, с новым локальным крейтом, раскрывающим новые версии API без дженериков, которые я использую из lol_html и deadpool_postgres

... что обеспечит нам время компиляции 32,3 с.

Дополнение

После того, как я опубликовал этот пост, пара пользователей Bluesky дала мне хорошие советы!

1. Включить -Zshare-generics; и

2. Заменить Alpine

Включаем -Zshare-generics

Пётр Осевич с Bluesky предложил включить -Zshare-generics:

При этом будут заново использоваться экземпляры дженериков из зависимостей крейта. Флаг не включён в релизных сборках (по умолчанию), потому что отрицательно сказывается на кодогенерации.

[ ... ]

Флаг доступен только в nightly-сборках, но включён для dev-сборок даже при использовании стабильного тулчейна.

Звучит неплохо, давайте попробуем его включить!

RUSTFLAGS="-Zshare-generics -Cllvm-args=-inline-threshold=10 -Cllvm-args=-inlinedefault-threshold=10 -Cllvm-args=-inlinehint-threshold=10" ...

Конечный результат любопытен — снижение общего времени компиляции с 32,3 с до 29,1 с, даже несмотря на то, что многие из core::ptr::drop_in_place, которые мы компилировали ранее, всё ещё присутствуют.

В поисках самого большого времени отфильтруем только по drop_in_place, чтобы найти конкретные типы, раскрытые другими крейтами:

$ # Before
$ cat ... | jq ... \
    | grep -P 'core::ptr::drop_in_place::<(?!web_http_server)[a-zA-Z0-9_:]+>$' \
    | head -n5
0.42s core::ptr::drop_in_place::<tracing_subscriber::filter::directive::ParseError>
0.13s core::ptr::drop_in_place::<http::uri::Uri>
0.12s core::ptr::drop_in_place::<toml_edit::item::Item>
0.11s core::ptr::drop_in_place::<std::io::error::Error>
0.1s core::ptr::drop_in_place::<hyper::body::incoming::Incoming>

$ # After
$ cat ... | jq ... \
    | grep -P 'core::ptr::drop_in_place::<(?!web_http_server)[a-zA-Z0-9_:]+>$' \
    | head -n5
0.59s core::ptr::drop_in_place::<hyper::ext::Protocol>
0.28s core::ptr::drop_in_place::<http::header::map::HeaderMap>
0.1s core::ptr::drop_in_place::<std::io::error::Error>
0.09s core::ptr::drop_in_place::<http::uri::Uri>
0.08s core::ptr::drop_in_place::<tokio::runtime::io::registration::Registration>

Между ними есть некоторые изменения, но для многих зависимостей всё равно выполняется компиляция того же core::ptr::drop_in_place!

Впрочем, несмотря на это, время оптимизации существенно снизилось — если смотреть только на экземпляры drop_in_place, то с 21,7 с до 17,4 с, и гораздо больше, если учитывать всё вместе (с 128 с до 104 с; при многопоточности и с оверхедом профилирования LLVM).

Уходим с Alpine

Уэсли Мур в Lobsters (через Bluesky) предложил уйти с Alpine, потому что используемый в нём по умолчанию распределитель памяти может влиять на время компиляции:

По моему опыту, распределитель памяти может сильно влиять на время сборки. Например, когда Chimera Linux перешёл со scudo (который уже был лучше, чем стандартный распределитель памяти musl) на mimalloc, время чистой сборки Gleam снизилось с 67 с до 46 с.

Схожие результаты можно наблюдать, сменив базовый образ сборки в docker [ ... ]

Это привело к огромным изменениям.

Перейдя с alpine на debian и убрав --target=x86_64-unknown-linux-musl, я снизил время компиляции с 29,1 с аж до 9,1 с!

Подведём итог

1. Мы начинали примерно с 175 с

2. Отключив LTO (и отладочные символы!), мы получили 51 с (-71%)

3. Перейдя на opt-level = 1 для финального крейта, мы получили 48,8 с (-4%)

4. Уменьшив встраивание при помощи -C llvm-args, мы получили 40,7 с (-16%)

5. Локальные изменения позволили добиться 37,7 с (-7%)

6. Изменения в зависимостях дали нам 32,3 с (-14%)

С дополнениями:

7. Включив -Zshare-generics, мы получили 29,1 с (-10%)

8. А уйдя с alpine, получили 9,1 с (-69%)

Что дальше?

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

Часть проблем решить было легко: это устранения багов, после которых человеку, попавшему в похожую ситуацию, разбираться будет удобнее.

С другими всё было сложнее:

• Необходимо улучшить время компиляции графов глубоких вызовов async-функций: возможно, у LLVM есть неудачный пограничный случай, который легко вызвать при помощи того, что генерирует rustc; а может, это просто плохая эвристика, которая в других языках почти не используется.

• Возможно, rustc стоит создать особый случай для core::ptr::drop_in_place<T> , чтобы он компилировался в крейт, определяющий T. Такое решение подойдёт не во всех случаях (например, для обобщённых типов), зато благодаря нему даунстрим-крейтам не потребуется повторно компилировать один и тот же деструктор несколько раз.

  • Дополнение: -Zshare-generics здесь помог, но это не полное решение проблемы. Однако я обнаружил, что это уже обсуждалось и, к сожалению, похоже, это существенно повышает время компиляции из-за компиляции всего drop-клея, который в ином случае не использовался бы. Возможно, здесь можно найти какой-то компромисс (например, сигнализировать, что мы хотим отдать приоритет времени компиляции финального двоичного файла в ущерб зависимостям), но сложно понять, какой подход был бы правильным.

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

А пока вам вполне может подойти opt-level = 0!