在'unkn-4'状态下TCP套接字非常慢，bacula备份

几个bacula-fd客户端备份到一个bacula SD（在大规模RAID上使用2G磁盘文件，而不是磁带），通常同时有2-3个。它工作正常，除了当两个更大的客户端（每个约400-900GB）需要运行完整备份，速度非常慢（通常约200-2500千字节/秒），所以完整备份不会在几天内完成，这是一个问题给我们（所以我们取消它，并增量）。

服务器和客户端位于不同的VLAN /子网中，因此通过另一个带有VLAN和交换机的debian wheezy机器进行路由。所有机器上的NIC都是1Gbps（有一个主动 – 被动networking绑定 – 失败不会影响速度），交换机也一样。机器是四核和八核，具有8-64GB RAM，不会进入交换，并具有0.2-2之间的负载，所以我想这不是CPU，I / O或内存不足。 Bacula-SD也在硬件RAID上，似乎没有负载。当时networking也大多是空闲的，所以不应该是带宽拥塞。 Bacula版本是标准版5.2.6 + dfsg-9，而Linux内核版本也是标准版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)

并继续备份（通过bconsole status client=blowgun-fd blowgun status client=blowgun-fd确认）。例如：

 * 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.2MB，并且保留了几分钟。

在导演，SD和文件deamonconfiguration中，Hearbeat间隔设置为120，似乎工作正常。使用setdebug level=200 trace=1 all启用debugging跟踪文件，我看到：

 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的networking连接，写入的过程被阻塞。研究unkn-4似乎表明它实际上是“零窗口探测计时器正在等待”。

所以，在我看来，它是要么由于某种原因（bug？）或者（更可能是恕我直言）某种forms的networking问题来进行节stream。

它似乎没有活动的以太网适配器上的错误。我试过使用ethtool禁用卸载和其他function，但没有帮助。 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

我正在寻找如何进行故障排除（当然，最后修复）这个想法？

UPDATE1 ：甚至在调优TCP缓冲区之后，情况并没有好转 – 只是队列变大了，但仍然阻塞，备份仍然很慢。在看Wireshark转储之后，似乎是bacula-sd的软件问题，而TCP ZeroWindow是在这种情况下节制TCP的正常核心方式。所以机器似乎收到的数据OK，但是bacula-sd似乎不能够快速处理数据，尽pipe机器没有负载; 这是在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超出取消的备份。而且即使有多个备份运行，由于体系结构的原因，所有这些都会减慢。

解决scheme（种）是补充：

 Spool Data = no Spool Attributes = yes

在bacula-dir.conf JobDefs {...}部分（注意我使用Spool Data = no因为它是磁盘存储，不是磁带存储，所以只会增加开销）。使用Spool Attributes = yes bacula将文件属性写入文件，并且只有在作业完成时才将文件发送到SQL服务器。请注意，在数据传输完成后， bacula-fd被释放（客户端的磁盘/networking负载），因此不会等待SQL插入完成。

一些说明：

“你的SQL不是非常快”，意味着它每秒只能处理几十个查询。
在我的情况下，有问题的服务器有大约300万个文件和350GB的磁盘空间。无法在4天内完成完整备份，传输速度降至200 Kbyte / sec。
随着属性假脱机，它设法在2天13小时内完成。数据传输本身只需要4.5小时 ，平均速度为〜18 Mbytes / sec（这对于第一次备份来说并不是那么糟糕）大量的小文件和压缩，而服务器做其他事情）。但是，从本地文件到SQL服务器的脱离属性需要56.5小时 ！两天以上！
所讨论的SQL服务器是在8核I7 @ 3.70GHz上的专用MySQL（5.5.40-0 + wheezy1），具有64GB RAM，位于4个磁盘RAID-10上。它也执行其他操作，启用了二进制日志，但在备份运行时大部分处于空闲状态。对其他负载工作相当好，innodb_buffer_pool_size比bacula的所有指标都大。它应该工作正常。
似乎即使启用了属性假脱机，bacula也不使用批量插入（也不是LOAD DATA LOCAL INFILE ），而是LOAD DATA LOCAL INFILE 300万个逐一插入，等待每个确认（属性数据存储在1GB左右的紧凑二进制文件中。转换为ASCII的SQL INSERT语句肯定是双倍的）。所以，由于MySQL在其他机器上的延迟而导致的延迟似乎完全消除了性能。
我会试着更深入地探讨为什么SQL很慢，但我想最好的解决scheme是将MySQL放在（低得多的性能）本地机器上。当我在这里时可能用首选的PostgreSQLreplace它。

编辑1 ：将bacula升级到（手动创build的包）5.2.13其中包含对批量插入的支持（而不是在Debian wheezy / jessie中打包5.2.6），并调整MySQL数据库，以便在tmpfs中创build临时表，将提到的属性假脱机时间从56.5小时减less到30分钟。我想用本地机器上的PostgreSQLreplace它（bacula-sd＆bacula-dir也是如此）可能会改善，但这对我们来说已经足够了。