Linux 5.10.0-13에서 Debian 11.3을 실행하는 NFSv4 서버와 클라이언트를 설정했습니다. 기본적으로 작동합니다. 즉, 올바른 권한이 있는 모든 파일을 볼 수 있으며 열고 수정하는 등의 작업을 할 수 있습니다. 그러나 파일을 열면 5초의 지연이 발생합니다.
서버는 다음과 같은 디렉터리를 내보냅니다 /etc/exports.
/path/to gss/krb5(rw,sync,fsid=0,crossmnt,no_subtree_check)
/path/to/NFS gss/krb5(rw,sync,no_subtree_check)
NFS4 내보내기는 다음 종류의 /etc/fstab항목을 사용하여 마운트됩니다.
server:/NFS /path/to/nfs nfs4 defaults,auto,sec=krb5,proto=tcp,port=2049,nolock 0 3
다음 데이터는 파일을 열었다 가 표시되자마자 emacs닫는 것을 의미합니다.emacs
분석해 strace보니 해당 openat()syscall이 5.1초 동안 상당히 안정적으로 걸리는 것으로 나타났습니다! openat(), stat(), ...NFS와 관련된 다른 syscall은 마이크로초 내에 실행됩니다. 이는 예를 들어 를 수행할 때 일관되게 나타나는 것으로 ls, 로컬 파일 시스템과 다르지 않은 느낌입니다. 다음은 syscall에 소요된 시간 앞에 문제의 파일과 관련된 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
Wireshark에서는 다음을 볼 수 있습니다.
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
NFS4ERR_STALE이 조건이 문제의 힌트인지 는 모르겠습니다 . RFC7530에 따르면 파일 시스템 개체가 제거되었음을 나타냅니다. 글쎄, 지연된 파일은 openat()확실히 삭제되지 않습니다. 그래서 그것이 무엇을 가리키는지 잘 모르겠습니다. 하지만 12시와 13시 사이에는 5.1초의 지연도 나타납니다.
나는 여기서 보는 내용을 잘 이해하지 못한다는 것을 인정해야 합니다. 그러나 다른 프로그램에서도 동일한 종류의 지연이 발생합니다. 즉, 이는 emacs. libreoffice다른 프로그램에서 파일에 액세스할 때까지 저장이 중단될 수도 있습니다.
일부 환경에서 문제가 있는 것을 어디선가 본 적이 있어서 krb5p로 줄 krb5였지만 아무런 변화가 없었습니다.
클라이언트와 서버가 모두 실행됩니다 gssproxy. 클라이언트에는 디버깅 항목이 표시되고 nfsidmap설정 후에 sysctl sunrpc.rpc_debug=0xFFFF는 시나리오에 대해 다음이 표시됩니다 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
이 로그를 정확히 해석하는 방법은 모르겠지만 5초 지연도 명확하게 표시되며 모든 RPC 호출이 100ms 이내에 처리되는 것처럼 보입니다.
무슨 일이 일어나고 있는지, 아니면 적어도 문제를 더 자세히 파악하는 방법에 대한 아이디어가 있습니까?
답변1
얼마 전에 두 번째 사이트에 대한 VPN이 중단되었을 때 문제를 해결했습니다. NFS 서버가 사용하는 Kerberos 슬레이브 서버에는 느린 VPN을 통해 다른 사이트를 가리키는 DNS 서버가 있었습니다. VPN이 그렇게 느리지 않고 예를 들어 로그온 중에 5초 지연이 표시되지 않았기 때문에 여전히 수수께끼입니다. 그러나 DNS를 로컬 슬레이브로 변경한 후 문제가 사라졌습니다.
그 사이에 새 서버를 출시했는데 문제 없이 실행되었습니다.