我正在使用 rsync 将数据备份到外部 USB3 磁盘(使用 dmcrypt/luks 加密),问题是传输挂在文件上,持续时间从几秒到几分钟不等,然后用没有错误或问题。在同一个 rsync“会话”期间,多个文件(显然是随机的)会发生这种情况,导致速度非常慢,尽管某些文件传输速度可以达到 100MB/s。
我运行的是 Debian Jessie 8.5,rsync
版本为 3.1.1,源文件系统使用 btrfs(版本 3.17)格式化,外部磁盘使用crypsetup
1.6.6 加密。
加密分区是用 btrfs 格式化的,但是在注意到这个问题并发现这显然不相关之后ubuntu错误,我将分区重新格式化为 ext4,虽然这似乎使问题不再那么频繁,但问题仍然存在。
在这些“挂起”期间,不会检测到奇怪的 CPU 或内存使用情况,但磁盘读取和写入会降至零。这是iotop
冻结期间的输出:
Total DISK READ : 0.00 B/s | Total DISK WRITE : 0.00 B/s
Actual DISK READ: 0.00 B/s | Actual DISK WRITE: 0.00 B/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
21879 be/4 root 0.00 B/s 0.00 B/s 0.00 % 99.00 % [kworker/6:1]
1085 be/4 root 0.00 B/s 0.00 B/s 0.00 % 99.00 % [kworker/3:2]
31994 be/4 root 0.00 B/s 0.00 B/s 0.00 % 99.00 % [kworker/4:3]
1 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % init
2 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % [kthreadd]
3 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % [ksoftirqd/0]
5 be/0 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % [kworker/0:0H]
7 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % [rcu_sched]
kworker 进程总是在变化,但保持 99% 的 IO。
这是iostat
其中一次冻结期间的输出(外部磁盘是 sdg):
avg-cpu: %user %nice %system %iowait %steal %idle
0.00 0.00 0.25 99.75 0.00 0.00
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdc 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdd 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sde 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdf 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
md0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
md1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdg 0.00 0.00 0.00 141.00 0.00 16920.00 240.00 135.94 868.20 0.00 868.20 7.09 100.00
dm-0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 20343.88 0.00 0.00 0.00 0.00 100.00
我也ps aux | awk '$8 ~ /D/ { print $0 }'
戴着手表跑步,在冻结期间是这样的:
root 1080 0.1 0.0 0 0 ? D 16:23 0:00 [kworker/0:0]
root 5851 0.0 0.0 0 0 ? D 01:41 0:02 [btrfs-transacti]
root 17455 4.4 0.0 105028 5192 pts/3 D+ 14:10 6:11 rsync -avr --stats --progress --inplace --delete /data/ /media/BKP-DISK/
root 24219 0.1 0.0 0 0 ? D 15:16 0:08 [kworker/5:0]
root 31892 0.2 0.0 0 0 ? D Aug02 2:08 [usb-storage]
root 31956 0.1 0.0 0 0 ? D 15:41 0:04 [kworker/7:0]
root 31994 0.0 0.0 0 0 ? D 15:42 0:01 [kworker/4:3]
root 32100 0.1 0.0 0 0 ? D 15:52 0:03 [kworker/u16:2]
当传输正常运行时是这样的:
root 17453 4.4 0.1 105020 33304 pts/3 D+ 14:10 6:32 rsync -avr --stats --progress --inplace --delete /data/ /media/BKP-DISK/
我没有想法和专业知识,所以我需要帮助来进一步解决这个问题。
编辑
@derobert
我在 USB2 端口中进行了测试,但问题仍然出现(在strace
日志中发现了 11 秒的间隙,然后停止了测试)。
最后一次 dmesg 回溯是当外部磁盘仍使用 btrfs 进行格式化时,这是输出(还有更多,但都相同):
INFO: task kworker/u16:21:12881 blocked for more than 120 seconds.
Not tainted 3.16.0-4-amd64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/u16:21 D ffff8807f72bfa48 0 12881 2 0x00000000
Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
ffff8807f72bf5f0 0000000000000046 0000000000012f00 ffff88022dcfbfd8
0000000000012f00 ffff8807f72bf5f0 ffff880103b92c00 ffff88026de241f0
ffff88026de241f0 0000000000000001 0000000000000000 ffff88010c4662d8
Call Trace:
[<ffffffffa02843ef>] ? wait_current_trans.isra.20+0x9f/0xf0 [btrfs]
[<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0
[<ffffffffa0285948>] ? start_transaction+0x298/0x570 [btrfs]
[<ffffffffa028da90>] ? btrfs_finish_ordered_io+0x250/0x5c0 [btrfs]
[<ffffffffa02b2f25>] ? normal_work_helper+0xb5/0x290 [btrfs]
[<ffffffff810817c2>] ? process_one_work+0x172/0x420
[<ffffffff81081e53>] ? worker_thread+0x113/0x4f0
[<ffffffff81510d61>] ? __schedule+0x2b1/0x700
[<ffffffff81081d40>] ? rescuer_thread+0x2d0/0x2d0
[<ffffffff8108809d>] ? kthread+0xbd/0xe0
[<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180
[<ffffffff81514958>] ? ret_from_fork+0x58/0x90
[<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180
@roaima
因为我运行 rsync ,所以--progress
我可以看到传输的当前状态,这就是我第一次发现问题的方式。例如,对于 1GB 的文件,它可能会挂在 100MB 处,并且我会看到所有传输信息(传输的字节数、速度等)停止更新(这是 iotop 将显示磁盘读取和写入为 0 的位置),并且当info 将再次开始更新 iotop 将显示正常的读取和写入值。
@activesheetd
这是 strace 日志的一部分(我添加了时间戳选项):
29253 03:47:18 <... select resumed> ) = 1 (in [0], left {59, 999999})
29253 03:47:18 read(0, "\355\1H\347?~\0\255", 8) = 8
29251 03:47:18 select(6, [5], [4], [5], {60, 0} <unfinished ...>
29253 03:47:18 write(1, "\235\356\374|\f\230\310u\330{\7\24\3169<\255\213>\347m\335kX\350\234\253\1\226M\6#\341"..., 262144) = 262144
29253 03:47:31 select(1, [0], [], [0], {60, 0}) = 1 (in [0], left {59, 999997})
29253 03:47:31 read(0, <unfinished ...>
29251 03:47:31 <... select resumed> ) = 1 (out [4], left {47, 597230})
在第 4 行和第 5 行之间,我们可以看到有 13 秒的间隙,这对应于挂起,然后又恢复了。
@Fiximan
日志选项没有为我提供有关此问题的更多信息。由于冻结是在日志文件传输过程中发生的,所以就像什么都没有发生一样(甚至 strace 日志也显示时间戳间隙)。
答案1
尝试以下操作来了解发生了什么:
执行 strace 以分析系统调用及其响应:
sudo strace -o strace-output.log -f <your rsync command here>
然后分析 strace-output.log 日志文件,查看“man strace”了解更多详细信息或与我们分享该日志文件。
运行 rsync 时执行 lsof,它会显示卡在哪个文件上
sudo lsof -p <rsync PID> | grep data
答案2
经过大量测试但没有结果后,我决定遵循 @derobert 的建议,并将内核和 btrfs-progs 升级到 jessie-backports 的最新版本。
看起来问题已经解决,因为使用新内核 ( 4.6.4-1~bpo8+1
),我在 rsync 传输期间无法检测到任何冻结。 btrfs 向后移植版本现在是4.6.1
.