Merge pull request #8216 from drewnoakes/fix-8213-extend-telemetry

Extend fast up-to-date check telemetry

src/Microsoft.VisualStudio.ProjectSystem.Managed.VS/ProjectSystem/VS/Debug/StartupProjectRegistrar.cs

@@ -58,7 +58,7 @@ public Task InitializeAsync()
 
         protected override async Task InitializeCoreAsync(CancellationToken cancellationToken)
         {
-            _projectGuid = await _projectGuidService.GetProjectGuidAsync();
+            _projectGuid = await _projectGuidService.GetProjectGuidAsync(cancellationToken);
 
             Assumes.False(_projectGuid == Guid.Empty);
 

src/Microsoft.VisualStudio.ProjectSystem.Managed/ProjectSystem/ISafeProjectGuidService.cs

@@ -30,6 +30,6 @@ internal interface ISafeProjectGuidService
         /// <exception cref="OperationCanceledException">
         ///     The project was unloaded before project load had finished.
         /// </exception>
-        Task<Guid> GetProjectGuidAsync();
+        Task<Guid> GetProjectGuidAsync(CancellationToken cancellationToken = default);
     }
 }

src/Microsoft.VisualStudio.ProjectSystem.Managed/ProjectSystem/UpToDate/BuildUpToDateCheck.Log.cs

@@ -12,26 +12,30 @@ private sealed class Log
             private readonly TextWriter _writer;
             private readonly Stopwatch _stopwatch;
             private readonly TimestampCache _timestampCache;
+            private readonly Guid _projectGuid;
             private readonly string _fileName;
             private readonly ITelemetryService? _telemetryService;
             private readonly UpToDateCheckConfiguredInput _upToDateCheckConfiguredInput;
             private readonly string? _ignoreKinds;
+            private readonly int _checkNumber;
 
             public LogLevel Level { get; }
 
             public int Indent { get; set; }
 
             public string? FailureReason { get; private set; }
 
-            public Log(TextWriter writer, LogLevel requestedLogLevel, Stopwatch stopwatch, TimestampCache timestampCache, string projectPath, ITelemetryService? telemetryService, UpToDateCheckConfiguredInput upToDateCheckConfiguredInput, string? ignoreKinds)
+            public Log(TextWriter writer, LogLevel requestedLogLevel, Stopwatch stopwatch, TimestampCache timestampCache, string projectPath, Guid projectGuid, ITelemetryService? telemetryService, UpToDateCheckConfiguredInput upToDateCheckConfiguredInput, string? ignoreKinds, int checkNumber)
             {
                 _writer = writer;
                 Level = requestedLogLevel;
                 _stopwatch = stopwatch;
                 _timestampCache = timestampCache;
+                _projectGuid = projectGuid;
                 _telemetryService = telemetryService;
                 _upToDateCheckConfiguredInput = upToDateCheckConfiguredInput;
                 _ignoreKinds = ignoreKinds;
+                _checkNumber = checkNumber;
                 _fileName = Path.GetFileNameWithoutExtension(projectPath);
             }
 
@@ -159,6 +163,8 @@ public bool Fail(string reason, string resourceName, params object[] values)
                     (TelemetryPropertyName.UpToDateCheckFileCount, _timestampCache.Count),
                     (TelemetryPropertyName.UpToDateCheckConfigurationCount, _upToDateCheckConfiguredInput.ImplicitInputs.Length),
                     (TelemetryPropertyName.UpToDateCheckLogLevel, Level),
+                    (TelemetryPropertyName.UpToDateCheckProject, _projectGuid),
+                    (TelemetryPropertyName.UpToDateCheckNumber, _checkNumber),
                     (TelemetryPropertyName.UpToDateCheckIgnoreKinds, _ignoreKinds ?? "")
                 });
 
@@ -181,6 +187,8 @@ public void UpToDate()
                     (TelemetryPropertyName.UpToDateCheckFileCount, _timestampCache.Count),
                     (TelemetryPropertyName.UpToDateCheckConfigurationCount, _upToDateCheckConfiguredInput.ImplicitInputs.Length),
                     (TelemetryPropertyName.UpToDateCheckLogLevel, Level),
+                    (TelemetryPropertyName.UpToDateCheckProject, _projectGuid),
+                    (TelemetryPropertyName.UpToDateCheckNumber, _checkNumber),
                     (TelemetryPropertyName.UpToDateCheckIgnoreKinds, _ignoreKinds ?? "")
                 });
 

src/Microsoft.VisualStudio.ProjectSystem.Managed/ProjectSystem/UpToDate/BuildUpToDateCheck.cs

@@ -48,6 +48,7 @@ internal sealed partial class BuildUpToDateCheck
         private readonly IProjectAsynchronousTasksService _tasksService;
         private readonly ITelemetryService _telemetryService;
         private readonly IFileSystem _fileSystem;
+        private readonly ISafeProjectGuidService _guidService;
         private readonly IUpToDateCheckHost _upToDateCheckHost;
 
         private IImmutableDictionary<string, string> _lastGlobalProperties = ImmutableStringDictionary<string>.EmptyOrdinal;
@@ -56,6 +57,7 @@ internal sealed partial class BuildUpToDateCheck
 
         private ISubscription _subscription;
         private int _isDisposed;
+        private int _checkNumber;
 
         [ImportingConstructor]
         public BuildUpToDateCheck(
@@ -66,6 +68,7 @@ public BuildUpToDateCheck(
             [Import(ExportContractNames.Scopes.ConfiguredProject)] IProjectAsynchronousTasksService tasksService,
             ITelemetryService telemetryService,
             IFileSystem fileSystem,
+            ISafeProjectGuidService guidService,
             IUpToDateCheckHost upToDateCheckHost)
         {
             _inputDataSource = inputDataSource;
@@ -75,6 +78,7 @@ public BuildUpToDateCheck(
             _tasksService = tasksService;
             _telemetryService = telemetryService;
             _fileSystem = fileSystem;
+            _guidService = guidService;
             _upToDateCheckHost = upToDateCheckHost;
             _subscription = new Subscription(inputDataSource, configuredProject, upToDateCheckHost, persistence);
         }
@@ -848,8 +852,21 @@ private async Task<bool> IsUpToDateInternalAsync(
 
                 globalProperties.TryGetValue(FastUpToDateCheckIgnoresKindsGlobalPropertyName, out string? ignoreKindsString);
 
-                LogLevel requestedLogLevel = await _projectSystemOptions.GetFastUpToDateLoggingLevelAsync(token);
-                var logger = new Log(logWriter, requestedLogLevel, sw, timestampCache, _configuredProject.UnconfiguredProject.FullPath ?? "", isValidationRun ? null : _telemetryService, state, ignoreKindsString);
+                (LogLevel requestedLogLevel, Guid projectGuid) = await WhenAll(
+                    _projectSystemOptions.GetFastUpToDateLoggingLevelAsync(token),
+                    _guidService.GetProjectGuidAsync(token));
+
+                var logger = new Log(
+                    logWriter,
+                    requestedLogLevel,
+                    sw,
+                    timestampCache,
+                    _configuredProject.UnconfiguredProject.FullPath ?? "",
+                    projectGuid,
+                    isValidationRun ? null : _telemetryService,
+                    state,
+                    ignoreKindsString,
+                    isValidationRun ? -1 : Interlocked.Increment(ref _checkNumber));
 
                 try
                 {
@@ -923,6 +940,13 @@ private async Task<bool> IsUpToDateInternalAsync(
                     _lastFailureReason = logger.FailureReason ?? "";
                 }
             }
+
+            static async Task<(T1, T2)> WhenAll<T1, T2>(Task<T1> t1, Task<T2> t2)
+            {
+                await Task.WhenAll(t1, t2);
+
+                return (await t1, await t2);
+            }
         }
 
         public Task<bool> IsUpToDateCheckEnabledAsync(CancellationToken cancellationToken = default)

src/Microsoft.VisualStudio.ProjectSystem.Managed/ProjectSystem/VsSafeProjectGuidService.cs

@@ -1,5 +1,7 @@
 // Licensed to the .NET Foundation under one or more agreements. The .NET Foundation licenses this file to you under the MIT license. See the LICENSE.md file in the project root for more information.
 
+using Microsoft.VisualStudio.Threading;
+
 namespace Microsoft.VisualStudio.ProjectSystem.VS
 {
     /// <summary>
@@ -24,9 +26,9 @@ public VsSafeProjectGuidService(UnconfiguredProject project, IUnconfiguredProjec
         [ImportMany]
         public OrderPrecedenceImportCollection<IProjectGuidService> ProjectGuidServices { get; }
 
-        public async Task<Guid> GetProjectGuidAsync()
+        public async Task<Guid> GetProjectGuidAsync(CancellationToken cancellationToken = default)
         {
-            await _tasksService.PrioritizedProjectLoadedInHost;
+            await _tasksService.PrioritizedProjectLoadedInHost.WithCancellation(cancellationToken);
 
 #pragma warning disable RS0030 // IProjectGuidService is banned
             IProjectGuidService? projectGuidService = ProjectGuidServices.FirstOrDefault()?.Value;

src/Microsoft.VisualStudio.ProjectSystem.Managed/Telemetry/TelemetryPropertyName.cs

@@ -50,6 +50,17 @@ internal static class TelemetryPropertyName
         /// </summary>
         public const string UpToDateCheckIgnoreKinds = Prefix + ".uptodatecheck.ignorekinds";
 
+        /// <summary>
+        ///     Identifies the project to which data in the telemetry event applies.
+        /// </summary>
+        public const string UpToDateCheckProject = Prefix + ".uptodatecheck.projectid";
+
+        /// <summary>
+        ///     Indicates the number of checks performed for this project so far in the current session, starting at one.
+        ///     This number resets when the project is reloaded.
+        /// </summary>
+        public const string UpToDateCheckNumber = Prefix + ".uptodatecheck.checknumber";
+
         /// <summary>
         ///     Indicates the project when the dependency tree is updated with all resolved dependencies.
         /// </summary>

tests/Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests/Mocks/ISafeProjectGuidServiceFactory.cs

@@ -7,7 +7,7 @@ internal static class ISafeProjectGuidServiceFactory
         public static ISafeProjectGuidService ImplementGetProjectGuidAsync(Guid guid)
         {
             var mock = new Mock<ISafeProjectGuidService>();
-            mock.Setup(s => s.GetProjectGuidAsync())
+            mock.Setup(s => s.GetProjectGuidAsync(It.IsAny<CancellationToken>()))
                 .ReturnsAsync(guid);
 
             return mock.Object;

tests/Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests/ProjectSystem/UpToDate/BuildUpToDateCheckTests.cs

@@ -84,6 +84,8 @@ public BuildUpToDateCheckTests(ITestOutputHelper output)
             projectAsynchronousTasksService.SetupGet(s => s.UnloadCancellationToken).Returns(CancellationToken.None);
             projectAsynchronousTasksService.Setup(s => s.IsTaskQueueEmpty(ProjectCriticalOperation.Build)).Returns(() => _isTaskQueueEmpty);
 
+            var guidService = ISafeProjectGuidServiceFactory.ImplementGetProjectGuidAsync(Guid.NewGuid());
+
             _fileSystem = new IFileSystemMock();
             _fileSystem.AddFolder(_projectDir);
             _fileSystem.AddFile(_projectPath, _projectFileTimeUtc);
@@ -98,6 +100,7 @@ public BuildUpToDateCheckTests(ITestOutputHelper output)
                 projectAsynchronousTasksService.Object,
                 ITelemetryServiceFactory.Create(_telemetryEvents.Add),
                 _fileSystem,
+                guidService,
                 upToDateCheckHost.Object);
         }
 
@@ -1923,7 +1926,7 @@ private void AssertTelemetryFailureEvent(string reason, string ignoreKinds)
 
             Assert.Equal(TelemetryEventName.UpToDateCheckFail, telemetryEvent.EventName);
             Assert.NotNull(telemetryEvent.Properties);
-            Assert.Equal(6, telemetryEvent.Properties.Count);
+            Assert.Equal(8, telemetryEvent.Properties.Count);
 
             var reasonProp = Assert.Single(telemetryEvent.Properties.Where(p => p.propertyName == TelemetryPropertyName.UpToDateCheckFailReason));
             Assert.Equal(reason, reasonProp.propertyValue);
@@ -1948,6 +1951,9 @@ private void AssertTelemetryFailureEvent(string reason, string ignoreKinds)
             var ignoreKindsStr = Assert.IsType<string>(ignoreKindsProp.propertyValue);
             Assert.Equal(ignoreKinds, ignoreKindsStr);
 
+            Assert.Single(telemetryEvent.Properties.Where(p => p.propertyName == TelemetryPropertyName.UpToDateCheckProject));
+            Assert.Single(telemetryEvent.Properties.Where(p => p.propertyName == TelemetryPropertyName.UpToDateCheckNumber));
+
             _telemetryEvents.Clear();
         }
 
@@ -1958,7 +1964,7 @@ private void AssertTelemetrySuccessEvent(string ignoreKinds)
             Assert.Equal(TelemetryEventName.UpToDateCheckSuccess, telemetryEvent.EventName);
 
             Assert.NotNull(telemetryEvent.Properties);
-            Assert.Equal(5, telemetryEvent.Properties.Count);
+            Assert.Equal(7, telemetryEvent.Properties.Count);
 
             var durationProp = Assert.Single(telemetryEvent.Properties.Where(p => p.propertyName == TelemetryPropertyName.UpToDateCheckDurationMillis));
             var duration = Assert.IsType<double>(durationProp.propertyValue);
@@ -1980,6 +1986,9 @@ private void AssertTelemetrySuccessEvent(string ignoreKinds)
             var ignoreKindsStr = Assert.IsType<string>(ignoreKindsProp.propertyValue);
             Assert.Equal(ignoreKinds, ignoreKindsStr);
 
+            Assert.Single(telemetryEvent.Properties.Where(p => p.propertyName == TelemetryPropertyName.UpToDateCheckProject));
+            Assert.Single(telemetryEvent.Properties.Where(p => p.propertyName == TelemetryPropertyName.UpToDateCheckNumber));
+
             _telemetryEvents.Clear();
         }
 

tests/Microsoft.VisualStudio.ProjectSystem.Managed.VS.UnitTests/Telemetry/SDKVersionTelemetryTests.cs

@@ -100,7 +100,7 @@ private static IUnconfiguredProjectVsServices CreateProjectServices(string? vers
         private static ISafeProjectGuidService CreateISafeProjectGuidService(Guid guid)
         {
             var mock = new Mock<ISafeProjectGuidService>();
-            mock.Setup(s => s.GetProjectGuidAsync())
+            mock.Setup(s => s.GetProjectGuidAsync(It.IsAny<CancellationToken>()))
                 .ReturnsAsync(guid);
 
             return mock.Object;