Помогите локализовать проблемму - ошибки с udp-пакетами

[midn]

Добрый день.

Может, не совсем в этот форум — но очень интересная ситуация.
Есть программа для сбора flow — flow-tools. Она собирает т.н. Flow-траффик с маршрутизаторов. На сервере поднимается демон — flow-capture. При запуске указывается порт udp, на котором он будет принимать пакеты, директорию, где складывать файлы, период ротации и пр.
Была машина — 32 bit x86, 4 Gb памяти, debian 3.0. Там стоял flow-capture версии 0.66

Обьем данных, что идет на этот порт — довольно большой. В сутки в сжатом виде собирается порядка 80 Gb. Скорость на интерфейсе — порядка 20-25Mbit/s.

Сейчас поставили более мощную машину — x86_64, Centos 5.2 x86_64,
8 Gb памяти. В разы мощней старой машины. Обновили и версию flow-tools — поставил 0.68-4. Перевели сбор флоу на новую машину — и получили неприятный сюрприз. Размер файла раз в 10-20 стал меньше, чем за аналогичный период времени, но на старой машине.
Стал копать.
Ifconfig -a показывает 0 ошибок на примем и передачу.
А вот netstat -su (статистика по udp-пакетам) показал


Udp:
2712928083 packets received
3743615 packets to unknown port received.
14582447 packet receive errors
60633183 packets sent
Раздел
packet receive errors
увеличивался чуть ли не 1000 пакетов в сек.

Перезапуск программы ничего не дал.

Стал подкручивать параметры ядра.

Итак,
uname -a
2.6.18-92.el5 #1 SMP Tue Jun 10 18:51:06 EDT 2008 x86_64 x86_64 x86_64 GNU/Linux

в файле sysctl.conf


# Controls the maximum size of a message, in bytes
kernel.msgmnb = 65536

# Controls the default maxmimum size of a mesage queue
kernel.msgmax = 65536

# Controls the maximum shared segment size, in bytes
kernel.shmmax = 68719476736

# Controls the maximum number of shared memory segments, in pages
kernel.shmall = 4294967296
kernel.sem = 250 32000 100 128
kernel.msgmni = 2878
net.ipv4.ip_local_port_range = 1024 65000
fs.file-max = 65536
fs.aio-max-nr = 4194304
kernel.shmmni = 4096

net.core.wmem_default = 4194304
net.core.wmem_max = 16777216
net.core.rmem_default = 8388608
net.core.rmem_max = 67108864
net.ipv4.tcp_rmem = 8388608 12582912 16777216
net.ipv4.tcp_wmem = 8388608 12582912 16777216
net.ipv4.tcp_mem = 8388608 12582912 16777216

net.ipv4.udp_wmem_min = 4194304
net.ipv4.udp_rmem_min = 8388608
net.ipv4.udp_mem = 8388608 33554432 67108864

net.ipv4.tcp_fin_timeout = 30
net.ipv4.tcp_keepalive_time = 600

# For huge UDP traffic
net.unix.max_dgram_qlen = 120

net.core.netdev_max_backlog = 30000 # number of unprocessed input packets before
# kernel starts dropping them, default 300

Перезапустил машину — какое-то время все было нормально.
netstat -su показывал, что поле packet receive errors не меняется. А потом раз — и опять то же самое. Перезапустил программу — опять все нормально. Потом опять раз — и та же беда.
На старой машине стоял компилятор gcc-3
На новой -
gcc version 4.1.2 20071124 (Red Hat 4.1.2-42)

И на старой было 32 битная программа, на новой машине я собрал 64-битную версию.
Решил постепенно идти — вначале собрал 32-битную версию программы — не помогло. Взял со старой машины бинарный файл, запустил — то же самое — работает, работает — может днями работать нормально — а потом раз — и пошел расти packet receive errors.

Собрал на старой машине gcc-3 пакет версии 0.68-4 (было подозрение, что может с компилятором 4 версии что не так, ибо пакет 0.68 4 версией компилятора не собирается). Тоже не помогло.

Ситуация такая — работает прогрмма, периодически проверяется, не растет ли поле packet receive errors. Если оно резко растет — то надо перезапускать программу. Перезапуск программы на какое-то время спасает — но потом опять растут ошибки -
и надо перезапускать.
Насколько я понял -
ifconfig -a — он показывает, что на уровне драйвера сетевой платы ошибок в приеме пакетов нет

RX packets:8498323782 errors:0 dropped:0 overruns:0 frame:2

А вот netstat -su — это уже дальше по стэку — ошибки на уровне udp.
Т.е., либо сама программа, либо где-то на уровне ядра начинается резкое либо сбрасывание этих пакетов, либо они начинают портиться.

И тут вопрос — это проблема с программой или все же на уровне ядра может быть какая-то ошибка или какой-то параметр надо подркутить? Как это посмотреть?
Я, увы, не настолько силен в отладчике ядра — но может есть какие-то более-менее понятные методы, как посмотреть — какая программа или какой уровень ядра порождает эти ошибки?

Заранее спасибо.

[кодировщик]

а на предыдущию версию программы откатывались?!

[midn]

а на предыдущию версию программы откатывались?!

Тут идея такая.
На новой машине стоит gcc-4 - им можно собрать только flow-tools-068.-4 - версия
0.68 не собирается - там какой-то прикол в gcc-4 - и разработчикам пришлось патч на свою
программу делать.
Версия 0.66 у меня на gcc-4 не собралась.
Я просто взял бинарник со старой машины и запустил на новой - спустя некоторое время пошло
тоже самое.
Вот теперь ломаю голову - то ли именно в этом ядре какие-то приколы, либо уже приколы на уровне
самой программы...

[midn]

Посоветовали попробовать прицепиться к процессу при помощи strace.

Как начали сыпаться ошибки в netstat -su
прицепился к процессу
strace -tt -p 10854 -o bad

Потом перезапустил flow-capture - ошибки ушли - также прицепился к процессу

strace -tt -p 32342 -o good

В результате 2 файла трассировки - good - это когда нормально работала,
bad - когда плохо. Может, кто поможет в их разборе - я там мало что понял.

[xsignal]

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

[midn]

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

Узнать бы, где и из-за чего такое происходит. Может, есть какой-то параметр или какой-то способ - в момент, когда это происходить - какую-то статистику из ядра получить? Возможно, надо какие-то параметры ядра докрутить - но знать бы, какие (((
А может быть такое, что программа просто начала захлебываться - и стала отбрасывать пакеты?
Или это было бы видно в тех логах, что я привел?

[xsignal]

А может быть такое, что программа просто начала захлебываться - и стала отбрасывать пакеты?
Или это было бы видно в тех логах, что я привел?

Программа спотыкается ны вызове send():
15:48:37.809262 send(0, "<182>Aug 12 15:48:37 flow-captur"..., 162, MSG_NOSIGNAL) = 162
15:48:37.827355 select(2, [1], NULL, NULL, {1, 0}) = 1 (in [1], left {1, 0})

В логах "bad" send блокируется в среднем на 0.015 с, в "good" - меньше 0.0003 с, в этот момент похоже и дропаются пакеты. Что и куда отправляет flow-capture? В буфере: "Aug 12 15:48:37 flow-captur..." - логи программы? Видимо приемная сторона не успевает обрабатывать эти сообщения.

[midn]

Программа спотыкается ны вызове send():
15:48:37.809262 send(0, "<182>Aug 12 15:48:37 flow-captur"..., 162, MSG_NOSIGNAL) = 162
15:48:37.827355 select(2, [1], NULL, NULL, {1, 0}) = 1 (in [1], left {1, 0})

В логах "bad" send блокируется в среднем на 0.015 с, в "good" - меньше 0.0003 с, в этот момент похоже и дропаются пакеты. Что и куда отправляет flow-capture? В буфере: "Aug 12 15:48:37 flow-captur..." - логи программы? Видимо приемная сторона не успевает обрабатывать эти сообщения.

Я саму логику программы мало знаю - видимо, у flow-capture есть буффер в оперативке - там она собирает данные, сжимает - и затем сбрасывает в файл на диске. Раз в полчаса закрывается старый
файл и открывается новый. Возможно, какие-то странности с дисковой системой? Но на этой машине
дисковая система в разы быстрей, чем на старой. Весь аппаратный дисковый кэш включен только на запись.

[xsignal]

write() проскакивает быстро, значит с дисковой системой всё в порядке, а вот на send() возникает значительная задержка. flow-capture периодически что-то отправляет через сокет. Судя по началу сообщения: "Aug 12 15:48:37 flow-captur..", это логи. Может flow-capture заваливает какую-то программу логами, а она не успевает их разгребать? Это, кстати, объясняет, почему какое-то время всё работает нормально: сообщения накапливаются в буфере передачи, а когда он заполняется, send() начинает тормозить.

[midn]

write() проскакивает быстро, значит с дисковой системой всё в порядке, а вот на send() возникает значительная задержка. flow-capture периодически что-то отправляет через сокет. Судя по началу сообщения: "Aug 12 15:48:37 flow-captur..", это логи. Может flow-capture заваливает какую-то программу логами, а она не успевает их разгребать? Это, кстати, объясняет, почему какое-то время всё работает нормально: сообщения накапливаются в буфере передачи, а когда он заполняется, send() начинает тормозить.

Вот тебе и раз...
Я не знаю, как именно - но программа шлет логи в syslog - уровень 6. И на старой машине тоже самое было. В принципе, там не так много логов она шлет. Неужели логирование работы может так кардинально задавить работу????
А почему тогда пакеты теряются, что в программу идут? Они каким образом могут на логгирование быть завязаны?

[xsignal]

В логах "bad" она шлёт в среднем 55 сообщений в секунду, что не мало. Кстати, было бы неплохо посмотреть, что она там пишет. А пакеты теряются потому что send() блокируется, если не может сразу передать сообщение в сокет, т.е. программа на некоторое время просто останавливается.

[midn]

В логах "bad" она шлёт в среднем 55 сообщений в секунду, что не мало. Кстати, было бы неплохо посмотреть, что она там пишет. А пакеты теряются потому что send() блокируется, если не может сразу передать сообщение в сокет, т.е. программа на некоторое время просто останавливается.

В логи шлет примерно такое
Aug 28 15:37:16 my_comp flow-capture[17555]: ftpdu_seq_check(): src_ip=10.10.2.26 dst_ip=10.10.10.2
d_version=5 expecting=2030255941 received=2030257321 lost=900

Как я понял - у меня есть несколько цисок - в принципе, где-то в районе 5-10 штук. И от них маршрут до флоу-сервера - динамический. Т.е., один пакет может идти по одному маршруту, другой - по другому. Поскольку flow работает по udp, то последовательность пакетов играет ключевую роль - т.е., если пакет с номером 2 пришел раньше 1, то мы и имеем ту запись, что приведена выше.
При запуске же flow-capture имеем
setcokopt(size=4194306)

Т.е., по тем данным, что вы привели - выходит так - по udp идет куча пакетов - они, как я понимаю, в программу попадают из сокета. И через сокет же пишутся логи. Когда логов слишком много - программа блокирует работу с сокетом и пакеты с флоу просто отбрасываются. Перезапуск программы, естественно, сбрасывает это все это - и работа идет до следующего затыка.