Kerberos化されたNFS4ではファイルを開くのに5秒かかる

Kerberos化されたNFS4ではファイルを開くのに5秒かかる

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

以下のデータは、ファイルを開いてemacsemacs表示されたらすぐに閉じることを指します。

分析してみると、対応するシステムコールは 5.1 秒とかなり安定しているstraceことがわかります。NFSに関連するその他のシステムコールはマイクロ秒単位で実行されます。これは、たとえば を実行するときに一貫して見られるもので、ローカル ファイル システムと違いは感じられません。以下は、問題のファイルに関連するシステムコールの抜粋で、システムコールに費やされた時間が先頭に追加されています。openat()openat(), stat(), ...ls

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 呼び出しが 100 ミリ秒以内に処理されているように見えます。

何が起こっているのか、あるいは少なくとも問題をさらに突き止めるにはどうすればよいのか、何かアイデアはありますか?

答え1

しばらく前に 2 番目のサイトへの VPN が故障したときに、この問題を解決しました。NFS サーバーが使用する Kerberos スレーブ サーバーの DNS サーバーは、他のサイト (つまり、低速の VPN 経由) を指していました。VPN はそれほど遅くなく、ログオン時に 5 秒の遅延は見られなかったため、まだ不可解ですが、DNS をローカル スレーブに変更した後、問題は解消しました。

その間に、新しいサーバーを展開し、問題なく稼働しました。

関連情報