Ich habe einen NFSv4-Server und einen Client eingerichtet, die beide Debian 11.3 unter Linux 5.10.0-13 ausführen. Grundsätzlich funktioniert es, d. h. ich sehe alle Dateien mit den richtigen Berechtigungen und kann sie öffnen, ändern usw. Das Öffnen einer Datei verursacht jedoch eine Verzögerung von 5 Sekunden.
Der Server exportiert Verzeichnisse wie folgt in /etc/exports:
/path/to gss/krb5(rw,sync,fsid=0,crossmnt,no_subtree_check)
/path/to/NFS gss/krb5(rw,sync,no_subtree_check)
Der NFS4-Export wird mit diesem Eintragstyp gemountet /etc/fstab:
server:/NFS /path/to/nfs nfs4 defaults,auto,sec=krb5,proto=tcp,port=2049,nolock 0 3
Die nachfolgenden Daten beziehen sich auf das Öffnen emacsund Schließen einer Datei emacs, sobald diese angezeigt wird.
Bei der Analyse stracesehe ich, dass der entsprechende openat()Systemaufruf ziemlich stabile 5,1 Sekunden dauert! Andere openat(), stat(), ...Systemaufrufe in Bezug auf NFS werden innerhalb von Mikrosekunden ausgeführt. Das ist das, was ich durchgängig sehe, wenn ich zB ausführe ls, was sich nicht anders anfühlt als das lokale Dateisystem. Dies ist ein Auszug von Systemaufrufen in Bezug auf die betreffende Datei, denen die im Systemaufruf verbrachte Zeit vorangestellt ist:
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
In Wireshark sehe ich Folgendes:
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
Ich weiß nicht, ob dieser NFS4ERR_STALEZustand ein Hinweis auf das Problem ist. Laut RFC7530 zeigt er an, dass das Dateisystemobjekt entfernt wurde. Nun, die Datei in der Verzögerung openat()wurde definitiv nicht gelöscht. Ich bin mir also nicht sicher, worauf sich das bezieht. Es zeigt jedoch auch die 5,1 Sekunden Verzögerung zwischen 12 und 13.
Ich muss zugeben, dass ich nicht ganz verstehe, was ich hier sehe. Allerdings sehe ich die gleiche Art von Verzögerungen auch bei anderen Programmen, d. h. das ist keine Eigenart von emacs. Das Speichern in libreofficekann sogar einfrieren, bis die Datei von einem anderen Programm aufgerufen wird.
Da ich irgendwo gesehen habe, dass es in manchen Umgebungen Probleme mit gibt krb5p, habe ich auf reduziert krb5, aber das hat nichts geändert.
Sowohl auf dem Client als auch auf dem Server wird ausgeführt gssproxy. Auf dem Client sehe ich Debugeinträge von nfsidmapund nach dem Festlegen sehe ich für das Szenario sysctl sunrpc.rpc_debug=0xFFFFFolgendes :emacs
[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
Ich habe keine Ahnung, wie ich dieses Protokoll genau interpretieren soll, aber es zeigt auch deutlich die 5-Sekunden-Verzögerung und es scheint mir, als würden alle RPC-Aufrufe innerhalb von 100 ms verarbeitet.
Irgendwelche Ideen, was los ist oder zumindest, wie man das Problem weiter eingrenzen kann?
Antwort1
Ich habe das Problem gelöst, als das VPN zu meiner zweiten Site vor einiger Zeit zusammenbrach. Der vom NFS-Server verwendete Kerberos-Slave-Server hatte seinen DNS-Server auf die andere Site gerichtet, d. h. über ein langsames VPN. Es ist immer noch rätselhaft, da das VPN nicht so langsam ist und ich z. B. beim Anmelden keine 5-Sekunden-Verzögerungen festgestellt habe, aber nachdem ich den DNS auf den lokalen Slave geändert hatte, verschwand das Problem.
Mittlerweile habe ich den neuen Server ausgerollt und dieser läuft ohne Probleme.