Merge pull request #39560 from dotnet/merges/release/dev16.4-to-master

Merge release/dev16.4 to master

src/EditorFeatures/Core/Implementation/CodeFixes/CodeFixService.cs

@@ -14,6 +14,7 @@
 using Microsoft.CodeAnalysis.ErrorLogger;
 using Microsoft.CodeAnalysis.Extensions;
 using Microsoft.CodeAnalysis.Host.Mef;
+using Microsoft.CodeAnalysis.Internal.Log;
 using Microsoft.CodeAnalysis.PooledObjects;
 using Microsoft.CodeAnalysis.Shared.Extensions;
 using Microsoft.CodeAnalysis.Shared.Utilities;
@@ -303,15 +304,17 @@ public async Task<Document> ApplyCodeFixesForSpecificDiagnosticIdAsync(Document
                     hasFix: d => this.GetFixableDiagnosticIds(fixer, extensionManager).Contains(d.Id),
                     getFixes: dxs =>
                     {
-                        if (fixAllForInSpan)
+                        using (RoslynEventSource.LogInformationalBlock(FunctionId.CodeFixes_GetCodeFixesAsync, fixer, cancellationToken))
                         {
-                            var primaryDiagnostic = dxs.First();
-                            return GetCodeFixesAsync(document, primaryDiagnostic.Location.SourceSpan, fixer, isBlocking, ImmutableArray.Create(primaryDiagnostic), cancellationToken);
-
-                        }
-                        else
-                        {
-                            return GetCodeFixesAsync(document, span, fixer, isBlocking, dxs, cancellationToken);
+                            if (fixAllForInSpan)
+                            {
+                                var primaryDiagnostic = dxs.First();
+                                return GetCodeFixesAsync(document, primaryDiagnostic.Location.SourceSpan, fixer, isBlocking, ImmutableArray.Create(primaryDiagnostic), cancellationToken);
+                            }
+                            else
+                            {
+                                return GetCodeFixesAsync(document, span, fixer, isBlocking, dxs, cancellationToken);
+                            }
                         }
                     },
                     cancellationToken: cancellationToken).ConfigureAwait(false);
@@ -357,12 +360,15 @@ public async Task<Document> ApplyCodeFixesForSpecificDiagnosticIdAsync(Document
             // append CodeFixCollection for each CodeFixProvider
             foreach (var provider in lazyConfigurationProviders.Value)
             {
-                await AppendFixesOrConfigurationsAsync(
-                    document, diagnosticsSpan, diagnostics, fixAllForInSpan: false, result, provider,
-                    hasFix: d => provider.IsFixableDiagnostic(d),
-                    getFixes: dxs => provider.GetFixesAsync(
-                        document, diagnosticsSpan, dxs, cancellationToken),
-                    cancellationToken: cancellationToken).ConfigureAwait(false);
+                using (RoslynEventSource.LogInformationalBlock(FunctionId.CodeFixes_GetCodeFixesAsync, provider, cancellationToken))
+                {
+                    await AppendFixesOrConfigurationsAsync(
+                        document, diagnosticsSpan, diagnostics, fixAllForInSpan: false, result, provider,
+                        hasFix: d => provider.IsFixableDiagnostic(d),
+                        getFixes: dxs => provider.GetFixesAsync(
+                            document, diagnosticsSpan, dxs, cancellationToken),
+                        cancellationToken: cancellationToken).ConfigureAwait(false);
+                }
             }
         }
 

src/Features/Core/Portable/CodeRefactorings/CodeRefactoringService.cs

@@ -111,7 +111,14 @@ private IEnumerable<CodeRefactoringProvider> GetProviders(Document document)
                 foreach (var provider in GetProviders(document))
                 {
                     tasks.Add(Task.Run(
-                        () => GetRefactoringFromProviderAsync(document, state, provider, extensionManager, isBlocking, cancellationToken), cancellationToken));
+                        () =>
+                        {
+                            using (RoslynEventSource.LogInformationalBlock(FunctionId.Refactoring_CodeRefactoringService_GetRefactoringsAsync, provider, cancellationToken))
+                            {
+                                return GetRefactoringFromProviderAsync(document, state, provider, extensionManager, isBlocking, cancellationToken);
+                            }
+                        },
+                        cancellationToken));
                 }
 
                 var results = await Task.WhenAll(tasks).ConfigureAwait(false);

src/Features/Core/Portable/Diagnostics/EngineV2/DiagnosticIncrementalAnalyzer_GetDiagnosticsForSpan.cs

@@ -4,10 +4,12 @@
 using System.Collections.Generic;
 using System.Collections.Immutable;
 using System.Diagnostics;
+using System.Diagnostics.Tracing;
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.CodeAnalysis.ErrorReporting;
+using Microsoft.CodeAnalysis.Internal.Log;
 using Microsoft.CodeAnalysis.LanguageServices;
 using Microsoft.CodeAnalysis.Shared.Extensions;
 using Microsoft.CodeAnalysis.Text;
@@ -111,32 +113,35 @@ public async Task<bool> TryGetAsync(List<DiagnosticData> list, CancellationToken
                     var containsFullResult = true;
                     foreach (var stateSet in _stateSets)
                     {
-                        cancellationToken.ThrowIfCancellationRequested();
-
-                        containsFullResult &= await TryGetSyntaxAndSemanticDiagnosticsAsync(stateSet, list, cancellationToken).ConfigureAwait(false);
-
-                        // check whether compilation end code fix is enabled
-                        if (!_document.Project.Solution.Workspace.Options.GetOption(InternalDiagnosticsOptions.CompilationEndCodeFix))
+                        using (RoslynEventSource.LogInformationalBlock(FunctionId.DiagnosticAnalyzerService_GetDiagnosticsForSpanAsync, stateSet.Analyzer, cancellationToken))
                         {
-                            continue;
-                        }
+                            cancellationToken.ThrowIfCancellationRequested();
 
-                        // check whether heuristic is enabled
-                        if (_blockForData && _document.Project.Solution.Workspace.Options.GetOption(InternalDiagnosticsOptions.UseCompilationEndCodeFixHeuristic))
-                        {
-                            var avoidLoadingData = true;
-                            var state = stateSet.GetProjectState(_project.Id);
-                            var result = await state.GetAnalysisDataAsync(_document, avoidLoadingData, cancellationToken).ConfigureAwait(false);
+                            containsFullResult &= await TryGetSyntaxAndSemanticDiagnosticsAsync(stateSet, list, cancellationToken).ConfigureAwait(false);
 
-                            // no previous compilation end diagnostics in this file.
-                            var version = await GetDiagnosticVersionAsync(_project, cancellationToken).ConfigureAwait(false);
-                            if (state.IsEmpty(_document.Id) || result.Version != version)
+                            // check whether compilation end code fix is enabled
+                            if (!_document.Project.Solution.Workspace.Options.GetOption(InternalDiagnosticsOptions.CompilationEndCodeFix))
                             {
                                 continue;
                             }
-                        }
 
-                        containsFullResult &= await TryGetProjectDiagnosticsAsync(stateSet, GetProjectDiagnosticsAsync, list, cancellationToken).ConfigureAwait(false);
+                            // check whether heuristic is enabled
+                            if (_blockForData && _document.Project.Solution.Workspace.Options.GetOption(InternalDiagnosticsOptions.UseCompilationEndCodeFixHeuristic))
+                            {
+                                var avoidLoadingData = true;
+                                var state = stateSet.GetProjectState(_project.Id);
+                                var result = await state.GetAnalysisDataAsync(_document, avoidLoadingData, cancellationToken).ConfigureAwait(false);
+
+                                // no previous compilation end diagnostics in this file.
+                                var version = await GetDiagnosticVersionAsync(_project, cancellationToken).ConfigureAwait(false);
+                                if (state.IsEmpty(_document.Id) || result.Version != version)
+                                {
+                                    continue;
+                                }
+                            }
+
+                            containsFullResult &= await TryGetProjectDiagnosticsAsync(stateSet, GetProjectDiagnosticsAsync, list, cancellationToken).ConfigureAwait(false);
+                        }
                     }
 
                     // if we are blocked for data, then we should always have full result.

src/Workspaces/Core/Portable/Log/EtwLogger.cs

@@ -40,18 +40,18 @@ public void Log(FunctionId functionId, LogMessage logMessage)
 
         public void LogBlockStart(FunctionId functionId, LogMessage logMessage, int uniquePairId, CancellationToken cancellationToken)
         {
-            RoslynEventSource.Instance.BlockStart(GetMessage(logMessage), functionId, uniquePairId);
+            _source.BlockStart(GetMessage(logMessage), functionId, uniquePairId);
         }
 
         public void LogBlockEnd(FunctionId functionId, LogMessage logMessage, int uniquePairId, int delta, CancellationToken cancellationToken)
         {
             if (cancellationToken.IsCancellationRequested)
             {
-                RoslynEventSource.Instance.BlockCanceled(functionId, delta, uniquePairId);
+                _source.BlockCanceled(functionId, delta, uniquePairId);
             }
             else
             {
-                RoslynEventSource.Instance.BlockStop(functionId, delta, uniquePairId);
+                _source.BlockStop(functionId, delta, uniquePairId);
             }
         }
 

src/Workspaces/Core/Portable/Log/FunctionId.cs

@@ -466,5 +466,8 @@ internal enum FunctionId
         Liveshare_SyntacticTagger,
 
         CommandHandler_GoToBase,
+
+        DiagnosticAnalyzerService_GetDiagnosticsForSpanAsync,
+        CodeFixes_GetCodeFixesAsync,
     }
 }

src/Workspaces/Core/Portable/Log/RoslynEventSource.LogBlock.cs

+// Copyright (c) Microsoft.  All Rights Reserved.  Licensed under the Apache License, Version 2.0.  See License.txt in the project root for license information.
+
+#nullable enable
+
+using System;
+using System.Diagnostics;
+using System.Diagnostics.Tracing;
+using System.Threading;
+
+namespace Microsoft.CodeAnalysis.Internal.Log
+{
+    internal partial class RoslynEventSource
+    {
+        /// <summary>
+        /// Logs an informational block with given <paramref name="entity"/>'s <see cref="object.ToString"/> representation as the message
+        /// and specified <paramref name="functionId"/>.
+        /// On dispose of the returned disposable object, it logs the 'tick' count between the start and end of the block.
+        /// Unlike other logging methods on <see cref="RoslynEventSource"/>, this method does not check
+        /// if the specified <paramref name="functionId"/> was explicitly enabled.
+        /// Instead it checks if the <see cref="RoslynEventSource"/> was enabled at <see cref="EventLevel.Informational"/> level.
+        /// </summary>
+        public static LogBlock LogInformationalBlock(FunctionId functionId, object entity, CancellationToken cancellationToken)
+            => LogBlock.Create(functionId, entity, EventLevel.Informational, cancellationToken);
+
+        /// <summary>
+        /// Logs an informational message block with the given <paramref name="message"/>> and specified <paramref name="functionId"/>.
+        /// On dispose of the returned disposable object, it logs the 'tick' count between the start and end of the block.
+        /// Unlike other logging methods on <see cref="RoslynEventSource"/>, this method does not check
+        /// if the specified <paramref name="functionId"/> was explicitly enabled.
+        /// Instead it checks if the <see cref="RoslynEventSource"/> was enabled at <see cref="EventLevel.Informational"/> level.
+        /// </summary>
+        public static LogBlock LogInformationalBlock(FunctionId functionId, string message, CancellationToken cancellationToken)
+            => LogBlock.Create(functionId, message, EventLevel.Informational, cancellationToken);
+
+        /// <summary>
+        /// This tracks the logged message. On instantiation, it logs 'Started block' with other event data.
+        /// On dispose, it logs 'Ended block' with the same event data so we can track which block started and ended when looking at logs.
+        /// </summary>
+        internal struct LogBlock : IDisposable
+        {
+            private readonly FunctionId _functionId;
+            private readonly object? _entityForMessage;
+            private readonly EventLevel _eventLevel;
+            private readonly int _blockId;
+            private readonly CancellationToken _cancellationToken;
+
+            private int _tick;
+            private bool _startLogged;
+            private string? _message;
+
+            /// <summary>
+            /// next unique block id that will be given to each LogBlock
+            /// </summary>
+            private static int s_lastUniqueBlockId;
+
+            private LogBlock(
+                FunctionId functionId,
+                string? message,
+                object? entityForMessage,
+                EventLevel eventLevel,
+                int blockId,
+                CancellationToken cancellationToken)
+            {
+                Debug.Assert(message != null || entityForMessage != null);
+
+                _functionId = functionId;
+                _message = message;
+                _entityForMessage = entityForMessage;
+                _eventLevel = eventLevel;
+                _blockId = blockId;
+                _cancellationToken = cancellationToken;
+                _tick = Environment.TickCount;
+                _startLogged = false;
+            }
+
+            public static LogBlock Create(
+                FunctionId functionId,
+                object entityForMessage,
+                EventLevel eventLevel,
+                CancellationToken cancellationToken)
+            {
+                var blockId = GetNextUniqueBlockId();
+                var logBlock = new LogBlock(functionId, message: null, entityForMessage, eventLevel, blockId, cancellationToken);
+                logBlock.OnStart();
+                return logBlock;
+            }
+
+            public static LogBlock Create(
+                FunctionId functionId,
+                string message,
+                EventLevel eventLevel,
+                CancellationToken cancellationToken)
+            {
+                var blockId = GetNextUniqueBlockId();
+                var logBlock = new LogBlock(functionId, message, entityForMessage: null, eventLevel, blockId, cancellationToken);
+                logBlock.OnStart();
+                return logBlock;
+            }
+
+            /// <summary>
+            /// return next unique pair id
+            /// </summary>
+            private static int GetNextUniqueBlockId()
+            {
+                return Interlocked.Increment(ref s_lastUniqueBlockId);
+            }
+
+            private void OnStart()
+            {
+                if (EnsureMessageIfLoggingEnabled())
+                {
+                    Debug.Assert(_message != null);
+                    Debug.Assert(!_startLogged);
+
+                    Instance.BlockStart(_message, _functionId, _blockId);
+                    _startLogged = true;
+                }
+            }
+
+            private bool EnsureMessageIfLoggingEnabled()
+            {
+                if (Instance.IsEnabled(_eventLevel, EventKeywords.None))
+                {
+                    _message ??= (_entityForMessage?.ToString() ?? string.Empty);
+                    return true;
+                }
+
+                return false;
+            }
+
+            public void Dispose()
+            {
+                if (!EnsureMessageIfLoggingEnabled())
+                {
+                    return;
+                }
+
+                Debug.Assert(_message != null);
+
+                if (!_startLogged)
+                {
+                    // User enabled logging after the block start.
+                    // We log a block start to log the message along with the block ID.
+                    Instance.BlockStart(_message, _functionId, _blockId);
+                    _startLogged = true;
+                }
+
+                // This delta is valid for durations of < 25 days
+                var delta = Environment.TickCount - _tick;
+
+                if (_cancellationToken.IsCancellationRequested)
+                {
+                    Instance.BlockCanceled(_functionId, delta, _blockId);
+                }
+                else
+                {
+                    Instance.BlockStop(_functionId, delta, _blockId);
+                }
+            }
+        }
+    }
+}

src/Workspaces/Core/Portable/Log/RoslynEventSource.cs

@@ -20,7 +20,7 @@ namespace Microsoft.CodeAnalysis.Internal.Log
     /// "\\clrmain\tools\managed\etw\eventRegister\bin\Debug\eventRegister.exe" Microsoft.CodeAnalysis.Workspaces.dll
     /// </summary>
     [EventSource(Name = "RoslynEventSource")]
-    internal sealed class RoslynEventSource : EventSource
+    internal sealed partial class RoslynEventSource : EventSource
     {
         // might not "enabled" but we always have this singleton alive
         public static readonly RoslynEventSource Instance = new RoslynEventSource();

src/Workspaces/Core/Portable/Workspace/Host/SyntaxTreeFactory/AbstractSyntaxTreeFactoryService.AbstractRecoverableSyntaxRoot.cs

@@ -3,7 +3,6 @@
 using System;
 using System.Collections.Immutable;
 using System.Diagnostics;
-using System.Diagnostics.Tracing;
 using System.IO;
 using System.Text;
 using System.Threading;
@@ -160,32 +159,11 @@ protected override async Task<TRoot> RecoverAsync(CancellationToken cancellation
             {
                 Contract.ThrowIfNull(_storage);
 
-                var tickCount = Environment.TickCount;
-                try
+                using (RoslynEventSource.LogInformationalBlock(FunctionId.Workspace_Recoverable_RecoverRootAsync, _containingTree.FilePath, cancellationToken))
                 {
-                    if (RoslynEventSource.Instance.IsEnabled(EventLevel.Informational, EventKeywords.None))
-                    {
-                        RoslynEventSource.Instance.BlockStart(_containingTree.FilePath, FunctionId.Workspace_Recoverable_RecoverRootAsync, blockId: 0);
-                    }
-
                     using var stream = await _storage.ReadStreamAsync(cancellationToken).ConfigureAwait(false);
                     return RecoverRoot(stream, cancellationToken);
                 }
-                finally
-                {
-                    if (RoslynEventSource.Instance.IsEnabled(EventLevel.Informational, EventKeywords.None))
-                    {
-                        var tick = Environment.TickCount - tickCount;
-                        if (cancellationToken.IsCancellationRequested)
-                        {
-                            RoslynEventSource.Instance.BlockCanceled(FunctionId.Workspace_Recoverable_RecoverRootAsync, tick, blockId: 0);
-                        }
-                        else
-                        {
-                            RoslynEventSource.Instance.BlockStop(FunctionId.Workspace_Recoverable_RecoverRootAsync, tick, blockId: 0);
-                        }
-                    }
-                }
             }
 
             protected override TRoot Recover(CancellationToken cancellationToken)
@@ -193,31 +171,11 @@ protected override TRoot Recover(CancellationToken cancellationToken)
                 Contract.ThrowIfNull(_storage);
 
                 var tickCount = Environment.TickCount;
-                try
+                using (RoslynEventSource.LogInformationalBlock(FunctionId.Workspace_Recoverable_RecoverRoot, _containingTree.FilePath, cancellationToken))
                 {
-                    if (RoslynEventSource.Instance.IsEnabled(EventLevel.Informational, EventKeywords.None))
-                    {
-                        RoslynEventSource.Instance.BlockStart(_containingTree.FilePath, FunctionId.Workspace_Recoverable_RecoverRoot, blockId: 0);
-                    }
-
                     using var stream = _storage.ReadStream(cancellationToken);
                     return RecoverRoot(stream, cancellationToken);
                 }
-                finally
-                {
-                    if (RoslynEventSource.Instance.IsEnabled(EventLevel.Informational, EventKeywords.None))
-                    {
-                        var tick = Environment.TickCount - tickCount;
-                        if (cancellationToken.IsCancellationRequested)
-                        {
-                            RoslynEventSource.Instance.BlockCanceled(FunctionId.Workspace_Recoverable_RecoverRoot, tick, blockId: 0);
-                        }
-                        else
-                        {
-                            RoslynEventSource.Instance.BlockStop(FunctionId.Workspace_Recoverable_RecoverRoot, tick, blockId: 0);
-                        }
-                    }
-                }
             }
 
             private TRoot RecoverRoot(Stream stream, CancellationToken cancellationToken)