几个 bacula-fd 客户端正在备份到一个 bacula SD(使用大规模 RAID 上的 2G 磁盘文件,而不是磁带),通常同时备份 2-3 个。它工作正常,除非 2 个较大的客户端(每个大约 400-900GB)需要运行完整备份,速度会变得非常慢(通常大约 200-2500 Kbyte/s),因此完整备份需要几天才能完成,这对我们来说是个问题(所以我们取消它并采用增量备份)。
服务器和客户端位于不同的 VLAN/子网中,因此通过另一台具有 VLAN 和少量交换机的 debian wheezy 机器进行路由。所有机器上的 NIC 均为 1Gbps(其中一台具有主动-被动网络绑定 - 故障转移对速度没有帮助),交换机也是如此。机器是四核和八核的,具有 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,并且它停留在上面几分钟......
在导演、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
答案1
它是 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 = yes
bacula 将文件属性写入文件,并且只有当作业完成时,文件才会发送到 SQL 服务器。请注意,在该连接中,bacula-fd
一旦数据传输完成,就会释放(以及客户端上的磁盘/网络负载)(因此它不会等待 SQL 插入完成)。
一些说明:
- “你的 SQL 速度不是很快”的意思是它每秒只能执行几十个查询。
- 在我的情况下,有问题的服务器有大约 300 万个文件和 350 GB 磁盘空间。它无法在4天,传输速度下降至200 Kbyte/sec。
- 使用属性假脱机,它设法在 2 天 13 小时内完成。乍一看,这并不是很大的改进(尽管原始备份从未完成,所以嘿,也许是),但是:数据传输本身只需要4.5 小时,平均速度约为 18 Mbytes/sec(对于大量小文件和压缩来说,这还不算太糟糕,而服务器则执行其他操作)。但是,从本地文件到 SQL 服务器的属性解压需要56.5 小时!两天多!!
- 有问题的 SQL 服务器是专用的 MySQL (5.5.40-0+wheezy1),8 核 I7 @ 3.70GHz,64GB RAM,4 磁盘 RAID-10。它还执行其他操作并启用了 binlog,但在备份运行时大部分时间处于空闲状态。它在其他负载下工作得很好,并且 innodb_buffer_pool_size 比 bacula 的所有索引都大。它应该工作正常。
- 似乎即使启用了属性假脱机,bacula 也不会使用批量插入(也不会
LOAD DATA LOCAL INFILE
),而是逐个发送 300 万个插入,等待每个插入确认(属性数据存储在约 1GB 大小的紧凑二进制文件中。转换为 ASCII SQL INSERT 语句,它肯定会是这个大小的两倍)。因此,由于 MySQL 位于其他机器上而增加的延迟似乎完全破坏了性能。 - 我会尝试进一步研究 SQL 速度慢的原因,但我想最好的解决方案是将 MySQL 放在(性能低得多的)本地机器上。我可能会用首选的 PostgreSQL 替换它。
編輯1:将 bacula 升级到(手动创建包)5.2.13做包含对批量插入的支持(而不是 Debian wheezy/jessie 中打包的 5.2.6没有),并调整 MySQL 数据库以便在 tmpfs 中创建临时表,将上述属性释放时间从 56.5 小时缩短至 30 分钟。我猜在本地机器上用 PostgreSQL 替换它(与 bacula-sd 和 bacula-dir 相同)可能会改善这一点,但这对我们来说已经足够了。