Маленькая админская история: как поймать OOM

    Админская загадка: На сервере произошло три 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 встречается 119287 раз (3.16-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, SO_RCVBUF). Продолжаем спринт с препятствиями по гуглу — есть опция в конфигуах logstash'а, называется buffer_size. По здравому размышлению, мы подняли его до 1Мб. Так же нагуглено существование net.core.rmem_max — по-умолчанию она 200+кб. К нашему случаю (всего 12кб) вероятнее всего не относится, но поднять до 2Мб не помешает.

    Результат


    0. Причина несрабатывания мониторинга точно выяснена.
    1. Теперь shinken следит за drop'ами на всех сетевых интерфейсах.
    2. logstash готов принять больший всплеск логгинга без потери пакетов.

    P. S. Для тех, кто говорит про «tcp для syslog'а». Netconsole очень низкоуровневый, и никаких тисипей не умеет, даже UDP оно делает методом «заполнили поля и отправили ethernet-frame». И, наверное, ядро выглядело бы очень забавно, если бы начало подтормаживать из-за задумавшейся записи логов по TCP…
    Webzilla
    Компания

    Похожие публикации

    Реклама
    AdBlock похитил этот баннер, но баннеры не зубы — отрастут

    Подробнее

    Комментарии 19

      +6
      Прочитал как детектив, хотя и не все понял
        +2
        scribe или flume тебе в помощь. отправляет сообщения пачками. если он не может отправить сообщение, то оно накапливается в очереди. такие ситуации как у тебя сведены к минимуму.
          0
          А как они с netconsole помогут? Или предполагается прокси между logstash и отправителем? За названия спасибо, почитаю.
            0
            Верно, как прокси должно помочь.
              0
              А зачем ещё один сервер в разрыве, когда можно просто увеличить размер буфера со стороны принимающего? В общем случае, у прокси будут ровно те же проблемы — ядро пишет так быстро, как может, а принимающему всё-таки что-то с пакетом делать надо (хотя бы заголовки сетевого/транспортных уровней разобрать, да в userspace передать).
                0
                Оно не только это умеет, flume может взять на себя роль балансировщика, плюс один агент может выполнять несколько задач. Со скоростью разбора пакетов у него проблем нет. Также в нем можно настроить длину очереди и правила ее записи (трешолды по количеству сообщений, размеру данных), делать первичную обработку и т.д.

                И не обязательно на отдельный сервер, ставьте там же где logstash.
                  0
                  Ну, если увеличение буфера не поможет, будем смотреть в сторону специальных решений. За совет спасибо.
            +1
            Но да, к сожалению, scribe никто еще в ядро не встроил.
            +2
            Как вариант, можно попробовать Serial-over-lan — в современных IPMI такое есть.
            Ну, или написать свой netconsole:)
              +1
              Serial over lan отличная штука и в некоторых случаях работает даже круче, чем impi. Например, когда у меня (на предыдущей работе) были очень тонкие и трудноуловимые глюки зена, именно логгинг на последовательный порт (который SOL) помог локализовать источник проблем.

              С SOL проблема другая: он очень медленный. И тут возникает два варианта:

              1) Асинхронный вывод. В этом случае оно сначала ломается и начинает трейситься, а потом уныло из буффера кормит SOL данными. Всё работает быстро, но если всё виснет, то буфер теряется.
              2) Синхронный вывод. В этом случае когда проблема (или просто INFO) возникает, то оно синхронно пишется в SOL до победного конца. В это время всё замирает. То есть буквально всё — ядро ЗАНЯТО ОНО ЛОГИ ПИШЕТ. В это время не обрабатываются прерывания, не идёт сетевой трафик, не работает консоль и т.д. Если это отладка любой ценой — всё ок, мы получаем самую последнуюю предсмертную записку самым надёжным способом. Но в продакшен так нельзя.

              Так что для мониторинга продакшена чуть менее надёжный, зато быстрый netconsole оказывается лучше. Если начинаются странные процессы, ведущие к зависанию, то вероятность, что большой кусок лога уйдёт с сервера через асинхронный netconsole выше, чем через асинхронный последовательный порт (например, с момента начала трейса до момента полного зависания 10мс — на гигабитной сети это резерв для примерно 10 тысяч udp-пакетов, а на SOL на скорости в 112 килобод — меньше 200).

                0
                Оно то конечно так, но SOL незаменим, когда косяки в сетевой части(например в драйвере сетевой карты).
                Ну, и 12.5Кб = 100 Кбод ~= 1c передачи, так что могло и отправить — в Вашем случае.
                  +1
                  В нашем конкретном случае сервер остался жив (велика потеря — апача завалили), и более того, сообщение дошло в полном комплекте через syslog (куда kernel messages тоже идут), то есть любой метод доставки сработал бы. Я выше писал про более тяжкие случаи, когда, например, ядро решает поубивать всех и пишет про то, что убивает init (это означает panic). Чем быстрее утаскивается трейс, тем выше вероятность утащить в нём важное для разбирательств.
                    0
                    Понятно, спасибо!
              0
              А можно узнать, в каком режиме работает бондинг? Это 802.3ad или что-то другое (active-backup, какой-то из режимов балансировки)?

              Получилось ли воспроизвести ситуацию, в которой отправка сообщений вызывала видимое увеличение количества dropped (предполагается, что в остальных случаях данная величина не изменяется)?
                0
                Bonding Mode: fault-tolerance (active-backup)

                Воспроизводить не пробовали, поскольку есть строгая уверенность, что потеря логов вызывает рост dropped, мониторинг (теперь) скажет, если что не так.

                В принципе, воспроизвести легко можно — hping3/nping на порт, который logstash слушает, думаю, --flood ни одна софтика не переживёт (хотя бедный эластик при этом жалко).
                  +1
                  Есть смысл посмотреть, какое количество dropped-пакетов на slave-интерфейсе и на master-интерфейсе. Если эта величина на slave-интерфейсе совпадает со значением на bond-интерфейсе (а на мастере при этом 0), скорее всего, причина обсуждаемой проблемы в чем-то другом.

                  Сразу скажу, что я не сумел нагуглить или определить точную причину возникновения dropped-пакетов, но встречал упоминания, что это особенность реализации bonding в Linux.

                  Буду рад, если кто-то подскажет какую-либо информацию по теме.
                    +1
                    Очень, очень любопытно.

                    На одном сервере:

                    bond0: dropped:146630
                    eth0: 0
                    eth1: 21

                    На другом сервере:
                    bond0: dropped:93304
                    eth0: 0
                    eth1: 93304

                    Спасибо за наводку, буду копать дальше.
                0
                Этому нетконсолю бы ещё dot1.q-тег. Не понимаю ядерщиков с их 'netconsole is very very log level'. Если мы всё равно формируем кадр и отсылаем его в сеть, что мешает заполнить его указанным тегом…
                  0
                  Я смотрел на эту тему, насколько я понял, там нужны изменения для самих виланов (поддержка netpoll). Хотя да, я не понимаю, почему нельзя в ethernet-frame дописать ещё одно поле «вслепую» (например, выставляя тег, которого на местных интерфейсах ородясь не было).

                Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

                Самое читаемое