Диагностика медленной загрузки Linux из-за systemd-journal-flush и настройка журнала

Сервер после ребута висит в загрузке лишнюю минуту, systemd-analyze показывает цифру, которой стыдно показать руководству, а виновником оказывается вовсе не старт nginx и не сетевой юнит, а скромная служба systemd-journal-flush.service. Ситуация знакома многим администраторам, но далеко не все понимают, почему простое "дописать логи на диск" способно тормозить всю систему и главное, что с этим делать правильно, а не костылём под названием mask. Ниже разберём диагностику через systemd-analyze blame и critical-chain, устройство journald-хранилища и рабочие настройки journald.conf, которые реально применяют в продакшене.

Симптомы проблемы и первичная диагностика через systemd-analyze

Первый шаг всегда одинаков: измерить, сколько длится загрузка и куда уходят секунды. Базовая команда выглядит так:

systemd-analyze

Типичный вывод на проблемной машине:

Startup finished in 14.245s (kernel) + 1min 34.132s (userspace) = 1min 48.377s
graphical.target reached after 1min 33.890s in userspace.

Ядро отработало за 14 секунд, а пространство пользователя молотило полторы минуты. Уже подозрительно. Смотрим, кто именно тормозит:

systemd-analyze blame

Образец вывода:

52.437s systemd-journal-flush.service
12.103s network-online.target
 8.944s fstrim.service
 6.231s NetworkManager-wait-online.service
 1.402s plymouth-quit-wait.service
 ...

Первая колонка здесь - чистое время инициализации юнита, вторая - имя службы. Строка systemd-journal-flush.service с половиной минуты на первом месте - это и есть наш пациент. Blame сортирует по убыванию, так что виновник обычно торчит наверху, как гвоздь из старой доски. Важный нюанс: blame показывает изолированное время каждого юнита, но не учитывает, что службы стартуют параллельно. Чтобы увидеть реальную критическую цепочку загрузки, применяют:

systemd-analyze critical-chain

Фрагмент вывода:

The time when unit became active or started is printed after the "@" character.
graphical.target @1min 33.890s
└─multi-user.target @1min 33.889s
  └─systemd-journal-flush.service @8.412s +52.437s
    └─systemd-remount-fs.service @7.980s +431ms

Жирнее всего здесь бьёт строка flush: он начался на восьмой секунде (значение после @) и занял 52 секунды, при этом целевая группа multi-user ждала его завершения. Пока идёт flush, journald ещё не принимает сообщения в постоянное хранилище, и часть юнитов вынуждена стоять. Для наглядности полезно построить SVG-карту:

systemd-analyze plot > boot-trace.svg

Файл открывают в браузере и сразу видят длинную красную полосу flush, растянувшуюся через весь таймлайн.

Почему systemd-journal-flush вообще нужен и почему он тормозит

Сначала журнал systemd накапливается в оперативной памяти, в каталоге /run/log/journal. Хранилище /run - это tmpfs, оно сотрётся при выключении, но на стадии ранней загрузки диск ещё не смонтирован и писать больше некуда. Когда корневая ФС смонтирована, юнит systemd-journal-flush копирует накопленные сообщения из /run/log/journal в постоянный каталог /var/log/journal, после чего journald переключается на запись на диск. Заодно применяются ротация и очистка по лимитам. И вот тут начинается боль. Если накопилось 300 МБ логов от болтливых юнитов, диск медленный (бюджетный медленный SATA-диск или перегруженная виртуалка с iowait 40%), а ротация затрагивает десятки файлов, операция растягивается на десятки секунд. Весь userspace стоит.

Типичные причины медленного flush:

1. включён Storage=persistent при медленном или перегруженном диске, особенно HDD и сетевые тома;
2. избыточное логирование: включённый debug-режим udev, юниты с StandardOutput=journal и уровнем debug, спамный auditd;
3. большие лимиты SystemMaxUse, из-за которых journald хранит гигабайты и долго их перебирает при vacuum;
4. фрагментированные журналы вручную после удаления части файлов, journald тратит время на сверку индексов;
5. повреждённые файлы журнала, которые приходится проверять и ремонтировать.

Текущее занятое пространство проверяется командой:

journalctl --disk-usage

Вывод, например:

Archived and active journals take up 1.8G in the file system.

Полтора и более гигабайт - прямое свидетельство того, что flush и ротация будут недёшевы.

Тюнинг journald.conf: volatile-хранилище и честные лимиты

Основной файл настройки - /etc/systemd/journald.conf. Для серверов, где логи гонят в централизованный сборщик (syslog, rsyslog, journald forward), а локальная история за ребут не нужна, оптимальная конфигурация выглядит так:

[Journal]
# Storage=volatile: журнал живёт только в /run/log/journal (tmpfs),
# flush на диск не требуется вовсе, секция постоянного хранилища отключена
Storage=volatile
# Общий потолок для всех volatile-журналов в /run: 200 МБ,
# при превышении journald начинает удалять старое
RuntimeMaxUse=200M
# Максимальный размер одного файла журнала, чтобы ротация была быстрой
RuntimeMaxFileSize=20M
# Сколько файлов хранить одновременно
RuntimeMaxFiles=8
# Ограничение скорости: за 30 секунд не более 1000 сообщений от одного сервиса,
# дальше идёт подавление, защита от спамеров
RateLimitIntervalSec=30s
RateLimitBurst=1000
# Куда пересылать: syslog получает поток для централизованного сбора
ForwardToSyslog=yes

После правки применяем изменения без ребута:

systemctl restart systemd-journald

С Storage=volatile юнит systemd-journal-flush теряет смысл: переносить в /var/log/journal попросту нечего. Если journal-flush всё равно тянет время из-за проснувшегося flush-триггера, бывает удобно замаскировать его явно, но строго осознанно и только при volatile:

systemctl mask systemd-journal-flush.service

Честно говоря, mask здесь - вторая стадия решения. Первая и главная - правильный Storage и разумные лимиты. Если local-логи всё же нужны, но нормально вся история не влезает в память, есть компромисс Storage=auto: journald пишет на диск, только если каталог /var/log/journal существует, иначе работает в памяти. Хороший паттерн для golden image - просто не создавать /var/log/journal на эталонном образе, и система автоматически останется на volatile.

Различие двух каталогов и тонкости миграции.
/run/log/journal - tmpfs, существует от старта ядра до выключения, содержит журналы текущей загрузки и быстрый в записи, но съедает оперативную память. /var/log/journal - постоянное хранилище на диске, переживает reboot, зато платит ценой flush и медленной ротации. Проверить, куда пишет journald сейчас, можно так:

ls -la /var/log/journal/ /run/log/journal/

Если /var/log/journal отсутствует в выводе и есть только /run - система уже в режиме volatile или auto без каталога. Сколько занято в памяти:

du -sh /run/log/journal/

Например:

96M     /run/log/journal/

При RuntimeMaxUse=200M и 8 ГБ ОЗУ это несущественно. Но на контейнерном хосте со 128 МБ под /run перебор лимита приведёт к вытеснению данных. Тут математика простая: лимит не должен превышать примерно 10-15% объёма tmpfs.

Очистка старых журналов через vacuum

Если постоянное хранилище всё же используется, его надо регулярно вычищать, а не ждать, пока диск набухнет. Два ручных способа:

# По времени: удалить всё, что старше 14 дней
journalctl --vacuum-time=14d

# По объёму: оставить не более 500 МБ
journalctl --vacuum-size=500M

Вывод после выполнения:

Vacuuming done, freed 1.2G of archived journals from 38 files.
Deleted archived journal /var/log/journal/.../Адрес электронной почты защищен от спам-ботов. Для просмотра адреса в браузере должен быть включен Javascript. (128.0M).

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

journalctl --rotate
journalctl --vacuum-time=1d

Для автоматики удобно повесить в cron или systemd-таймер связку rotate + vacuum-size, чтобы журналы никогда не разрастались. Тогда и flush на следующей загрузке будет коротким.

Пошаговый план действий администратора в проде

Порядок, отработанный на десятках серверов, выглядит понятно. Сначала измерить: systemd-analyze, systemd-analyze blame, systemd-analyze critical-chain - и зафиксировать время flush. Затем оценить объём через journalctl --disk-usage и du -sh /var/log/journal /run/log/journal. Следом найти спамеров: journalctl -b | awk '{print $5}' | sort | uniq -c | sort -rn | head покажет, кто генерирует львиную долю сообщений за загрузку. Дальше принять решение о хранилище: volatile с централизованным сбором журналов либо persistent с жёсткими лимитами. Потом прописать journald.conf, выполнить systemctl restart systemd-journald и journalctl --vacuum-size для расчистки старой истории. Финальный шаг - перезагрузить сервер в окне обслуживания и снова снять blame, сравнив цифры до и после: эффект честно измеряется, а не предполагается.

После перехода на volatile с лимитом 200 МБ на средней нагрузке время systemd-journal-flush падает с десятков секунд до нуля - юнит либо отсутствует, либо завершается мгновенно. Загрузка userspace из 1min 34s ужимается до 30-40 секунд, и это без единой строчки кода в приложениях.

Проверка целостности журнала и глубже в debug

Если flush медленный даже при небольшом объёме логов, подозревайте повреждённые файлы журнала. Journald при монтировании хранилища проверяет индексы и на битых файлах может зависнуть надолго. Проверка простая:

journalctl --verify

Вывод при проблемах:

FAIL: /var/log/journal/.../Адрес электронной почты защищен от спам-ботов. Для просмотра адреса в браузере должен быть включен Javascript. (truncated)
PASS: /var/log/journal/.../system.journal

Строки с FAIL - повреждённые файлы, их проще всего переместить в карантинный каталог и выполнить journalctl --rotate, после чего journald создаст свежие файлы. Такие битые файлы нередко прячутся за непонятными подвисаниями. Заодно полезно глянуть, кто из юнитов пишет больше всех на прошлой загрузке, ключ -b -1 берёт предыдущий boot:

journalctl -b -1 --no-pager | awk '{print $5}' | sort | uniq -c | sort -rn | head -10

Типичный верх списка:

 24103 systemd[1]:
 19877 NetworkManager[812]:
  8704 kernel:
  4402 audit[1]:

Первое число - количество строк, второе - источник. Если NetworkManager выдал девятнадцать тысяч строк за загрузку, копать надо его логирование, а не journald. Меньше данных на входе - быстрее flush. Для особо болтливых юнитов в override-юните можно уменьшить поток:

# /etc/systemd/system/example.service.d/override.conf
[Service]
# Ошибки и выше, без информационного шума
LogLevelMax=warning

После systemctl daemon-reload и рестарта службы журнал заметно худеет.

Частые ошибки при борьбе с медленным flush.
В практике встречается несколько антипаттернов, которые маскируют симптом, но не лечат причину. Первый - слепой mask systemd-journal-flush на системе с Storage=persistent: сообщения копятся в /run, переполняют tmpfs и система валится уже в рантайме, а не при загрузке. Второй - выставление SystemMaxUse=0 в надежде снять ограничение: ноль не означает "без лимита", journald либо поднимет значение до минимально допустимого, либо вернётся к умолчаниям; для отключения записи на диск нужен Storage=volatile или Storage=none. Третий - удаление файлов журнала вручную через rm под живым journald: служба держит файловые дескрипторы, место не освобождается, а индексы расходятся с реальностью, что перебирает flush на следующем старте. Правильный путь только через journalctl --vacuum-* или через полную остановку journald перед чисткой. Четвёртая ошибка - забыть, что значения в журнале read-only на лету: после правки journald.conf без systemctl restart systemd-journald старые лимиты продолжают действовать, и администратор ждёт эффекта, которого нет. Изменения видно сразу в статусе:

systemctl status systemd-journald --no-pager

Строки вывода с Runtime journal (/run/log/journal/...): 48.0M, max 200.0M подтверждают, что лимит применён. Такой контроль заменяет час отладки, когда конфиг вдруг лежит в /etc/systemd/journald.conf.d с другими значениями.

Профилактика и что мониторить дальше

Проблема любит возвращаться, если её не прибить процессом. Минимум - контролировать journalctl --disk-usage алертом, следить за ростом логов конкретных юнитов после каждого релиза и держать RateLimitBurst на адекватном уровне. На машинах, где journald форвардит в syslog, полезно проверять, что внешний collect реально забирает поток, иначе можно остаться и без дисковых логов, и без централизованных. Для критичных серверов держите в документации эталонный journald.conf и скрипт расчёта до-после через systemd-analyze - это снимает споры "а стало ли быстрее" намертво. Быстрая загрузка - не везение, а следствие честных измерений и настроенного журнала.