OutOfMemoryError в mailboxd: PDF на 10 КБ, который весит 112 МБ

Гостиница на Дмитровском шоссе, 34 рабочих места, февраль 2020-го. Почта у них ложилась каждые три-четыре часа: сотрудники переставали получать брони, ресепшен звонил айтишнику, тот перезапускал службу, всё оживало до вечера. Так продолжалось девять дней. Перед моим приездом виртуалке добавили памяти вдвое — и это не изменило ровным счётом ничего. Разбираю, почему добавленная память не доехала до Zimbra и как одно письмо роняло сервер на 34 человека.

Узнаёте? Сервер живёт по расписанию: утром всё хорошо, к обеду почта тормозит, к трём часам веб-клиент не открывается, кто-то из своих перезапускает службу — и цикл повторяется. Пользователи привыкают и заранее пишут в мессенджер: «почта опять легла».

Опасность такой аварии в том, что она не выглядит аварией. Есть человек, который знает волшебную команду, и формально всё работает. Проблема живёт месяцами, пока не совпадает с чем-то важным — у моего клиента совпало с заездом группы на 40 номеров, когда подтверждения броней от агрегатора не доехали до отдела размещения.

Отдельный момент, который надо понимать про Zimbra: когда mailboxd лежит, почта не просто «не открывается в браузере». Она не доставляется вообще. Письма копятся в очереди, ни отправить, ни прочитать нельзя, мобильные клиенты отваливаются. Это полная остановка, а не частичная.

Первое, что я сделал на сервере, — прошёлся по журналу за девять дней и посчитал падения. Их было 47.

grep -c 'OutOfMemoryError' /opt/zimbra/log/mailbox.log*
# 47

grep -n 'OutOfMemoryError' /opt/zimbra/log/mailbox.log | tail -3
# 2020-02-11 15:22:41,908 FATAL [qtp1863..-1229:https:...] [] system - Exception in thread
#   java.lang.OutOfMemoryError: Java heap space

grep 'LockFailedException' /opt/zimbra/log/mailbox.log | wc -l
# 236

Две вещи сразу. Java heap space — это не «на сервере кончилась память», это «кончилась куча внутри процесса Java». Разные вещи, и путают их постоянно. И вторая: 236 срабатываний MailboxLock$LockFailedException: timeout — блокировки на ящиках не снимались вовремя. Это спутник нехватки heap, а не отдельная болезнь: когда сборщик мусора не успевает, потоки висят, блокировки держатся дольше таймаута.

Свободная память на самой машине при этом была. free -g показывал 6 ГБ свободных из 16. Именно эта картинка и сбивает с толку всех, кто смотрит на аварию первый раз: памяти на сервере полно, а приложение падает по нехватке памяти.

Вот главный факт этой статьи, и он стоит того, чтобы прочитать его дважды. Размер java-кучи для mailboxd задаётся инсталлятором один раз — как 30% физической памяти на момент установки. Дальше он живёт в конфигурации константой. Вы можете добавить виртуалке хоть сто гигабайт: Zimbra продолжит работать в старых границах, потому что никто не пересчитывает этот параметр автоматически.

У гостиницы сервер ставили в 2017 году на 8 ГБ. Значит, куча получила примерно 2,4 ГБ. Перед моим приездом машине выдали 16 ГБ — и куча осталась 2,4 ГБ. Проверяется одной командой:

su - zimbra -c 'zmlocalconfig -s mailboxd_java_heap_size'
# mailboxd_java_heap_size = 2457

free -m | head -2
#               total        used        free      shared  buff/cache   available
# Mem:          16045        9012        6110         312         923        6421

# сколько реально выдано процессу
ps -eo pid,rss,args -u zimbra | grep '[j]ava' | grep -o 'Xmx[0-9]*m'
# Xmx2457m

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

tail -f /opt/zimbra/log/zmmailboxd.out | grep -i 'gc'
# [Full GC (Ergonomics)  2401M->2388M(2457M), 0,9412 sec]
# [Full GC (Ergonomics)  2402M->2391M(2457M), 1,0233 sec]

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

Логика была такая: сервер работает годами, нагрузка не менялась, а падать начал девять дней назад. Значит, что-то течёт. Утечка памяти — версия правильная по форме и неправильная по существу, но проверять её всё равно надо, поэтому я включил снятие дампа при аварии.

su - zimbra
zmlocalconfig -e mailboxd_java_options="$(zmlocalconfig -m nokey mailboxd_java_options) -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/zimbra/data/heapdumps"
mkdir -p /opt/zimbra/data/heapdumps && chown zimbra:zimbra /opt/zimbra/data/heapdumps
zmmailboxdctl restart

Дамп прилетел через два с половиной часа, 2,3 ГБ файла. Я утащил его к себе и открыл в анализаторе. Ожидал увидеть тысячи однотипных объектов, накопленных за сутки, — картину утечки. Увидел другое: один массив байтов на 112 МБ, рядом с ним объект письма, и ещё несколько таких же массивов поменьше, все из одного и того же ящика.

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

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

Из дампа я вытащил идентификатор ящика. Дальше — обычная работа в консоли Zimbra.

# из дампа известен только номер ящика. Адрес по номеру отдаёт база,
# а не zmprov: в таблице mailbox поле comment хранит адрес владельца
su - zimbra -c 'mysql zimbra -e "select id, comment from mailbox where id=136"'
# id   comment
# 136  reception@hotel.ru

# обратная сторона — по адресу zmprov отдаёт номер ящика и занятый объём
su - zimbra -c 'zmprov gmi reception@hotel.ru'
# mailboxId: 136
# quotaUsed: 22548301776

# ищем всё крупное в подозрительном ящике
su - zimbra -c 'zmmailbox -z -m reception@hotel.ru search -l 20 "larger:20000000"'

# и то же самое по хранилищу, мимо метаданных
find /opt/zimbra/store -name '*.msg' -size +90M -printf '%s\t%p\n' | sort -rn | head

Нашлось письмо от февраля с вложением-счётом. Файл на диске — чуть больше 10 КБ. Заявленный в MIME-заголовках размер — 112 МБ. Классическое битое вложение: отправитель прислал письмо из системы, которая при кодировании соврала о размере части, а Zimbra честно попыталась выделить под неё память. Не из злого умысла, просто у контрагента коряво отработала выгрузка из их бухгалтерии.

Проверить расхождение можно прямо на файле, не гадая:

ls -l /opt/zimbra/store/0/136/msg/0/312904-1057.msg
# -rw-r----- 1 zimbra zimbra 10486 фев 3 09:14 ...
grep -i -m3 -E 'Content-Length|Content-Type|Content-Transfer-Encoding' \
  /opt/zimbra/store/0/136/msg/0/312904-1057.msg

Само письмо мы не удаляли молча — сначала выгрузили его в файл и показали ответственному за бронирование, чтобы он подтвердил: счёт этот давно оплачен, оригинал есть в бухгалтерии. Только после этого удалили из ящика и перезапустили mailboxd.

Три команды из-под пользователя zimbra плюс одна от root. Займут именно две минуты.

zmlocalconfig -s mailboxd_java_heap_size
free -m | awk '/Mem:/ {print "RAM всего, МБ:", $2}'
grep -c 'OutOfMemoryError' /opt/zimbra/log/mailbox.log*
tail -200 /opt/zimbra/log/zmmailboxd.out | grep -c 'Full GC'

Теперь сопоставьте первое со вторым и найдите свою строку.

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

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

su - zimbra
zmlocalconfig -e mailboxd_java_heap_size=6144
zmlocalconfig -s mailboxd_java_heap_size
zmmailboxdctl restart

# убеждаемся, что процесс поднялся с новым Xmx
ps -eo pid,args -u zimbra | grep '[j]ava' | grep -o 'Xmx[0-9]*m'
# Xmx6144m

Оговорка первая: 6 ГБ, а не 12 и не 16, хотя памяти на машине хватало. Гигантская куча — не бесплатное благо: полная сборка мусора по большой куче занимает больше времени, и вместо частых коротких пауз вы получаете редкие, но длинные, во время которых почта не отвечает. Для нагруженных сред разумный диапазон — 6–8 ГБ, максимум до 10. Прыгать сразу к потолку смысла нет.

Оговорка вторая: оставьте память операционной системе, MariaDB и файловому кэшу. У Zimbra кроме mailboxd есть буферный пул InnoDB, который по умолчанию тоже забирает около четверти памяти машины, плюс amavis с ClamAV. Если раздать всё под java-кучу, начнётся своп, и медленно станет уже везде.

Из 16 ГБ у гостиницы получилось: 6 ГБ куча mailboxd, около 3,5 ГБ InnoDB, остальное — система, антивирус и кэш. Своп при пиковой нагрузке не трогался ни разу за следующий месяц, я специально смотрел.

Честно, как было. В первый день я сделал именно то, что делает большинство: поднял кучу, перезапустил, дождался стабильной работы, отчитался клиенту. Битое письмо в тот момент я ещё не нашёл — дамп разбирал позже.

Через девять дней сервер упал снова. Один раз, не сериями, но упал. Причина та же: кто-то из отдела бронирования открыл ту самую переписку, письмо развернулось в памяти, и 6 ГБ на пике не хватило. Больше куча просто отодвигает порог — она не делает так, чтобы стомегабайтный объект перестал быть стомегабайтным.

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

И ещё один частный случай, на который я натыкался позже: отдельно от mailboxd падает по нехватке памяти утилита zmmailbox при выгрузке или импорте больших ящиков. Она буферизует данные в куче собственного процесса Java и границ mailboxd не наследует. Если ваш бэкап сделан через неё и вдруг перестал доезжать на самых больших ящиках — ищите в логе бэкапа ту же строку про Java heap space.

Что было у клиента по факту. Ящиков 48, из них активных 34, store 268 ГБ, самый большой ящик — 21 ГБ у отдела бронирования, туда падают все агрегаторы. Девять дней аварий, 47 падений, каждое — от 20 до 50 минут простоя, пока кто-то замечал и перезапускал. Суммарно около 26 часов, когда почта не работала совсем.

Деньги я считал вместе с управляющей. У гостиницы 40% броней приходило письмами от агрегаторов и корпоративных клиентов. Письмо, не доехавшее до отдела размещения вовремя, — это либо задвоенная бронь, либо потерянная. За те девять дней они насчитали 11 сорванных подтверждений и один переселённый в другой отель заезд. В деньгах — около 163 000 ₽, не считая скидок, которые пришлось дать в качестве извинений.

Моя работа: 6 часов в первый день (разбор, дамп, правка heap), 3 часа через две недели (поиск письма, чистка, наблюдение), 22 000 ₽ суммарно — по моим ценам 2020 года. Плюс мы поставили простой сторож, который пишет в мониторинг, если в mailbox.log появляется строка про нехватку кучи, — чтобы в следующий раз узнавать об этом не от ресепшена.

Что из этого следует вам. Если ваш сервер перезапускают «чтобы почта заработала» — у вас, скорее всего, ровно эта история, и она уже стоит денег, просто счёт никто не выставлял. Начните с одной строки: сравните mailboxd_java_heap_size с реальным объёмом памяти машины. Расхождение — самый частый диагноз из всех, что я встречаю на чужих серверах.

Пришлите мне вывод четырёх команд из блока самопроверки — размер кучи, объём памяти, число OutOfMemoryError в логах и счётчик полных сборок мусора. За день отвечу, что у вас: тесная куча, битое письмо или настоящая утечка, — и что с этим делать по шагам.

Мы добавили серверу памяти, а Zimbra всё равно падает. Почему?

Потому что размер java-кучи для mailboxd — отдельный параметр, который инсталлятор выставил один раз как 30% памяти на момент установки. Он не пересчитывается сам ни при добавлении RAM, ни при апгрейде. У гостиницы на Дмитровском сервер ставили на 8 ГБ, куча получила 2457 МБ, потом машине выдали 16 ГБ — куча осталась 2457 МБ. Проверяется командой zmlocalconfig -s mailboxd_java_heap_size и сравнением с выводом free -m. Если куча заметно меньше трети памяти — вы платите за память, которой приложение не пользуется.

Сколько ставить heap? Может, отдать половину сервера?

Не стоит. Большая куча даёт редкие, но длинные паузы сборки мусора, во время которых почта не отвечает вообще — пользователи это чувствуют как зависания. Разумный ориентир для нагруженных сред: 6–8 ГБ, в отдельных случаях до 10. И помните про соседей по памяти: буферный пул InnoDB по умолчанию забирает около четверти RAM, плюс amavis, ClamAV, файловый кэш и сама система. У гостиницы из 16 ГБ получилось 6 ГБ под кучу и 3,5 ГБ под InnoDB, свободного запаса хватало, своп не трогался.

Как отличить нехватку памяти от утечки?

Только дампом. Включаете снятие дампа при аварии через -XX:+HeapDumpOnOutOfMemoryError и -XX:HeapDumpPath в java-опциях, ждёте падения, разбираете файл в анализаторе. Утечка выглядит как тысячи однотипных объектов, накопленных со временем. Нехватка выглядит как рабочий набор, который просто не влезает. У меня в дампе на 2,3 ГБ лежал один массив байтов на 112 МБ и рядом объект письма — это не утечка и не теснота, это конкретное битое вложение. Без дампа я бы поднял кучу, увидел улучшение и оставил мину в ящике.

Как найти письмо с битым вложением, если дамп разбирать некому?

Есть путь попроще, хотя он и грубее. Поиск по хранилищу: find /opt/zimbra/store -name '*.msg' -size +90M — вы увидите физически крупные файлы. Затем поиск средствами Zimbra по подозрительным ящикам: zmmailbox -z -m адрес search "larger:20000000". Аномалия видна по расхождению: файл на диске маленький, а заявленный размер вложения огромный. У клиента файл весил 10 КБ при заявленных 112 МБ. Перед удалением обязательно выгрузите письмо в файл и согласуйте с владельцем ящика — это чужая переписка, а не мусор.

Пока mailboxd лежит, письма теряются?

Нет, но и не доставляются. Входящие копятся в очереди MTA и доедут до ящиков после того, как mailboxd поднимется. Опасность в другом: пока служба лежит, пользователи не могут ни читать, ни отправлять, мобильные клиенты отваливаются, а отправители на той стороне начинают получать задержки. Если простой затягивается на сутки и больше, часть отправителей получит уведомления о задержке доставки, а по истечении срока — возврат. У гостиницы падения длились по 20–50 минут, до возвратов не доходило, но 11 подтверждений броней приехали позже, чем были нужны.