I have strange behaviour with page cache in nfs. I hope someone can help me.
The environment:
Linux RedHat 8.6, 2 vCPU (VMWare VM) and 8 GB RAM
One nfs filesystem mounted with sync and without sync
1x.1x.2xx.1xx:/test_fs on /mnt/test_fs_with_sync type nfs (rw,relatime,sync,vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=1x.1x.2xx.1xx,mountvers=3,mountport=2050,mountproto=udp,local_lock=none,addr=1x.1x.2xx.1xx)
1x.1x.2xx.1xx:/test_fs on /mnt/test_fs_without_sync type nfs (rw,relatime,vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=1x.1x.2xx.1xx,mountvers=3,mountport=2050,mountproto=udp,local_lock=none,addr=1x.1x.2xx.1xx:)
The tests:
1.- dd in /mnt/test_fs_without_sync
dd if=/dev/zero of=test.out bs=1M count=5000
5000+0 records in
5000+0 records out
5242880000 bytes (5.2 GB, 4.9 GiB) copied, 21.4122 s, 245 MB/s
2.- dd in /mnt/test_fs_with_sync
dd if=/dev/zero of=test.out bs=1M count=5000
5000+0 records in
5000+0 records out
5242880000 bytes (5.2 GB, 4.9 GiB) copied, 35.6462 s, 147 MB/s
3.- dd in /mnt/test_fs_with_sync with oflag=direct
dd if=/dev/zero of=test.out bs=1M oflag=direct count=5000
5000+0 records in
5000+0 records out
5242880000 bytes (5.2 GB, 4.9 GiB) copied, 34.6491 s, 151 MB/s
The results:
1.- dd in /mnt/test_fs_without_sync
- CPU iowait is high:
dstat
----total-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read writ| recv send| in out | int csw
4 8 82 6 0| 15M 8193B| 14k 1756B| 0 0 |2635 2961
1 0 97 0 0| 0 32k| 16k 2058B| 0 0 |1826 1791
2 1 97 0 0| 0 32k| 16k 2360B| 0 0 |2004 1744
2 21 76 0 0| 0 0 | 61k 54M| 0 0 |4038 2108
5 23 39 32 0| 0 52k| 231k 305M| 0 0 | 12k 5034
2 12 44 40 0| 0 8192B| 121k 212M| 0 0 |7333 4155
3 11 42 40 0| 0 1408k| 82k 201M| 0 0 |6586 4541
3 11 44 40 0| 0 48k| 125k 220M| 0 0 |7642 4233
2 12 43 40 0| 0 0 | 83k 195M| 0 0 |6737 4742
3 11 45 39 0| 0 196k| 110k 214M| 0 49.0 |8073 3887
4 12 44 40 0| 0 8199B| 130k 215M| 0 0 |8363 4301
3 12 43 40 0| 0 40k| 98k 208M| 0 0 |6674 3943
3 11 44 41 0| 0 16k| 140k 216M| 0 0 |8274 4752
4 14 41 41 0| 0 40k| 136k 208M| 0 0 |8122 4681
4 9 44 39 0| 0 0 | 147k 216M| 0 0 |8062 4560
3 8 43 41 0| 0 0 | 135k 214M| 0 0 |7851 4235
3 10 44 40 0| 0 76k| 144k 207M| 0 0 |8259 4688
3 10 44 40 0| 0 572k| 137k 214M| 0 0 |8251 4606
2 10 44 40 0| 0 52k| 127k 216M| 0 0 |7998 4910
3 10 44 41 0| 0 8192B| 131k 205M| 0 0 |7819 4291
3 9 44 40 0| 0 44k| 137k 209M| 0 0 |7940 4406
3 10 43 41 0| 0 0 | 138k 198M| 0 0 |7948 4334
3 10 44 40 0| 0 52k| 151k 211M| 0 0 |8489 4631
4 13 41 40 0| 0 40k| 344k 465M| 0 0 | 16k 8725
4 9 44 44 0| 0 0 | 261k 387M| 0 0 | 12k 7450
2 2 84 13 0|4096B 24k| 56k 25M| 0 0 |2940 3512
1 0 98 0 0| 0 12k| 15k 1952B| 0 0 |1756 1678
2 1 96 0 0| 0 88k| 14k 1936B| 0 0 |2064 2033
1 0 98 0 0| 0 0 | 16k 2132B| 0 0 |1969 1673
- Page cache is in use:
while true; do echo "###" ;date ; egrep "^Cached:|^Dirty:|^Writeback:|file" /proc/meminfo; sleep 1; done
Thu Sep 8 17:09:21 CEST 2022
Cached: 2892308 kB
Active(file): 1011076 kB
Inactive(file): 1999592 kB
Dirty: 304292 kB
Writeback: 628800 kB
- High latency:
nfsiostat 1 100
read: ops/s kB/s kB/op retrans avg RTT (ms) avg exe (ms) avg queue (ms) errors
0.000 0.000 0.000 0 (0.0%) 0.000 0.000 0.000 0 (0.0%)
write: ops/s kB/s kB/op retrans avg RTT (ms) avg exe (ms) avg queue (ms) errors
208.000 213050.500 1024.281 0 (0.0%) 631.212 1494.486 863.192 0 (0.0%)
2.- dd in /mnt/test_fs_with_sync and without oflag=direct
- CPU iowait is high:
dstat
----total-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read writ| recv send| in out | int csw
1 1 97 0 0| 0 0 | 18k 1594B| 0 0 |1979 1764
3 0 96 0 0| 0 100k| 14k 1393B| 0 0 |2145 2044
2 1 98 0 0| 0 0 | 16k 314B| 0 0 |1732 1538
1 5 54 39 0| 0 1468k| 81k 70M| 0 0 |6218 6808
4 8 45 44 0| 0 0 | 136k 122M| 0 0 |9447 11k
3 7 46 44 0| 0 556k| 101k 94M| 0 72.0 |8085 9162
4 9 43 43 0| 48k 92k| 121k 115M| 0 0 |8671 9485
2 7 46 43 0| 0 0 | 109k 95M| 0 0 |7083 6576
3 10 44 44 0| 0 56k| 127k 121M| 0 0 |8838 10k
3 10 45 42 0| 0 0 | 138k 127M| 0 0 |8393 7446
3 10 44 41 0| 0 36k| 142k 136M| 0 0 |9320 10k
3 10 44 43 0| 0 36k| 131k 135M| 0 0 |9038 10k
3 11 44 41 0| 0 0 | 139k 138M| 0 0 |9433 11k
2 11 44 43 0| 0 12k| 152k 141M| 0 0 | 11k 13k
4 10 45 41 0| 0 12k| 148k 140M| 0 0 |9918 10k
3 9 44 41 0| 0 48k| 154k 139M| 0 0 | 10k 11k
5 10 44 41 0| 0 8199B| 155k 139M| 0 0 | 10k 11k
19 11 34 36 0| 584k 24k| 173k 130M|15.0 0 |9708 8790
3 9 44 42 0| 0 0 | 158k 142M| 0 0 | 11k 12k
7 11 41 41 0| 100k 44k| 157k 140M| 0 0 |9845 9785
2 10 44 41 0| 0 88k| 153k 138M| 0 0 |9506 8770
8 9 42 42 0| 156k 556k| 138k 134M| 0 0 |8478 8707
2 10 44 43 0| 0 168k| 137k 136M| 0 0 |9078 10k
3 11 44 43 0| 0 0 | 151k 140M| 0 0 | 10k 12k
3 8 44 42 0| 0 28k| 143k 136M| 0 0 | 10k 12k
2 9 44 44 0| 0 8194B| 145k 135M| 0 0 |9270 11k
3 8 45 43 0|4096B 76k| 143k 134M| 0 0 |9325 11k
15 9 38 39 0|8192B 72k| 160k 137M| 0 0 | 10k 11k
3 8 45 42 0| 0 0 | 159k 142M| 0 0 | 10k 10k
7 9 41 43 0| 0 60k| 160k 138M| 0 0 | 10k 12k
3 8 46 42 0| 0 0 | 157k 144M| 0 0 |8960 7677
4 8 47 43 0| 0 0 | 141k 135M| 0 0 |8406 7522
2 9 45 44 0| 0 44k| 163k 140M| 0 0 | 10k 12k
3 9 45 43 0| 0 0 | 134k 138M| 0 0 |9061 11k
2 9 45 41 0| 0 20k| 152k 144M| 0 0 | 11k 13k
3 10 45 43 0| 0 272k| 144k 134M| 0 0 | 10k 12k
4 8 44 43 0| 0 600k| 141k 137M| 0 0 |9786 12k
3 10 45 43 0| 0 0 | 161k 142M| 0 0 | 11k 13k
3 9 44 42 0| 0 0 | 148k 138M| 0 0 | 10k 11k
5 9 44 43 0| 0 0 | 151k 134M| 0 0 |9106 9861
2 9 50 37 0|4093B 80k| 127k 123M| 0 0 |8743 10k
2 1 97 0 0| 0 8198B| 15k 1683B| 0 0 |1989 1689
2 1 98 0 0| 0 8193B| 16k 2038B| 0 0 |2132 1797
2 1 97 0 0| 0 56k| 15k 1888B| 0 0 |2138 1925
1 0 98 0 0| 0 0 | 15k 2254B| 0 0 |1825 1679
- Page cache is not in use:
while true; do echo "###" ;date ; egrep "^Cached:|^Dirty:|^Writeback:|file" /proc/meminfo; sleep 1; done
Thu Sep 8 17:20:24 CEST 2022
Cached: 3340720 kB
Active(file): 995888 kB
Inactive(file): 2470764 kB
Dirty: 20 kB
Writeback: 1044 kB
- Low latency:
nfsiostat 1 100
read: ops/s kB/s kB/op retrans avg RTT (ms) avg exe (ms) avg queue (ms) errors
0.000 0.000 0.000 0 (0.0%) 0.000 0.000 0.000 0 (0.0%)
write: ops/s kB/s kB/op retrans avg RTT (ms) avg exe (ms) avg queue (ms) errors
142.000 145447.938 1024.281 0 (0.0%) 6.338 6.359 0.014 0 (0.0%)
3.- dd in /mnt/test_fs_with_sync and with oflag=direct
- CPU iowait is low:
dstat
----total-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read writ| recv send| in out | int csw
2 1 98 1 0| 0 16k| 15k 436B| 0 0 |1948 2057
2 0 97 0 0| 0 280k| 16k 1569B| 0 0 |1787 1665
1 1 88 9 0| 0 1141k| 13k 601B| 0 0 |2250 2398
7 10 50 31 0| 132k 3394k| 50k 30M| 0 0 |4336 3397
3 3 93 1 0| 0 44k| 135k 109M| 0 0 |7188 3545
3 3 94 0 0| 0 0 | 107k 103M| 0 0 |6470 3083
3 3 94 1 0| 144k 20k| 121k 105M| 0 0 |6665 3226
1 4 95 0 0| 0 104k| 100k 98M| 0 0 |6064 3138
7 4 87 1 0| 16k 32k| 175k 142M| 0 0 |8533 3714
4 4 93 1 0| 0 80k| 157k 151M| 0 0 |8290 3721
3 4 94 0 0| 0 8192B| 155k 149M| 0 0 |8388 3786
1 3 94 0 0| 0 16k| 160k 151M| 0 0 |8666 3964
2 4 93 0 0| 0 68k| 161k 147M| 0 0 |8546 3879
3 4 93 0 0| 0 0 | 228k 158M| 0 0 |9604 4073
3 4 91 0 0| 0 420k| 332k 153M| 0 0 | 10k 3949
3 3 93 0 0| 0 24k| 314k 153M| 0 0 |9611 4156
3 4 94 0 0| 0 28k| 317k 149M| 0 0 |9572 3649
2 4 93 0 0| 0 0 | 308k 147M| 0 0 |9450 3854
3 4 94 0 0| 0 32k| 322k 151M| 0 0 |9458 3682
2 3 93 0 0| 0 0 | 334k 154M| 0 0 |9988 4132
3 3 93 0 0| 0 92k| 296k 149M| 0 0 |9286 3669
3 4 92 0 0| 0 16k| 290k 152M| 0 0 |9573 4142
2 4 93 0 0| 0 1952k| 300k 145M| 0 0 |9359 3796
4 4 92 1 0| 0 16k| 316k 145M| 0 0 |9272 3895
2 3 93 0 0| 0 8192B| 314k 152M| 0 0 |9512 4053
5 4 91 0 0| 0 120k| 321k 151M| 0 0 |9621 4019
3 4 94 0 0| 0 0 | 292k 150M| 0 0 |9334 3915
2 4 93 0 0| 0 72k| 285k 147M| 0 0 |8965 3581
3 4 93 0 0| 0 16k| 298k 154M| 0 0 |9693 4017
3 4 92 0 0| 0 24k| 272k 148M| 0 0 |9033 3863
3 4 92 0 0| 0 16k| 301k 153M| 0 0 |9740 4296
3 4 93 0 0| 0 0 | 319k 152M| 0 0 |9612 3769
3 4 93 1 0| 0 108k| 286k 144M| 0 0 |9133 3941
3 4 93 0 0| 0 48k| 315k 152M| 0 0 |9392 3704
2 4 94 0 0| 0 264k| 324k 152M| 0 0 |9643 4246
2 4 91 0 0| 0 172k| 333k 156M| 0 0 |9755 4017
4 2 91 0 0| 0 32k| 328k 155M| 0 0 |9875 4227
3 3 94 0 0| 0 0 | 296k 145M| 0 0 |9300 3634
2 2 96 0 0| 0 0 | 128k 54M| 0 0 |4751 2605
1 0 97 0 0| 0 0 | 15k 2960B| 0 0 |1860 1776
1 1 98 1 0| 0 84k| 15k 1666B| 0 0 |1767 1669
- Page cache is not in use:
while true; do echo "###" ;date ; egrep "^Cached:|^Dirty:|^Writeback:|file" /proc/meminfo; sleep 1; done
Thu Sep 8 17:27:27 CEST 2022
Cached: 946948 kB
Active(file): 967840 kB
Inactive(file): 57688 kB
Dirty: 2056 kB
Writeback: 0 kB
- Low latency:
nfsiostat 1 100
read: ops/s kB/s kB/op retrans avg RTT (ms) avg exe (ms) avg queue (ms) errors
0.000 0.000 0.000 0 (0.0%) 0.000 0.000 0.000 0 (0.0%)
write: ops/s kB/s kB/op retrans avg RTT (ms) avg exe (ms) avg queue (ms) errors
153.000 156715.031 1024.281 0 (0.0%) 6.288 6.314 0.013 0 (0.0%)
The flame graphs:
1.- dd in /mnt/test_fs_without_sync dd fs without sync
2.- dd in /mnt/test_fs_with_sync and without oflag=direct dd fs with sync and dd without oflag=direct
3.- dd in /mnt/test_fs_with_sync and with oflag=direct dd fs with sync and dd with oflag=direct
The questions: I know write back is an old issue in linux and seems is the problem here. Link between nfs client an nfs server is a 10Gb (Fiber) and iperf3 data show the link works at maximum speed. No problems here. I know there are nfs options like nconnect to improve perfomance but I am interested in linux kernel internals. I played with vm.dirty_background_bytes/vm.dirty_background_ratio and vm.dirty_background_ratio/vm.dirty_background_ratio but whatever value put in this tunables I always have iowait (except from dd with oflag=direct)
In test number 2. How is it possible that it has no nfs latency but has a high cpu wait?
In test number 2. How is it possible that have almost the same code path than test number 1? Test number 2 use a nfs filesystem mounted with sync option but seems to use pagecache codepath.
In test number 1. Why there aren't a change in cpu wait behavior when vm.dirty tunables are changed? (i have tested a lot of combinations)