Using FileWatcher on non-windows has a very large impact on startup time

[rynowak]

Related to dotnet/aspnetcore#20488

I did some investigation about some startup cost of the filewatching we set up by default. What I found may shock you. In the case that I'm measuring on macOS - the impact of first call to IFileProvider.Watch() is 100ms in wall clock time.

Background

Some background...

One of the features of IFileProvider is that it implements globbing in a non-OS-native way. So IFileProvider implements file system globbing /**/*.cshtml which is separate from what the underlying OS does. IFileProvider also implements file-watching, and since you have mix globbing (not implemented by the OS) and file watching (implemented by the OS) it uses a big hammer to implement this. When Watch is called, IFileProvider will watch the entire directory hierarchy it has access to, and will do the filtering of notifications based on the globbing feature.

On windows watching a directory tree maps directly to the Win32 API FindFirstChangeNotification or ReadDirectoryChanges. So watching a directory and it's subdirectories is implemented by the OS directly, and it takes one call from .NET -> native to set this up.

On Linux, there isn't an API for recursive subdirectory watching, the filewatcher code has to walk the directory hierarchy and register a watch on each subdirectory.

On macOS there is an API for recursive file watching. So it's not totally clear why it's taking 100ms.

How I'm measuring

I wrote the following test code:

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.IO;
using System.Linq;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.FileProviders;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;

namespace startupexperiment
{
    public class Program
    {
        public static async Task Main(string[] args)
        {
            if (args.Contains("--empty"))
            {
                var stopwatch = Stopwatch.StartNew();
                using (var host = CreateEmptyHostBuilder(args).Build())
                {
                    await host.StartAsync();
                    Console.WriteLine($"Empty Elapsed: {stopwatch.ElapsedMilliseconds}ms");

                    await host.StopAsync();
                }
            }
            else if (args.Contains("--watch"))
            {
                var stopwatch = Stopwatch.StartNew();
                using (var host = CreateEmptyHostBuilder(args).Build())
                {
                    await host.StartAsync();
                    var provider = host.Services.GetRequiredService<IHostEnvironment>().ContentRootFileProvider;
                    provider.Watch("appsettings.json");
                    Console.WriteLine($"Manual Elapsed: {stopwatch.ElapsedMilliseconds}ms");

                    await host.StopAsync();
                }
            }
            else if (args.Contains("--manual"))
            {
                var stopwatch = Stopwatch.StartNew();
                using (var host = CreateEmptyHostBuilder(args).Build())
                {
                    await host.StartAsync();
                    var provider = host.Services.GetRequiredService<IHostEnvironment>().ContentRootFileProvider;

                    var watcher = new FileSystemWatcher(((PhysicalFileProvider)provider).Root, "appsettings.json");
                    watcher.EnableRaisingEvents = true;

                    Console.WriteLine($"Manual Elapsed: {stopwatch.ElapsedMilliseconds}ms");

                    await host.StopAsync();
                }
            }
            else
            {
                var stopwatch = Stopwatch.StartNew();
                using (var host = CreateHostBuilderDefault(args).Build())
                {
                    await host.StartAsync();
                    Console.WriteLine($"Default Elapsed: {stopwatch.ElapsedMilliseconds}ms");

                    await host.StopAsync();
                }
            }
        }

        public static IHostBuilder CreateHostBuilderDefault(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseStartup<Startup>();
                });

        public static IHostBuilder CreateEmptyHostBuilder(string[] args) =>
            new HostBuilder().ConfigureWebHostDefaults(webBuilder =>
            {
                webBuilder.UseStartup<Startup>();
            });
    }
}

Publishing this with -c Release and then running it repeatedly yields pretty consistent results with a variation of about ~10ms. This is measured with the MVC template, which has some files to watch. Note that I'm doing a publish so that we're measuring all of the files that need to be in the app's output, not measuring obj/.

Results on macOS

Scenario	Approx Time (ms)	Description
Default	410 ms	Uses CreateDefaultHost (default experience users get)
--watch	365 ms	Uses new HostBuilder() and a single call to IFileProvider.Watch
--manual	365 ms	Uses new HostBuilder() and FileSystemWatcher
--empty	275 ms	Uses new HostBuilder() no configuration files or file watching

Next Steps

My next step here is to retake these measurements on Linux. We care a little bit more about Linux as a production scenario.

I can measure that this is pretty slow on macOS, but it's not slow for the reasons I expected. Using FileSystemWatcher and IFileProvider.Watch had the same result.

[DamianEdwards]

Related issue in the runtime RE swapping to newer Linux API that could improve this #30495

[ghost]

Tagging subscribers to this area: @eerhardt, @maryamariyan
See info in area-owners.md if you want to be subscribed.

[ghost]

Tagging subscribers to this area: @maryamariyan
See info in area-owners.md if you want to be subscribed.

[maryamariyan]

My next step here is to retake these measurements on Linux. We care a little bit more about Linux as a production scenario.

@rynowak did you get a chance to also do the same measurements on linux?

[rynowak]

Newp.