Eu configurei um servidor NFSv4 e um cliente rodando Debian 11.3 no Linux 5.10.0-13. Basicamente funciona, ou seja, vejo todos os arquivos com permissões corretas e posso abrir, modificar, etc. No entanto, abrir um arquivo causa um atraso de 5 segundos.
O servidor exporta diretórios como este em /etc/exports:
/path/to gss/krb5(rw,sync,fsid=0,crossmnt,no_subtree_check)
/path/to/NFS gss/krb5(rw,sync,no_subtree_check)
A exportação NFS4 é montada usando este tipo de /etc/fstabentrada:
server:/NFS /path/to/nfs nfs4 defaults,auto,sec=krb5,proto=tcp,port=2049,nolock 0 3
Os dados a seguir referem-se à abertura emacse fechamento de um arquivo emacsassim que ele é exibido.
Analisando strace, vejo que o openat()syscall correspondente leva 5,1 segundos bastante estáveis! Outras openat(), stat(), ...syscalls pertencentes ao NFS são executadas em microssegundos. Isso é o que vejo consistentemente ao fazer, por exemplo ls, o que não parece diferente do sistema de arquivos local. Este é um trecho de syscalls relacionadas ao arquivo em questão, precedido pelo tempo gasto na syscall:
0.000014 openat(AT_FDCWD, "/path/to/nfs/file", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = -1 ENOTDIR (Ist kein Verzeichnis)
0.000005 readlinkat(AT_FDCWD, "/path/to/nfs/file", 0x7fff202f6880, 1024) = -1 EINVAL (Das Argument ist ungültig)
0.000006 openat(AT_FDCWD, "/path/to/nfs/file", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 14
0.000005 readlinkat(AT_FDCWD, "/path/to/nfs/file", 0x7fff202f64d0, 1024) = -1 EINVAL (Das Argument ist ungültig)
0.000005 openat(AT_FDCWD, "/path/to/nfs/file", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 14
5.108682 openat(AT_FDCWD, "/path/to/nfs/file", O_RDONLY|O_CLOEXEC) = 14
0.000006 faccessat(AT_FDCWD, "/path/to/nfs/file", W_OK) = 0
0.000005 stat("/path/to/nfs/file", {st_mode=S_IFREG|0640, st_size=2192, ...}) = 0
0.000007 faccessat(AT_FDCWD, "/path/to/nfs/file,v", F_OK) = -1 ENOENT (Datei oder Verzeichnis nicht gefunden)
0.000009 openat(AT_FDCWD, "/path/to/nfs/file", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = -1 ENOTDIR (Ist kein Verzeichnis)
0.000008 openat(AT_FDCWD, "/path/to/nfs/file", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = -1 ENOTDIR (Ist kein Verzeichnis)
0.000008 openat(AT_FDCWD, "/path/to/nfs/file", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = -1 ENOTDIR (Ist kein Verzeichnis)
0.000008 openat(AT_FDCWD, "/path/to/nfs/file", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = -1 ENOTDIR (Ist kein Verzeichnis)
0.000008 openat(AT_FDCWD, "/path/to/nfs/file", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = -1 ENOTDIR (Ist kein Verzeichnis)
0.000012 stat("/path/to/nfs/file", {st_mode=S_IFREG|0640, st_size=2192, ...}) = 0
0.000015 write(14, "/path/to/nfs/file"..., 90) = 90
No wireshark vejo o seguinte:
No. Time Source Destination Protocol Length Info
7 0.623097 client.ip server.ip NFS 276 V4 Call (Reply In 8) GETATTR FH: 0xecf8d891
8 0.624231 server.ip client.ip NFS 376 V4 Reply (Call In 7) GETATTR
9 0.624239 client.ip server.ip TCP 72 951 → 2049 [ACK] Seq=601 Ack=917 Win=4176 Len=0 TSval=1071244404 TSecr=3950562910
10 0.624696 client.ip server.ip NFS 344 V4 Call (Reply In 11) OPEN DH: 0xecf8d891/
11 0.625669 server.ip client.ip NFS 452 V4 Reply (Call In 10) OPEN StateID: 0xb42f
12 0.625693 client.ip server.ip TCP 72 951 → 2049 [ACK] Seq=873 Ack=1297 Win=4176 Len=0 TSval=1071244405 TSecr=3950562911
13 5.742166 client.ip server.ip NFS 340 V4 Call (Reply In 14) CLOSE StateID: 0xb42f
14 5.743331 server.ip client.ip NFS 232 V4 Reply (Call In 13) SEQUENCE | PUTFH Status: NFS4ERR_STALE
15 5.743359 client.ip server.ip TCP 72 951 → 2049 [ACK] Seq=1141 Ack=1457 Win=4176 Len=0 TSval=1071249523 TSecr=3950568029
Não sei se esta NFS4ERR_STALEcondição é uma dica para o problema. De acordo com o RFC7530 indica que o objeto do sistema de arquivos foi removido. Bem, o arquivo atrasado openat()definitivamente não foi excluído. Então, não tenho certeza a que se refere. No entanto, também mostra o atraso de 5,1 segundos entre 12 e 13.
Devo admitir que não entendo muito bem o que vejo aqui. No entanto, vejo o mesmo tipo de atraso em outros programas, ou seja, isso não é uma peculiaridade do emacs. Salvar libreofficepode até congelar até que o arquivo seja acessado por outro programa.
Como vi em algum lugar que há problemas krb5pem alguns ambientes, reduzi para krb5, mas isso não mudou nada.
Tanto o cliente quanto o servidor são executados gssproxy. No cliente, vejo entradas de depuração nfsidmape, após a configuração, sysctl sunrpc.rpc_debug=0xFFFFvejo o seguinte para o emacscenário:
[423544.865600] RPC: gss_get_mic_v2
[423544.865628] RPC: xs_tcp_send_request(200) = 0
[423544.867049] RPC: xs_data_ready...
[423544.867309] RPC: gss_verify_mic_v2
[423545.373665] RPC: gss_get_mic_v2
[423545.373691] RPC: xs_tcp_send_request(200) = 0
[423545.374692] RPC: xs_data_ready...
[423545.374748] RPC: gss_verify_mic_v2
[423545.375009] RPC: gss_get_mic_v2
[423545.375025] RPC: xs_tcp_send_request(268) = 0
[423545.375909] RPC: xs_data_ready...
[423545.375957] RPC: gss_verify_mic_v2
[423550.467227] RPC: gss_get_mic_v2
[423550.467307] RPC: xs_tcp_send_request(216) = 0
[423550.468395] RPC: xs_data_ready...
[423550.468513] RPC: gss_verify_mic_v2
[423550.468621] RPC: gss_get_mic_v2
[423550.468646] RPC: gss_get_mic_v2
[423550.468689] RPC: xs_tcp_send_request(264) = 0
[423550.469403] RPC: xs_data_ready...
[423550.469541] RPC: gss_verify_mic_v2
[423550.469564] RPC: gss_verify_mic_v2
[423550.472794] RPC: gss_get_mic_v2
[423550.472849] RPC: xs_tcp_send_request(208) = 0
[423550.473758] RPC: xs_data_ready...
[423550.473903] RPC: gss_verify_mic_v2
[423550.474234] RPC: gss_get_mic_v2
[423550.474290] RPC: xs_tcp_send_request(200) = 0
[423550.475147] RPC: xs_data_ready...
[423550.475257] RPC: gss_verify_mic_v2
Não tenho ideia de como interpretar exatamente esse log, mas ele também mostra claramente o atraso de 5 segundos e parece-me que todas as chamadas RPC são processadas em 100 ms.
Alguma idéia do que está acontecendo, ou pelo menos como definir melhor o problema?
Responder1
Resolvi o problema quando a VPN do meu segundo site quebrou há algum tempo. O servidor escravo Kerberos usado pelo servidor NFS tinha seu servidor DNS apontando para o outro site, ou seja, através de uma VPN lenta. Ainda é intrigante, pois a VPN não é tão lenta e não vi atrasos de 5 segundos, por exemplo, durante o logon, mas depois de alterar o DNS para o escravo local, o problema desapareceu.
Enquanto isso, implementei o novo servidor e ele funciona sem problemas.