EFC Tooling always forces a rebuild

[Suchiman]

Running any EFC CLI (be it dotnet ef or the powershell ones) command will always print

PM> dotnet ef ...
Build started...
Build succeeded.

even if the project is up to date. Our Database project (which only contains database classes) takes almost a minute to build so having to wait for a build everytime you issue a command severely degrades the innerloop experience. And as for the Powershell Commands, they'll lock up VS until the command has completed.

Include provider and version information

EF Core version: 8.0.1
Database provider: Microsoft.EntityFrameworkCore.SqlServer
Target framework: .NET 8.0
Operating system: Windows 10
IDE: Visual Studio 2022 17.9P1

[ErikEJ]

What commands do you typically run?

[Suchiman]

A typical flow might look like this:
I modify the database project, then trigger a build to see if i've gotten everything right and then i issue Add-Migration which prompty does another unnecessary build.
I then usually hit F5 to build and start debugging the project which calls context.Database.Migrate() on the startup path.
I might now for whatever reason need the SQL that was used for the migration, so i hit up Script-Migration which does me another unnecessary build.
From that or because i realized that my changes are not quite done yet i do a Update-Database -To <previous> to undo the migration which does another unnecessary build.
Then after that i need to issue Remove-Migration which does another unnecessary build (unless i just git undo the migration files).
I'm planning to add dotnet ef dbcontext optimize to my workflow because the cold boot time of EFC with debug is currently 9s and that reduces it to 3s.

So as you can see with the time it takes to build my database project, that wastes like 4 minutes at minimum, not accounting for any typo's or incorrect inputs / context's fed to the commands.

[ajcvickers]

@Suchiman If you are sure the project is up-to-date, then just pass --no-build.

[Suchiman]

@Suchiman If you are sure the project is up-to-date, then just pass --no-build.

huh i've never noticed that flag, thanks! Is there a particular reason though to not rely on msbuild's up-to-date check?

[ajcvickers]

@Suchiman The idea is that when you do dotnet build, which is effectively what EF does, then the up-to-date check should kick in automatically. However, MSBUILD is complicated and has gotten more so, such that, for example, a build in VS is now a different beast to build on the command line. That being said, building is a safeguard against the very common problem of people issuing a command without having first built their code. If you are okay to not have that safeguard, then --no-build is the way to go. Or you could write your own shell script to do the build however you want it and then call the tool with --no-build.

[Suchiman]

@ajcvickers even if i issue dotnet ef migrations script multiple times back to back (which makes no changes to the project), it (re)builds everytime, having VBCSCompiler peg the CPU for quite a while. I found that the command is built and issued here:

efcore/src/dotnet-ef/Project.cs

Lines 137 to 174 in 9a1b7fc

	public void Build()
	{
	var args = new List<string> { "build" };
	if (_file != null)
	{
	args.Add(_file);
	}
	// TODO: Only build for the first framework when unspecified
	if (_framework != null)
	{
	args.Add("--framework");
	args.Add(_framework);
	}
	if (_configuration != null)
	{
	args.Add("--configuration");
	args.Add(_configuration);
	}
	if (_runtime != null)
	{
	args.Add("--runtime");
	args.Add(_runtime);
	}
	args.Add("/verbosity:quiet");
	args.Add("/nologo");
	args.Add("/p:PublishAot=false"); // Avoid NativeAOT warnings
	var exitCode = Exe.Run("dotnet", args, interceptOutput: true);
	if (exitCode != 0)
	{
	throw new CommandException(Resources.BuildFailed);
	}
	}

which is called from here

efcore/src/dotnet-ef/RootCommand.cs

Lines 79 to 84 in 9a1b7fc

	if (!_noBuild!.HasValue())
	{
	Reporter.WriteInformation(Resources.BuildStarted);
	startupProject.Build();
	Reporter.WriteInformation(Resources.BuildSucceeded);
	}

Grabing the command line from taskmgr reveals it issues
dotnet build C:\Path\To\Database.csproj /verbosity:quiet /nologo /p:PublishAot=false
which matches that code and looks fine. If i issue it manually in the cmd, it finishes quickly, printing

The build completed successfully.
     0 warning(s)
     0 errors

Elapsed time 00:00:01.26

indicating that the up-to-date check is working, however everytime i invoke dotnet ef it does not, i don't quite understand where the difference lies.
I'll try digging deeper later to see if i can figure that out.

[ajcvickers]

@Suchiman Note that this area has been investigated previously. If you find something simple and safe to change that helps, that's great, but in general if you want full control over how builds happen then build outside of the EF command line.

[joakimriedel]

I find this issue interesting. For my solution, a dotnet build takes ~3 seconds to complete when the project is already built. It is the time it needs to do the up-to-date check. It is slower than building within Visual Studio itself, where it only needs ~1.5 seconds for the same up-to-date check, but still I think both builds are fast enough.

Running dotnet ef migrations list however, measuring the time between the output of Build started... and Build succeeded., it takes exactly three times as long to complete, ~9 seconds.

Digging deeper into this, I put the code from dotnet ef which calls dotnet build out into a separate console application.

Console app for dotnet build

using System.Diagnostics; using System.Diagnostics.CodeAnalysis; using System.Text; using System.Text.RegularExpressions; using static AnsiConstants;

var exeArgs = new List { "build" };

exeArgs.Add("/verbosity:quiet");
exeArgs.Add("/nologo");
exeArgs.Add("/p:PublishAot=false"); // Avoid NativeAOT warnings

var exitCode = Exe.Run("dotnet", exeArgs, interceptOutput: true);
if (exitCode != 0)
{
throw new ArgumentException("dotnet build failed");
}

internal static class AnsiConstants
{
public const string Reset = "\x1b[22m\x1b[39m";
public const string Bold = "\x1b[1m";
public const string Dark = "\x1b[22m";
public const string Black = "\x1b[30m";
public const string Red = "\x1b[31m";
public const string Green = "\x1b[32m";
public const string Yellow = "\x1b[33m";
public const string Blue = "\x1b[34m";
public const string Magenta = "\x1b[35m";
public const string Cyan = "\x1b[36m";
public const string Gray = "\x1b[37m";
}

internal class AnsiTextWriter
{
private readonly TextWriter _writer;

public AnsiTextWriter(TextWriter writer)
{
    _writer = writer;
}

public void WriteLine(string? text)
{
    if (text != null)
    {
        Interpret(text);
    }

    _writer.Write(Environment.NewLine);
}

private void Interpret(string value)
{
    var matches = Regex.Matches(value, "\x1b\\[([0-9]+)?m");

    var start = 0;
    foreach (var match in matches.Cast<Match>())
    {
        var length = match.Index - start;
        if (length != 0)
        {
            _writer.Write(value.Substring(start, length));
        }

        Apply(match.Groups[1].Value);

        start = match.Index + match.Length;
    }

    if (start != value.Length)
    {
        _writer.Write(value.Substring(start));
    }
}

private static void Apply(string parameter)
{
    switch (parameter)
    {
        case "1":
            ApplyBold();
            break;

        case "22":
            ResetBold();
            break;

        case "30":
            ApplyColor(ConsoleColor.Black);
            break;

        case "31":
            ApplyColor(ConsoleColor.DarkRed);
            break;

        case "32":
            ApplyColor(ConsoleColor.DarkGreen);
            break;

        case "33":
            ApplyColor(ConsoleColor.DarkYellow);
            break;

        case "34":
            ApplyColor(ConsoleColor.DarkBlue);
            break;

        case "35":
            ApplyColor(ConsoleColor.DarkMagenta);
            break;

        case "36":
            ApplyColor(ConsoleColor.DarkCyan);
            break;

        case "37":
            ApplyColor(ConsoleColor.Gray);
            break;

        case "39":
            ResetColor();
            break;

        default:
            Debug.Fail("Unsupported parameter: " + parameter);
            break;
    }
}

private static void ApplyBold()
    => Console.ForegroundColor = (ConsoleColor)((int)Console.ForegroundColor | 8);

private static void ResetBold()
    => Console.ForegroundColor = (ConsoleColor)((int)Console.ForegroundColor & 7);

private static void ApplyColor(ConsoleColor color)
{
    var wasBold = ((int)Console.ForegroundColor & 8) != 0;

    Console.ForegroundColor = color;

    if (wasBold)
    {
        ApplyBold();
    }
}

private static void ResetColor()
{
    var wasBold = ((int)Console.ForegroundColor & 8) != 0;

    Console.ResetColor();

    if (wasBold)
    {
        ApplyBold();
    }
}

}

internal static class AnsiConsole
{
public static readonly AnsiTextWriter Out = new(Console.Out);

public static void WriteLine(string? text)
    => Out.WriteLine(text);

}

internal static class Reporter
{
public static bool IsVerbose { get; set; }
public static bool NoColor { get; set; }
public static bool PrefixOutput { get; set; }

[return: NotNullIfNotNull("value")]
public static string? Colorize(string? value, Func<string?, string> colorizeFunc)
    => NoColor ? value : colorizeFunc(value);

public static void WriteError(string? message)
    => WriteLine(Prefix("error:   ", Colorize(message, x => Bold + Red + x + Reset)));

public static void WriteWarning(string? message)
    => WriteLine(Prefix("warn:    ", Colorize(message, x => Bold + Yellow + x + Reset)));

public static void WriteInformation(string? message)
    => WriteLine(Prefix("info:    ", message));

public static void WriteData(string? message)
    => WriteLine(Prefix("data:    ", Colorize(message, x => Bold + Gray + x + Reset)));

public static void WriteVerbose(string? message)
{
    if (IsVerbose)
    {
        WriteLine(Prefix("verbose: ", Colorize(message, x => Bold + Black + x + Reset)));
    }
}

private static string? Prefix(string prefix, string? value)
    => PrefixOutput
        ? value == null
            ? prefix
            : string.Join(
                Environment.NewLine,
                value.Split([Environment.NewLine], StringSplitOptions.None).Select(l => prefix + l))
        : value;

private static void WriteLine(string? value)
{
    if (NoColor)
    {
        Console.WriteLine(value);
    }
    else
    {
        AnsiConsole.WriteLine(value);
    }
}

}

internal static class Exe
{
public static int Run(
string executable,
IReadOnlyList args,
string? workingDirectory = null,
bool interceptOutput = false)
{
var arguments = ToArguments(args);

    Reporter.WriteVerbose(executable + " " + arguments);

    var startInfo = new ProcessStartInfo
    {
        FileName = executable,
        Arguments = arguments,
        UseShellExecute = false,
        RedirectStandardOutput = interceptOutput
    };
    if (workingDirectory != null)
    {
        startInfo.WorkingDirectory = workingDirectory;
    }

    var process = Process.Start(startInfo)!;

    if (interceptOutput)
    {
        string? line;
        while ((line = process.StandardOutput.ReadLine()) != null)
        {
            Reporter.WriteVerbose(line);
        }
    }

    process.WaitForExit();

    return process.ExitCode;
}

private static string ToArguments(IReadOnlyList<string> args)
{
    var builder = new StringBuilder();
    for (var i = 0; i < args.Count; i++)
    {
        if (i != 0)
        {
            builder.Append(' ');
        }

        if (args[i].Length == 0)
        {
            builder.Append("\"\"");

            continue;
        }

        if (args[i].IndexOf(' ') == -1)
        {
            builder.Append(args[i]);

            continue;
        }

        builder.Append('"');

        var pendingBackslashes = 0;
        for (var j = 0; j < args[i].Length; j++)
        {
            switch (args[i][j])
            {
                case '\"':
                    if (pendingBackslashes != 0)
                    {
                        builder.Append('\\', pendingBackslashes * 2);
                        pendingBackslashes = 0;
                    }

                    builder.Append("\\\"");
                    break;

                case '\\':
                    pendingBackslashes++;
                    break;

                default:
                    if (pendingBackslashes != 0)
                    {
                        if (pendingBackslashes == 1)
                        {
                            builder.Append('\\');
                        }
                        else
                        {
                            builder.Append('\\', pendingBackslashes * 2);
                        }

                        pendingBackslashes = 0;
                    }

                    builder.Append(args[i][j]);
                    break;
            }
        }

        if (pendingBackslashes != 0)
        {
            builder.Append('\\', pendingBackslashes * 2);
        }

        builder.Append('"');
    }

    return builder.ToString();
}

}


Running this command, takes exactly the same amount of time as dotnet build, ~3 seconds. I cannot find anything from the source code of dotnet ef that it would do anything differently than this minimal console app. Does dotnet build behave differently within the context of a "tool" ? How come it is three times as slow, consistently? Anyone on the team, @ajcvickers perhaps, could shed some light on this?

[Suchiman]

One thing i've noticed in my first analysis was that the command is running with the MSBUILDUSESERVER=0 environment variable set, which means it would need to boot up VBCSCompiler fresh every time which might explain it taking so much longer. Although i've tried issuing dotnet build with that env variable set and it didn't really seem to have an effect on build time or the outcome of the up-to-date check

It is slower than building within Visual Studio itself, where it only needs ~1.5 seconds for the same up-to-date check

That is not entirely true, it's not the same check, VS has something called the "fast up-to-date-check" where it bypasses MSBuild entirely and judges if a project is up-to-date on its own. That can be turned off though if needed.

[Suchiman]

I have identified the issue, it's this piece of code:

efcore/src/dotnet-ef/Project.cs

Lines 56 to 66 in 9a1b7fc

	var efTargetsPath = Path.Combine(
	buildExtensionsDir,
	Path.GetFileName(file) + ".EntityFrameworkCore.targets");
	using (var input = typeof(Resources).Assembly.GetManifestResourceStream(
	"Microsoft.EntityFrameworkCore.Tools.Resources.EntityFrameworkCore.targets")!)
	using (var output = File.OpenWrite(efTargetsPath))
	{
	// NB: Copy always in case it changes
	Reporter.WriteVerbose(Resources.WritingFile(efTargetsPath));
	input.CopyTo(output);
	}

which writes a .target file into the obj directory on every tool invocation, thus always bumping its last modified timestamp and thus always failing the up-to-date check.

The reason for that is explained as well as // NB: Copy always in case it changes but that's a hefty price to pay.
There are two ways to resolve this IMO:

1. Do not override the file if it already exists and rely on the user to clean the project if it's not working right (i think that's in the toolbelt of every VS developer to just nuke obj and bin if things are not working as expected).
2. Read the existing file and check if it matches the file we expect to be there, only (over)write the file if it doesn't match what we expect. The file in question is less than 2kb in size, it would hardly matter for performance in comparison to always doing a project rebuild

@ajcvickers is any of these options acceptable and would be accepted as a PR?

[ajcvickers]

We had a discussion on this in the team yesterday. In general, we don't want to make changes here just for perf. In other words, the bottom line is that it should be as reliable as possible, even if that's slower than it needs to be. The reason for this is that anybody is free to do their own thing and use --no-build. And this can even be added to a script if desired.

We have a history of changes in MSBUILD and tooling impact what we do, especially when we try to be clever and do something non-standard. So, I can see we might accept a PR that removed some cleverness, as long as the impact is good or not too bad, but I suspect we would reject anything that added in any cleverness.

[joakimriedel]

We had a discussion on this in the team yesterday. In general, we don't want to make changes here just for perf. In other words, the bottom line is that it should be as reliable as possible, even if that's slower than it needs to be. The reason for this is that anybody is free to do their own thing and use --no-build. And this can even be added to a script if desired.

I tried with --no-build and it seems as if some of the project's dependencies are still affected by the tool, probably the .target file mentioned above, which leads to the project not being up to date after executing dotnet ef.

> dotnet build

<build completed>

> dotnet ef migrations list --no-build

<results>

> dotnet build

<starts building, project not up-to-date>

[Mike-E-angelo]

Awesome, thank you so much to @Suchiman and the team there for all your work in diagnosing and addressing this. 🙏 Adding migrations is becoming quite the pain point for me lately, taking many minutes to both build and optimize the model after the change. Any improvement to this process is greatly appreciated and welcomed.