From 5d4ac3a06b0e69b87122726568913e16d10e81d4 Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Wed, 12 Aug 2020 15:50:13 -0700 Subject: [PATCH 1/2] Create an opt-in performance log for the Dotnet CLI. --- src/Cli/Microsoft.DotNet.Cli.Utils/Env.cs | 5 + .../DirectoryWrapper.cs | 5 + .../IDirectory.cs | 2 + src/Cli/dotnet/PerformanceLogEventListener.cs | 163 +++++++ src/Cli/dotnet/PerformanceLogEventSource.cs | 449 ++++++++++++++++++ src/Cli/dotnet/PerformanceLogManager.cs | 140 ++++++ src/Cli/dotnet/Program.cs | 129 +++-- .../commands/dotnet-build/BuildCommand.cs | 8 +- .../dotnet-msbuild/MSBuildForwardingApp.cs | 14 +- .../GivenAFirstTimeUseNoticeSentinel.cs | 5 + ...nAFunctionReturnStringAndFakeFileSystem.cs | 5 + .../Mock/FileSystemMockBuilder.cs | 9 + 12 files changed, 897 insertions(+), 37 deletions(-) create mode 100644 src/Cli/dotnet/PerformanceLogEventListener.cs create mode 100644 src/Cli/dotnet/PerformanceLogEventSource.cs create mode 100644 src/Cli/dotnet/PerformanceLogManager.cs diff --git a/src/Cli/Microsoft.DotNet.Cli.Utils/Env.cs b/src/Cli/Microsoft.DotNet.Cli.Utils/Env.cs index 6aad6f4c4911..b15f9131f1ca 100644 --- a/src/Cli/Microsoft.DotNet.Cli.Utils/Env.cs +++ b/src/Cli/Microsoft.DotNet.Cli.Utils/Env.cs @@ -36,5 +36,10 @@ public static bool GetEnvironmentVariableAsBool(string name, bool defaultValue = { return _environment.GetEnvironmentVariableAsBool(name, defaultValue); } + + public static string GetEnvironmentVariable(string name) + { + return _environment.GetEnvironmentVariable(name); + } } } diff --git a/src/Cli/Microsoft.DotNet.InternalAbstractions/DirectoryWrapper.cs b/src/Cli/Microsoft.DotNet.InternalAbstractions/DirectoryWrapper.cs index c09bd8dfa290..312d6fecd7d4 100644 --- a/src/Cli/Microsoft.DotNet.InternalAbstractions/DirectoryWrapper.cs +++ b/src/Cli/Microsoft.DotNet.InternalAbstractions/DirectoryWrapper.cs @@ -19,6 +19,11 @@ public ITemporaryDirectory CreateTemporaryDirectory() return new TemporaryDirectory(); } + public IEnumerable EnumerateDirectories(string path) + { + return Directory.EnumerateDirectories(path); + } + public IEnumerable EnumerateFiles(string path) { return Directory.EnumerateFiles(path); diff --git a/src/Cli/Microsoft.DotNet.InternalAbstractions/IDirectory.cs b/src/Cli/Microsoft.DotNet.InternalAbstractions/IDirectory.cs index f6bfb38850b0..983bba34afc3 100644 --- a/src/Cli/Microsoft.DotNet.InternalAbstractions/IDirectory.cs +++ b/src/Cli/Microsoft.DotNet.InternalAbstractions/IDirectory.cs @@ -11,6 +11,8 @@ internal interface IDirectory ITemporaryDirectory CreateTemporaryDirectory(); + IEnumerable EnumerateDirectories(string path); + IEnumerable EnumerateFiles(string path); IEnumerable EnumerateFileSystemEntries(string path); diff --git a/src/Cli/dotnet/PerformanceLogEventListener.cs b/src/Cli/dotnet/PerformanceLogEventListener.cs new file mode 100644 index 000000000000..9d1b7b9c0f05 --- /dev/null +++ b/src/Cli/dotnet/PerformanceLogEventListener.cs @@ -0,0 +1,163 @@ +using System; +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.IO; +using System.Text; +using Microsoft.Extensions.EnvironmentAbstractions; + +namespace Microsoft.DotNet.Cli.Utils +{ + internal sealed class PerformanceLogEventListener : EventListener + { + internal struct ProviderConfiguration + { + internal string Name { get; set; } + internal EventKeywords Keywords { get; set; } + internal EventLevel Level { get; set; } + } + + private static ProviderConfiguration[] s_config = new ProviderConfiguration[] + { + new ProviderConfiguration() + { + Name = "Microsoft-Dotnet-CLI-Performance", + Keywords = EventKeywords.All, + Level = EventLevel.Verbose + } + }; + + private const char EventDelimiter = '\n'; + private string _processIDStr; + private StreamWriter _writer; + + [ThreadStatic] + private static StringBuilder s_builder = new StringBuilder(); + + internal static PerformanceLogEventListener Create(IFileSystem fileSystem, string logDirectory) + { + // Only create a listener if the log directory exists. + if(string.IsNullOrWhiteSpace(logDirectory) || !fileSystem.Directory.Exists(logDirectory)) + { + return null; + } + + PerformanceLogEventListener eventListener = null; + try + { + // Initialization happens as a separate step and not in the constructor to ensure that + // if an exception is thrown during init, we have the opportunity to dispose of the listener, + // which will disable any EventSources that have been enabled. Any EventSources that existed before + // this EventListener will be passed to OnEventSourceCreated before our constructor is called, so + // we if we do this work in the constructor, and don't get an opportunity to call Dispose, the + // EventSources will remain enabled even if there aren't any consuming EventListeners. + eventListener = new PerformanceLogEventListener(); + eventListener.Initialize(fileSystem, logDirectory); + } + catch + { + if(eventListener != null) + { + eventListener.Dispose(); + } + } + + return eventListener; + } + + private PerformanceLogEventListener() + { + } + + internal void Initialize(IFileSystem fileSystem, string logDirectory) + { + _processIDStr = Process.GetCurrentProcess().Id.ToString(); + + // Use a GUID disambiguator to make sure that we have a unique file name. + string logFilePath = Path.Combine(logDirectory, $"perf-{_processIDStr}-{Guid.NewGuid().ToString("N")}.log"); + + Stream outputStream = fileSystem.File.OpenFile( + logFilePath, + FileMode.Create, // Create or overwrite. + FileAccess.Write, // Open for writing. + FileShare.Read, // Allow others to read. + 4096, // Default buffer size. + FileOptions.None); // No hints about how the file will be written. + + _writer = new StreamWriter(outputStream); + } + + public override void Dispose() + { + lock (this) + { + if (_writer != null) + { + _writer.Dispose(); + _writer = null; + } + } + + base.Dispose(); + } + + protected override void OnEventSourceCreated(EventSource eventSource) + { + try + { + // Enable the provider if it matches a requested configuration. + foreach (ProviderConfiguration entry in s_config) + { + if (entry.Name.Equals(eventSource.Name)) + { + EnableEvents(eventSource, entry.Level, entry.Keywords); + } + } + } + catch + { + // If we fail to enable, just skip it and continue. + } + + base.OnEventSourceCreated(eventSource); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + try + { + if (s_builder == null) + { + s_builder = new StringBuilder(); + } + else + { + s_builder.Clear(); + } + + s_builder.Append($"[{DateTime.UtcNow.ToString("o")}] Event={eventData.EventSource.Name}/{eventData.EventName} ProcessID={_processIDStr} ThreadID={System.Threading.Thread.CurrentThread.ManagedThreadId}\t "); + for (int i = 0; i < eventData.PayloadNames.Count; i++) + { + s_builder.Append($"{eventData.PayloadNames[i]}=\"{eventData.Payload[i]}\" "); + } + + lock (this) + { + if (_writer != null) + { + foreach (ReadOnlyMemory mem in s_builder.GetChunks()) + { + _writer.Write(mem); + } + _writer.Write(EventDelimiter); + } + } + } + catch + { + // If we fail to log an event, just skip it and continue. + } + + base.OnEventWritten(eventData); + } + } +} diff --git a/src/Cli/dotnet/PerformanceLogEventSource.cs b/src/Cli/dotnet/PerformanceLogEventSource.cs new file mode 100644 index 000000000000..beb4d2388968 --- /dev/null +++ b/src/Cli/dotnet/PerformanceLogEventSource.cs @@ -0,0 +1,449 @@ +using System; +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.IO; +using System.Reflection; +using System.Runtime.InteropServices; +using Microsoft.DotNet.Cli.Utils; +using RuntimeEnvironment = Microsoft.DotNet.Cli.Utils.RuntimeEnvironment; + +namespace Microsoft.DotNet.Cli +{ + [EventSource(Name = "Microsoft-Dotnet-CLI-Performance", Guid = "cbd57d06-3b9f-5374-ed53-cfbcc23cf44f")] + internal sealed class PerformanceLogEventSource : EventSource + { + internal static PerformanceLogEventSource Log = new PerformanceLogEventSource(); + + private PerformanceLogEventSource() + { + } + + [NonEvent] + internal void LogStartUpInformation(PerformanceLogStartupInformation startupInfo) + { + if(!IsEnabled()) + { + return; + } + + DotnetVersionFile versionFile = DotnetFiles.VersionFileObject; + string commitSha = versionFile.CommitSha ?? "N/A"; + + LogMachineConfiguration(); + OSInfo(RuntimeEnvironment.OperatingSystem, RuntimeEnvironment.OperatingSystemVersion, RuntimeEnvironment.OperatingSystemPlatform.ToString()); + SDKInfo(Product.Version, commitSha, RuntimeInformation.RuntimeIdentifier, versionFile.BuildRid, AppContext.BaseDirectory); + EnvironmentInfo(Environment.CommandLine); + LogMemoryConfiguration(); + LogDrives(); + + // It's possible that IsEnabled returns true if an out-of-process collector such as ETW is enabled. + // If the perf log hasn't been enabled, then startupInfo will be null, so protect against nullref here. + if (startupInfo != null) + { + if (startupInfo.TimedAssembly != null) + { + AssemblyLoad(startupInfo.TimedAssembly.GetName().Name, startupInfo.AssemblyLoadTime.TotalMilliseconds); + } + + Process currentProcess = Process.GetCurrentProcess(); + TimeSpan latency = startupInfo.MainTimeStamp - currentProcess.StartTime; + HostLatency(latency.TotalMilliseconds); + } + } + + [Event(1)] + internal void OSInfo(string osname, string osversion, string osplatform) + { + WriteEvent(1, osname, osversion, osplatform); + } + + [Event(2)] + internal void SDKInfo(string version, string commit, string currentRid, string buildRid, string basePath) + { + WriteEvent(2, version, commit, currentRid, buildRid, basePath); + } + + [Event(3)] + internal void EnvironmentInfo(string commandLine) + { + WriteEvent(3, commandLine); + } + + [Event(4)] + internal void HostLatency(double timeInMs) + { + WriteEvent(4, timeInMs); + } + + [Event(5)] + internal void CLIStart() + { + WriteEvent(5); + } + + [Event(6)] + internal void CLIStop() + { + WriteEvent(6); + } + + [Event(7)] + internal void FirstTimeConfigurationStart() + { + WriteEvent(7); + } + + [Event(8)] + internal void FirstTimeConfigurationStop() + { + WriteEvent(8); + } + + [Event(9)] + internal void TelemetryRegistrationStart() + { + WriteEvent(9); + } + + [Event(10)] + internal void TelemetryRegistrationStop() + { + WriteEvent(10); + } + + [Event(11)] + internal void TelemetrySaveIfEnabledStart() + { + WriteEvent(11); + } + + [Event(12)] + internal void TelemetrySaveIfEnabledStop() + { + WriteEvent(12); + } + + [Event(13)] + internal void BuiltInCommandStart() + { + WriteEvent(13); + } + + [Event(14)] + internal void BuiltInCommandStop() + { + WriteEvent(14); + } + + [Event(15)] + internal void BuiltInCommandParserStart() + { + WriteEvent(15); + } + + [Event(16)] + internal void BuiltInCommandParserStop() + { + WriteEvent(16); + } + + [Event(17)] + internal void ExtensibleCommandResolverStart() + { + WriteEvent(17); + } + + [Event(18)] + internal void ExtensibleCommandResolverStop() + { + WriteEvent(18); + } + + [Event(19)] + internal void ExtensibleCommandStart() + { + WriteEvent(19); + } + + [Event(20)] + internal void ExtensibleCommandStop() + { + WriteEvent(20); + } + + [Event(21)] + internal void TelemetryClientFlushStart() + { + WriteEvent(21); + } + + [Event(22)] + internal void TelemetryClientFlushStop() + { + WriteEvent(22); + } + + [NonEvent] + internal void LogMachineConfiguration() + { + if(IsEnabled()) + { + MachineConfiguration(Environment.MachineName, Environment.ProcessorCount); + } + } + + [Event(23)] + internal void MachineConfiguration(string machineName, int processorCount) + { + WriteEvent(23, machineName, processorCount); + } + + [NonEvent] + internal void LogDrives() + { + if (IsEnabled()) + { + foreach (DriveInfo driveInfo in DriveInfo.GetDrives()) + { + try + { + DriveConfiguration(driveInfo.Name, driveInfo.DriveFormat, driveInfo.DriveType.ToString(), + (double)driveInfo.TotalSize/1024/1024, (double)driveInfo.AvailableFreeSpace/1024/1024); + } + catch + { + // If we fail to log a drive, skip it and continue. + } + } + } + } + + [Event(24)] + internal void DriveConfiguration(string name, string format, string type, double totalSizeMB, double availableFreeSpaceMB) + { + WriteEvent(24, name, format, type, totalSizeMB, availableFreeSpaceMB); + } + + [Event(25)] + internal void AssemblyLoad(string assemblyName, double timeInMs) + { + WriteEvent(25, assemblyName, timeInMs); + } + + [NonEvent] + internal void LogMemoryConfiguration() + { + if (IsEnabled()) + { + if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows)) + { + Interop.MEMORYSTATUSEX memoryStatusEx = new Interop.MEMORYSTATUSEX(); + memoryStatusEx.dwLength = (uint)Marshal.SizeOf(memoryStatusEx); + + if (Interop.GlobalMemoryStatusEx(ref memoryStatusEx)) + { + MemoryConfiguration((int)memoryStatusEx.dwMemoryLoad, (int)(memoryStatusEx.ullAvailPhys / 1024 / 1024), + (int)(memoryStatusEx.ullTotalPhys / 1024 / 1024)); + } + } + else if(RuntimeInformation.IsOSPlatform(OSPlatform.Linux)) + { + ProcMemInfo memInfo = new ProcMemInfo(); + if(memInfo.Valid) + { + MemoryConfiguration(memInfo.MemoryLoad, memInfo.AvailableMemoryMB, memInfo.TotalMemoryMB); + } + } + } + } + + [Event(26)] + internal void MemoryConfiguration(int memoryLoad, int availablePhysicalMB, int totalPhysicalMB) + { + WriteEvent(26, memoryLoad, availablePhysicalMB, totalPhysicalMB); + } + + [NonEvent] + internal void LogMSBuildStart(ProcessStartInfo startInfo) + { + if (IsEnabled()) + { + MSBuildStart($"{startInfo.FileName} {startInfo.Arguments}"); + } + } + + [Event(27)] + internal void MSBuildStart(string cmdline) + { + WriteEvent(27, cmdline); + } + + [Event(28)] + internal void MSBuildStop(int exitCode) + { + WriteEvent(28, exitCode); + } + + [Event(29)] + internal void CreateBuildCommandStart() + { + WriteEvent(29); + } + + [Event(30)] + internal void CreateBuildCommandStop() + { + WriteEvent(30); + } + } + + internal class PerformanceLogStartupInformation + { + public PerformanceLogStartupInformation(DateTime mainTimeStamp) + { + // Save the main timestamp. + MainTimeStamp = mainTimeStamp; + + // Attempt to load an assembly. + // Ideally, we've picked one that we'll already need, so we're not adding additional overhead. + MeasureModuleLoad(); + } + + internal DateTime MainTimeStamp { get; private set; } + internal Assembly TimedAssembly { get; private set; } + internal TimeSpan AssemblyLoadTime { get; private set; } + + private void MeasureModuleLoad() + { + // Make sure the assembly hasn't been loaded yet. + string assemblyName = "Microsoft.DotNet.Configurer"; + try + { + foreach (Assembly loadedAssembly in AppDomain.CurrentDomain.GetAssemblies()) + { + if (loadedAssembly.GetName().Name.Equals(assemblyName)) + { + // If the assembly is already loaded, then bail. + return; + } + } + } + catch + { + // If we fail to enumerate, just bail. + return; + } + + Stopwatch stopWatch = Stopwatch.StartNew(); + Assembly assembly = null; + try + { + assembly = Assembly.Load(assemblyName); + } + catch + { + return; + } + stopWatch.Stop(); + if (assembly != null) + { + // Save the results. + TimedAssembly = assembly; + AssemblyLoadTime = stopWatch.Elapsed; + } + } + } + + /// + /// Global memory statistics on Windows. + /// + internal static class Interop + { + [StructLayout(LayoutKind.Sequential)] + internal struct MEMORYSTATUSEX + { + // The length field must be set to the size of this data structure. + internal uint dwLength; + internal uint dwMemoryLoad; + internal ulong ullTotalPhys; + internal ulong ullAvailPhys; + internal ulong ullTotalPageFile; + internal ulong ullAvailPageFile; + internal ulong ullTotalVirtual; + internal ulong ullAvailVirtual; + internal ulong ullAvailExtendedVirtual; + } + + [DllImport("kernel32.dll")] + internal static extern bool GlobalMemoryStatusEx(ref MEMORYSTATUSEX lpBuffer); + } + + /// + /// Global memory statistics on Linux. + /// + internal sealed class ProcMemInfo + { + private const string MemTotal = "MemTotal:"; + private const string MemAvailable = "MemAvailable:"; + + private short _matchingLineCount = 0; + + internal ProcMemInfo() + { + Initialize(); + } + + /// + /// The data in this class is valid if we parsed the file, found, and properly parsed the two matching lines. + /// + internal bool Valid + { + get { return _matchingLineCount == 2; } + } + + internal int MemoryLoad + { + get { return (int)((double)(TotalMemoryMB - AvailableMemoryMB) / TotalMemoryMB * 100); } + } + + internal int AvailableMemoryMB + { + get; + private set; + } + + internal int TotalMemoryMB + { + get; + private set; + } + + private void Initialize() + { + using (StreamReader reader = new StreamReader(File.OpenRead("/proc/meminfo"))) + { + string line; + while (!Valid && ((line = reader.ReadLine()) != null)) + { + if (line.StartsWith(MemTotal) || line.StartsWith(MemAvailable)) + { + string[] tokens = line.Split(' ', StringSplitOptions.RemoveEmptyEntries); + if (tokens.Length == 3) + { + if (MemTotal.Equals(tokens[0])) + { + TotalMemoryMB = (int)Convert.ToUInt64(tokens[1]) / 1024; + _matchingLineCount++; + } + else if (MemAvailable.Equals(tokens[0])) + { + AvailableMemoryMB = (int)Convert.ToUInt64(tokens[1]) / 1024; + _matchingLineCount++; + } + } + } + } + } + } + } +} diff --git a/src/Cli/dotnet/PerformanceLogManager.cs b/src/Cli/dotnet/PerformanceLogManager.cs new file mode 100644 index 000000000000..6b735841fa2a --- /dev/null +++ b/src/Cli/dotnet/PerformanceLogManager.cs @@ -0,0 +1,140 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.IO; +using System.Threading.Tasks; +using Microsoft.DotNet.Configurer; +using Microsoft.Extensions.EnvironmentAbstractions; + +namespace Microsoft.DotNet.Cli.Utils +{ + internal sealed class PerformanceLogManager + { + internal const string PerfLogDirEnvVar = "DOTNET_PERFLOG_DIR"; + private const string PerfLogRoot = "PerformanceLogs"; + private const int DefaultNumLogsToKeep = 10; + + private IFileSystem _fileSystem; + private string _perfLogRoot; + private string _currentLogDir; + + internal static PerformanceLogManager Instance + { + get; + private set; + } + + internal static void InitializeAndStartCleanup(IFileSystem fileSystem) + { + if(Instance == null) + { + Instance = new PerformanceLogManager(fileSystem); + + // Check to see if this instance is part of an already running chain of processes. + string perfLogDir = Env.GetEnvironmentVariable(PerfLogDirEnvVar); + if (!string.IsNullOrEmpty(perfLogDir)) + { + // This process has been provided with a log directory, so use it. + Instance.UseExistingLogDirectory(perfLogDir); + } + else + { + // This process was not provided with a log root, so make a new one. + Instance._perfLogRoot = Path.Combine(CliFolderPathCalculator.DotnetUserProfileFolderPath, PerfLogRoot); + Instance.CreateLogDirectory(); + + Task.Factory.StartNew(() => + { + Instance.CleanupOldLogs(); + }); + } + } + } + + internal PerformanceLogManager(IFileSystem fileSystem) + { + _fileSystem = fileSystem; + } + + internal string CurrentLogDirectory + { + get { return _currentLogDir; } + } + + private void CreateLogDirectory() + { + // Ensure the log root directory exists. + if(!_fileSystem.Directory.Exists(_perfLogRoot)) + { + _fileSystem.Directory.CreateDirectory(_perfLogRoot); + } + + // Create a new perf log directory. + _currentLogDir = Path.Combine(_perfLogRoot, Guid.NewGuid().ToString("N")); + _fileSystem.Directory.CreateDirectory(_currentLogDir); + } + + private void UseExistingLogDirectory(string logDirectory) + { + _currentLogDir = logDirectory; + } + + private void CleanupOldLogs() + { + if(_fileSystem.Directory.Exists(_perfLogRoot)) + { + List logDirectories = new List(); + foreach(string directoryPath in _fileSystem.Directory.EnumerateDirectories(_perfLogRoot)) + { + logDirectories.Add(new DirectoryInfo(directoryPath)); + } + + // Sort the list. + logDirectories.Sort(new LogDirectoryComparer()); + + // Figure out how many logs to keep. + int numLogsToKeep; + string strNumLogsToKeep = Env.GetEnvironmentVariable("DOTNET_PERF_LOG_COUNT"); + if(!int.TryParse(strNumLogsToKeep, out numLogsToKeep)) + { + numLogsToKeep = DefaultNumLogsToKeep; + + // -1 == keep all logs + if(numLogsToKeep == -1) + { + numLogsToKeep = int.MaxValue; + } + } + + // Skip the first numLogsToKeep elements. + if(logDirectories.Count > numLogsToKeep) + { + // Prune the old logs. + for(int i = logDirectories.Count - numLogsToKeep - 1; i>=0; i--) + { + try + { + logDirectories[i].Delete(true); + } + catch + { + // Do nothing if a log can't be deleted. + // We'll get another chance next time around. + } + } + } + } + } + } + + /// + /// Used to sort log directories when deciding which ones to delete. + /// + internal sealed class LogDirectoryComparer : IComparer + { + int IComparer.Compare(DirectoryInfo x, DirectoryInfo y) + { + return x.CreationTime.CompareTo(y.CreationTime); + } + } +} diff --git a/src/Cli/dotnet/Program.cs b/src/Cli/dotnet/Program.cs index e4b1f369102c..20128ed56b19 100644 --- a/src/Cli/dotnet/Program.cs +++ b/src/Cli/dotnet/Program.cs @@ -16,6 +16,7 @@ using Microsoft.DotNet.Tools.Help; using Microsoft.Extensions.EnvironmentAbstractions; using NuGet.Frameworks; +using Command = Microsoft.DotNet.Cli.Utils.Command; using LocalizableStrings = Microsoft.DotNet.Cli.Utils.LocalizableStrings; using RuntimeEnvironment = Microsoft.DotNet.Cli.Utils.RuntimeEnvironment; @@ -29,55 +30,87 @@ public static int Main(string[] args) { DebugHelper.HandleDebugSwitch(ref args); - new MulticoreJitActivator().TryActivateMulticoreJit(); + // Capture the current timestamp to calculate the host overhead. + DateTime mainTimeStamp = DateTime.Now; - if (Env.GetEnvironmentVariableAsBool("DOTNET_CLI_CAPTURE_TIMING", false)) + bool perfLogEnabled = Env.GetEnvironmentVariableAsBool("DOTNET_CLI_PERF_LOG", false); + PerformanceLogStartupInformation startupInfo = null; + if (perfLogEnabled) { - PerfTrace.Enabled = true; + startupInfo = new PerformanceLogStartupInformation(mainTimeStamp); + PerformanceLogManager.InitializeAndStartCleanup(FileSystemWrapper.Default); } - InitializeProcess(); - + PerformanceLogEventListener perLogEventListener = null; try { - using (PerfTrace.Current.CaptureTiming()) + if (perfLogEnabled) { - return ProcessArgs(args); + perLogEventListener = PerformanceLogEventListener.Create(FileSystemWrapper.Default, PerformanceLogManager.Instance.CurrentLogDirectory); } - } - catch (HelpException e) - { - Reporter.Output.WriteLine(e.Message); - return 0; - } - catch (Exception e) when (e.ShouldBeDisplayedAsError()) - { - Reporter.Error.WriteLine(CommandContext.IsVerbose() - ? e.ToString().Red().Bold() - : e.Message.Red().Bold()); - var commandParsingException = e as CommandParsingException; - if (commandParsingException != null) + new MulticoreJitActivator().TryActivateMulticoreJit(); + + PerformanceLogEventSource.Log.LogStartUpInformation(startupInfo); + PerformanceLogEventSource.Log.CLIStart(); + + if (Env.GetEnvironmentVariableAsBool("DOTNET_CLI_CAPTURE_TIMING", false)) { - Reporter.Output.WriteLine(commandParsingException.HelpText); + PerfTrace.Enabled = true; } - return 1; - } - catch (Exception e) when (!e.ShouldBeDisplayedAsError()) - { - // If telemetry object has not been initialized yet. It cannot be collected - TelemetryEventEntry.SendFiltered(e); - Reporter.Error.WriteLine(e.ToString().Red().Bold()); + InitializeProcess(); + + try + { + using (PerfTrace.Current.CaptureTiming()) + { + return ProcessArgs(args); + } + } + catch (HelpException e) + { + Reporter.Output.WriteLine(e.Message); + return 0; + } + catch (Exception e) when (e.ShouldBeDisplayedAsError()) + { + Reporter.Error.WriteLine(CommandContext.IsVerbose() + ? e.ToString().Red().Bold() + : e.Message.Red().Bold()); + + var commandParsingException = e as CommandParsingException; + if (commandParsingException != null) + { + Reporter.Output.WriteLine(commandParsingException.HelpText); + } + + return 1; + } + catch (Exception e) when (!e.ShouldBeDisplayedAsError()) + { + // If telemetry object has not been initialized yet. It cannot be collected + TelemetryEventEntry.SendFiltered(e); + Reporter.Error.WriteLine(e.ToString().Red().Bold()); - return 1; + return 1; + } + finally + { + if (PerfTrace.Enabled) + { + Reporter.Output.WriteLine("Performance Summary:"); + PerfTraceOutput.Print(Reporter.Output, PerfTrace.GetEvents()); + } + + PerformanceLogEventSource.Log.CLIStop(); + } } finally { - if (PerfTrace.Enabled) + if(perLogEventListener != null) { - Reporter.Output.WriteLine("Performance Summary:"); - PerfTraceOutput.Print(Reporter.Output, PerfTrace.GetEvents()); + perLogEventListener.Dispose(); } } } @@ -140,6 +173,8 @@ internal static int ProcessArgs(string[] args, ITelemetry telemetryClient = null command = "help"; } + PerformanceLogEventSource.Log.FirstTimeConfigurationStart(); + var environmentProvider = new EnvironmentProvider(); bool generateAspNetCertificate = @@ -177,6 +212,8 @@ internal static int ProcessArgs(string[] args, ITelemetry telemetryClient = null dotnetFirstRunConfiguration, environmentProvider); + PerformanceLogEventSource.Log.FirstTimeConfigurationStop(); + break; } } @@ -186,12 +223,16 @@ internal static int ProcessArgs(string[] args, ITelemetry telemetryClient = null return 1; } + PerformanceLogEventSource.Log.TelemetryRegistrationStart(); + if (telemetryClient == null) { telemetryClient = new Telemetry.Telemetry(firstTimeUseNoticeSentinel); } TelemetryEventEntry.Subscribe(telemetryClient.TrackEvent); TelemetryEventEntry.TelemetryFilter = new TelemetryFilter(Sha256Hasher.HashWithNormalizedCasing); + + PerformanceLogEventSource.Log.TelemetryRegistrationStop(); } IEnumerable appArgs = @@ -204,18 +245,27 @@ internal static int ProcessArgs(string[] args, ITelemetry telemetryClient = null Console.WriteLine($"Telemetry is: {(telemetryClient.Enabled ? "Enabled" : "Disabled")}"); } + PerformanceLogEventSource.Log.TelemetrySaveIfEnabledStart(); TelemetryEventEntry.SendFiltered(topLevelCommandParserResult); + PerformanceLogEventSource.Log.TelemetrySaveIfEnabledStop(); int exitCode; if (BuiltInCommandsCatalog.Commands.TryGetValue(topLevelCommandParserResult.Command, out var builtIn)) { + PerformanceLogEventSource.Log.BuiltInCommandParserStart(); var parseResult = Parser.Instance.ParseFrom($"dotnet {topLevelCommandParserResult.Command}", appArgs.ToArray()); + PerformanceLogEventSource.Log.BuiltInCommandParserStop(); + if (!parseResult.Errors.Any()) { + PerformanceLogEventSource.Log.TelemetrySaveIfEnabledStart(); TelemetryEventEntry.SendFiltered(parseResult); + PerformanceLogEventSource.Log.TelemetrySaveIfEnabledStop(); } + PerformanceLogEventSource.Log.BuiltInCommandStart(); exitCode = builtIn.Command(appArgs.ToArray()); + PerformanceLogEventSource.Log.BuiltInCommandStop(); } else if (string.IsNullOrEmpty(topLevelCommandParserResult.Command)) { @@ -223,15 +273,24 @@ internal static int ProcessArgs(string[] args, ITelemetry telemetryClient = null } else { - CommandResult result = CommandFactoryUsingResolver.Create( + PerformanceLogEventSource.Log.ExtensibleCommandResolverStart(); + Command resolvedCommand = CommandFactoryUsingResolver.Create( "dotnet-" + topLevelCommandParserResult.Command, appArgs, - FrameworkConstants.CommonFrameworks.NetStandardApp15) - .Execute(); + FrameworkConstants.CommonFrameworks.NetStandardApp15); + PerformanceLogEventSource.Log.ExtensibleCommandResolverStop(); + + PerformanceLogEventSource.Log.ExtensibleCommandStart(); + CommandResult result = resolvedCommand.Execute(); + PerformanceLogEventSource.Log.ExtensibleCommandStop(); + exitCode = result.ExitCode; } + PerformanceLogEventSource.Log.TelemetryClientFlushStart(); telemetryClient.Flush(); + PerformanceLogEventSource.Log.TelemetryClientFlushStop(); + return exitCode; } diff --git a/src/Cli/dotnet/commands/dotnet-build/BuildCommand.cs b/src/Cli/dotnet/commands/dotnet-build/BuildCommand.cs index bcfecbc35b6e..b802237fd7f7 100644 --- a/src/Cli/dotnet/commands/dotnet-build/BuildCommand.cs +++ b/src/Cli/dotnet/commands/dotnet-build/BuildCommand.cs @@ -27,6 +27,8 @@ public BuildCommand( public static BuildCommand FromArgs(string[] args, string msbuildPath = null) { + PerformanceLogEventSource.Log.CreateBuildCommandStart(); + var msbuildArgs = new List(); var parser = Parser.Instance; @@ -50,12 +52,16 @@ public static BuildCommand FromArgs(string[] args, string msbuildPath = null) bool noRestore = appliedBuildOptions.HasOption("--no-restore"); - return new BuildCommand( + BuildCommand command = new BuildCommand( msbuildArgs, appliedBuildOptions.OptionValuesToBeForwarded(), appliedBuildOptions.Arguments, noRestore, msbuildPath); + + PerformanceLogEventSource.Log.CreateBuildCommandStop(); + + return command; } public static int Run(string[] args) diff --git a/src/Cli/dotnet/commands/dotnet-msbuild/MSBuildForwardingApp.cs b/src/Cli/dotnet/commands/dotnet-msbuild/MSBuildForwardingApp.cs index 995fb1e5fb70..6f1f1ecfca95 100644 --- a/src/Cli/dotnet/commands/dotnet-msbuild/MSBuildForwardingApp.cs +++ b/src/Cli/dotnet/commands/dotnet-msbuild/MSBuildForwardingApp.cs @@ -49,6 +49,12 @@ public MSBuildForwardingApp(IEnumerable argsToForward, string msbuildPat _forwardingAppWithoutLogging = new MSBuildForwardingAppWithoutLogging( ConcatTelemetryLogger(argsToForward), msbuildPath); + + // Add the performance log location to the environment of the target process. + if (PerformanceLogManager.Instance != null && !string.IsNullOrEmpty(PerformanceLogManager.Instance.CurrentLogDirectory)) + { + EnvironmentVariable(PerformanceLogManager.PerfLogDirEnvVar, PerformanceLogManager.Instance.CurrentLogDirectory); + } } public void EnvironmentVariable(string name, string value) @@ -69,7 +75,13 @@ public virtual int Execute() // Forwarding commands will just spawn the child process and exit Console.CancelKeyPress += (sender, e) => { e.Cancel = true; }; - return GetProcessStartInfo().Execute(); + ProcessStartInfo startInfo = GetProcessStartInfo(); + + PerformanceLogEventSource.Log.LogMSBuildStart(startInfo); + int exitCode = startInfo.Execute(); + PerformanceLogEventSource.Log.MSBuildStop(exitCode); + + return exitCode; } } } diff --git a/src/Tests/Microsoft.DotNet.Configurer.UnitTests/GivenAFirstTimeUseNoticeSentinel.cs b/src/Tests/Microsoft.DotNet.Configurer.UnitTests/GivenAFirstTimeUseNoticeSentinel.cs index 7daf6962436c..843f882ffdb6 100644 --- a/src/Tests/Microsoft.DotNet.Configurer.UnitTests/GivenAFirstTimeUseNoticeSentinel.cs +++ b/src/Tests/Microsoft.DotNet.Configurer.UnitTests/GivenAFirstTimeUseNoticeSentinel.cs @@ -174,6 +174,11 @@ public ITemporaryDirectory CreateTemporaryDirectory() throw new NotImplementedException(); } + public IEnumerable EnumerateDirectories(string path) + { + throw new NotImplementedException(); + } + public IEnumerable EnumerateFiles(string path) { throw new NotImplementedException(); diff --git a/src/Tests/Microsoft.DotNet.Configurer.UnitTests/GivenAFunctionReturnStringAndFakeFileSystem.cs b/src/Tests/Microsoft.DotNet.Configurer.UnitTests/GivenAFunctionReturnStringAndFakeFileSystem.cs index 0b35c3e23a21..10e3f1930814 100644 --- a/src/Tests/Microsoft.DotNet.Configurer.UnitTests/GivenAFunctionReturnStringAndFakeFileSystem.cs +++ b/src/Tests/Microsoft.DotNet.Configurer.UnitTests/GivenAFunctionReturnStringAndFakeFileSystem.cs @@ -158,6 +158,11 @@ public ITemporaryDirectory CreateTemporaryDirectory() throw new NotImplementedException(); } + public IEnumerable EnumerateDirectories(string path) + { + throw new NotImplementedException(); + } + public IEnumerable EnumerateFiles(string path) { throw new NotImplementedException(); diff --git a/src/Tests/Microsoft.NET.TestFramework/Mock/FileSystemMockBuilder.cs b/src/Tests/Microsoft.NET.TestFramework/Mock/FileSystemMockBuilder.cs index 943d7f4f4b0d..7eb9e5381989 100644 --- a/src/Tests/Microsoft.NET.TestFramework/Mock/FileSystemMockBuilder.cs +++ b/src/Tests/Microsoft.NET.TestFramework/Mock/FileSystemMockBuilder.cs @@ -541,6 +541,15 @@ public ITemporaryDirectory CreateTemporaryDirectory() return temporaryDirectoryMock; } + public IEnumerable EnumerateDirectories(string path) + { + if (path == null) throw new ArgumentNullException(nameof(path)); + + return _files.EnumerateDirectory(path, + subs => subs.Where(s => s.Value is DirectoryNode) + .Select(s => Path.Combine(path, s.Key))); + } + public IEnumerable EnumerateFiles(string path) { if (path == null) throw new ArgumentNullException(nameof(path)); From 9efa0baa95fc0610d9a7a1ac7f986df23428807a Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Mon, 2 Nov 2020 16:00:12 -0800 Subject: [PATCH 2/2] Implement a few tests. --- .../GivenThatTheUserEnablesThePerfLog.cs | 94 +++++++++++++++++++ 1 file changed, 94 insertions(+) create mode 100644 src/Tests/dotnet.Tests/GivenThatTheUserEnablesThePerfLog.cs diff --git a/src/Tests/dotnet.Tests/GivenThatTheUserEnablesThePerfLog.cs b/src/Tests/dotnet.Tests/GivenThatTheUserEnablesThePerfLog.cs new file mode 100644 index 000000000000..5073d461c4ad --- /dev/null +++ b/src/Tests/dotnet.Tests/GivenThatTheUserEnablesThePerfLog.cs @@ -0,0 +1,94 @@ +// 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.IO; +using System.Collections.Generic; +using Microsoft.DotNet.Cli.Utils; +using Microsoft.DotNet.Cli; +using Microsoft.DotNet.Configurer; +using Xunit; +using Xunit.Abstractions; +using FluentAssertions; +using Microsoft.NET.TestFramework; +using Microsoft.NET.TestFramework.Assertions; +using Microsoft.NET.TestFramework.Commands; +using System.Runtime.CompilerServices; +using System.Diagnostics.Tracing; + +namespace Microsoft.DotNet.Tests +{ + public class GivenThatTheUserEnablesThePerfLog : SdkTest + { + public GivenThatTheUserEnablesThePerfLog(ITestOutputHelper log) : base(log) + { + } + + [Fact] + public void WhenPerfLogDisabledDotNetDoesNotWriteToThePerfLog() + { + var dir = _testAssetsManager.CreateTestDirectory(); + + var result = new DotnetCommand(Log, "--help") + .WithEnvironmentVariable("DOTNET_PERFLOG_DIR", dir.Path) + .Execute(); + + result.ExitCode.Should().Be(0); + Assert.Empty(new DirectoryInfo(dir.Path).GetFiles()); + } + + [Fact] + public void WhenPerfLogEnabledDotNetWritesToThePerfLog() + { + var dir = _testAssetsManager.CreateTestDirectory(); + + var result = new DotnetCommand(Log, "--help") + .WithEnvironmentVariable("DOTNET_CLI_PERF_LOG", "1") + .WithEnvironmentVariable("DOTNET_PERFLOG_DIR", dir.Path) + .Execute(); + + result.ExitCode.Should().Be(0); + + DirectoryInfo logDir = new DirectoryInfo(dir.Path); + FileInfo[] logFiles = logDir.GetFiles(); + Assert.NotEmpty(logFiles); + Assert.All(logFiles, f => Assert.StartsWith("perf-", f.Name)); + Assert.All(logFiles, f => Assert.NotEqual(0, f.Length)); + } + + [Fact] + public void WhenPerfLogEnabledDotNetBuildWritesAPerfLog() + { + using (PerfLogTestEventListener listener = new PerfLogTestEventListener()) + { + int exitCode = Cli.Program.Main(new string[] { "--help" }); + Assert.Equal(0, exitCode); + Assert.NotEqual(0, listener.EventCount); + } + } + } + + internal sealed class PerfLogTestEventListener : EventListener + { + private const string PerfLogEventSourceName = "Microsoft-Dotnet-CLI-Performance"; + + public int EventCount + { + get; private set; + } + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if(eventSource.Name.Equals(PerfLogEventSourceName)) + { + EnableEvents(eventSource, EventLevel.Verbose); + } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + Assert.Equal(PerfLogEventSourceName, eventData.EventSource.Name); + EventCount++; + } + } +}