From 106bb59ec199bfee329260f1c50ac41a5b96ded5 Mon Sep 17 00:00:00 2001 From: Nikolche Kolev Date: Mon, 16 Mar 2020 12:55:00 -0700 Subject: [PATCH] Cleanup unnecessary thread affinity in the Visual Studio logging codepath (#3295) --- .../RestoreOperationLogger.cs | 202 +++++++----------- .../RestoreOperationProgressUI.cs | 5 +- .../SolutionRestoreJob.cs | 102 ++++----- 3 files changed, 116 insertions(+), 193 deletions(-) diff --git a/src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationLogger.cs b/src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationLogger.cs index 02cb9e05a11..2935bf63576 100644 --- a/src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationLogger.cs +++ b/src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationLogger.cs @@ -137,9 +137,6 @@ public override void LogInformationSummary(string data) Log(LogLevel.Debug, data); } - /// - /// Same as LogAsync but uses Do instead of DoAsync. - /// public sealed override void Log(ILogMessage logMessage) { HandleErrorsAndWarnings(logMessage); @@ -159,19 +156,16 @@ public sealed override void Log(ILogMessage logMessage) // to actually show it. _loggedMessages.Enqueue(Tuple.Create(reportProgress, showAsOutputMessage, logMessage)); - // Run on the UI thread var _ = _taskFactory.RunAsync(async () => { // capture current progress from the current execution context var progress = RestoreOperationProgressUI.Current; - await _taskFactory.SwitchToMainThreadAsync(); - // This might be a different message than the one enqueued above, but overall the printing order // will match the order of calls to LogAsync. if (_loggedMessages.TryDequeue(out var message)) { - LogToVS(reportProgress: message.Item1, showAsOutputMessage: message.Item2, logMessage: message.Item3, progress: progress); + await LogToVSAsync(reportProgress: message.Item1, showAsOutputMessage: message.Item2, logMessage: message.Item3, progress: progress); } }); } @@ -189,20 +183,20 @@ public sealed override Task LogAsync(ILogMessage logMessage) return Task.CompletedTask; } - private void LogToVS(bool reportProgress, bool showAsOutputMessage, ILogMessage logMessage, RestoreOperationProgressUI progress) + private async Task LogToVSAsync(bool reportProgress, bool showAsOutputMessage, ILogMessage logMessage, RestoreOperationProgressUI progress) { var verbosityLevel = GetMSBuildLevel(logMessage.Level); // Progress dialog if (reportProgress) { - progress?.ReportProgress(logMessage.Message); + await progress?.ReportProgressAsync(logMessage.Message); } // Output console if (showAsOutputMessage) { - WriteLine(verbosityLevel, logMessage.FormatWithCode()); + await WriteLineAsync(verbosityLevel, logMessage.FormatWithCode()); } } @@ -240,14 +234,13 @@ private static bool ShouldReportProgress(ILogMessage logMessage) /// The verbosity level. /// The format string. /// An array of objects to write using format. - public void WriteLine(MSBuildVerbosityLevel verbosity, string format, params object[] args) + public Task WriteLineAsync(MSBuildVerbosityLevel verbosity, string format, params object[] args) { - ThreadHelper.ThrowIfNotOnUIThread(); - if (ShouldShowMessageAsOutput(verbosity)) { - NuGetUIThreadHelper.JoinableTaskFactory.Run(() => _outputConsole.WriteLineAsync(format, args)); + return _outputConsole.WriteLineAsync(format, args); } + return Task.CompletedTask; } /// @@ -284,36 +277,33 @@ public bool ShouldShowMessageAsOutput(MSBuildVerbosityLevel verbosity) return _outputConsole != null && OutputVerbosity >= (int)verbosity; } - public Task LogExceptionAsync(Exception ex) + public async Task LogExceptionAsync(Exception ex) { - return DoAsync((_, __) => + string message; + if (OutputVerbosity < 3) { - string message; - if (OutputVerbosity < 3) - { - message = string.Format(CultureInfo.CurrentCulture, - Resources.ErrorOccurredRestoringPackages, - ex.Message); - } - else - { - // output exception detail when _msBuildOutputVerbosity is >= Detailed. - message = string.Format(CultureInfo.CurrentCulture, Resources.ErrorOccurredRestoringPackages, ex); - } + message = string.Format(CultureInfo.CurrentCulture, + Resources.ErrorOccurredRestoringPackages, + ex.Message); + } + else + { + // output exception detail when _msBuildOutputVerbosity is >= Detailed. + message = string.Format(CultureInfo.CurrentCulture, Resources.ErrorOccurredRestoringPackages, ex); + } - if (_operationSource == RestoreOperationSource.Explicit) - { - // Write to the error window and console - Log(LogMessage.Create(LogLevel.Error, message)); - } - else - { - // Write to console - WriteLine(MSBuildVerbosityLevel.Quiet, message); - } + if (_operationSource == RestoreOperationSource.Explicit) + { + // Write to the error window and console + Log(LogMessage.Create(LogLevel.Error, message)); + } + else + { + // Write to console + await WriteLineAsync(MSBuildVerbosityLevel.Quiet, message); + } - ExceptionHelper.WriteErrorToActivityLog(ex); - }); + ExceptionHelper.WriteErrorToActivityLog(ex); } public void ShowError(string errorText) @@ -330,104 +320,66 @@ public Task WriteHeaderAsync() { _hasHeaderBeenShown = true; - return DoAsync((_, __) => + switch (_operationSource) { - switch (_operationSource) - { - case RestoreOperationSource.Implicit: - WriteLine(MSBuildVerbosityLevel.Normal, Resources.RestoringPackages); - break; - case RestoreOperationSource.OnBuild: - WriteLine(MSBuildVerbosityLevel.Normal, Resources.PackageRestoreOptOutMessage); - break; - case RestoreOperationSource.Explicit: - WriteLine(MSBuildVerbosityLevel.Normal, Resources.RestoringPackages); - break; - } - }); - } - else - { - return Task.CompletedTask; + case RestoreOperationSource.Implicit: + return WriteLineAsync(MSBuildVerbosityLevel.Normal, Resources.RestoringPackages); + case RestoreOperationSource.OnBuild: + return WriteLineAsync(MSBuildVerbosityLevel.Normal, Resources.PackageRestoreOptOutMessage); + case RestoreOperationSource.Explicit: + return WriteLineAsync(MSBuildVerbosityLevel.Normal, Resources.RestoringPackages); + } } + return Task.CompletedTask; } - public Task WriteSummaryAsync(NuGetOperationStatus operationStatus, TimeSpan duration) + public async Task WriteSummaryAsync(NuGetOperationStatus operationStatus, TimeSpan duration) { var forceStatusWrite = _operationSource == RestoreOperationSource.Explicit; var quietOrMinimal = forceStatusWrite ? MSBuildVerbosityLevel.Quiet : MSBuildVerbosityLevel.Minimal; var quietOrNormal = forceStatusWrite ? MSBuildVerbosityLevel.Quiet : MSBuildVerbosityLevel.Normal; var quietOrDetailed = forceStatusWrite ? MSBuildVerbosityLevel.Quiet : MSBuildVerbosityLevel.Detailed; - return DoAsync((_, __) => + switch (operationStatus) { - switch (operationStatus) - { - case NuGetOperationStatus.Cancelled: - WriteLine( - quietOrMinimal, - Resources.PackageRestoreCanceled); - break; - case NuGetOperationStatus.NoOp: - if (forceStatusWrite) - { - WriteLine( + case NuGetOperationStatus.Cancelled: + await WriteLineAsync( + quietOrMinimal, + Resources.PackageRestoreCanceled); + break; + case NuGetOperationStatus.NoOp: + if (forceStatusWrite) + { + await WriteLineAsync( quietOrDetailed, Resources.NothingToRestore); - } - break; - case NuGetOperationStatus.Failed: - WriteLine( + } + break; + case NuGetOperationStatus.Failed: + await WriteLineAsync( quietOrMinimal, Resources.PackageRestoreFinishedWithError); - break; - case NuGetOperationStatus.Succeeded: - WriteLine( + break; + case NuGetOperationStatus.Succeeded: + await WriteLineAsync( quietOrNormal, Resources.PackageRestoreFinished); - break; - } - - if (_operationSource != RestoreOperationSource.OnBuild && (_hasHeaderBeenShown || forceStatusWrite)) - { - WriteLine( - quietOrMinimal, - Resources.Operation_TotalTime, - duration); - WriteLine(quietOrMinimal, Resources.Operation_Finished); - WriteLine(quietOrMinimal, string.Empty); - } - }); - } - - /// - /// Helper async method to run batch of logging call on the main UI thread. - /// - /// Sync callback invoking logger. - /// An awaitable task. - public async Task DoAsync(Action action) - { - // capture current progress from the current execution context - var progress = RestoreOperationProgressUI.Current; - - await _taskFactory.SwitchToMainThreadAsync(); - action(this, progress); - } - - /// - /// Helper synchronous method to run batch of logging call on the main UI thread. - /// - /// Sync callback invoking logger. - public void Do(Action action) - { - // capture current progress from the current execution context - var progress = RestoreOperationProgressUI.Current; + break; + } - _taskFactory.Run(async () => + if (_operationSource != RestoreOperationSource.OnBuild && (_hasHeaderBeenShown || forceStatusWrite)) { - await _taskFactory.SwitchToMainThreadAsync(); - action(this, progress); - }); + // Submit all messages at once. Avoid needless thread switching + var fullMessage = + string.Format(CultureInfo.CurrentCulture, Resources.Operation_TotalTime, duration) + + Environment.NewLine + + Resources.Operation_Finished + + Environment.NewLine + + string.Empty + + Environment.NewLine; + + await WriteLineAsync(quietOrMinimal, fullMessage); + } } public async Task RunWithProgressAsync( @@ -462,7 +414,7 @@ public Task RunWithProgressAsync( /// private async Task GetMSBuildOutputVerbositySettingAsync() { - await NuGetUIThreadHelper.JoinableTaskFactory.SwitchToMainThreadAsync(); + await _taskFactory.SwitchToMainThreadAsync(); var dte = await _asyncServiceProvider.GetDTEAsync(); @@ -565,12 +517,12 @@ public override void Dispose() }); } - public override void ReportProgress( + public override async Task ReportProgressAsync( string progressMessage, uint currentStep, uint totalSteps) { - ThreadHelper.ThrowIfNotOnUIThread(); + await _taskFactory.SwitchToMainThreadAsync(); // When both currentStep and totalSteps are 0, we get a marquee on the dialog var progressData = new ThreadedWaitDialogProgressData( @@ -621,7 +573,7 @@ public static async Task StartAsync( statusBar.Animation(1, ref Icon); RestoreOperationProgressUI progress = new StatusBarProgress(statusBar, jtf); - progress.ReportProgress(Resources.RestoringPackages); + await progress.ReportProgressAsync(Resources.RestoringPackages); return progress; } @@ -639,12 +591,12 @@ public override void Dispose() }); } - public override void ReportProgress( + public override async Task ReportProgressAsync( string progressMessage, uint currentStep, uint totalSteps) { - ThreadHelper.ThrowIfNotOnUIThread(); + await _taskFactory.SwitchToMainThreadAsync(); // Make sure the status bar is not frozen int frozen; diff --git a/src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationProgressUI.cs b/src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationProgressUI.cs index 1bbc05ac9c0..efeb29b19ef 100644 --- a/src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationProgressUI.cs +++ b/src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationProgressUI.cs @@ -1,8 +1,9 @@ -// Copyright (c) .NET Foundation. All rights reserved. +// Copyright (c) .NET Foundation. All rights reserved. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; using System.Threading; +using System.Threading.Tasks; namespace NuGet.SolutionRestoreManager { @@ -24,7 +25,7 @@ public static RestoreOperationProgressUI Current public CancellationToken UserCancellationToken { get; protected set; } = CancellationToken.None; - public abstract void ReportProgress( + public abstract Task ReportProgressAsync( string progressMessage, uint currentStep = 0, uint totalSteps = 0); diff --git a/src/NuGet.Clients/NuGet.SolutionRestoreManager/SolutionRestoreJob.cs b/src/NuGet.Clients/NuGet.SolutionRestoreManager/SolutionRestoreJob.cs index a58c8c9bf70..3c75ec0d62c 100644 --- a/src/NuGet.Clients/NuGet.SolutionRestoreManager/SolutionRestoreJob.cs +++ b/src/NuGet.Clients/NuGet.SolutionRestoreManager/SolutionRestoreJob.cs @@ -175,12 +175,9 @@ private async Task RestoreAsync(bool forceRestore, RestoreOperationSource restor if (projects.Any() && solutionDirectory == null) { - await _logger.DoAsync((l, _) => - { - _status = NuGetOperationStatus.Failed; - l.ShowError(Resources.SolutionIsNotSaved); - l.WriteLine(VerbosityLevel.Minimal, Resources.SolutionIsNotSaved); - }); + _status = NuGetOperationStatus.Failed; + _logger.ShowError(Resources.SolutionIsNotSaved); + await _logger.WriteLineAsync(VerbosityLevel.Minimal, Resources.SolutionIsNotSaved); return; } @@ -300,15 +297,13 @@ private async Task RestorePackageSpecProjectsAsync( var globalPackagesFolder = SettingsUtility.GetGlobalPackagesFolder(_settings); if (!Path.IsPathRooted(globalPackagesFolder)) { - await _logger.DoAsync((l, _) => - { - var message = string.Format( - CultureInfo.CurrentCulture, - Resources.RelativeGlobalPackagesFolder, - globalPackagesFolder); - l.WriteLine(VerbosityLevel.Quiet, message); - }); + var message = string.Format( + CultureInfo.CurrentCulture, + Resources.RelativeGlobalPackagesFolder, + globalPackagesFolder); + + await _logger.WriteLineAsync(VerbosityLevel.Quiet, message); // Cannot restore packages since globalPackagesFolder is a relative path // and the solution is not available @@ -374,11 +369,7 @@ await _logger.RunWithProgressAsync( } else if (restoreSource == RestoreOperationSource.Explicit) { - // Log an error when restore is disabled and user explicitly restore. - await _logger.DoAsync((l, _) => - { - l.ShowError(Resources.PackageRefNotRestoredBecauseOfNoConsent); - }); + _logger.ShowError(Resources.PackageRefNotRestoredBecauseOfNoConsent); } } @@ -392,16 +383,20 @@ private void PackageRestoreManager_PackageRestored( var packageIdentity = args.Package; Interlocked.Increment(ref _currentCount); - _logger.Do((_, progress) => + NuGetUIThreadHelper.JoinableTaskFactory.Run(async () => { - progress?.ReportProgress( - string.Format( - CultureInfo.CurrentCulture, - Resources.RestoredPackage, - packageIdentity), - (uint)_currentCount, - (uint)_missingPackagesCount); + // capture current progress from the current execution context + var progress = RestoreOperationProgressUI.Current; + + await progress?.ReportProgressAsync( + string.Format( + CultureInfo.CurrentCulture, + Resources.RestoredPackage, + packageIdentity), + (uint)_currentCount, + (uint)_missingPackagesCount); }); + } } @@ -437,12 +432,12 @@ private void PackageRestoreManager_PackageRestoreFailedEvent( { _status = NuGetOperationStatus.Failed; - _logger.Do((l, _) => + NuGetUIThreadHelper.JoinableTaskFactory.Run(async () => { foreach (var projectName in args.ProjectNames) { var exceptionMessage = - l.OutputVerbosity >= (int)VerbosityLevel.Detailed + _logger.OutputVerbosity >= (int)VerbosityLevel.Detailed ? args.Exception.ToString() : args.Exception.Message; var message = string.Format( @@ -450,9 +445,9 @@ private void PackageRestoreManager_PackageRestoreFailedEvent( Resources.PackageRestoreFailedForProject, projectName, exceptionMessage); - l.WriteLine(VerbosityLevel.Quiet, message); - l.ShowError(message); - l.WriteLine(VerbosityLevel.Normal, Resources.PackageRestoreFinishedForProject, projectName); + await _logger.WriteLineAsync(VerbosityLevel.Quiet, message); + _logger.ShowError(message); + await _logger.WriteLineAsync(VerbosityLevel.Normal, Resources.PackageRestoreFinishedForProject, projectName); } }); } @@ -483,11 +478,8 @@ private async Task RestorePackagesOrCheckForMissingPackagesAsync( if (!isSolutionAvailable && await CheckPackagesConfigAsync()) { - await _logger.DoAsync((l, _) => - { - l.ShowError(Resources.SolutionIsNotSaved); - l.WriteLine(VerbosityLevel.Quiet, Resources.SolutionIsNotSaved); - }); + _logger.ShowError(Resources.SolutionIsNotSaved); + await _logger.WriteLineAsync(VerbosityLevel.Quiet, Resources.SolutionIsNotSaved); } // Restore is not applicable, since, there is no project with installed packages @@ -569,21 +561,19 @@ private void ValidatePackagesConfigLockFiles(IEnumerable allProjec /// Checks if there are missing packages that should be restored. If so, a warning will /// be added to the error list. /// - private async Task CheckForMissingPackagesAsync(IEnumerable installedPackages) + private Task CheckForMissingPackagesAsync(IEnumerable installedPackages) { var missingPackages = installedPackages.Where(p => p.IsMissing); if (missingPackages.Any()) { - await _logger.DoAsync((l, _) => - { - var errorText = string.Format( - CultureInfo.CurrentCulture, - Resources.PackageNotRestoredBecauseOfNoConsent, - string.Join(", ", missingPackages.Select(p => p.PackageReference.PackageIdentity.ToString()))); - l.ShowError(errorText); - }); + var errorText = string.Format( + CultureInfo.CurrentCulture, + Resources.PackageNotRestoredBecauseOfNoConsent, + string.Join(", ", missingPackages.Select(p => p.PackageReference.PackageIdentity.ToString()))); + _logger.ShowError(errorText); } + return Task.CompletedTask; } private async Task RestoreMissingPackagesInSolutionAsync( @@ -612,26 +602,6 @@ await _packageRestoreManager.RestoreMissingPackagesAsync( } } - /// - /// Returns true if the package restore user consent is granted. - /// - /// True if the package restore user consent is granted. - private static bool IsConsentGranted(ISettings settings) - { - var packageRestoreConsent = new PackageRestoreConsent(settings); - return packageRestoreConsent.IsGranted; - } - - /// - /// Returns true if automatic package restore on build is enabled. - /// - /// True if automatic package restore on build is enabled. - private static bool IsAutomatic(ISettings settings) - { - var packageRestoreConsent = new PackageRestoreConsent(settings); - return packageRestoreConsent.IsAutomatic; - } - private async Task CheckPackagesConfigAsync() { return await NuGetUIThreadHelper.JoinableTaskFactory.RunAsync(async () =>