diff --git a/src/Microsoft.DotNet.Cli.Utils/Command.cs b/src/Microsoft.DotNet.Cli.Utils/Command.cs index 058109c8e..24837d76e 100644 --- a/src/Microsoft.DotNet.Cli.Utils/Command.cs +++ b/src/Microsoft.DotNet.Cli.Utils/Command.cs @@ -92,16 +92,16 @@ namespace Microsoft.DotNet.Cli.Utils { return new Command(commandSpec); } - + public static Command CreateForScript( - string commandName, - IEnumerable args, - Project project, + string commandName, + IEnumerable args, + Project project, string[] inferredExtensionList) { - var commandSpec = CommandResolver.TryResolveScriptCommandSpec(commandName, - args, - project, + var commandSpec = CommandResolver.TryResolveScriptCommandSpec(commandName, + args, + project, inferredExtensionList); if (commandSpec == null) @@ -128,15 +128,18 @@ namespace Microsoft.DotNet.Cli.Utils var sw = Stopwatch.StartNew(); Reporter.Verbose.WriteLine($"> {FormatProcessInfo(_process.StartInfo)}".White()); #endif - _process.Start(); + using (PerfTrace.Current.CaptureTiming($"{Path.GetFileNameWithoutExtension(_process.StartInfo.FileName)} {_process.StartInfo.Arguments}")) + { + _process.Start(); - Reporter.Verbose.WriteLine($"Process ID: {_process.Id}"); + Reporter.Verbose.WriteLine($"Process ID: {_process.Id}"); - var taskOut = _stdOut.BeginRead(_process.StandardOutput); - var taskErr = _stdErr.BeginRead(_process.StandardError); - _process.WaitForExit(); + var taskOut = _stdOut.BeginRead(_process.StandardOutput); + var taskErr = _stdErr.BeginRead(_process.StandardError); + _process.WaitForExit(); - Task.WaitAll(taskOut, taskErr); + Task.WaitAll(taskOut, taskErr); + } var exitCode = _process.ExitCode; diff --git a/src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTrace.cs b/src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTrace.cs new file mode 100644 index 000000000..abbf866d8 --- /dev/null +++ b/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 _threads = new ConcurrentBag(); + + [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 GetEvents() + { + return _threads; + } + } +} \ No newline at end of file diff --git a/src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTraceEvent.cs b/src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTraceEvent.cs new file mode 100644 index 000000000..bcfb53bae --- /dev/null +++ b/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 Children { get; } + + public PerfTraceEvent(string type, string instance, IEnumerable children, DateTime startUtc, TimeSpan duration) + { + Type = type; + Instance = instance; + StartUtc = startUtc; + Duration = duration; + Children = children.OrderBy(e => e.StartUtc).ToList(); + } + } +} \ No newline at end of file diff --git a/src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTraceOutput.cs b/src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTraceOutput.cs new file mode 100644 index 000000000..2212efb14 --- /dev/null +++ b/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 contexts) + { + foreach (var threadContext in contexts) + { + Print(reporter, new[] { threadContext.Root }, threadContext.Root, null); + } + } + + private static void Print(Reporter reporter, IEnumerable 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(" "); + } + } + } +} \ No newline at end of file diff --git a/src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTraceThreadContext.cs b/src/Microsoft.DotNet.Cli.Utils/Tracing/PerfTraceThreadContext.cs new file mode 100644 index 000000000..41a42d746 --- /dev/null +++ b/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 Children { get; set; } = new ConcurrentBag(); + + 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); + } + } +} \ No newline at end of file diff --git a/src/dotnet/ITelemetry.cs b/src/dotnet/ITelemetry.cs index 858a2b93f..e687d13bd 100644 --- a/src/dotnet/ITelemetry.cs +++ b/src/dotnet/ITelemetry.cs @@ -8,6 +8,8 @@ namespace Microsoft.DotNet.Cli { public interface ITelemetry { + bool Enabled { get; } + void TrackEvent(string eventName, IDictionary properties, IDictionary measurements); } } diff --git a/src/dotnet/Program.cs b/src/dotnet/Program.cs index 1ab628b14..11d9970e1 100644 --- a/src/dotnet/Program.cs +++ b/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. diff --git a/src/dotnet/Telemetry.cs b/src/dotnet/Telemetry.cs index ca6e7504a..f5470907b 100644 --- a/src/dotnet/Telemetry.cs +++ b/src/dotnet/Telemetry.cs @@ -22,36 +22,41 @@ 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 { - _client = new TelemetryClient(); - _client.InstrumentationKey = InstrumentationKey; - _client.Context.Session.Id = Guid.NewGuid().ToString(); + using (PerfTrace.Current.CaptureTiming()) + { + _client = new TelemetryClient(); + _client.InstrumentationKey = InstrumentationKey; + _client.Context.Session.Id = Guid.NewGuid().ToString(); - var runtimeEnvironment = PlatformServices.Default.Runtime; - _client.Context.Device.OperatingSystem = runtimeEnvironment.OperatingSystem; + var runtimeEnvironment = PlatformServices.Default.Runtime; + _client.Context.Device.OperatingSystem = runtimeEnvironment.OperatingSystem; - _commonProperties = new Dictionary(); - _commonProperties.Add(OSVersion, runtimeEnvironment.OperatingSystemVersion); - _commonProperties.Add(OSPlatform, runtimeEnvironment.OperatingSystemPlatform.ToString()); - _commonProperties.Add(RuntimeId, runtimeEnvironment.GetRuntimeIdentifier()); - _commonProperties.Add(ProductVersion, Product.Version); - _commonMeasurements = new Dictionary(); + _commonProperties = new Dictionary(); + _commonProperties.Add(OSVersion, runtimeEnvironment.OperatingSystemVersion); + _commonProperties.Add(OSPlatform, runtimeEnvironment.OperatingSystemPlatform.ToString()); + _commonProperties.Add(RuntimeId, runtimeEnvironment.GetRuntimeIdentifier()); + _commonProperties.Add(ProductVersion, Product.Version); + _commonMeasurements = new Dictionary(); + } _isInitialized = true; } catch (Exception) { - // we dont want to fail the tool if telemetry fais. We should be able to detect abnormalities from data + // we dont want to fail the tool if telemetry fais. We should be able to detect abnormalities from data // at the server end Debug.Fail("Exception during telemetry initialization"); } @@ -64,17 +69,20 @@ namespace Microsoft.DotNet.Cli return; } - Dictionary eventMeasurements = GetEventMeasures(measurements); - Dictionary eventProperties = GetEventProperties(properties); + using (PerfTrace.Current.CaptureTiming()) + { + Dictionary eventMeasurements = GetEventMeasures(measurements); + Dictionary eventProperties = GetEventProperties(properties); - try - { - _client.TrackEvent(eventName, eventProperties, eventMeasurements); - _client.Flush(); - } - catch (Exception) - { - Debug.Fail("Exception during TrackEvent"); + try + { + _client.TrackEvent(eventName, eventProperties, eventMeasurements); + _client.Flush(); + } + catch (Exception) + { + Debug.Fail("Exception during TrackEvent"); + } } } diff --git a/src/dotnet/commands/dotnet-build/Program.cs b/src/dotnet/commands/dotnet-build/Program.cs index a42320362..1f02e06fa 100644 --- a/src/dotnet/commands/dotnet-build/Program.cs +++ b/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); - var graph = graphCollector.Collect(contexts).ToArray(); + IEnumerable contexts; + 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))); } } - return Task.WhenAll(tasks).GetAwaiter().GetResult(); + using (PerfTrace.Current.CaptureTiming(string.Empty, "Waiting for project contexts to finish loading")) + { + return Task.WhenAll(tasks).GetAwaiter().GetResult(); + } } } } diff --git a/src/dotnet/commands/dotnet-build/ProjectBuilder.cs b/src/dotnet/commands/dotnet-build/ProjectBuilder.cs index b06164c5c..4118fb0f7 100644 --- a/src/dotnet/commands/dotnet-build/ProjectBuilder.cs +++ b/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 { @@ -25,7 +27,10 @@ namespace Microsoft.DotNet.Tools.Build { foreach (var projectNode in roots) { - yield return Build(projectNode); + using (PerfTrace.Current.CaptureTiming($"{projectNode.ProjectContext.ProjectName()}")) + { + yield return Build(projectNode); + } } } @@ -79,18 +84,33 @@ namespace Microsoft.DotNet.Tools.Build } var context = projectNode.ProjectContext; - if (!HasSourceFiles(context)) + using (PerfTrace.Current.CaptureTiming($"{projectNode.ProjectContext.ProjectName()}", nameof(HasSourceFiles))) { - return CompilationResult.IncrementalSkip; + if (!HasSourceFiles(context)) + { + return CompilationResult.IncrementalSkip; + } } - if (NeedsRebuilding(projectNode)) + bool needsRebuilding; + using (PerfTrace.Current.CaptureTiming($"{projectNode.ProjectContext.ProjectName()}", nameof(NeedsRebuilding))) { - return RunCompile(projectNode); + needsRebuilding = NeedsRebuilding(projectNode); + } + + if (needsRebuilding) + { + using (PerfTrace.Current.CaptureTiming($"{projectNode.ProjectContext.ProjectName()}",nameof(RunCompile))) + { + return RunCompile(projectNode); + } } else { - ProjectSkiped(projectNode); + using (PerfTrace.Current.CaptureTiming($"{projectNode.ProjectContext.ProjectName()}", nameof(ProjectSkiped))) + { + ProjectSkiped(projectNode); + } return CompilationResult.IncrementalSkip; } } diff --git a/src/dotnet/commands/dotnet-build/ProjectGraphNode.cs b/src/dotnet/commands/dotnet-build/ProjectGraphNode.cs index 35cc764b7..88aa8f841 100644 --- a/src/dotnet/commands/dotnet-build/ProjectGraphNode.cs +++ b/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 Dependencies { get; } diff --git a/test/dotnet.Tests/TelemetryCommandTest.cs b/test/dotnet.Tests/TelemetryCommandTest.cs index 95c2818a8..185dc458b 100644 --- a/test/dotnet.Tests/TelemetryCommandTest.cs +++ b/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 properties, IDictionary measurements) { EventName = eventName;