Estou usando o rsync para fazer backup de meus dados em um disco USB3 externo (criptografado com dmcrypt / luks) e o problema é que a transferência trava em um arquivo, por um período de tempo que pode ir de segundos a minutos, e então recomeça sem erros ou problemas. Isso acontece com vários arquivos (aparentemente aleatórios) durante a mesma "sessão" de rsync, tornando-a muito lenta, mesmo que algumas transferências de arquivos possam atingir velocidades de 100MB / s.
Estou executando o Debian Jessie 8.5, rsync está na versão 3.1.1, o sistema de arquivos de origem está formatado com o btrfs (versão 3.17) e o disco externo foi criptografado com crypsetup 1.6.6.
A partição criptografada foi formatada com o btrfs, mas depois de perceber esse problema e encontrar esse bug do ubuntu aparentemente não relacionado , eu reformatei a partição para ext4 e, embora pareça tornar o problema menos frequente, o problema ainda estava lá.
Durante esses "travamentos" não é detectado nenhum uso estranho da CPU ou da memória, mas as leituras e gravações do disco caem para zero. Esta é uma saída de iotop durante um congelamento:
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]
Os processos do kworker estão sempre mudando, mas mantenham os 99% de IO.
Esta é uma saída iostat durante um dos congelamentos (o disco externo é 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
Eu também corri ps aux | awk '$8 ~ /D/ { print $0 }' com o relógio e durante o congelamento é isso:
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]
Quando a transferência está em andamento, é isso:
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/
Estou sem ideias e know-how, por isso preciso de ajuda para resolver isso ainda mais.
Editar
@derobert
Eu testei em uma porta USB2, mas o problema continua a aparecer (encontrado um intervalo de 11 segundos no log strace e, em seguida, parou o teste).
O último dmesg backtrace foi quando o disco externo ainda estava formatado com o btrfs e aqui está a saída (havia mais, mas todos iguais):
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
Como executo o rsync com --progress , posso ver o estado atual da transferência e foi assim que percebi o problema. Por exemplo, para um arquivo de 1 GB, ele poderia travar a 100 MB e veria todas as informações de transferência (bytes transferidos, velocidade, etc) parar de atualizar (é onde o iotop mostraria as leituras de disco e gravaria em 0) e quando info iria começar a atualizar novamente iotop iria mostrar valores normais de leitura e escrita.
@activesheetd
Aqui está uma seção do log strace (eu adicionei a opção timestamp):
29253 03:47:18 <... select resumed> ) = 1 (in [0], left {59, 999999})
29253 03:47:18 read(0, "5H7?~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]
5", 8) = 8
29251 03:47:18 select(6, [5], [4], [5], {60, 0} <unfinished ...>
29253 03:47:18 write(1, "564|\f00u0{69<53>7m5kX0436M#1"..., 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})
Entre as linhas 4 e 5, podemos ver uma lacuna de 13 segundos, que correspondia a um travamento e, em seguida, foi retomada.
@Fiximan
A opção de log não me fornece mais informações sobre esse problema. Como o congelamento está no meio de uma transferência de arquivo para os logs, é como se nada tivesse acontecido (até mesmo os logs de strace mostram intervalos de timestamp).
Depois de muitos testes sem resultados, decidi seguir o conselho @derobert e atualizei o kernel e o btrfs-progs para o mais recente em jessie-backports.
Parece que o problema foi corrigido, pois com o novo kernel ( 4.6.4-1~bpo8+1 ) não consigo detectar nenhum congelamento durante a transferência de rsync.
A versão backport do btrfs agora é 4.6.1 .
Tente o seguinte para entender o que está acontecendo:
Execute strace para analisar as chamadas do sistema e suas respostas:
sudo strace -o strace-output.log -f <your rsync command here>
Em seguida, analize o arquivo de log strace-output.log, olhe para "man strace" para mais detalhes ou compartilhe o arquivo de log conosco.
Execute o lsof enquanto executa o rsync, ele mostrará em qual arquivo ele fica preso
sudo lsof -p <rsync PID> | grep data