I've installed an NFS server on Ubuntu 20.04 and a FreeIPA Ubuntu 20.04 client with the users home directories served by the NFS server. Performance is extremely slow when accessing files. When I strace the process with time spent in syscalls, I find that openat can take over 1 second at times for the NFS files! (see below). Needless to say file access on the server displays no such issue. openat is the only slow operation.
I've attached a histogram of the times spent in openat (I've trimmed the top bin so the tail can be seen). There are over 800 openat calls that complete in under 10mSec, but it's the tail that makes the difference in the total time, and there are a lot of calls that take over 100mSec which is unreasonable.
I suspect it may have to do with the Kerberos authorisation or something of the kind, but I don't know how to investigate the issue.
Options in /etc/exports:
/home *(rw,sec=krb5:krb5i:krb5p,async,no_subtree_check)
Mount on client:
server:/home/... on /home/... type nfs4 (rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=krb5,clientaddr=xx.xx.xx.x1,local_lock=none,addr=xx.xx.xx.x2)
Any help or clue would be appreciated,
Yuval.
0.000064 : stat("/home/.../lib/python3.8/site-packages/pandas/core", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
0.000040 : stat("/home/.../lib/python3.8/site-packages/pandas/core/nanops.py", {st_mode=S_IFREG|0664, st_size=50002, ...}) = 0
0.000095 : stat("/home/.../lib/python3.8/site-packages/pandas/core/nanops.py", {st_mode=S_IFREG|0664, st_size=50002, ...}) = 0
0.664737 : openat(AT_FDCWD, "/home/.../lib/python3.8/site-packages/pandas/core/__pycache__/nanops.cpython-38.pyc", O_RDONLY|O_CLOEXEC) = 6
0.000122 : fstat(6, {st_mode=S_IFREG|0664, st_size=36431, ...}) = 0
0.000116 : ioctl(6, TCGETS, 0x7ffed1278d60) = -1 ENOTTY (Inappropriate ioctl for device)
0.000049 : lseek(6, 0, SEEK_CUR) = 0
0.000024 : lseek(6, 0, SEEK_CUR) = 0
0.000028 : fstat(6, {st_mode=S_IFREG|0664, st_size=36431, ...}) = 0
0.000052 : read(6, "U\r\r\n\0\0\0\0\216t\362aR\303\0\0\343\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 36432) = 36431
0.000024 : read(6, "", 1) = 0
0.000438 : close(6) = 0
0.000083 : mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f23fcbaf000
0.000100 : stat("/home/.../bin", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
0.000120 : stat("/usr/lib/python3.8", {st_mode=S_IFDIR|0755, st_size=20480, ...}) = 0
0.000122 : stat("/usr/lib/python3.8/lib-dynload", {st_mode=S_IFDIR|0755, st_size=12288, ...}) = 0
0.000037 : getcwd("/home/yuval/src/themis", 1024) = 23
0.000046 : stat("/home/yuval/src/themis", {st_mode=S_IFDIR|0775, st_size=130, ...}) = 0
0.000037 : stat("/home/.../lib/python3.8/site-packages", {st_mode=S_IFDIR|0775, st_size=12288, ...}) = 0
0.000051 : stat("/home/.../lib/python3.8/site-packages/pandas/core/array_algos", {st_mode=S_IFDIR|0775, st_size=163, ...}) = 0
0.000041 : stat("/home/.../lib/python3.8/site-packages/pandas/core/array_algos/masked_reductions.py", {st_mode=S_IFREG|0664, st_size=3721, ...}) = 0
0.000085 : stat("/home/.../lib/python3.8/site-packages/pandas/core/array_algos/masked_reductions.py", {st_mode=S_IFREG|0664, st_size=3721, ...}) = 0
0.411113 : openat(AT_FDCWD, "/home/.../lib/python3.8/site-packages/pandas/core/array_algos/__pycache__/masked_reductions.cpython-38.pyc", O_RDONLY|O_CLOEXEC) = 6
0.000053 : fstat(6, {st_mode=S_IFREG|0664, st_size=3329, ...}) = 0
0.000027 : ioctl(6, TCGETS, 0x7ffed1278d60) = -1 ENOTTY (Inappropriate ioctl for device)
0.000043 : lseek(6, 0, SEEK_CUR) = 0
0.000037 : lseek(6, 0, SEEK_CUR) = 0
0.000025 : fstat(6, {st_mode=S_IFREG|0664, st_size=3329, ...}) = 0
0.000032 : read(6, "U\r\r\n\0\0\0\0\216t\362a\211\16\0\0\343\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 3330) = 3329
0.000025 : read(6, "", 1) = 0
0.000438 : close(6) = 0
0.000105 : stat("/home/.../lib/python3.8/site-packages/pandas/core/arrays", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
0.000102 : stat("/home/.../lib/python3.8/site-packages/pandas/core/arrays/categorical.py", {st_mode=S_IFREG|0664, st_size=94502, ...}) = 0
0.000101 : stat("/home/.../lib/python3.8/site-packages/pandas/core/arrays/categorical.py", {st_mode=S_IFREG|0664, st_size=94502, ...}) = 0
0.413090 : openat(AT_FDCWD, "/home/.../lib/python3.8/site-packages/pandas/core/arrays/__pycache__/categorical.cpython-38.pyc", O_RDONLY|O_CLOEXEC) = 6
0.000063 : fstat(6, {st_mode=S_IFREG|0664, st_size=77947, ...}) = 0
0.000041 : ioctl(6, TCGETS, 0x7ffed127b180) = -1 ENOTTY (Inappropriate ioctl for device)
0.000037 : lseek(6, 0, SEEK_CUR) = 0
0.000023 : lseek(6, 0, SEEK_CUR) = 0
0.000031 : fstat(6, {st_mode=S_IFREG|0664, st_size=77947, ...}) = 0
0.000085 : read(6, "U\r\r\n\0\0\0\0\216t\362a&q\1\0\343\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 77948) = 77947
