主页 / server / 问题 / 639808
Accepted
Matija Nalis
Asked: 2014-10-27 14:19:30 +0800 CST

bacula 备份非常慢，TCP 套接字处于“unkn-4”状态

  • 772

几个 bacula-fd 客户端正在备份一个 bacula SD（使用大规模 RAID 上的 2G 磁盘文件，而不是磁带），通常同时备份 2-3 个。它工作正常，除非 2 个更大的客户端（每个大约 400-900GB）需要运行完全备份，这会变得非常慢（通常大约 200-2500 KB/s），所以完全备份不会在几天内完成，这是对我们来说有问题（所以我们取消它并使用增量）。

服务器和客户端位于不同的 VLAN/子网中，因此通过另一台具有 VLAN 和少量交换机的 debian wheezy 机器进行路由。所有机器上的 NIC 都是 1Gbps（具有主动-被动网络绑定的机器 - 故障转移对速度没有帮助），交换机也是如此。机器是四核和 8 核，具有 8-64GB RAM，不进入交换，负载在 0.2-2 之间，所以我猜这不是 CPU、I/O 或内存不足。Bacula-sd 也在硬件 RAID 上，似乎没有负载。当时网络也大多是空闲的，所以应该不是带宽拥塞。Bacula 版本是标准 wheezy 5.2.6+dfsg-9，Linux 内核也是标准 wheezy 3.2.60-1+deb7u3。

似乎传输开始得很好（大约 20+ Mbytes/sec，这是对大量小文件的预期），而不是在某一时刻 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.2MB，它在上面停留了几分钟......

在 director、SD 和文件守护程序配置中，心跳间隔设置为 120，并且似乎工作正常。使用 启用调试跟踪文件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 出于某种原因（错误？）或（更可能是恕我直言）某种网络问题而进行节流。

活动以太网适配器似乎没有错误。我尝试使用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 缓冲区后情况也没有好转——只是队列变大了，但仍然阻塞，备份仍然很慢。在查看了更多wireshark转储之后，这似乎是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
linux-networking

1 个回答

  1. Best Answer

    它是 SQL。

    默认情况下，每次 bacula-fd 发送一个新文件时，bacula-sd 都会尝试（通过 bacula-dir）将文件属性插入到 SQLbatch表中。如果你有很多小文件，并且你的 SQL 不是非常快，它会插入小的延迟。许多小的延迟 = 限制速度 = 由于Max Run Sched Time超出而取消备份。而且由于架构的原因，即使您运行了多个备份，所有备份都会变慢。

    解决方案（某种）是添加：

    Spool Data = no
Spool Attributes = yes

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

    一些注意事项：

    • “你的 SQL 速度不是很快”意味着它每秒只执行很少的几十个查询。
    • 就我而言，有问题的服务器有大约 300 万个文件和 350 GB 磁盘空间。它无法在4 天内完成完整备份，传输速度降至 200 KB/秒。
    • 使用属性假脱机，它设法在 2 天 13 小时内完成。乍一看并没有那么大的改进（尽管原始备份从未完成，所以嘿，也许是），但是：数据传输本身只需要4.5 小时，平均速度约为 18 Mbytes/sec（这对于很多小文件和压缩，而服务器做其他事情）。但是，从本地文件到 SQL Server 的属性反假脱机需要接下来的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），而是一个接一个地发送 300 万个插入，等待每个插入的确认（属性数据存储在大约 1GB 大的紧凑二进制文件中。转换为 ASCII SQL INSERT 语句肯定会加倍）。因此，由于 MySQL 在其他机器上而增加的延迟似乎完全扼杀了性能。
    • 我将尝试更多地研究为什么 SQL 慢，但我想最好的解决方案是将 MySQL 放在（性能低得多的）本地机器上。在我使用它时，可能会用首选的 PostgreSQL 替换它。

    Edit1：将 bacula 升级到（手动创建的包）5.2.13，其中包含对批量插入的支持（而不是在 Debian wheezy/jessie 中打包的 5.2.6不支持），并调整 MySQL 数据库以便在 tmpfs 中创建临时表，将提到的属性假脱机时间从 56.5 小时减少到 30 分钟。我猜想在本地机器上用 PostgreSQL 替换它（与 bacula-sd 和 bacula-dir 相同）可能会改进，但这对我们来说已经足够了。

    • 2

相关问题