Unexpected high latency

Unexpected high latency

[Benoit Gschwind]

Hello,

I did set up nfs client[1]/server[2] backed by raid6/btrfs filesystem,
and I get very noticeable latency, i.e. opening/closing files take 5
seconds. 
To access the issue, I did basic benchmark of the filesystem using
bonnie++2.00a and when I use it on the server without nfs in the middle
I get the following results:

Version  2.00       ------Sequential Output------ --Sequential Input- --Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Name:Size etc        /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
SERVER       63808M  200k  98  379m  64  183m  51 1146k  99  1.0g  84 533.8  62
Latency               162ms   38609us     494ms   25987us     452ms     204ms
Version  2.00       ------Sequential Create------ --------Random Create--------
SERVER              -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16 16384  29 +++++ +++ 16384  92 16384  66 +++++ +++ 16384  84
Latency              1106us     420us     824us     321us      25us    3788us
1.98,2.00,SERVER,1,1693984997,63808M,,8192,5,200,98,387908,64,187033,51,1146,99,1078676,84,533.8,62,16,,,,,3780,29,+++++,+++,16381,92,15276,66,+++++,+++,13370,84,162ms,38609us,494ms,25987us,452ms,204ms,1106us,420us,824us,321us,25us,3788us

In this benchmark, all seems good enoush, even if they are slow legacy disk (i.e. not SSD).

But When I put the nfs + network in the middle with following settings (cat /proc/mount):

X.X.X.X:/m0 /mnt/m0 nfs4 rw,nosuid,nodev,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=6000,retrans=2,sec=krb5i,clientaddr=X.X.X.X,fsc,local_lock=none,addr=X.X.X.X 0 0

I get the following result (from nfs client):

Version  2.00       ------Sequential Output------ --Sequential Input- --Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Name:Size etc        /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
CLIENT         126G  702k  96  111m  18 31.7m  11 1852k  98 47.1m  10 407.8  16
Latency             27010us   56044us   12422ms   33647us     506ms     260ms
Version  2.00       ------Sequential Create------ --------Random Create--------
CLIENT              -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16 16384  23 +++++ +++ 16384  16 16384   7 16384  32 16384  18
Latency             11543us   22772us    1871us    8949ms     840us    3654us
1.98,2.00,CLIENT,1,1694022898,126G,,8192,5,702,96,113319,18,32419,11,1852,98,48229,10,407.8,16,16,,,,,627,23,+++++,+++,2620,16,587,7,3147,32,2846,18,27010us,56044us,12422ms,33647us,506ms,260ms,11543us,22772us,1871us,8949ms,840us,3654us

In this benchmark I get top speed at 100 MB/s wich is expected because
I'm using 1Gb/s network link. But for the rewrite benchmark I get an
unexpected 30 MB/s and more over *12 seconds* of latency. I also get
the unexpected latency for the create bechmark where I jump from <1ms
to nearly *9 seconds*.

Did I my setup is wrong ? Does it expected ?


Thank you, best regards

[1] client kernel: Linux 5.10.0-23-amd64 #1 SMP Debian 5.10.179-1 (2023-05-12) x86_64 GNU/Linux
[2] server kernel: Linux 5.10.0-25-amd64 #1 SMP Debian 5.10.191-1 (2023-08-16) x86_64 GNU/Linux

--
Benoit Gschwind