Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Slow file access times when accessing NFS server #48757

Closed
DomiStyle opened this issue Feb 25, 2021 · 17 comments
Closed

Slow file access times when accessing NFS server #48757

DomiStyle opened this issue Feb 25, 2021 · 17 comments
Labels
area-System.IO help wanted [up-for-grabs] Good issue for external contributors tenet-performance Performance related issue
Projects
System.IO - File system
Milestone
7.0.0

Comments

@DomiStyle
Copy link

Description

NFS performance is awful in .NET while Python and Bash have no problem accessing files at expected speeds.

As the tests below show, .NET needs around 6 seconds to access a file on an NFS share, doesn't matter if reading or writing. File size doesn't matter, access times are slow. Creating folders, deleting folders and deleting files works normally.

Configuration

.NET 5.0.103
Ubuntu 20.04.2 LTS x64 (with 5.11 kernel)
Issue happens on all my .NET applications across various Linux distros

Regression?

Didn't work since at least the introduction of .NET Core 3.0

Other information

Test files are available in this repository.

All times in milliseconds

Network speed according to iperf3: 9.13 Gbits/sec
Files on NFS server are on HDD

1GB file size

Shell:

From local to NFS: 10847
From NFS to local: 636

.NET:

From local to NFS: 16814
From NFS to local: 6776
Time to create folder: 3
Time to delete folder: 0
Time to create 10MB file: 6252
Time to read 10MB file: 6235
Time to delete 10MB file: 1

Python:

From local to NFS:  10812.782049179077
From NFS to local:  571.5739727020264

10MB file size

Shell:

From local to NFS: 167
From NFS to local: 8

.NET:

From local to NFS: 6352
From NFS to local: 6208
Time to create folder: 4
Time to delete folder: 0
Time to create 10MB file: 6319
Time to read 10MB file: 6216
Time to delete 10MB file: 1

Python:

From local to NFS:  183.42185020446777
From NFS to local:  6.532192230224609

10MB file size
Local control test (SSD)

Shell:

From local to local: 1
From local to local: 1

.NET:

From local to local: 4
From local to local: 0
Time to create folder: 6
Time to delete folder: 0
Time to create 10MB file: 5
Time to read 10MB file: 3
Time to delete 10MB file: 0

Python:

From local to local:  0.05602836608886719
From local to local:  0.010967254638671875
@dotnet-issue-labeler dotnet-issue-labeler bot added the untriaged New issue has not been triaged by the area owner label Feb 25, 2021
@dotnet-issue-labeler
Copy link

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

@DomiStyle DomiStyle mentioned this issue Feb 25, 2021
Closed
@DomiStyle
Copy link
Author

Area label is probably area-System.IO.

@jeffhandley @adamsitnik @carlossanlop @Jozkee

@Jozkee Jozkee added area-System.IO needs-further-triage Issue has been initially triaged, but needs deeper consideration or reconsideration and removed untriaged New issue has not been triaged by the area owner labels Feb 25, 2021
@Jozkee Jozkee added this to the 6.0.0 milestone Feb 25, 2021
@Jozkee Jozkee added this to To do in System.IO - File system via automation Feb 25, 2021
@adamsitnik adamsitnik modified the milestones: 6.0.0, 7.0.0 Jul 22, 2021
@adamsitnik adamsitnik added tenet-performance Performance related issue help wanted [up-for-grabs] Good issue for external contributors labels Jul 22, 2021
@jeffhandley
Copy link
Member

Removing "needs further triage" since we've marked this as "up-for-grabs".

@jeffhandley jeffhandley removed the needs-further-triage Issue has been initially triaged, but needs deeper consideration or reconsideration label Oct 10, 2021
@DomiStyle
Copy link
Author

I can still reproduce this on .NET 6. I tested a few different server distros to see if there are differences:

  • Ubuntu 20.04.3: Same behavior as in original issue
  • Debian 11: Same behavior as in original issue
  • Alpine Linux 3.15: Only the very first read after a NFS server restart is (very) delayed, all successive requests work as expected
  • Fedora Server 35: Same behavior as Alpine Linux

The control applications in Python and Bash still experience none of these issues. The client is always Ubuntu 21.10.

If the Python or Bash control application accesses the NFS mount on Alpine or Fedora first the .NET application will have no further issues afterwards.

@adamsitnik
Copy link
Member

Hi @DomiStyle

I am sorry but we have not investigated this issue yet.

I suspect that File.Move is slower due to three additional lstat sys-calls that verify whether the source and destination files exist:

runtime/src/libraries/System.Private.CoreLib/src/System/IO/File.cs

Line 417 in 71393d0

if (!FileSystem.FileExists(fullSourceFileName))

runtime/src/libraries/System.Private.CoreLib/src/System/IO/FileSystem.Unix.cs

Lines 225 to 226 in 71393d0

if (Interop.Sys.LStat(sourceFullPath, out sourceStat) == 0 && // source file exists
(Interop.Sys.LStat(destFullPath, out destStat) != 0 || // dest file does not exist

Is there any chance you could modify the code to use the overload that allows for overwriting?

- File.Move(nfsFile, localFile);
+ File.Move(nfsFile, localFile, true);

This one uses just one extra sys-call beside rename.

We could definitely try remove some of these sys-calls similarly to what I am trying to do in #63675 for Directory.Move

@DomiStyle
Copy link
Author

Hey @adamsitnik

Is there any chance you could modify the code to use the overload that allows for overwriting?

Sure, I tried with the overloaded method in both directions but unfortunately it is still slow.

I added some File.Exists calls in between to test this and checking if a file exists is blazing fast:

Run 1
Check if file exists (does not exist): 3
Move from local to NFS: 6317
Check if file exists (exists): 0
Move from NFS to local: 6303
Check if file exists (does not exist): 0
Time to create folder: 8
Time to delete folder: 6
Time to create 10MB file: 6212
Time to read 10MB file: 6303
Time to delete 10MB file: 14

Run 2
Check if file exists (does not exist): 14
Move from local to NFS: 6249
Check if file exists (exists): 0
Move from NFS to local: 6296
Check if file exists (does not exist): 0
Time to create folder: 4
Time to delete folder: 4
Time to create 10MB file: 6208
Time to read 10MB file: 6310
Time to delete 10MB file: 6

Run 3
Check if file exists (does not exist): 6
Move from local to NFS: 6256
Check if file exists (exists): 0
Move from NFS to local: 6290
Check if file exists (does not exist): 0
Time to create folder: 4
Time to delete folder: 4
Time to create 10MB file: 6230
Time to read 10MB file: 6295
Time to delete 10MB file: 7

Works normally: File.Exists, File.Delete, Directory.CreateDirectory, Directory.Delete

Stuck for ~6 seconds: File.WriteAllBytes, File.ReadAllBytes, File.Move

@adamsitnik
Copy link
Member

@DomiStyle is there any chance you could capture a trace file using perfcollect and share it with me?

Here you can find the instructions: https://github.com/dotnet/performance/blob/main/docs/profiling-workflow-dotnet-runtime.md#perfcollect

They refer to coreun which is used for local builds of dotnet runtime, you would need to publish a self-contained version of your app and just run the executable.

If you prefer a video I've demoed it here: https://www.youtube.com/watch?v=y4-h3qyDpJo&t=1309s&ab_channel=DotNext

@DomiStyle
Copy link
Author

DomiStyle commented Feb 7, 2022 •
edited

@adamsitnik Sure, here's the trace:
slowNfs.trace.zip

I simplified the program and just let it move a file to NFS and back 3 times.

I got Crossgen not found. Framework symbols will be unavailable. at the end, just tell me if I need to fix that warning in order for the trace to be useful.

edit: Just as a side note, there is no crossgen in my .nuget folder so I'm not sure where to find it. I did a self-contained build before checking.

@adamsitnik
Copy link
Member

@DomiStyle big thanks for sharing the trace file! I was able to open it and identify the problem.

So the code performs 3 lstats (#65092) to find out that the source and destination files are not on the same drive (and file system):

runtime/src/libraries/System.Private.CoreLib/src/System/IO/FileSystem.Unix.cs

Line 227 in 71393d0

(sourceStat.Dev == destStat.Dev && // source and dest are on the same device

and falls back to the slow path:

runtime/src/libraries/System.Private.CoreLib/src/System/IO/FileSystem.Unix.cs

Lines 235 to 236 in 71393d0

LinkOrCopyFile(sourceFullPath, destFullPath);
DeleteFile(sourceFullPath);

Which performs multiple sys-calls instead of single rename:

image

And spends most of the time in sendfile64

@tmds I can see that rename fails with EXDEV when the files are not on the same file system. Is my understanding correct that your recent work on #64264 should help us here as the copy_file_range is capable of copying files across different file systems?

You can see the trace file here, please go directly to "Left Heavy" tab as there is only 20ms of data in the trace file and "Time Order" is empty.

@tmds
Copy link
Member

tmds commented Feb 10, 2022

I don't expect copy_file_range to be much better than sendfile when copying between file systems.

Does the timing change if you avoid the file locking by setting DOTNET_SYSTEM_IO_DISABLEFILELOCKING=1?

Can you share the output of strace -c cp src dst for copying from and to the NFS share? And also without the -c flag.

@DomiStyle
Copy link
Author

Does the timing change if you avoid the file locking by setting DOTNET_SYSTEM_IO_DISABLEFILELOCKING=1?

Yes, that drastically reduces the access time from 6s to <100ms, which seems to be inline with what bash can do.

Can you share the output of strace -c cp src dst for copying from and to the NFS share? And also without the -c flag.

strace -c cp non-nfs-mount/testfile nfs-mount/testfile 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 49,78    0,002188         109        20           write
 28,56    0,001255          44        28           read
 18,82    0,000827          63        13           close
  1,21    0,000053           5        10           openat
  0,75    0,000033          16         2           munmap
  0,32    0,000014           0        27           mmap
  0,11    0,000005           2         2         2 statfs
  0,09    0,000004           4         1         1 stat
  0,09    0,000004           0        10         1 newfstatat
  0,07    0,000003           1         2           fstat
  0,05    0,000002           0         3           brk
  0,05    0,000002           1         2         2 access
  0,05    0,000002           2         1           fadvise64
  0,02    0,000001           1         1         1 lseek
  0,02    0,000001           1         1           prlimit64
  0,02    0,000001           1         1           getrandom
  0,00    0,000000           0        10           mprotect
  0,00    0,000000           0         4           pread64
  0,00    0,000000           0         1           execve
  0,00    0,000000           0         1           geteuid
  0,00    0,000000           0         2         1 arch_prctl
  0,00    0,000000           0         1           set_tid_address
  0,00    0,000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100,00    0,004395          30       144         8 total
strace -c cp nfs-mount/testfile non-nfs-mount/testfile 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 60,21    0,003314         165        20           write
 22,04    0,001213          43        28           read
 10,74    0,000591          45        13           close
  4,60    0,000253          25        10           openat
  0,94    0,000052           5        10           newfstatat
  0,51    0,000028          14         2           munmap
  0,38    0,000021           0        27           mmap
  0,20    0,000011           1        10           mprotect
  0,09    0,000005           2         2         2 statfs
  0,07    0,000004           2         2         2 access
  0,04    0,000002           2         1           stat
  0,04    0,000002           1         2           fstat
  0,04    0,000002           2         1         1 lseek
  0,02    0,000001           0         3           brk
  0,02    0,000001           1         1           geteuid
  0,02    0,000001           1         1           set_tid_address
  0,02    0,000001           1         1           fadvise64
  0,02    0,000001           1         1           prlimit64
  0,02    0,000001           1         1           getrandom
  0,00    0,000000           0         4           pread64
  0,00    0,000000           0         1           execve
  0,00    0,000000           0         2         1 arch_prctl
  0,00    0,000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100,00    0,005504          38       144         6 total
strace cp non-nfs-mount/testfile nfs-mount/testfile 
execve("/usr/bin/cp", ["cp", "non-nfs-mount/testfile", "nfs-mount/testfile"], 0x7ffeff29b050 /* 60 vars */) = 0
brk(NULL)                               = 0x557ee7417000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffc6e7636a0) = -1 EINVAL (Invalid argument)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=118925, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 118925, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa2a4040000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240o\0\0\0\0\0\0"..., 832) = 832
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=166280, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa2a403e000
mmap(NULL, 177672, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa2a4012000
mprotect(0x7fa2a4018000, 139264, PROT_NONE) = 0
mmap(0x7fa2a4018000, 106496, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7fa2a4018000
mmap(0x7fa2a4032000, 28672, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x20000) = 0x7fa2a4032000
mmap(0x7fa2a403a000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x27000) = 0x7fa2a403a000
mmap(0x7fa2a403c000, 5640, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa2a403c000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libacl.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220#\0\0\0\0\0\0"..., 832) = 832
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=34888, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 36896, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa2a4008000
mprotect(0x7fa2a400a000, 24576, PROT_NONE) = 0
mmap(0x7fa2a400a000, 16384, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7fa2a400a000
mmap(0x7fa2a400e000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7fa2a400e000
mmap(0x7fa2a4010000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7fa2a4010000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libattr.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@$\0\0\0\0\0\0"..., 832) = 832
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=26696, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 28696, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa2a4000000
mmap(0x7fa2a4002000, 12288, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7fa2a4002000
mmap(0x7fa2a4005000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5000) = 0x7fa2a4005000
mmap(0x7fa2a4006000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5000) = 0x7fa2a4006000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000\342\2\0\0\0\0\0"..., 832) = 832
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
pread64(3, "\4\0\0\0 \0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0"..., 48, 848) = 48
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\270\3{b`\206SF\200#!\335\"V\270\255"..., 68, 896) = 68
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=2215936, ...}, AT_EMPTY_PATH) = 0
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
mmap(NULL, 2260144, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa2a3dd8000
mprotect(0x7fa2a3e04000, 2002944, PROT_NONE) = 0
mmap(0x7fa2a3e04000, 1654784, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2c000) = 0x7fa2a3e04000
mmap(0x7fa2a3f98000, 344064, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c0000) = 0x7fa2a3f98000
mmap(0x7fa2a3fed000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x214000) = 0x7fa2a3fed000
mmap(0x7fa2a3ff3000, 52400, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa2a3ff3000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\"\0\0\0\0\0\0"..., 832) = 832
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=608968, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 611088, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa2a3d42000
mmap(0x7fa2a3d44000, 438272, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7fa2a3d44000
mmap(0x7fa2a3daf000, 159744, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6d000) = 0x7fa2a3daf000
mmap(0x7fa2a3dd6000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x93000) = 0x7fa2a3dd6000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa2a3d40000
arch_prctl(ARCH_SET_FS, 0x7fa2a3d41140) = 0
set_tid_address(0x7fa2a3d41410)         = 26650
set_robust_list(0x7fa2a3d41420, 24)     = 0
mprotect(0x7fa2a3fed000, 12288, PROT_READ) = 0
mprotect(0x7fa2a3dd6000, 4096, PROT_READ) = 0
mprotect(0x7fa2a4006000, 4096, PROT_READ) = 0
mprotect(0x7fa2a4010000, 4096, PROT_READ) = 0
mprotect(0x7fa2a403a000, 4096, PROT_READ) = 0
mprotect(0x557ee679e000, 4096, PROT_READ) = 0
mprotect(0x7fa2a4091000, 8192, PROT_READ) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
munmap(0x7fa2a4040000, 118925)          = 0
statfs("/sys/fs/selinux", 0x7ffc6e763680) = -1 ENOENT (No such file or directory)
statfs("/selinux", 0x7ffc6e763680)      = -1 ENOENT (No such file or directory)
getrandom("\x88\xdd\xf7\xd8\x3c\x3e\x26\x4b", 8, GRND_NONBLOCK) = 8
brk(NULL)                               = 0x557ee7417000
brk(0x557ee7438000)                     = 0x557ee7438000
openat(AT_FDCWD, "/proc/filesystems", O_RDONLY|O_CLOEXEC) = 3
newfstatat(3, "", {st_mode=S_IFREG|0444, st_size=0, ...}, AT_EMPTY_PATH) = 0
read(3, "nodev\tsysfs\nnodev\ttmpfs\nnodev\tbd"..., 1024) = 477
read(3, "", 1024)                       = 0
close(3)                                = 0
access("/etc/selinux/config", F_OK)     = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=6055600, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 6055600, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa2a3779000
close(3)                                = 0
geteuid()                               = 1000
stat("nfs-mount/testfile", {st_mode=S_IFREG|0664, st_size=10485760, ...}) = 0
newfstatat(AT_FDCWD, "non-nfs-mount/testfile", {st_mode=S_IFREG|0664, st_size=10485760, ...}, 0) = 0
newfstatat(AT_FDCWD, "nfs-mount/testfile", {st_mode=S_IFREG|0664, st_size=10485760, ...}, 0) = 0
openat(AT_FDCWD, "non-nfs-mount/testfile", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=10485760, ...}) = 0
openat(AT_FDCWD, "nfs-mount/testfile", O_WRONLY|O_TRUNC) = 4
fstat(4, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
mmap(NULL, 532480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa2a36f7000
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "", 524288)                     = 0
close(4)                                = 0
close(3)                                = 0
munmap(0x7fa2a36f7000, 532480)          = 0
lseek(0, 0, SEEK_CUR)                   = -1 ESPIPE (Illegal seek)
close(0)                                = 0
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++
strace cp nfs-mount/testfile non-nfs-mount/testfile 
execve("/usr/bin/cp", ["cp", "nfs-mount/testfile", "non-nfs-mount/testfile"], 0x7fff12c2ee50 /* 60 vars */) = 0
brk(NULL)                               = 0x55f6dc42e000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffd9e371680) = -1 EINVAL (Invalid argument)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=118925, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 118925, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7faef2a14000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240o\0\0\0\0\0\0"..., 832) = 832
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=166280, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7faef2a12000
mmap(NULL, 177672, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7faef29e6000
mprotect(0x7faef29ec000, 139264, PROT_NONE) = 0
mmap(0x7faef29ec000, 106496, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7faef29ec000
mmap(0x7faef2a06000, 28672, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x20000) = 0x7faef2a06000
mmap(0x7faef2a0e000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x27000) = 0x7faef2a0e000
mmap(0x7faef2a10000, 5640, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7faef2a10000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libacl.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220#\0\0\0\0\0\0"..., 832) = 832
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=34888, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 36896, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7faef29dc000
mprotect(0x7faef29de000, 24576, PROT_NONE) = 0
mmap(0x7faef29de000, 16384, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7faef29de000
mmap(0x7faef29e2000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7faef29e2000
mmap(0x7faef29e4000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7faef29e4000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libattr.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@$\0\0\0\0\0\0"..., 832) = 832
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=26696, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 28696, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7faef29d4000
mmap(0x7faef29d6000, 12288, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7faef29d6000
mmap(0x7faef29d9000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5000) = 0x7faef29d9000
mmap(0x7faef29da000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5000) = 0x7faef29da000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000\342\2\0\0\0\0\0"..., 832) = 832
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
pread64(3, "\4\0\0\0 \0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0"..., 48, 848) = 48
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\270\3{b`\206SF\200#!\335\"V\270\255"..., 68, 896) = 68
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=2215936, ...}, AT_EMPTY_PATH) = 0
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
mmap(NULL, 2260144, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7faef27ac000
mprotect(0x7faef27d8000, 2002944, PROT_NONE) = 0
mmap(0x7faef27d8000, 1654784, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2c000) = 0x7faef27d8000
mmap(0x7faef296c000, 344064, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c0000) = 0x7faef296c000
mmap(0x7faef29c1000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x214000) = 0x7faef29c1000
mmap(0x7faef29c7000, 52400, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7faef29c7000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\"\0\0\0\0\0\0"..., 832) = 832
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=608968, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 611088, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7faef2716000
mmap(0x7faef2718000, 438272, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7faef2718000
mmap(0x7faef2783000, 159744, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6d000) = 0x7faef2783000
mmap(0x7faef27aa000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x93000) = 0x7faef27aa000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7faef2714000
arch_prctl(ARCH_SET_FS, 0x7faef2715140) = 0
set_tid_address(0x7faef2715410)         = 26672
set_robust_list(0x7faef2715420, 24)     = 0
mprotect(0x7faef29c1000, 12288, PROT_READ) = 0
mprotect(0x7faef27aa000, 4096, PROT_READ) = 0
mprotect(0x7faef29da000, 4096, PROT_READ) = 0
mprotect(0x7faef29e4000, 4096, PROT_READ) = 0
mprotect(0x7faef2a0e000, 4096, PROT_READ) = 0
mprotect(0x55f6dc25e000, 4096, PROT_READ) = 0
mprotect(0x7faef2a65000, 8192, PROT_READ) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
munmap(0x7faef2a14000, 118925)          = 0
statfs("/sys/fs/selinux", 0x7ffd9e371660) = -1 ENOENT (No such file or directory)
statfs("/selinux", 0x7ffd9e371660)      = -1 ENOENT (No such file or directory)
getrandom("\x2a\x3a\xe6\x67\x0f\x07\xa7\x21", 8, GRND_NONBLOCK) = 8
brk(NULL)                               = 0x55f6dc42e000
brk(0x55f6dc44f000)                     = 0x55f6dc44f000
openat(AT_FDCWD, "/proc/filesystems", O_RDONLY|O_CLOEXEC) = 3
newfstatat(3, "", {st_mode=S_IFREG|0444, st_size=0, ...}, AT_EMPTY_PATH) = 0
read(3, "nodev\tsysfs\nnodev\ttmpfs\nnodev\tbd"..., 1024) = 477
read(3, "", 1024)                       = 0
close(3)                                = 0
access("/etc/selinux/config", F_OK)     = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=6055600, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 6055600, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7faef214d000
close(3)                                = 0
geteuid()                               = 1000
stat("non-nfs-mount/testfile", {st_mode=S_IFREG|0664, st_size=10485760, ...}) = 0
newfstatat(AT_FDCWD, "nfs-mount/testfile", {st_mode=S_IFREG|0664, st_size=10485760, ...}, 0) = 0
newfstatat(AT_FDCWD, "non-nfs-mount/testfile", {st_mode=S_IFREG|0664, st_size=10485760, ...}, 0) = 0
openat(AT_FDCWD, "nfs-mount/testfile", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=10485760, ...}) = 0
openat(AT_FDCWD, "non-nfs-mount/testfile", O_WRONLY|O_TRUNC) = 4
fstat(4, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
mmap(NULL, 532480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7faef20cb000
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 524288
read(3, "", 524288)                     = 0
close(4)                                = 0
close(3)                                = 0
munmap(0x7faef20cb000, 532480)          = 0
lseek(0, 0, SEEK_CUR)                   = -1 ESPIPE (Illegal seek)
close(0)                                = 0
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++
strace -c mv non-nfs-mount/testfile nfs-mount/testfile 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 39,45    0,001859          92        20           write
 21,14    0,000996          35        28           read
 20,06    0,000945         945         1           unlinkat
 17,23    0,000812         812         1           utimensat
  1,00    0,000047          23         2           munmap
  0,53    0,000025          25         1           fsetxattr
  0,21    0,000010           0        13           close
  0,13    0,000006           6         1         1 fgetxattr
  0,11    0,000005           0        13           newfstatat
  0,08    0,000004           2         2           flistxattr
  0,04    0,000002           2         1           lstat
  0,02    0,000001           1         1         1 lseek
  0,00    0,000000           0         1           stat
  0,00    0,000000           0         2           fstat
  0,00    0,000000           0        27           mmap
  0,00    0,000000           0        10           mprotect
  0,00    0,000000           0         3           brk
  0,00    0,000000           0         2         1 ioctl
  0,00    0,000000           0         4           pread64
  0,00    0,000000           0         3         2 access
  0,00    0,000000           0         1           execve
  0,00    0,000000           0         1         1 rename
  0,00    0,000000           0         1           unlink
  0,00    0,000000           0         1           getuid
  0,00    0,000000           0         1           getgid
  0,00    0,000000           0         3           geteuid
  0,00    0,000000           0         1           getegid
  0,00    0,000000           0         2         2 statfs
  0,00    0,000000           0         2         1 arch_prctl
  0,00    0,000000           0         1           set_tid_address
  0,00    0,000000           0         1           fadvise64
  0,00    0,000000           0        10           openat
  0,00    0,000000           0         1           set_robust_list
  0,00    0,000000           0         1           prlimit64
  0,00    0,000000           0         1         1 renameat2
  0,00    0,000000           0         1           getrandom
------ ----------- ----------- --------- --------- ----------------
100,00    0,004712          28       165        10 total

@tmds
Copy link
Member

tmds commented Feb 11, 2022

Yes, that drastically reduces the access time from 6s to <100ms, which seems to be inline with what bash can do.

The locking is what is causing the long delay. To improve it you should look at your NFS client/server configuration.

NFS locking implementation changed significantly between NFSv3 and NFS4.

With NFSv3, you can disable locking for a mount using the nolock option. It should have an effect similar as setting DOTNET_SYSTEM_IO_DISABLEFILELOCKING.

@DomiStyle
Copy link
Author

The locking is what is causing the long delay. To improve it you should look at your NFS client/server configuration.

I think you're right.

I wrote a test application for locking and unlocking in bash and I get the same ~6 second delay with a no locks available message.

NFS locking implementation changed significantly between NFSv3 and NFS4.

Turns out that Ubuntu and Debian don't enable the service required for locks to work over NFSv3 anymore by default while Fedora does. Still doesn't explain why the first lock is delayed by 40s on Fedora but it's unlikely that a .NET application accesses my NFS server first so not an issue for me.

With NFSv3, you can disable locking for a mount using the nolock option. It should have an effect similar as setting DOTNET_SYSTEM_IO_DISABLEFILELOCKING.

Enabling the service on Ubuntu resolves the issue, as does adding the nolock mount option or just switching to NFSv4.

That just leaves the question why .NET requires locks to move a file while bash and Python do not?

@tmds
Copy link
Member

tmds commented Feb 11, 2022

That just leaves the question why .NET requires locks to move a file while bash and Python do not?

The locks are used to emulate Windows FileShare behavior.

In this case, they prevent other .NET processes to write to the source file, and read from the destination file.

@DomiStyle
Copy link
Author

In this case, they prevent other .NET processes to write to the source file, and read from the destination file.

Interesting, does DOTNET_SYSTEM_IO_DISABLEFILELOCKING work in every release .NET application or only in debug mode?

@tmds
Copy link
Member

tmds commented Feb 11, 2022

Interesting, does DOTNET_SYSTEM_IO_DISABLEFILELOCKING work in every release .NET application or only in debug mode?

It was introduced in .NET 6.

@tmds
Copy link
Member

tmds commented Feb 16, 2022

I'm going to close the issue.

The root cause for the delay is .NET locking over NFSv3 without the lock service being available.

The options are:

  • Disable .NET locking using DOTNET_SYSTEM_IO_DISABLEFILELOCKING (introduced in .NET 6).
  • Disable locking for the mount using the nolock option.
  • Enable the lock service.
  • Use NFS4 which has built-in lock support.

@tmds tmds closed this as completed Feb 16, 2022
System.IO - File system automation moved this from To do to Done Feb 16, 2022
@ghost ghost locked as resolved and limited conversation to collaborators Mar 18, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
area-System.IO help wanted [up-for-grabs] Good issue for external contributors tenet-performance Performance related issue
Projects
System.IO - File system
  
Done
Milestone
7.0.0
Development

No branches or pull requests
5 participants
@DomiStyle @tmds @jeffhandley @adamsitnik @Jozkee