Add performance tracing

src/Microsoft.DotNet.Cli.Utils/Command.cs

@@ -128,6 +128,8 @@ namespace Microsoft.DotNet.Cli.Utils
             var sw = Stopwatch.StartNew();
             Reporter.Verbose.WriteLine($"> {FormatProcessInfo(_process.StartInfo)}".White());
 #endif
+            using (PerfTrace.Current.CaptureTiming($"{Path.GetFileNameWithoutExtension(_process.StartInfo.FileName)} {_process.StartInfo.Arguments}"))
+            {
                 _process.Start();
 
                 Reporter.Verbose.WriteLine($"Process ID: {_process.Id}");
@@ -137,6 +139,7 @@ namespace Microsoft.DotNet.Cli.Utils
                 _process.WaitForExit();
 
                 Task.WaitAll(taskOut, taskErr);
+            }
 
             var exitCode = _process.ExitCode;
 

src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTrace.cs

@@ -0,0 +1,34 @@
+// Copyright (c) .NET Foundation and contributors. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+
+using System;
+using System.Collections.Concurrent;
+using System.Collections.Generic;
+using System.Threading;
+
+namespace Microsoft.DotNet.Cli.Utils
+{
+    public static class PerfTrace
+    {
+        private static ConcurrentBag<PerfTraceThreadContext> _threads = new ConcurrentBag<PerfTraceThreadContext>();
+
+        [ThreadStatic]
+        private static PerfTraceThreadContext _current;
+
+        public static bool Enabled { get; set; }
+
+        public static PerfTraceThreadContext Current => _current ?? (_current = InitializeCurrent());
+
+        private static PerfTraceThreadContext InitializeCurrent()
+        {
+            var context = new PerfTraceThreadContext(Thread.CurrentThread.ManagedThreadId);
+            _threads.Add(context);
+            return context;
+        }
+
+        public static IEnumerable<PerfTraceThreadContext> GetEvents()
+        {
+            return _threads;
+        }
+    }
+}

src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTraceEvent.cs

@@ -0,0 +1,27 @@
+// Copyright (c) .NET Foundation and contributors. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+
+using System;
+using System.Collections.Generic;
+using System.Linq;
+
+namespace Microsoft.DotNet.Cli.Utils
+{
+    public class PerfTraceEvent
+    {
+        public string Type { get; }
+        public string Instance { get; }
+        public DateTime StartUtc { get; }
+        public TimeSpan Duration { get; }
+        public IList<PerfTraceEvent> Children { get; }
+
+        public PerfTraceEvent(string type, string instance, IEnumerable<PerfTraceEvent> children, DateTime startUtc, TimeSpan duration)
+        {
+            Type = type;
+            Instance = instance;
+            StartUtc = startUtc;
+            Duration = duration;
+            Children = children.OrderBy(e => e.StartUtc).ToList();
+        }
+    }
+}

src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTraceOutput.cs

@@ -0,0 +1,81 @@
+// Copyright (c) .NET Foundation and contributors. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Text;
+
+namespace Microsoft.DotNet.Cli.Utils
+{
+    public class PerfTraceOutput
+    {
+        private static TimeSpan _minDuration = TimeSpan.FromSeconds(0.001);
+
+        public static void Print(Reporter reporter, IEnumerable<PerfTraceThreadContext> contexts)
+        {
+            foreach (var threadContext in contexts)
+            {
+                Print(reporter, new[] { threadContext.Root }, threadContext.Root, null);
+            }
+        }
+
+        private static void Print(Reporter reporter, IEnumerable<PerfTraceEvent> events, PerfTraceEvent root, PerfTraceEvent parent, int padding = 0)
+        {
+            foreach (var e in events)
+            {
+                if (e.Duration < _minDuration)
+                {
+                    continue;
+                }
+                reporter.Write(new string(' ', padding));
+                reporter.WriteLine(FormatEvent(e, root, parent));
+                Print(reporter, e.Children, root, e, padding + 2);
+            }
+        }
+
+        private static string FormatEvent(PerfTraceEvent e, PerfTraceEvent root, PerfTraceEvent parent)
+        {
+            var builder = new StringBuilder();
+            FormatEventTimeStat(builder, e, root, parent);
+            builder.Append($" {e.Type.Bold()} {e.Instance}");
+            return builder.ToString();
+        }
+
+        private static void FormatEventTimeStat(StringBuilder builder, PerfTraceEvent e, PerfTraceEvent root, PerfTraceEvent parent)
+        {
+            builder.Append("[");
+            if (root != e)
+            {
+                AppendTime(builder, e.Duration.TotalSeconds / root.Duration.TotalSeconds, 0.2);
+            }
+            AppendTime(builder, e.Duration.TotalSeconds / parent?.Duration.TotalSeconds, 0.5);
+            builder.Append($"{e.Duration.ToString("ss\\.fff\\s").Blue()}]");
+        }
+
+        private static void AppendTime(StringBuilder builder, double? percent, double treshold)
+        {
+            if (percent != null)
+            {
+                var formattedPercent = $"{percent*100:00\\.00%}";
+                if (percent > treshold)
+                {
+                    builder.Append(formattedPercent.Red());
+                }
+                else if (percent > treshold / 2)
+                {
+                    builder.Append(formattedPercent.Yellow());
+                }
+                else if (percent > treshold / 5)
+                {
+                    builder.Append(formattedPercent.Green());
+                }
+                else
+                {
+                    builder.Append(formattedPercent);
+                }
+                builder.Append(" ");
+            }
+        }
+    }
+}

src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTraceThreadContext.cs

@@ -0,0 +1,76 @@
+// Copyright (c) .NET Foundation and contributors. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+
+using System;
+using System.Collections.Concurrent;
+using System.Diagnostics;
+using System.IO;
+using System.Runtime.CompilerServices;
+using System.Threading;
+
+namespace Microsoft.DotNet.Cli.Utils
+{
+    public class PerfTraceThreadContext
+    {
+        private readonly int _threadId;
+
+        private TimerDisposable _activeEvent;
+
+        public PerfTraceEvent Root => _activeEvent.CreateEvent();
+
+        public PerfTraceThreadContext(int threadId)
+        {
+            _activeEvent = new TimerDisposable(this, "Thread", $"{threadId.ToString()}");
+            _threadId = threadId;
+        }
+
+        public IDisposable CaptureTiming(string instance = "", [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "")
+        {
+            if(!PerfTrace.Enabled)
+            {
+                return null;
+            }
+
+            var newTimer = new TimerDisposable(this, $"{Path.GetFileNameWithoutExtension(filePath)}:{memberName}", instance);
+            var previousTimer = Interlocked.Exchange(ref _activeEvent, newTimer);
+            newTimer.Parent = previousTimer;
+            return newTimer;
+        }
+
+        private void RecordTiming(PerfTraceEvent newEvent, TimerDisposable parent)
+        {
+            Interlocked.Exchange(ref _activeEvent, parent);
+            _activeEvent.Children.Add(newEvent);
+        }
+
+        private class TimerDisposable : IDisposable
+        {
+            private readonly PerfTraceThreadContext _context;
+            private string _eventType;
+            private string _instance;
+            private DateTime _startUtc;
+            private Stopwatch _stopwatch = Stopwatch.StartNew();
+
+            public TimerDisposable Parent { get; set; }
+
+            public ConcurrentBag<PerfTraceEvent> Children { get; set; } = new ConcurrentBag<PerfTraceEvent>();
+
+            public TimerDisposable(PerfTraceThreadContext context, string eventType, string instance)
+            {
+                _context = context;
+                _eventType = eventType;
+                _instance = instance;
+                _startUtc = DateTime.UtcNow;
+            }
+
+            public void Dispose()
+            {
+                _stopwatch.Stop();
+
+                _context.RecordTiming(CreateEvent(), Parent);
+            }
+
+            public PerfTraceEvent CreateEvent() => new PerfTraceEvent(_eventType, _instance, Children, _startUtc, _stopwatch.Elapsed);
+        }
+    }
+}

src/dotnet/ITelemetry.cs

@@ -8,6 +8,8 @@ namespace Microsoft.DotNet.Cli
 {
     public interface ITelemetry
     {
+        bool Enabled { get; }
+
         void TrackEvent(string eventName, IDictionary<string, string> properties, IDictionary<string, double> measurements);
     }
 }

src/dotnet/Program.cs

@@ -42,17 +42,33 @@ namespace Microsoft.DotNet.Cli
         {
             DebugHelper.HandleDebugSwitch(ref args);
 
+            if (Env.GetEnvironmentVariableAsBool("DOTNET_CLI_CAPTURE_TIMING", false))
+            {
+                PerfTrace.Enabled = true;
+            }
+
             InitializeProcess();
 
             try
             {
-                return Program.ProcessArgs(args, new Telemetry());
+                using (PerfTrace.Current.CaptureTiming())
+                {
+                    return ProcessArgs(args, new Telemetry());
+                }
             }
             catch (GracefulException e)
             {
                 Console.WriteLine(e.Message.Red().Bold());
                 return 1;
             }
+            finally
+            {
+                if (PerfTrace.Enabled)
+                {
+                    Reporter.Output.WriteLine("Performance Summary:");
+                    PerfTraceOutput.Print(Reporter.Output, PerfTrace.GetEvents());
+                }
+            }
         }
 
         internal static int ProcessArgs(string[] args, ITelemetry telemetryClient)
@@ -107,6 +123,7 @@ namespace Microsoft.DotNet.Cli
             if (verbose.HasValue)
             {
                 Environment.SetEnvironmentVariable(CommandContext.Variables.Verbose, verbose.ToString());
+                Console.WriteLine($"Telemetry is: {(telemetryClient.Enabled ? "Enabled" : "Disabled")}");
             }
 
             if (string.IsNullOrEmpty(command))
@@ -141,6 +158,7 @@ namespace Microsoft.DotNet.Cli
 
         }
 
+
         private static void InitializeProcess()
         {
             // by default, .NET Core doesn't have all code pages needed for Console apps.

src/dotnet/Telemetry.cs

@@ -22,16 +22,20 @@ namespace Microsoft.DotNet.Cli
         private const string RuntimeId = "Runtime Id";
         private const string ProductVersion = "Product Version";
 
+        public bool Enabled { get; }
+
         public Telemetry()
         {
-            bool optout = Env.GetEnvironmentVariableAsBool(TelemetryOptout);
+            Enabled = !Env.GetEnvironmentVariableAsBool(TelemetryOptout);
 
-            if (optout)
+            if (!Enabled)
             {
                 return;
             }
 
             try
+            {
+                using (PerfTrace.Current.CaptureTiming())
                 {
                     _client = new TelemetryClient();
                     _client.InstrumentationKey = InstrumentationKey;
@@ -46,6 +50,7 @@ namespace Microsoft.DotNet.Cli
                     _commonProperties.Add(RuntimeId, runtimeEnvironment.GetRuntimeIdentifier());
                     _commonProperties.Add(ProductVersion, Product.Version);
                     _commonMeasurements = new Dictionary<string, double>();
+                }
 
                 _isInitialized = true;
             }
@@ -64,6 +69,8 @@ namespace Microsoft.DotNet.Cli
                 return;
             }
 
+            using (PerfTrace.Current.CaptureTiming())
+            {
                 Dictionary<string, double> eventMeasurements = GetEventMeasures(measurements);
                 Dictionary<string, string> eventProperties = GetEventProperties(properties);
 
@@ -77,6 +84,7 @@ namespace Microsoft.DotNet.Cli
                     Debug.Fail("Exception during TrackEvent");
                 }
             }
+        }
 
 
         private Dictionary<string, double> GetEventMeasures(IDictionary<string, double> measurements)

src/dotnet/commands/dotnet-build/Program.cs

@@ -48,8 +48,17 @@ namespace Microsoft.DotNet.Tools.Build
                 !builderCommandApp.ShouldSkipDependencies,
                 (project, target) => args.Workspace.GetProjectContext(project, target));
 
-            var contexts = ResolveRootContexts(files, frameworks, args);
+            IEnumerable<ProjectContext> contexts;
-            var graph = graphCollector.Collect(contexts).ToArray();
+            using (PerfTrace.Current.CaptureTiming(string.Empty, nameof(ResolveRootContexts)))
+            {
+                contexts = ResolveRootContexts(files, frameworks, args);
+            }
+
+            ProjectGraphNode[] graph;
+            using (PerfTrace.Current.CaptureTiming(string.Empty, "Collect graph"))
+            {
+                graph = graphCollector.Collect(contexts).ToArray();
+            }
             var builder = new DotNetProjectBuilder(builderCommandApp);
             return builder.Build(graph).ToArray().All(r => r != CompilationResult.Failure);
         }
@@ -63,7 +72,11 @@ namespace Microsoft.DotNet.Tools.Build
 
             foreach (var file in files)
             {
-                var project = args.Workspace.GetProject(file);
+                Project project;
+                using (PerfTrace.Current.CaptureTiming(file, "Loading project.json"))
+                {
+                    project = args.Workspace.GetProject(file);
+                }
                 var projectFrameworks = project.GetTargetFrameworks().Select(f => f.FrameworkName);
                 if (!projectFrameworks.Any())
                 {
@@ -92,7 +105,10 @@ namespace Microsoft.DotNet.Tools.Build
                     tasks.Add(Task.Run(() => args.Workspace.GetProjectContext(file, framework)));
                 }
             }
+            using (PerfTrace.Current.CaptureTiming(string.Empty, "Waiting for project contexts to finish loading"))
+            {
                 return Task.WhenAll(tasks).GetAwaiter().GetResult();
             }
         }
+    }
 }

src/dotnet/commands/dotnet-build/ProjectBuilder.cs

@@ -7,6 +7,8 @@ using System.Linq;
 using Microsoft.DotNet.ProjectModel;
 using Microsoft.DotNet.ProjectModel.Files;
 using NuGet.Frameworks;
+using Microsoft.DotNet.Cli.Utils;
+using Microsoft.DotNet.Cli.Compiler.Common;
 
 namespace Microsoft.DotNet.Tools.Build
 {
@@ -17,10 +19,13 @@ namespace Microsoft.DotNet.Tools.Build
         public IEnumerable<CompilationResult> Build(IEnumerable<ProjectGraphNode> roots)
         {
             foreach (var projectNode in roots)
+            {
+                using (PerfTrace.Current.CaptureTiming($"{projectNode.ProjectContext.ProjectName()}"))
                 {
                     yield return Build(projectNode);
                 }
             }
+        }
 
         public CompilationResult? GetCompilationResult(ProjectGraphNode projectNode)
         {
@@ -68,18 +73,33 @@ namespace Microsoft.DotNet.Tools.Build
             }
 
             var context = projectNode.ProjectContext;
+            using (PerfTrace.Current.CaptureTiming($"{projectNode.ProjectContext.ProjectName()}", nameof(HasSourceFiles)))
+            {
                 if (!HasSourceFiles(context))
                 {
                     return CompilationResult.IncrementalSkip;
                 }
+            }
 
-            if (NeedsRebuilding(projectNode))
+            bool needsRebuilding;
+            using (PerfTrace.Current.CaptureTiming($"{projectNode.ProjectContext.ProjectName()}", nameof(NeedsRebuilding)))
+            {
+                needsRebuilding = NeedsRebuilding(projectNode);
+            }
+
+            if (needsRebuilding)
+            {
+                using (PerfTrace.Current.CaptureTiming($"{projectNode.ProjectContext.ProjectName()}",nameof(RunCompile)))
                 {
                     return RunCompile(projectNode);
                 }
+            }
             else
+            {
+                using (PerfTrace.Current.CaptureTiming($"{projectNode.ProjectContext.ProjectName()}", nameof(ProjectSkiped)))
                 {
                     ProjectSkiped(projectNode);
+                }
                 return CompilationResult.IncrementalSkip;
             }
         }

src/dotnet/commands/dotnet-build/ProjectGraphNode.cs

@@ -1,6 +1,7 @@
 // Copyright (c) .NET Foundation and contributors. All rights reserved.
 // Licensed under the MIT license. See LICENSE file in the project root for full license information.
 
+using Microsoft.DotNet.Cli.Utils;
 using Microsoft.DotNet.ProjectModel;
 using System;
 using System.Collections.Generic;
@@ -20,7 +21,16 @@ namespace Microsoft.DotNet.Tools.Build
             IsRoot = isRoot;
         }
 
-        public ProjectContext ProjectContext { get { return _projectContextCreator.GetAwaiter().GetResult(); } }
+        public ProjectContext ProjectContext
+        {
+            get
+            {
+                using (_projectContextCreator.IsCompleted ? null : PerfTrace.Current.CaptureTiming("", "Blocking ProjectContext wait"))
+                {
+                    return _projectContextCreator.GetAwaiter().GetResult();
+                }
+            }
+        }
 
         public IReadOnlyList<ProjectGraphNode> Dependencies { get; }
 

test/dotnet.Tests/TelemetryCommandTest.cs

@@ -14,7 +14,10 @@ namespace Microsoft.DotNet.Tests
 {
     public class MockTelemetry : ITelemetry
     {
-        public string EventName{get;set;}
+        public bool Enabled { get; set; }
+
+        public string EventName { get; set; }
+
         public void TrackEvent(string eventName, IDictionary<string, string> properties, IDictionary<string, double> measurements)
         {
             EventName = eventName;