Runtime: Environment.GetLogicalDrives is an order of magnitude slower on Linux compared to Windows

[adamsitnik]

Environment.GetLogicalDrives is an order of magnitude slower on Linux compared to Windows

| Slower | diff/base | Windows Median (ns) | Linux Median (ns) | Modality |
| -----------------------------------------------| ---------:| -------------------:| -----------------:| ---------- |
| System.Tests.Perf_Environment.GetLogicalDrives | 183.88 | 326.14 | 59971.81 | |

The contributor who wants to work on this issue should:

1. Run this simple benchmark from dotnet/performance repository and confirm the problem

git clone https://github.com/dotnet/performance.git
python3 ./performance/scripts/benchmarks_ci.py -f netcoreapp5.0 --filter System.Tests.Perf_Environment.GetLogicalDrives

1. Build dotnet runtime locally: https://github.com/dotnet/performance/blob/master/docs/profiling-workflow-dotnet-runtime.md#Build
2. Create a small repro app: https://github.com/dotnet/performance/blob/master/docs/profiling-workflow-dotnet-runtime.md#Repro
3. Use PerfCollect to identify issue https://github.com/dotnet/performance/blob/master/docs/profiling-workflow-dotnet-runtime.md#PerfCollect
4. Solve the issue

[GKotfis]

I'd like to try solve this one!
@adamsitnik docs links lead to 404 page. But don't worry - I've found correct :)

[danmosemsft]

@GKotfis I have assigned you. thanks

[adamsitnik]

docs links lead to 404 page

I have updated the links.

I'd like to try solve this one!

Awesome! Please let me know if something is not clear or you need some help

[GKotfis]

I configured my linux dev environment from scratch. First benchmark results are:

// * Detailed results *
Perf_Environment.GetLogicalDrives: Job-VLTGMM(PowerPlanMode=00000000-0000-0000-0000-000000000000, Runtime=.NET Core 5.0, Arguments=/p:DebugType=portable, Toolchain=netcoreapp5.0, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
Runtime = .NET Core 5.0.0 (CoreCLR 5.0.20.16901, CoreFX 5.0.20.16901), X64 RyuJIT; GC = Concurrent Workstation
Mean = 81.4933 us, StdErr = 0.2476 us (0.30%); N = 15, StdDev = 0.9589 us
Min = 80.3873 us, Q1 = 80.9320 us, Median = 81.0107 us, Q3 = 82.1696 us, Max = 83.8022 us
IQR = 1.2375 us, LowerFence = 79.0757 us, UpperFence = 84.0259 us
ConfidenceInterval = [80.4682 us; 82.5185 us] (CI 99.9%), Margin = 1.0251 us (1.26% of Mean)
Skewness = 1.13, Kurtosis = 3.09, MValue = 2
-------------------- Histogram --------------------
[80.260 us ; 84.142 us) | @@@@@@@@@@@@@@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet=v0.12.0, OS=ubuntu 18.04
Intel Core i5-5300U CPU 2.30GHz (Broadwell), 1 CPU, 4 logical and 2 physical cores
.NET Core SDK=5.0.100-preview.4.20202.2
  [Host]     : .NET Core 5.0.0 (CoreCLR 5.0.20.16901, CoreFX 5.0.20.16901), X64 RyuJIT
  Job-VLTGMM : .NET Core 5.0.0 (CoreCLR 5.0.20.16901, CoreFX 5.0.20.16901), X64 RyuJIT

PowerPlanMode=00000000-0000-0000-0000-000000000000  Runtime=.NET Core 5.0  Arguments=/p:DebugType=portable
Toolchain=netcoreapp5.0  IterationTime=250.0000 ms  MaxIterationCount=20
MinIterationCount=15  WarmupCount=1

|           Method |     Mean |    Error |   StdDev |   Median |      Min |      Max |  Gen 0 | Gen 1 | Gen 2 | Allocated |
|----------------- |---------:|---------:|---------:|---------:|---------:|---------:|-------:|------:|------:|----------:|
| GetLogicalDrives | 81.49 us | 1.025 us | 0.959 us | 81.01 us | 80.39 us | 83.80 us | 3.2051 |     - |     - |   5.01 KB |

In next step I'll do the do the same on Windows to compare results and confirm the problem.

[GKotfis]

Benchmark results for Win x64 Env:

// * Detailed results *
Perf_Environment.GetLogicalDrives: Job-LDKTHC(PowerPlanMode=00000000-0000-0000-0000-000000000000, Runtime=.NET Core 5.0, Arguments=/p:DebugType=portable, Toolchain=netcoreapp5.0, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
Runtime = .NET Core 5.0.0 (CoreCLR 5.0.20.16901, CoreFX 5.0.20.16901), X64 RyuJIT; GC = Concurrent Workstation
Mean = 642.9934 ns, StdErr = 2.7728 ns (0.43%); N = 15, StdDev = 10.7390 ns
Min = 631.5086 ns, Q1 = 634.5860 ns, Median = 640.1829 ns, Q3 = 649.7763 ns, Max = 669.5870 ns
IQR = 15.1903 ns, LowerFence = 611.8005 ns, UpperFence = 672.5618 ns
ConfidenceInterval = [631.5128 ns; 654.4741 ns] (CI 99.9%), Margin = 11.4806 ns (1.79% of Mean)
Skewness = 0.99, Kurtosis = 3.07, MValue = 2
-------------------- Histogram --------------------
[628.531 ns ; 650.634 ns) | @@@@@@@@@@@@
[650.634 ns ; 673.397 ns) | @@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet=v0.12.0, OS=Windows 10.0.18362
Intel Core i5-5300U CPU 2.30GHz (Broadwell), 1 CPU, 4 logical and 2 physical cores
.NET Core SDK=5.0.100-preview.4.20202.8
  [Host]     : .NET Core 5.0.0 (CoreCLR 5.0.20.16901, CoreFX 5.0.20.16901), X64 RyuJIT
  Job-LDKTHC : .NET Core 5.0.0 (CoreCLR 5.0.20.16901, CoreFX 5.0.20.16901), X64 RyuJIT

PowerPlanMode=00000000-0000-0000-0000-000000000000  Runtime=.NET Core 5.0  Arguments=/p:DebugType=portable
Toolchain=netcoreapp5.0  IterationTime=250.0000 ms  MaxIterationCount=20
MinIterationCount=15  WarmupCount=1

|           Method |     Mean |    Error |   StdDev |   Median |      Min |      Max |  Gen 0 | Gen 1 | Gen 2 | Allocated |
|----------------- |---------:|---------:|---------:|---------:|---------:|---------:|-------:|------:|------:|----------:|
| GetLogicalDrives | 643.0 ns | 11.48 ns | 10.74 ns | 640.2 ns | 631.5 ns | 669.6 ns | 0.0662 |     - |     - |     104 B |

Summary benchmark results:
Windows median (ns) | Linux Median (ns)
-|-
640.2|81 490

✅ Problem confirmed

In next step will try to identify where issue take place.

[GKotfis]

Before I'll jump into perf optimization I'd like to ask what exactly this method should return for Unix systems? All mount points like it is right now? https://github.com/dotnet/runtime/blob/a605729eee65344b4c63fb036a35405abcc1de31/src/libraries/Native/Unix/System.Native/pal_mount.c#L28
In my machine as a results I get 56 'logical drives'. Maybe I'm wrong but comparing this to Windows machines with couple of logical drives is improper. But still probably there is a room for improvements :)

Logical drives: 56
/sys
/proc
/dev
/dev/pts
/run
/
/sys/kernel/security
/dev/shm
/run/lock
/sys/fs/cgroup
/sys/fs/cgroup/unified
/sys/fs/cgroup/systemd
/sys/fs/pstore
/sys/firmware/efi/efivars
/sys/fs/cgroup/cpu,cpuacct
/sys/fs/cgroup/memory
/sys/fs/cgroup/hugetlb
/sys/fs/cgroup/net_cls,net_prio
/sys/fs/cgroup/pids
/sys/fs/cgroup/perf_event
/sys/fs/cgroup/devices
/sys/fs/cgroup/freezer
/sys/fs/cgroup/cpuset
/sys/fs/cgroup/blkio
/sys/fs/cgroup/rdma
/dev/mqueue
/dev/hugepages
/proc/sys/fs/binfmt_misc
/sys/kernel/debug
/sys/kernel/config
/sys/fs/fuse/connections
/snap/gnome-characters/495
/snap/gnome-logs/93
/snap/dotnet-sdk/67
/snap/gtk-common-themes/1474
/snap/core/8268
/snap/gnome-calculator/544
/snap/dotnet-sdk/76
/snap/rider/43
/snap/core18/1668
/snap/core18/1705
/snap/gtk-common-themes/1440
/snap/gnome-logs/81
/snap/gnome-system-monitor/135
/snap/gnome-characters/399
/snap/gnome-system-monitor/127
/snap/gnome-calculator/704
/snap/slack/22
/snap/core/8935
/snap/code/28
/snap/gnome-3-28-1804/116
/boot/efi
/proc/sys/fs/binfmt_misc
/run/user/1000
/run/user/1000/gvfs
/mnt/data

[danmosemsft]

If it isn’t “obviously returning the wrong thing” then we can probably assume we can’t change its behavior now. As you say, it’s arguably not comparable with the work windows has to do, but nevertheless faster is better for anyone calling it..

[GKotfis]

I've a problems with my dev environment and that stops me.
I'm working on external usb drive and it's unstable (probably problem with hdd usb controler).
Currently cannot even run a benchmark:

Running .NET micro benchmarks for 'netcoreapp5.0'
-------------------------------------------------
--------------------------------------------------
Dumping COMPlus environment:
--------------------------------------------------
$ pushd "/mnt/data/Prv/GitHub/dotnet/performance/src/benchmarks/micro"
$ dotnet run --project /mnt/data/Prv/GitHub/dotnet/performance/src/benchmarks/micro/MicroBenchmarks.csproj --configuration Release --framework netcoreapp5.0 --no-restore --no-build -- --filter System.Tests.Perf_Environment.GetLogicalDrives --packages /mnt/data/Prv/GitHub/dotnet/performance/artifacts/packages --runtimes netcoreapp5.0
// Validating benchmarks:
// ***** BenchmarkRunner: Start   *****
// ***** Found 1 benchmark(s) in total *****
Unhandled exception. System.TypeInitializationException: The type initializer for 'BenchmarkRuntimePropertiesComparer' threw an exception.
 ---> System.NotSupportedException: Unknown .NET Runtime
   at BenchmarkDotNet.Portability.RuntimeInformation.GetCurrentRuntime()
   at BenchmarkDotNet.Running.BenchmarkPartitioner.BenchmarkRuntimePropertiesComparer..cctor()
   --- End of inner exception stack trace ---
   at BenchmarkDotNet.Running.BenchmarkPartitioner.CreateForBuild(BenchmarkRunInfo[] supportedBenchmarks, IResolver resolver)
   at BenchmarkDotNet.Running.BenchmarkRunnerClean.Run(BenchmarkRunInfo[] benchmarkRunInfos)
   at BenchmarkDotNet.Running.BenchmarkSwitcher.RunWithDirtyAssemblyResolveHelper(String[] args, IConfig config)
   at BenchmarkDotNet.Running.BenchmarkSwitcher.Run(String[] args, IConfig config)
   at MicroBenchmarks.Program.Main(String[] args) in /mnt/data/Prv/GitHub/dotnet/performance/src/benchmarks/micro/Program.cs:line 35
rocess exited with status 134

Have a problem also with build runtime:

libtoolize : error : AC_CONFIG_MACRO_DIRS([m4]) conflicts with ACLOCAL_AMFLAGS=-I m4 [/mnt/data/Prv/GitHub/runtime/src/mono/mono.proj]
/mnt/data/Prv/GitHub/runtime/src/mono/mono.proj(471,5): error MSB3073: The command "NOCONFIGURE=1 /mnt/data/Prv/GitHub/runtime/src/mono/autogen.sh" exited with code -1.

But still would like to continue work on this ticket. Just need to overcome this problems.

[danmosemsft]

@adamsitnik can probably help with this when he's back next week.

[danmosemsft]

Actually for the Benchmark.NET runtime issue, you may want to open an issue in dotnet/performance since it seems more about that than this issue.

[GKotfis]

Sorry, I can't continue working on this ticket :(
Tried to resolve problems with my dev env, machine but without success.
Right now I don't have a time to setup all Linux env from scratch to try one more time.

[dn9090]

This does not seem to be the problem but the glib uses only 1024 bytes as buffer.
In gunixmounts.c:

#ifdef HAVE_GETMNTENT_R
  struct mntent ent;
  char buf[1024];
#endif

In pal_mount.c:

#define STRING_BUFFER_SIZE 8192
...
char buffer[STRING_BUFFER_SIZE] = {0};

[danmosemsft]

@GKotfis not a problem.
@dn9090 any interest in taking this one up?

[dn9090]

@danmosemsft Sorry, I don't have a lot of time right now. If the lockdown in Germany is over and no one has taken it, I might have time to look into it.

[danmosemsft]

OK!

[dn9090]

I had some free time today and did some small tests.
So it looks like changing the buffer size has some impact.
I compared the original

char buffer[STRING_BUFFER_SIZE] = {0};
struct mntent entry;
while (getmntent_r(fp, &entry, buffer, STRING_BUFFER_SIZE) != NULL)

with

char buffer[1024] = {0};
struct mntent entry;
while (getmntent_r(fp, &entry, buffer, sizeof(buffer)) != NULL)

and got a ~8% performance increase.
I'm not sure how small the buffer can be.
The documentation states that getmntent_r

stores the strings pointed to by the entries in that struct in the provided array buf of size buflen.

In my naive calculation the maximum length of all strings in

struct mntent {
    char *mnt_fsname;   /* name of mounted file system */
    char *mnt_dir;      /* file system path prefix */
    char *mnt_type;     /* mount type (see mntent.h) */
    char *mnt_opts;     /* mount options (see mntent.h) */
    int   mnt_freq;     /* dump frequency in days */
    int   mnt_passno;   /* pass number on parallel fsck */
};

is close to 640 bytes.
Some discussions note that the maximum length specified by the mount options can be infinite and therefore the method fails.

[danmosemsft]

@dn9090 are you running System.Tests.Perf_Environment.GetLogicalDrives as per the instructions at the top -- could you please include the output from Benchmark.NET? Have you a theory why a smaller buffer would help?

[dn9090]

@danmosemsft No, I only compiled the C side and did some small benchmarks.
It looks like a issue on my machine. I tried multiple larger buffer sizes including glibc's implementation

struct mntent_buffer
{
  struct mntent m;
  char buffer[4096];
};

and got no performance problems until about 6000 bytes (maybe a stack issue?).

[janvorli]

Maybe the function reads the whole passed in buffer from the file and then extracts one line from it. That would explain why the large buffer has worse perf.

[dn9090]

@janvorli The glibc implementation uses __fgets_unlocked , so a 1 line read.
But I think that I found the problem:
__getmntent_r removes junk like spaces and tabs automatically but iterates the buffer from right to left.

while (end_ptr != buffer && (end_ptr[-1] == ' ' || end_ptr[-1] == '\t')) 
    end_ptr--;
*end_ptr = '\0';

A small look into /proc/mounts shows that I have 1 mount that has a lot of these characters:

cat /proc/mounts | tr " " "*" | tr "\t" "&"
[...] rw,nosuid,nodev,noatime*0*0******************[...]

I guess a small buffer just cuts these off.