Назад | Перейти на главную страницу

очень медленное резервное копирование bacula с TCP-сокетом в состоянии 'unkn-4'

Несколько клиентов bacula-fd выполняют резервное копирование на одну SD-карту bacula (с использованием дисковых файлов 2 ГБ на массивном массиве RAID, а не на магнитной ленте), обычно 2-3 из них одновременно. Он работает нормально, за исключением случаев, когда 2 более крупных клиента (около 400-900 ГБ каждый) должны запускать полные резервные копии, которые становятся ужасно медленными (обычно около 200-2500 КБ / с), поэтому полное резервное копирование не завершается за несколько дней, что является проблема для нас (поэтому мы отменяем ее и переходим к инкрементальной).

Сервер и клиенты находятся в разных VLAN / подсетях, поэтому маршрутизируются через другую машину debian wheezy с VLAN и несколькими коммутаторами. Сетевые адаптеры имеют скорость 1 Гбит / с на всех машинах (одна из которых имеет соединение активно-пассивной сети - ее переключение не влияет на скорость), как и коммутаторы. Машины четырех- и 8-ядерные, имеют 8-64 ГБ ОЗУ, не переходят в свопинг и имеют нагрузку от 0,2 до 2, так что я предполагаю, что это не процессор, ввод-вывод или нехватка памяти. Bacula-sd также находится на аппаратном RAID, который, похоже, не загружен. В это время сеть также в основном простаивает, так что перегрузки полосы пропускания быть не должно. Версия Bacula - это стандартная wheezy 5.2.6 + dfsg-9, а ядро Linux также является стандартным wheezy 3.2.60-1 + deb7u3.

Кажется, что передача начинается нормально (примерно со скоростью 20+ Мбайт / сек, что и следовало ожидать при большом количестве небольших файлов), чем в один момент Send-Q поднимается и не отключается в течение десятков секунд (или минут) , а netstat показывает сокет в таймере "unkn-4", перезапускающийся с экспоненциально увеличивающимся таймаутом:

# netstat -tpno   | grep bacula
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name Timer
tcp        0 967688 10.66.3.135:49668   10.66.2.11:9103         ESTABLISHED 2964/bacula-fd   unkn-4 (1.86/0/0)
tcp        0      0 10.66.3.135:9102    10.66.2.11:54499        ESTABLISHED 2964/bacula-fd   keepalive (5882.64/0/0)

затем через некоторое время кажется, что пакеты снова запускаются:

# netstat -tpno    | grep bacula
tcp        0  38054 10.66.3.135:49668   10.66.2.11:9103         ESTABLISHED 2964/bacula-fd   on (0.21/0/0)
tcp        0      0 10.66.3.135:9102    10.66.2.11:54499        ESTABLISHED 2964/bacula-fd   keepalive (385.49/0/0)

и резервное копирование продолжается (подтверждено status client=blowgun-fd на bconsole). Например:

* status client=axe-fd
newaxe-fd Version: 5.2.6 (21 February 2012)  x86_64-pc-linux-gnu debian 7.0
Daemon started 24-Oct-14 17:27. Jobs: run=0 running=0.
 Heap: heap=683,600 smbytes=761,617 max_bytes=807,280 bufs=396 max_bufs=426
 Sizeof: boffset_t=8 size_t=8 debug=200 trace=1 
Running Jobs:
JobId 12640 Job axe.2014-10-24_23.05.01_40 is running.
    Full Backup Job started: 24-Oct-14 23:05
    Files=2,529,050 Bytes=253,018,715,824 Bytes/sec=1,479,901 Errors=6
    Files Examined=2,529,050
    Processing file: /home/users/novoselo/public_html/~2511/templates/js_corp/images/bg.jpg
    SDReadSeqNo=5 fd=5
Director connected at: 26-Oct-14 21:34

bg.jpg имеет размер 1,2 МБ, и он оставался на нем несколько минут ...

Интервал прослушивания установлен на 120 в конфигурациях режиссера, SD и файлового демона и, похоже, работает нормально. Включение файла трассировки отладки с помощью setdebug level=200 trace=1 all, Я вижу:

newaxe-fd: backup.c:371-0 FT_REG saving: /home/users/novoselo/public_html/~2511/templates/js_corp/images/bg.jpg
newaxe-fd: backup.c:469-0 bfiled: sending /home/users/novoselo/public_html/~2511/templates/js_corp/images/bg.jpg to stored
newaxe-fd: crypto.c:607-0 crypto_digest_new jcr=2f01748
newaxe-fd: backup.c:1467-0 No strip for /home/users/novoselo/public_html/~2511/templates/js_corp/images/bg.jpg
newaxe-fd: backup.c:609-0 type=3 do_read=1
newaxe-fd: bfile.c:963-0 open file /home/users/novoselo/public_html/~2511/templates/js_corp/images/bg.jpg
newaxe-fd: backup.c:1194-0 Send data to SD len=65135
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0

strace, похоже, подтверждает, что:

# strace -tt -ff -s999 -p 3907
Process 3907 attached with 4 threads - interrupt to quit
[pid 27650] 22:25:15.705796 write(5, "[....]"..., 55110 <unfinished ...>
[pid 27661] 22:25:15.706103 select(6, [5], NULL, NULL, {2, 804806} <unfinished ...>
[pid  3912] 22:25:15.706147 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid  3907] 22:25:15.706168 select(4, [3], NULL, NULL, NULL <unfinished ...>
[pid  3912] 22:25:16.619938 <... restart_syscall resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid  3912] 22:25:16.620008 futex(0x397d82d0240, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  3912] 22:25:16.620092 futex(0x397d82d0284, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 13229, {1414358746, 620076000}, ffffffff <unfinished ...>
[pid 27661] 22:25:18.513819 <... select resumed> ) = 0 (Timeout)
[pid 27661] 22:25:18.513858 write(15, "newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0\n", 47) = 47
[pid 27661] 22:25:18.513928 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout)
[pid 27661] 22:25:23.519025 write(15, "newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0\n", 47) = 47
[pid 27661] 22:25:23.519139 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout)
[pid 27661] 22:25:28.524240 write(15, "newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0\n", 47) = 47
[pid 27661] 22:25:28.524317 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout)
[pid 27661] 22:25:33.529409 write(15, "newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0\n", 47) = 47
[pid 27661] 22:25:33.529508 select(6, [5], NULL, NULL, {5, 0}^C <unfinished ...>

fd 5 - это сетевое подключение к bacula-sd, и при записи в него процесс блокируется. Исследования unkn-4 похоже, указывает на то, что на самом деле "ожидает таймер проверки нулевого окна".

Итак, мне кажется, что либо bacula-sd по какой-то причине выполняет дросселирование (ошибка?), Либо (что более вероятно, IMHO) какая-то проблема с сетью.

не похоже, что есть ошибки на активных адаптерах Ethernet. Я пробовал использовать ethtool отключить разгрузку и другие функции не помогло. ping -f не теряет пакеты даже тогда, когда проблема в TCP проявляется:

axe# ping -s1400 -f -c1000 10.66.2.11
--- slingshot.tomsoft.lan ping statistics ---
1000 packets transmitted, 1000 received, 0% packet loss, time 607ms
rtt min/avg/max/mdev = 0.391/0.582/0.672/0.039 ms, ipg/ewma 0.608/0.585 ms

Я ищу идеи, как приступить к устранению неполадок (и, конечно же, исправить) это?

ОБНОВЛЕНИЕ1: даже после настройка буферов TCP ситуация не лучше - просто очередь становится больше, но все равно блоки, а резервное копирование все еще медленное. Посмотрев еще раз на дампы wirehark, кажется, что это проблема программного обеспечения bacula-sd, и что TCP ZeroWindow является нормальным способом ядра для регулирования TCP в этом случае. Таким образом, кажется, что машина получает данные нормально, но bacula-sd не может обрабатывать данные достаточно быстро, хотя машина не загружена; это на стороне bacula-sd:

Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name Timer
tcp   3952353      0 10.66.2.11:9103         10.66.3.132:45226   ESTABLISHED 15839/bacula-sd  keepalive (4863.09/0/0)
# uptime
 05:23:13 up 2 days, 14:40,  2 users,  load average: 0.42, 0.32, 0.27

Это был SQL.

По умолчанию каждый раз, когда bacula-fd отправляет новый файл, bacula-sd пытается (через bacula-dir) вставить атрибуты файла в SQL. batch стол. Если у вас много маленьких файлов, а ваш SQL не очень быстрый, он вставит небольшую задержку. Множество мелких задержек = снижение скорости = резервное копирование отменено из-за Max Run Sched Time превышено. И из-за архитектуры, даже если у вас было несколько резервных копий, все замедлилось.

Решение (вроде) заключалось в добавлении:

Spool Data = no
Spool Attributes = yes

в JobDefs {...} раздел bacula-dir.conf (обратите внимание, я использую Spool Data = no потому что это дисковое хранилище, а не ленточное хранилище, поэтому это просто добавит накладных расходов). С участием Spool Attributes = yes bacula записывает атрибуты файла в файл, и только после завершения задания файл отправляется на SQL-сервер. Обратите внимание, что в связи с bacula-fd освобождается (и нагрузка на диск / сеть на стороне клиента) сразу после завершения передачи данных (поэтому он не дожидается завершения вставки SQL).

Некоторые примечания:

«ваш SQL не так уж быстр» означает, что он выполняет всего несколько десятков запросов в секунду.
в моем случае на проблемном сервере было около 3 миллионов файлов и 350 ГБ дискового пространства. Не удалось завершить полное резервное копирование за 4 дня, при этом скорость передачи упала до 200 Кбайт / сек.
со спулингом атрибутов ему удается завершить за 2 дня и 13 часов. Не такое уж большое улучшение на первый взгляд (хотя оригинальные резервные копии никогда не заканчивались, так что, может быть, это так), но: сама передача данных занимает только 4,5 часа, со средней скоростью ~ 18 Мбайт / сек (что неплохо для большого количества небольших файлов и сжатия, в то время как сервер делает другие вещи). Однако деактивация атрибута из локального файла на сервер SQL выполняется следующим образом. 56,5 часов! Больше двух дней !!
рассматриваемый SQL-сервер - это выделенный MySQL (5.5.40-0 + wheezy1) на 8-ядерном I7 @ 3,70 ГГц с 64 ГБ ОЗУ на 4 дисках RAID-10. Он делает и другие вещи и имеет включенные бинлоги, но в основном простаивает во время резервного копирования. Он отлично работает для других нагрузок, а innodb_buffer_pool_size больше, чем все индексы bacula. Это должно быть работает нормально.
кажется, что даже при включенной буферизации атрибутов bacula не использует пакетные вставки (и LOAD DATA LOCAL INFILE), но отправляет эти 3 миллиона вставок одну за другой, ожидая подтверждения для каждой (данные атрибутов хранятся в компактном двоичном файле размером около 1 ГБ. В переводе на инструкции ASCII SQL INSERT они наверняка будут вдвое больше). Таким образом, увеличенная задержка из-за того, что MySQL находится на другой машине, похоже, полностью убивает производительность.
Я попытаюсь подробнее разобраться, почему SQL работает медленно, но я думаю, что лучшим решением было бы разместить MySQL на локальном компьютере (с гораздо меньшей производительностью). Вероятно, заменив его предпочтительным PostgreSQL, пока я занимаюсь этим.

Edit1: обновление bacula до (созданного вручную пакета) 5.2.13, который делает содержат поддержку пакетных вставок (вместо пакета 5.2.6 в Debian wheezy / jessie, который не) и настройка базы данных MySQL таким образом, чтобы временные таблицы создавались в tmpfs, уменьшили время удаления указанного атрибута с 56,5 часов до 30 минут. Думаю, замена его на PostgreSQL на локальном компьютере (там же, где есть bacula-sd и bacula-dir), вероятно, улучшит даже это, но для нас этого достаточно.