Add support for vs code markers (#3399)

* Add Microsoft.VisualStudio.Utilities to package references.
* Add API to log telemetry markers.
* Implement posting the code marker.
* Emit a code marker at start of TelemetryActivity.
* Use scoped ETW activity instead of singular events.
* Reuse common prefix.
* Add activity unit tests for TelemetryActivity.
* Bracket complete activity, including timekeeping operations, inside code markers.

Co-authored-by: Srdjan Jovčić <srdjanj@microsoft.com>

build/packages.targets

@@ -60,6 +60,7 @@
         <PackageReference Update="Microsoft.VisualStudio.Threading" Version="$(VSThreadingVersion)" />
         <PackageReference Update="Microsoft.VisualStudio.Threading.Analyzers" Version="$(VSThreadingVersion)" />
         <PackageReference Update="Microsoft.VisualStudio.Workspace.VSIntegration" Version="16.3.43" />
+        <PackageReference Update="Microsoft.VisualStudio.Utilities" Version="16.5.29714.20" />
         <PackageReference Update="Microsoft.Web.Xdt" Version="2.1.2" />
         <PackageReference Update="Newtonsoft.Json" Version="$(NewtonsoftJsonPackageVersion)" />
         <PackageReference Update="System.Collections.Immutable" Version="1.5.0" />

src/NuGet.Clients/NuGet.VisualStudio.Common/GlobalSuppressions.cs

@@ -59,3 +59,4 @@
 [assembly: SuppressMessage("Build", "CA1062:In externally visible method 'void OutputConsoleLogger.Log(ILogMessage message)', validate parameter 'message' is non-null before using it. If appropriate, throw an ArgumentNullException when the argument is null or add a Code Contract precondition asserting non-null argument.", Justification = "<Pending>", Scope = "member", Target = "~M:NuGet.VisualStudio.Common.OutputConsoleLogger.Log(NuGet.Common.ILogMessage)")]
 [assembly: SuppressMessage("Build", "CA1823:Unused field 'LogEntrySource'.", Justification = "<Pending>", Scope = "member", Target = "~F:NuGet.VisualStudio.Common.OutputConsoleLogger.LogEntrySource")]
 [assembly: SuppressMessage("Build", "CA1063:Provide an overridable implementation of Dispose(bool) on 'OutputConsoleLogger' or mark the type as sealed. A call to Dispose(false) should only clean up native resources. A call to Dispose(true) should clean up both managed and native resources.", Justification = "<Pending>", Scope = "type", Target = "~T:NuGet.VisualStudio.Common.OutputConsoleLogger")]
+[assembly: SuppressMessage("Globalization", "CA1308:Normalize strings to uppercase", Justification = "Need to unify event names to be same as ones produced from telemetry.", Scope = "member", Target = "~M:NuGet.VisualStudio.NuGetVSTelemetryService.StartActivity(System.String)~System.IDisposable")]

src/NuGet.Clients/NuGet.VisualStudio.Common/NuGet.VisualStudio.Common.csproj

@@ -43,6 +43,7 @@
     <PackageReference Include="Microsoft.VisualStudio.ImageCatalog" />
     <PackageReference Include="Microsoft.VisualStudio.Threading" />
     <PackageReference Include="Microsoft.VisualStudio.Threading.Analyzers" />
+    <PackageReference Include="Microsoft.VisualStudio.Utilities" />
     <PackageReference Include="Newtonsoft.Json" NoWarn="NU1605" />
     <PackageReference Include="VSLangProj" />
     <PackageReference Include="System.Collections.Immutable" />

src/NuGet.Clients/NuGet.VisualStudio.Common/Telemetry/NuGetVSActionTelemetryService.cs

@@ -2,6 +2,7 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
+using Microsoft.Internal.VisualStudio.Diagnostics;
 using NuGet.Common;
 using NuGet.VisualStudio.Telemetry;
 
@@ -33,5 +34,33 @@ public virtual void EmitTelemetryEvent(TelemetryEvent telemetryData)
 
             _telemetrySession.PostEvent(telemetryData);
         }
+
+        public virtual IDisposable StartActivity(string activityName)
+        {
+            if (activityName == null)
+            {
+                throw new ArgumentNullException(nameof(activityName));
+            }
+
+            return new EtwLogActivity((VSTelemetrySession.VSEventNamePrefix + activityName).ToLowerInvariant().Replace('/', '_'));
+        }
+
+        private class EtwLogActivity : IDisposable
+        {
+            private readonly VsEtwActivity _activity;
+
+            public EtwLogActivity(string activityName)
+            {
+                if (VsEtwLogging.IsProviderEnabled(VsEtwKeywords.Ide, VsEtwLevel.Information))
+                {
+                    _activity = VsEtwLogging.CreateActivity(activityName, VsEtwKeywords.Ide, VsEtwLevel.Information);
+                }
+            }
+
+            void IDisposable.Dispose()
+            {
+                _activity?.Dispose();
+            }
+        }
     }
 }

src/NuGet.Core/NuGet.Common/Telemetry/INuGetTelemetryService.cs

@@ -1,13 +1,20 @@
 // 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;
 
 namespace NuGet.Common
 {
+    /// <summary> Abstraction of NuGet telemetry service. </summary>
     public interface INuGetTelemetryService
     {
+        /// <summary> Send a <see cref="TelemetryEvent"/> to VS telemetry. </summary>
+        /// <param name="telemetryData"> Telemetry event to send. </param>
         void EmitTelemetryEvent(TelemetryEvent telemetryData);
+
+        /// <summary> Log a start of telemetry activity to the event log. </summary>
+        /// <param name="activityName"> Name of telemetry activity to log. </param>
+        /// <returns> <see cref="IDisposable"/> which will log end activity marker. </returns>
+        IDisposable StartActivity(string activityName);
     }
 }

src/NuGet.Core/NuGet.Common/Telemetry/TelemetryActivity.cs

@@ -13,6 +13,7 @@ public class TelemetryActivity : IDisposable
         private readonly Stopwatch _stopwatch;
         private readonly Stopwatch _intervalWatch = new Stopwatch();
         private readonly List<Tuple<string, TimeSpan>> _intervalList;
+        private readonly IDisposable _telemetryActivity;
 
         public TelemetryEvent TelemetryEvent { get; set; }
 
@@ -42,6 +43,11 @@ public TelemetryActivity(Guid parentId, Guid operationId, TelemetryEvent telemet
 
         private TelemetryActivity(Guid parentId, TelemetryEvent telemetryEvent, Guid operationId)
         {
+            if (telemetryEvent != null)
+            {
+                _telemetryActivity = NuGetTelemetryService?.StartActivity(telemetryEvent.Name);
+            }
+
             TelemetryEvent = telemetryEvent;
             ParentId = parentId;
             OperationId = operationId;
@@ -90,6 +96,8 @@ public void Dispose()
 
                 NuGetTelemetryService.EmitTelemetryEvent(TelemetryEvent);
             }
+
+            _telemetryActivity?.Dispose();
         }
 
         public static void EmitTelemetryEvent(TelemetryEvent TelemetryEvent)

test/NuGet.Core.Tests/NuGet.Common.Test/TelemetryActivityTests.cs

@@ -13,14 +13,25 @@ namespace NuGet.Common.Test
 {
     public class TelemetryActivityTests
     {
-        private readonly Mock<INuGetTelemetryService> _telemetryService = new Mock<INuGetTelemetryService>();
+        private readonly Mock<INuGetTelemetryService> _telemetryService = new Mock<INuGetTelemetryService>(MockBehavior.Strict);
         private TelemetryEvent _telemetryEvent;
 
+        private readonly Mock<IDisposable> _activity = new Mock<IDisposable>(MockBehavior.Strict);
+        private bool _activityDisposed;
+        private string _activityName;
+
         public TelemetryActivityTests()
         {
             _telemetryService.Setup(x => x.EmitTelemetryEvent(It.IsAny<TelemetryEvent>()))
                 .Callback<TelemetryEvent>(x => _telemetryEvent = x);
 
+            _telemetryService.Setup(x => x.StartActivity(It.IsAny<string>()))
+                .Callback<string>(x => _activityName = x)
+                .Returns(_activity.Object);
+
+            _activity.Setup(x => x.Dispose())
+                     .Callback(() => _activityDisposed = true);
+
             TelemetryActivity.NuGetTelemetryService = _telemetryService.Object;
         }
 
@@ -125,6 +136,26 @@ public void Dispose_Always_EmitsDuration()
             Assert.InRange(duration, 0d, 10d);
         }
 
+        [Fact]
+        public void Create_will_start_activity()
+        {
+            using (var telemetry = TelemetryActivity.Create(CreateNewTelemetryEvent()))
+            {
+            }
+
+            Assert.Equal("testEvent", _activityName);
+        }
+
+        [Fact]
+        public void Dispose_will_dispose_activity()
+        {
+            using (var telemetry = TelemetryActivity.Create(CreateNewTelemetryEvent()))
+            {
+            }
+
+            Assert.True(_activityDisposed);
+        }
+
         private static TelemetryEvent CreateNewTelemetryEvent()
         {
             return new TelemetryEvent("testEvent", new Dictionary<string, object>());