A execução do strace no outro processo filho do rsync mostrou que ele estava interrompido durante uma chamada rename (). Isso me levou a descobrir que é esse bug:
Eu trabalhei com isso definindo a opção noatime mount.
Servidor NFS: CentOS7.1 (kernel 3.10.0-229, nfs-utils 1.3.0)
Alguns clientes são Ubuntu Precise (12.04) usando o NFSv3 ... eles funcionam bem.
Os clientes problemáticos estão executando o CentOS7.1 usando o NFSv4.1 (ou NFSv4.0). A maioria deles tempo, as coisas funcionam bem. Mas, às vezes, escrever um arquivo incorrerá em um tempo limite de 15 segundos. Estes são pequenos arquivos (< 10KiB).
Após 15 segundos, a gravação é concluída e o arquivo tem o conteúdo correto.
O tempo mais notável é ao salvar arquivos com o vi. Acontece apenas cerca de 5% do tempo (mas porque é tão frustrante, parece que é mais frequente do que realmente é).
Hoje aconteceu ao executar o rsync em várias centenas de arquivos (2KiB - 5KiB cada). Consegui executar strace no processo de rsync e ver que isso está acontecendo em mais de 50% do tempo.
# sudo strace -ttt -T -p 14186
Process 14186 attached
1452694932.030892 select(9, [8], [], NULL, {55, 59875}) = 1 (in [8], left {44, 963900}) <10.096109>
1452694942.127262 read(8, "nfs:/storage on /space type nfs4 (rw,relatime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=0,timeo=14,retrans=2,sec=sys,clientaddr=10.12.32.4,local_lock=none,addr=10.12.32.31)
/storage 10.0.0.0/8(rw,async,no_root_squash,no_subtree_check,mp=/storage)
k# sudo strace -ttt -T -p 14186
Process 14186 attached
1452694932.030892 select(9, [8], [], NULL, {55, 59875}) = 1 (in [8], left {44, 963900}) <10.096109>
1452694942.127262 read(8, "nfs:/storage on /space type nfs4 (rw,relatime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=0,timeo=14,retrans=2,sec=sys,clientaddr=10.12.32.4,local_lock=none,addr=10.12.32.31)
/storage 10.0.0.0/8(rw,async,no_root_squash,no_subtree_check,mp=/storage)
k%pre%%pre%", 8184) = 8 <0.000038>
1452694942.127378 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {59, 997018}) <0.003029>
1452694942.130529 read(8, "%pre%%pre%k\t%pre%%pre%", 8184) = 8 <0.000040>
1452694942.130715 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {44, 963694}) <15.036348>
1452694957.167236 read(8, "%pre%%pre%k\n%pre%%pre%", 8184) = 8 <0.000071>
1452694957.167419 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {59, 996528}) <0.003572>
1452694957.171122 read(8, "%pre%%pre%k\v%pre%%pre%", 8184) = 8 <0.000112>
1452694957.171340 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {44, 964372}) <15.035715>
1452694972.207210 read(8, "%pre%%pre%k\f%pre%%pre%", 8184) = 8 <0.000026>
1452694972.207303 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {44, 960236}) <15.039908>
1452694987.247375 read(8, "%pre%%pre%k\r%pre%%pre%", 8184) = 8 <0.000111>
1452694987.247616 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {44, 960455}) <15.039628>
1452695002.287486 read(8, "%pre%%pre%k%pre%%pre%", 8184) = 8 <0.000100>
1452695002.287665 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {59, 996177}) <0.004000>
1452695002.291819 read(8, "%pre%%pre%k%pre%%pre%", 8184) = 8 <0.000089>
1452695002.292014 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {44, 964982}) <15.035132>
1452695017.327303 read(8, "%pre%%pre%k%pre%%pre%", 8184) = 8 <0.000082>
1452695017.327491 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {59, 995793}) <0.004300>
1452695017.331931 read(8, "%pre%%pre%k%pre%%pre%", 8184) = 8 <0.000052>
%pre%", 8184) = 8 <0.000038>
1452694942.127378 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {59, 997018}) <0.003029>
1452694942.130529 read(8, "%pre%%pre%k\t%pre%%pre%", 8184) = 8 <0.000040>
1452694942.130715 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {44, 963694}) <15.036348>
1452694957.167236 read(8, "%pre%%pre%k\n%pre%%pre%", 8184) = 8 <0.000071>
1452694957.167419 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {59, 996528}) <0.003572>
1452694957.171122 read(8, "%pre%%pre%k\v%pre%%pre%", 8184) = 8 <0.000112>
1452694957.171340 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {44, 964372}) <15.035715>
1452694972.207210 read(8, "%pre%%pre%k\f%pre%%pre%", 8184) = 8 <0.000026>
1452694972.207303 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {44, 960236}) <15.039908>
1452694987.247375 read(8, "%pre%%pre%k\r%pre%%pre%", 8184) = 8 <0.000111>
1452694987.247616 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {44, 960455}) <15.039628>
1452695002.287486 read(8, "%pre%%pre%k%pre%%pre%", 8184) = 8 <0.000100>
1452695002.287665 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {59, 996177}) <0.004000>
1452695002.291819 read(8, "%pre%%pre%k%pre%%pre%", 8184) = 8 <0.000089>
1452695002.292014 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {44, 964982}) <15.035132>
1452695017.327303 read(8, "%pre%%pre%k%pre%%pre%", 8184) = 8 <0.000082>
1452695017.327491 select(9, [8], [], NULL, {60, 0}) = 1 (in [8], left {59, 995793}) <0.004300>
1452695017.331931 read(8, "%pre%%pre%k%pre%%pre%", 8184) = 8 <0.000052>
Eu não vi mais ninguém perguntando sobre esse problema. Eu estou sozinho?
Editar:
Opções de montagem:
%pre%Conteúdo de / etc / exports:
%pre%A execução do strace no outro processo filho do rsync mostrou que ele estava interrompido durante uma chamada rename (). Isso me levou a descobrir que é esse bug:
Eu trabalhei com isso definindo a opção noatime mount.