Веб-почта Zimbra открывается две минуты: IOwait и буфер InnoDB

У клиента-логистики в Химках страница входа в почту грузилась две минуты, и ещё две уходило на сам вход. Люди привыкли: нажал, пошёл за чаем, вернулся. Я приехал в декабре 2020-го, полдня искал не там, а причина оказалась в двух числах, которые никто не трогал с момента установки сервера в 2016 году.

Если ваши сотрудники перестали жаловаться на почту и просто научились с ней жить — это плохой знак, а не хороший. Человек нажимает «Войти», разворачивает соседнюю вкладку, отвечает на звонок, возвращается. Через полгода такой жизни никто уже не считает это проблемой. Считает бухгалтерия, когда смотрит на выработку, но связать одно с другим не догадывается.

Формулировка «тормозит почта» приходит в заявке примерно раз в месяц, и она бесполезна. Тормозить может страница логина, может сам вход после ввода пароля, может открытие письма с вложением, может поиск. Это четыре разные болезни с четырьмя разными причинами. Пока не спросишь у человека, что именно он делает и сколько это длится по часам на телефоне, лечить нечего.

Отдельная беда в том, что почтовый сервер редко тормозит равномерно. Утром в понедельник плохо, в четверг после обеда нормально. Из-за этого проверка «а сейчас как?» почти всегда даёт «сейчас нормально», и разговор заканчивается ничем.

Дальше — конкретный сервер, конкретные команды и один ложный след, на который я угробил половину рабочего дня.

Транспортно-логистическая компания, склад и офис в одном здании на Ленинградском шоссе, 23 рабочих места. Позвали меня в первую неделю декабря 2020 года — формально «посмотреть сервер», фактически потому что диспетчер не успевала отвечать на заявки перевозчиков.

Первое, что я сделал — сел за компьютер диспетчера и засёк секундомером. Страница входа отрисовывалась 1 минуту 50 секунд. После ввода пароля до появления списка писем прошло ещё 2 минуты 5 секунд. Итого почти четыре минуты, чтобы просто дойти до входящих. Открытие письма с накладной в PDF — от 8 до 20 секунд. В обеденные часы веб-клиент дважды отдал 504 Gateway Timeout.

Что было под капотом:

• Zimbra 8.8.15 Open Source Edition, CentOS 7, виртуалка на локальном ESXi;
• 6 vCPU, 24 ГБ памяти;
• дисковый том — RAID10 из четырёх SATA-дисков 7200 об/мин, всё на одном массиве: система, почта, база, индекс;
• store 310 ГБ, база MariaDB в /opt/zimbra/db/data — 9,4 ГБ, индекс — 26 ГБ.

Сервер поставили в феврале 2016 года — тогда это была ещё Zimbra 8.7, и виртуалке дали 8 ГБ памяти. В 2019-м память подняли до 24 ГБ, потому что «стало не хватать», и заодно докатили Zimbra до 8.8.15. Больше не трогали ничего. Пропорции памяти при этом так и остались от восьмигигабайтной машины: апгрейд Zimbra не пересчитывает ни размер кучи, ни буфер базы — эти значения пишутся один раз, при первой установке, и дальше живут сами по себе.

Загрузка процессора при этом была смешная — 12–18% в пике. Именно из-за неё владелец был уверен, что железа хватает с запасом и «дело в софте». Формально он был прав. Только не в том смысле, который вкладывал.

Полез в /opt/zimbra/log/mailbox.log и почти сразу нашёл красивое:

$ grep -c EofException /opt/zimbra/log/mailbox.log
147

$ grep EofException /opt/zimbra/log/mailbox.log | tail -1
2020-12-03 10:41:52,318 WARN  [qtp-...] [] http - handle failed
org.eclipse.jetty.io.EofException: timeout

147 штук за сутки. Я решил, что нашёл виновника: Jetty рвёт соединения по таймауту, значит надо разбираться с Jetty и с прокси перед ним. Ушёл в настройки таймаутов прокси, поднял значение, перезапустил, замерил. Стало ровно так же. Поднял ещё раз — снова так же, только 504 перестали появляться, а ждать пришлось столько же.

Вот тут я и понял, что перепутал причину со следствием. EofException: timeout в логе — это не «Jetty плохо работает». Это «Jetty ждал ответа от бэкенда и не дождался». Бэкенд у mailboxd один — база и хранилище. Увеличение таймаута прокси лечит только надпись 504: браузер перестаёт видеть ошибку и продолжает честно ждать те же четыре минуты.

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

Правило, которое я после этого случая записал себе: любую строчку со словом timeout в логе Java-приложения сначала считаем симптомом и только потом, если ничего больше не нашлось, — причиной.

Вернулся к началу и посмотрел на систему целиком, а не на логи приложения:

$ vmstat 1 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 1  3  10240 218704  91232 15980412    0    0  4912  1180 3402 5811 11  4 74 11
 0  4  10240 214880  91232 15981004    0    0  5240   960 3611 6002 12  3 73 12

$ iostat -x 1 3
Device  r/s     w/s   rkB/s   wkB/s  await r_await w_await  %util
sda   612.0    98.0  4912.0  1180.0  61.40   68.20   19.10  97.60

Столбец wa — 11–12% стабильно, не пиками. Утилизация массива под сотню, среднее время ответа на чтение 68 миллисекунд. Процессор при этом простаивал: id = 73–74%.

Это и есть та картина, ради которой я теперь начинаю любой разбор «почта тормозит» с vmstat, а не с логов. Ориентир простой: если IOwait держится около 10% и это не пик, а норма — упирается дисковая подсистема, и тормозить будут сразу все, кто ходит на диск. У Zimbra таких двое, и оба важные: MariaDB и mailboxd. Отсюда и ощущение «тормозит вообще всё» — оно честное.

Осталось понять, кто именно молотит диск на 4,9 МБ/с чтением при 23 пользователях. Это ненормально много.

Три команды. Первые две — от root, третья — из-под пользователя zimbra. Ничего не меняют, можно выполнять на живом сервере в рабочее время.

# 1. Ждёт ли система диск
vmstat 1 5

# 2. Сколько реально весит база
du -sh /opt/zimbra/db/data

# 3. Сколько памяти отдано под буфер InnoDB
grep innodb_buffer_pool_size /opt/zimbra/conf/my.cnf
su - zimbra -c 'zmlocalconfig | grep -i mysql_memory'

Дальше сравниваете второе с третьим и смотрите на первое:

Последняя строка таблицы — самая частая. Она же самая обидная: сервер получил память, но никто ею не воспользовался.

При установке Zimbra раскладывает память по двум большим карманам. Примерно 30% физической памяти уходит под кучу Java для mailboxd и около 25% — под буфер InnoDB для базы. Значения фиксируются один раз, в момент установки, от того объёма памяти, который есть на машине прямо сейчас.

В Химках это выглядело так. Февраль 2016 года, 8 ГБ памяти. Куча получила 2458 МБ, буфер InnoDB — 2048 МБ. Разумно для того сервера.

Дальше пять лет роста. База выросла с полутора гигабайт до 9,4. Памяти виртуалке добавили до 24 ГБ. А два числа остались прежними — они не пересчитываются сами, и никакое обновление их не тронет.

Механика деградации отсюда очевидна. База 9,4 ГБ, буфер 2 ГБ. Всё, что не поместилось, MariaDB читает с диска — при каждом открытии папки, при каждом поиске, при каждом логине, когда клиент запрашивает дерево папок и счётчики. Двадцать три человека утром заходят почти одновременно. Массив из четырёх SATA-дисков захлёбывается. Java-часть тоже ждёт диск, потому что диск один на всех. Веб-клиент отдаёт 504, а Jetty честно пишет в лог, что не дождался.

Как я считаю буфер: берём размер каталога /opt/zimbra/db/data, добавляем запас на год роста и округляем вверх, но не выходим за разумную долю памяти машины и не поднимаемся выше десяти гигабайт. Верхняя граница не выдумана: буфер InnoDB больше примерно 10 ГБ Zimbra эффективно не использует — особенности кода mailbox-сервера. Всё, что выше, лежит мёртвым грузом и отнято у Java.

Логика была простая и неправильная: раз базе не хватает буфера, дадим ей с запасом. Памяти 24 ГБ, база 9,4 — поставил 12 ГБ, чтобы влезла целиком и ещё осталось.

# /opt/zimbra/conf/my.cnf
innodb_buffer_pool_size = 12884901888

$ su - zimbra -c 'mysql.server restart'

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

Посмотрел на память — и увидел, во что вляпался:

$ free -g
              total        used        free      shared  buff/cache   available
Mem:             23          21           0           0           1           1
Swap:             3           1           2

Кэша страниц не осталось совсем, началась подкачка. Куча Java при этом была 2458 МБ — от старой установки, и mailboxd работал в тесноте, а теперь ещё и в свопе. Сборщик мусора отрабатывал каждую секунду с паузами, а это и есть те самые подвисания на секунду.

Откатился к 6144 МБ буфера. Одновременно поднял кучу до 7168 МБ, потому что она пять лет была рассчитана на восьмигигабайтную машину:

$ su - zimbra
$ zmlocalconfig -e mailboxd_java_heap_size=7168
$ zmmailboxdctl restart

Вот это и есть неочевидное место, из-за которого «просто добавить буфера» не работает. Память одна. Буфер InnoDB, куча Java и кэш файловой системы делят её между собой, и выигрыш одного — прямой проигрыш двух других. Крутить эти числа порознь нельзя, только вместе и глядя на free после каждого шага.

И ещё: my.cnf у Zimbra генерируемый. После крупного обновления значение имеет шанс вернуться к расчётному от процента в локальной конфигурации. Я теперь после каждого апгрейда сразу заглядываю в этот файл — дважды ловил откат.

Тюнинг памяти дал многое, но не всё: вход сократился с четырёх минут до сорока секунд. Хорошо, но не победа. Осталась главная беда — база, индекс и почта жили на одном шпиндельном массиве.

Добавили в сервер два SSD на 480 ГБ в зеркале и перенесли туда базу и индекс, оставив store на прежнем массиве. Том под них разметили с оглядкой на то, что там будет лежать: много мелких файлов и постоянная запись.

# разметка тома под базу и индекс
mkfs.ext4 -O dir_index -m 2 -i 10240 /dev/sdb1

# /etc/fstab
/dev/sdb1  /opt/zimbra/db   ext4  defaults,noatime  0 2

Ключ -i 10240 задаёт плотность inode под мелкие файлы, dir_index ускоряет каталоги с тысячами записей, noatime убирает лишнюю запись при каждом чтении. По отдельности проценты, вместе — заметно.

Перенос делали в ночь с четверга на пятницу, окно 2 часа, реально уложились в 1 час 20 минут. Всего по задаче — 9 часов работ.

Результат на утро понедельника:

Теперь про цену бездействия, потому что владелец задал ровно этот вопрос. Мы посчитали грубо и честно: каждый сотрудник терял на ожидании почты около 35 минут за смену — вход утром, вход после обеда, открытие вложений, повторные попытки. На 23 человека это 13 человеко-часов в день. При средней стоимости часа 450 рублей — примерно 5 800 рублей в день и около 128 тысяч в месяц. Сервер тормозил так минимум год.

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

Соберу коротко то, что считаю главным.

• Начинайте с vmstat, а не с логов. Логи приложения покажут вам симптом, причём убедительный. Система покажет, кого ждут.
• Низкая загрузка процессора ничего не доказывает. У нас было 12–18%, и именно поэтому железо считали избыточным.
• Смотрите, менялась ли память сервера после установки Zimbra. Если да — почти гарантированно и буфер, и куча остались от старого объёма.
• Больше не значит лучше. Буфер сверх десяти гигабайт бесполезен, а память у Java он отберёт сразу.
• База и индекс на шпинделях — приговор. На двадцати пользователях это ещё терпимо, на сорока уже нет.

Отдельно про популярный совет, который малому бизнесу вредит: «добавьте оперативки, Zimbra прожорливая». Добавить память — самое простое действие из всех возможных, поэтому его и советуют. Но пока пропорции остались от старой установки, ни один добавленный гигабайт до почты не дойдёт. Мы это увидели буквально: 24 ГБ в системе, из них под задачу работало около четырёх.

Если хотите понять, ваш ли это случай, не заказывая аудит: выполните три команды из раздела «Проверьте у себя за две минуты» и пришлите мне вывод — вывод vmstat 1 5, размер каталога /opt/zimbra/db/data и строку с буфером из my.cnf. Этого достаточно, чтобы за день сказать, упирается у вас диск или память, что именно надо менять и укладывается ли это в один вечер. Если по трём командам будет видно, что дело не в них, — так и напишу.

У нас процессор загружен на 15%, а почта еле шевелится. Разве это не значит, что железа хватает?

Не значит. Загрузка процессора показывает, сколько он считал, а не сколько ждал. В Химках было 12–18% загрузки и 11% ожидания диска — процессор буквально простаивал в очереди к массиву. Смотреть надо столбец wa в выводе vmstat 1 5: если он стабильно около десяти процентов, узкое место найдено, и никакие ядра тут не помогут. Заодно посмотрите iostat -x на среднее время ответа: у нас было 68 миллисекунд на чтение при норме в единицы миллисекунд для SSD.

Можно просто добавить серверу памяти и на этом успокоиться?

Память — вещь полезная, но сама по себе она ничего не даст. И буфер InnoDB, и куча Java фиксируются в момент установки Zimbra как доля от тогдашнего объёма памяти. Дальше это просто два числа в конфигурации, живущие своей жизнью. У клиента память подняли с 8 до 24 ГБ ещё в 2019 году, а куча так и осталась 2458 МБ, буфер — 2048 МБ. Из двадцати четырёх гигабайт под задачу реально работало около четырёх. Сначала пересчитайте пропорции, и очень может быть, что добавлять уже ничего не придётся.

Насколько большим стоит делать innodb_buffer_pool_size?

Отталкивайтесь от реального размера каталога /opt/zimbra/db/data, добавьте запас на год роста и округлите вверх. Верхняя граница — примерно десять гигабайт: больше Zimbra эффективно не использует из-за особенностей mailbox-сервера, зато память у Java отберёт сразу и целиком. Я на 9,4-гигабайтной базе поставил 6 ГБ и получил ровный результат. До этого пробовал 12 ГБ и сделал хуже: кэш файловой системы исчез, началась подкачка, веб-клиент начал подвисать. После правки обязательно посмотрите free -g — если available ушёл в ноль, вы перестарались.

В логе полно строк org.eclipse.jetty.io.EofException: timeout. Это ведь ошибка веб-сервера?

Это следствие, а не причина. Строка означает, что Jetty ждал ответа от бэкенда дольше отведённого и закрыл соединение. Бэкенд — база и хранилище. Я на этом потерял полдня: крутил таймауты прокси, добился только того, что пропали надписи 504 Gateway Timeout, а ждать пользователи стали ровно столько же. Увеличение таймаута прячет симптом, но никого не ускоряет. Если видите такие строки, идите смотреть, почему медленно отвечает бэкенд, и начинайте с дисковой подсистемы.

Обязательно ли переносить базу на SSD или хватит настроек?

Зависит от того, где вы находитесь. Настройки памяти у нас дали переход с четырёх минут до сорока секунд — это уже терпимо, но далеко не хорошо. Победу принёс перенос базы и индекса на зеркало из двух SSD: 40 секунд превратились в 6. Правило, которым я пользуюсь: до двадцати активных пользователей на шпинделях ещё можно жить, если пропорции памяти посчитаны верно; после тридцати нужен SSD хотя бы под базу и индекс, оставляя сам store на больших дисках. Это самая дешёвая часть модернизации — два диска, не сервер.