Админская загадка: На сервере произошло три oom kill'а, а мониторинг сказал только про два. Почему?
Конфигурация
Для мониторинга всего у нас настроена связка ganglia-shinken-logstash-elasticsearch-kibana. Полное описание довольно обширно, так что ограничусь только частью, имеющей отношение к проблеме.
В logstash присылаются логи со всех серверов. Он их складывает в elasticsearch. В конфиге logstash'а настроена реакция на всякие странные сообщения, которые свидетельствуют о проблемах. Если сообщение появляется, присылается event мониторингу (shinken), который разными методами начинает беспокоить админов.
Помимо syslog'ов, которые шлют сообщения от большинства приложений, у нас настроена ещё и отправка netconsole от всех ядер. Сама технология проста до невозможности — ядро помимо dmesg'а посылает сообщения в виде UDP-датаграмм на указанный IP и mac-адрес. MAC-адрес нужен потому, что netconsole очень низкоуровневая и заниматься разгадыванием «как из IP сделать MAC» (то есть ARP) не собирается. Благодаря низкоуровневости сообщения проходят даже в ситуациях полного катаклизма. Например, если программный коммутатор перестал работать (и сеть недоступна), сообщения всё равно будут посылаться. Более того, они будут посылаться, даже если в iptables сказано -j drop_vsyo_nafig. И, самое главное и ценное, эти сообщения успешно будут отправлены, если дисковая подсистема полностью не работает. То есть для post-mortem исследований «что именно случилось с зависшим сервером» — самое оно.
Очевидным кандидатом в «плохие» сообщения является сообщение от oom-killer'а.
[517935.914380] ntpd invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0 [517935.914730] Call Trace: [517935.914807] [<ffffffff816e14ce>] dump_header+0x83/0xbb [517935.914877] [<ffffffff816e155b>] oom_kill_process.part.6+0x55/0x2cf ... с финальным торжествующим: [517935.951044] Out of memory: Kill process 4550 (apache2) score 247 or sacrifice child [517935.951203] Killed process 4550 (apache2) total-vm:2610268kB, anon-rss:2012696kB, file-rss:3928kB
Итак, возвращаемся к загадке. Идёт пусконаладка, предпродакшен, как, вдруг, апач (точнее, wsgi-приложение) насасывается данных до неприличия, и его прибивают со словами «go be fat somewhere else». Админам приходит сообщение. Казалось бы всё хорошо (ну, в админском смысле «хорошо»). Но…
Случилось три oom'а, сообщения пришли о двух. Мониторинг в порядке, netconsole в порядке. Загадка? Проблемы? Симптомы таинственной неведомой фигни? Звать придворного шамана с бубном?
Сбор данных
Первый вопрос: А был ли этот «третий» oom? Перепроверяем локально на серверах — был. Ручками выписываю — три процесса точно были убиты.
Второй вопрос: почта? Проверяем — по логам shinken'а — два срабатывания, всё, что сгенерировал shinken дошло.
Третий вопрос: Не работает netconsole?
Проверяем: # echo "performing tests" > /dev/kmsg
В kibana сообщение появилось. Значит, отправка и приём работает.
А как выглядят сообщения об OOM в kibana? Наивный запрос «invoked» (не самое частое слово для логов) — три сообщения.
Как три? А почему тогда алертов два? Смотрим фильтры, фильтры возбуждаются не на строчку «invoked oom-killer», а на строчку «Out of memory: Kill process .+ (.+)».
Смотрим. Ух ты, а строчки-то «Out of memory: Kill process» в kibana две, а не три. invoked три, kill — две.
Настраиваем выборку в kibana так, чтобы остаться наедине с только с конкретным выводом netconsole про данный OOM. [Спойлер: как админу выжить с кибаной — в следующих сериях]. Смотрим. Вроде, всё есть. Начинаем построчно сравнивать c тем, что в dmesg на хосте. Виден трейс, виден довольно мерзко выглядящий дамп свободной памяти (он отсылается отдельными кусочками, так что в logstash превращается в набор бессвязных сообщений вида «5040», «1*256kB (U)» и т.д.), есть список процессов… Ага, список процессов не целиком, и вообще, нижней половины простыни нет.
Для двух предыдущих срабатываний OOM'а — всё на месте, а тут части сообщений нет.
Итак, конкретный факт №1: в elasticsearch был записан не полный лог oom'а. Поскольку возбуждение shinken'а происходит при получении сообщения, то можно предполагать, что до фильтров лог тоже дошёл не полностью, то есть elasticsearch и его взаимодействие с logstash пока что можно пропустить.
Сужаем фокус разбирательств до проблемы получения netconsole. Почему? Ну, с одной стороны UDP, не гарантированная доставка и всё такое, а с другой стороны — это наша локальная сеть, срабатываний мониторинга о повышенной загрузки сети не было, snmp от коммутаторов ни на что не жаловался, морганий сетевых линков тоже не было. Графики загрузки сети тоже ровные — никаких проблем со связностью не наблюдается.
Момент интуиции: А какого размера у нас запись от oom kill'а? Выписываю в файл, wc -c. Получается, 12.5kb. Гипотезы про «не лезет в UDP» не подходят, потому что каждое сообщение короткое — сотни байт. Но вот вопрос: кто быстрее — ядро, генерирующее UDP-пакеты на низком уровне в ядерном треде, или приложение на java, прогоняющее по полученным сообщениям фильтры и регэкспы, записывающая их базу и отправляющая по поводу сообщений event'ы в другие сервера? Очевидно, что "special high-grade class of software that makes careful use of relevant software architecture design principles to build particularly customizable and extensible solutions to real problems" справляется быстрее, чем грязный ядерный код на Си, в котором слово goto встречется 105823 раза (3.15-rc7).
Вопрос: а что происходит с пакетами, которые оказались быстрее, чем enterprise grade software может их обработать? Добрый волшебник помогает им уснуть, прямо на выходе из сетевого интерфейса с помощью хэдшота.
Фокусируемся на этой проблеме. Внезапно, сенсация, драма, скандал, сетевой интерфейс на одном из серверов с logstash'ем вопит о вселенской несправедливости, но никто его не слышит:
bond0 Link encap:Ethernet HWaddr бла-бла-бла
UP BROADCAST RUNNING MASTER MULTICAST MTU:1500 Metric:1
RX packets:455816267 errors:0 dropped:130361 overruns:0 frame:0
TX packets:73379669 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:0
Сто тридцать тысяч пакетов вместо того, чтобы жить, радоваться, приносить счастье, спят на сетевом интерфейсе, и никто их не может разбудить.
Фиксируем факт №2: мониторинг не контролирует число drop'ов на сетевых интерфейсах. Вне зависимости от дальнейших разбирательств «можно ли это починить?» — мы имеем ценное наблюдение, которое тут же превращается в задачу в task traker'е: «мониторить изменение числа drop'ов на сетевых интерфейсах». Очередной забег в гугль подсказывает, что, увы, сбрасывать счётчики на интерфейсе гуманными методами нельзя, так что фиксируем именно изменения.
Forensic system administration на этом этапе заканчивается. Причина несрабатывания мониторинга ясна до самого дна: OOM вызывает отправку большого числа сообщений за сверхкороткий промежуток времени, java за ним не поспевает, избыточные пакеты drop'аются. В рассматриваемом случае, в том числе, пропал пакет с сообщением о том, что приложение было убито — event в shinken отправлен не был.
Чиним
Вторая часть — как нам с этим быть?
Короткий забег в гугль показал, что размер буфера для сокета при чтении UDP-датаграмм контролируется приложением (man setsockopt). Продолжаем спринт с препятствиями по гуглу — есть опция в конфигуах logstash'а, называется buffer_size. Так же нануглено существование net.core.rmem_max — по-умолчанию она 200+кб. К нашему случаю (всего 12кб) вероятнее всего не относится, но поднять не помешает.
Результат
0. Причина несрабатывания мониторинга точно выяснена.
1. Теперь shinken следит за drop'ами на всех сетевых интерфейсах.
2. logstash готов принять больший всплеск логгинга без потери пакетов.
P. S. Для тех, кто говорит про «tcp для syslog'а». Netconsole очень низкоуровневый, и никаких тисипей не умеет, даже UDP оно делает методом «заполнили поля и отправили ethernet-frame». И, наверное, ядро выглядело бы очень забавно, если бы начало подтормаживать из-за задумавшейся записи логов по TCP…
Автор: amarao
