1

Author: tmat

src/BuiltInTools/dotnet-watch/HotReload/HotReloadDotNetWatcher.cs

@@ -189,7 +189,7 @@ void FileChangedCallback(ChangedPath change)
 
                     fileChangedCallback = FileChangedCallback;
                     fileWatcher.OnFileChange += fileChangedCallback;
-                    ReportWatchingForChanges();
+                    _context.Logger.Log(MessageDescriptor.WaitingForChanges);
 
                     // Hot Reload loop - exits when the root process needs to be restarted.
                     bool extendTimeout = false;
@@ -772,12 +772,6 @@ internal static IEnumerable<ChangedPath> NormalizePathChanges(IEnumerable<Change
                 .Where(item => item != null)
                 .Select(item => item!.Value);
 
-        private void ReportWatchingForChanges()
-        {
-            _context.Logger.Log(MessageDescriptor.WaitingForChanges
-                .WithSeverityWhen(MessageSeverity.Output, _context.EnvironmentOptions.TestFlags.HasFlag(TestFlags.ElevateWaitingForChangesMessageSeverity)));
-        }
-
         private void ReportFileChanges(IReadOnlyList<ChangedFile> changedFiles)
         {
             Report(kind: ChangeKind.Add);
@@ -823,6 +817,9 @@ private async ValueTask<EvaluationResult> EvaluateRootProjectAsync(bool restore,
             {
                 cancellationToken.ThrowIfCancellationRequested();
 
+                _context.Logger.LogInformation("Evaluating projects ...");
+                var stopwatch = Stopwatch.StartNew();
+
                 var result = EvaluationResult.TryCreate(
                     _context.RootProjectOptions.ProjectPath,
                     _context.RootProjectOptions.BuildArguments,
@@ -832,6 +829,8 @@ private async ValueTask<EvaluationResult> EvaluateRootProjectAsync(bool restore,
                     restore,
                     cancellationToken);
 
+                _context.Logger.LogInformation("Evaluation completed in {Time}ms.", stopwatch.ElapsedMilliseconds);
+
                 if (result != null)
                 {
                     return result;

src/BuiltInTools/dotnet-watch/HotReload/IncrementalMSBuildWorkspace.cs

@@ -15,6 +15,7 @@ namespace Microsoft.DotNet.Watch;
 internal sealed class IncrementalMSBuildWorkspace : Workspace
 {
     private readonly ILogger _logger;
+    private int _solutionUpdateId;
 
     public IncrementalMSBuildWorkspace(ILogger logger)
         : base(MSBuildMefHostServices.DefaultServices, WorkspaceKind.MSBuild)
@@ -35,6 +36,9 @@ public IncrementalMSBuildWorkspace(ILogger logger)
 
     public async Task UpdateProjectConeAsync(string rootProjectPath, CancellationToken cancellationToken)
     {
+        _logger.LogInformation("Loading projects ...");
+
+        var stopwatch = Stopwatch.StartNew();
         var oldSolution = CurrentSolution;
 
         var loader = new MSBuildProjectLoader(this);
@@ -94,9 +98,11 @@ public async Task UpdateProjectConeAsync(string rootProjectPath, CancellationTok
                 .WithCompilationOutputInfo(newProjectInfo.CompilationOutputInfo));
         }
 
-        await ReportSolutionFilesAsync(SetCurrentSolution(newSolution), cancellationToken);
+        await UpdateSolutionAsync(newSolution, operationDisplayName: "project update", cancellationToken);
         UpdateReferencesAfterAdd();
 
+        _logger.LogInformation("Projects loaded in {Time}ms.", stopwatch.ElapsedMilliseconds);
+
         ProjectReference MapProjectReference(ProjectReference pr)
             // Only C# and VB projects are loaded by the MSBuildProjectLoader, so some references might be missing.
             // When a new project is added along with a new project reference the old project id is also null.
@@ -154,6 +160,8 @@ public async ValueTask UpdateFileContentAsync(IEnumerable<ChangedFile> changedFi
 
                 var newText = await GetSourceTextAsync(changedFile.FilePath, oldText.Encoding, oldText.ChecksumAlgorithm, cancellationToken);
 
+                _logger.LogDebug("Updating document text of '{FilePath}'.", changedFile.FilePath);
+
                 updatedSolution = textDocument switch
                 {
                     Document document => document.WithText(newText).Project.Solution,
@@ -166,7 +174,7 @@ public async ValueTask UpdateFileContentAsync(IEnumerable<ChangedFile> changedFi
 
         updatedSolution = RemoveDocuments(updatedSolution, documentsToRemove);
 
-        await ReportSolutionFilesAsync(SetCurrentSolution(updatedSolution), cancellationToken);
+        await UpdateSolutionAsync(updatedSolution, operationDisplayName: "document update", cancellationToken);
     }
 
     private static Solution RemoveDocuments(Solution solution, IEnumerable<DocumentId> ids)
@@ -217,9 +225,19 @@ private static async ValueTask<SourceText> GetSourceTextAsync(string filePath, E
         return null;
     }
 
-    public async Task ReportSolutionFilesAsync(Solution solution, CancellationToken cancellationToken)
+    private Task UpdateSolutionAsync(Solution newSolution, string operationDisplayName, CancellationToken cancellationToken)
+        => ReportSolutionFilesAsync(SetCurrentSolution(newSolution), Interlocked.Increment(ref _solutionUpdateId), operationDisplayName, cancellationToken);
+
+    private async Task ReportSolutionFilesAsync(Solution solution, int updateId, string operationDisplayName, CancellationToken cancellationToken)
     {
-        _logger.LogDebug("Solution: {Path}", solution.FilePath);
+        //if (!_logger.IsEnabled(LogLevel.Debug))
+        //{
+        //    return;
+        //}
+
+        var stopwatch = Stopwatch.StartNew();
+
+        _logger.LogDebug("Solution after {Operation}: v{Version}", operationDisplayName, updateId);
         foreach (var project in solution.Projects)
         {
             _logger.LogDebug("  Project: {Path}", project.FilePath);
@@ -240,6 +258,8 @@ public async Task ReportSolutionFilesAsync(Solution solution, CancellationToken
             }
         }
 
+        _logger.LogInformation("Solution reported in {Time}ms.", stopwatch.ElapsedMilliseconds);
+
         async ValueTask InspectDocumentAsync(TextDocument document, string kind)
         {
             var text = await document.GetTextAsync(cancellationToken);

src/BuiltInTools/dotnet-watch/Properties/launchSettings.json

@@ -3,7 +3,7 @@
     "dotnet-watch": {
       "commandName": "Project",
       "commandLineArgs": "--verbose -bl",
-      "workingDirectory": "C:\\bugs\\9756\\aspire-watch-start-issue\\Aspire.AppHost",
+      "workingDirectory": "C:\\temp\\Razor",
       "environmentVariables": {
         "DOTNET_WATCH_DEBUG_SDK_DIRECTORY": "$(RepoRoot)artifacts\\bin\\redist\\$(Configuration)\\dotnet\\sdk\\$(Version)",
         "DCP_IDE_REQUEST_TIMEOUT_SECONDS": "100000",

src/BuiltInTools/dotnet-watch/UI/IReporter.cs

@@ -186,7 +186,7 @@ public MessageDescriptor WithSeverityWhen(MessageSeverity severity, bool conditi
         public static readonly MessageDescriptor ProjectsRestarted = Create("Projects restarted ({0})", Emoji.HotReload, MessageSeverity.Verbose);
         public static readonly MessageDescriptor ProjectDependenciesDeployed = Create("Project dependencies deployed ({0})", Emoji.HotReload, MessageSeverity.Verbose);
         public static readonly MessageDescriptor FixBuildError = Create("Fix the error to continue or press Ctrl+C to exit.", Emoji.Watch, MessageSeverity.Warning);
-        public static readonly MessageDescriptor WaitingForChanges = Create("Waiting for changes", Emoji.Watch, MessageSeverity.Verbose);
+        public static readonly MessageDescriptor WaitingForChanges = Create("Waiting for changes", Emoji.Watch, MessageSeverity.Output);
         public static readonly MessageDescriptor LaunchedProcess = Create("Launched '{0}' with arguments '{1}': process id {2}", Emoji.Launch, MessageSeverity.Verbose);
         public static readonly MessageDescriptor HotReloadChangeHandled = Create("Hot reload change handled in {0}ms.", Emoji.HotReload, MessageSeverity.Verbose);
         public static readonly MessageDescriptor HotReloadSucceeded = Create(LogEvents.HotReloadSucceeded, Emoji.HotReload);