From 389b6735a068fa61aa71a5824ac060668fd1f624 Mon Sep 17 00:00:00 2001 From: Paulo Morgado <470455+paulomorgado@users.noreply.github.com> Date: Sun, 11 Oct 2020 16:14:45 +0100 Subject: [PATCH] Initial version --- .gitignore | 1 + DotnetMSBuildLog.sln | 34 ++ .../CommandLine/Commands/CommandExtenions.cs | 18 + .../Commands/ConvertCommandHandler.cs | 90 +++++ .../CommandLine/Commands/ErrorCodes.cs | 16 + .../MSBuildLogFileFormatConverter.cs | 65 ++++ DotnetMSBuildLog/DotnetMSBuildLog.csproj | 18 + DotnetMSBuildLog/Program.cs | 20 ++ .../Writers/SpeedscopeMSBuildLogWriter.cs | 328 ++++++++++++++++++ 9 files changed, 590 insertions(+) create mode 100644 DotnetMSBuildLog.sln create mode 100644 DotnetMSBuildLog/CommandLine/Commands/CommandExtenions.cs create mode 100644 DotnetMSBuildLog/CommandLine/Commands/ConvertCommandHandler.cs create mode 100644 DotnetMSBuildLog/CommandLine/Commands/ErrorCodes.cs create mode 100644 DotnetMSBuildLog/Converters/MSBuildLogFileFormatConverter.cs create mode 100644 DotnetMSBuildLog/DotnetMSBuildLog.csproj create mode 100644 DotnetMSBuildLog/Program.cs create mode 100644 DotnetMSBuildLog/Writers/SpeedscopeMSBuildLogWriter.cs diff --git a/.gitignore b/.gitignore index dfcfd56..d57e752 100644 --- a/.gitignore +++ b/.gitignore @@ -57,6 +57,7 @@ dlldata.c BenchmarkDotNet.Artifacts/ # .NET Core +launchSettings.json project.lock.json project.fragment.lock.json artifacts/ diff --git a/DotnetMSBuildLog.sln b/DotnetMSBuildLog.sln new file mode 100644 index 0000000..d0a9091 --- /dev/null +++ b/DotnetMSBuildLog.sln @@ -0,0 +1,34 @@ + +Microsoft Visual Studio Solution File, Format Version 12.00 +# Visual Studio 15 +VisualStudioVersion = 15.0.26124.0 +MinimumVisualStudioVersion = 15.0.26124.0 +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "DotnetMSBuildLog", "DotnetMSBuildLog\DotnetMSBuildLog.csproj", "{2A4802B0-10A4-4618-81DA-C927837CFF68}" +EndProject +Global + GlobalSection(SolutionConfigurationPlatforms) = preSolution + Debug|Any CPU = Debug|Any CPU + Debug|x64 = Debug|x64 + Debug|x86 = Debug|x86 + Release|Any CPU = Release|Any CPU + Release|x64 = Release|x64 + Release|x86 = Release|x86 + EndGlobalSection + GlobalSection(SolutionProperties) = preSolution + HideSolutionNode = FALSE + EndGlobalSection + GlobalSection(ProjectConfigurationPlatforms) = postSolution + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Debug|Any CPU.Build.0 = Debug|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Debug|x64.ActiveCfg = Debug|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Debug|x64.Build.0 = Debug|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Debug|x86.ActiveCfg = Debug|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Debug|x86.Build.0 = Debug|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Release|Any CPU.ActiveCfg = Release|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Release|Any CPU.Build.0 = Release|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Release|x64.ActiveCfg = Release|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Release|x64.Build.0 = Release|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Release|x86.ActiveCfg = Release|Any CPU + {2A4802B0-10A4-4618-81DA-C927837CFF68}.Release|x86.Build.0 = Release|Any CPU + EndGlobalSection +EndGlobal diff --git a/DotnetMSBuildLog/CommandLine/Commands/CommandExtenions.cs b/DotnetMSBuildLog/CommandLine/Commands/CommandExtenions.cs new file mode 100644 index 0000000..1c5c36d --- /dev/null +++ b/DotnetMSBuildLog/CommandLine/Commands/CommandExtenions.cs @@ -0,0 +1,18 @@ +using System; +using System.Collections.Generic; +using System.CommandLine; +using System.CommandLine.Invocation; +using System.Linq; +using System.Text; +using System.Threading.Tasks; + +namespace PauloMorgado.DotnetMSBuildLog.CommandLine.Commands +{ + internal static class CommandExtenions + { + /// + /// Allows the command handler to be included in the collection initializer. + /// + public static void Add(this Command command, ICommandHandler handler) => command.Handler = handler; + } +} diff --git a/DotnetMSBuildLog/CommandLine/Commands/ConvertCommandHandler.cs b/DotnetMSBuildLog/CommandLine/Commands/ConvertCommandHandler.cs new file mode 100644 index 0000000..1f326eb --- /dev/null +++ b/DotnetMSBuildLog/CommandLine/Commands/ConvertCommandHandler.cs @@ -0,0 +1,90 @@ +using PauloMorgado.DotnetMSBuildLog.Converters; +using System.CommandLine; +using System.CommandLine.Invocation; +using System.CommandLine.IO; +using System.IO; + +namespace PauloMorgado.DotnetMSBuildLog.CommandLine.Commands +{ + internal sealed class ConvertCommandArguments + { +#pragma warning disable CS8618 // Non-nullable field must contain a non-null value when exiting constructor. Consider declaring as nullable. + public IConsole Console { get; set; } + public FileInfo InputFileName { get; set; } +#pragma warning restore CS8618 // Non-nullable field must contain a non-null value when exiting constructor. Consider declaring as nullable. + public MSBuildLogFileFormat Format { get; set; } + public FileInfo? OutputFileName { get; set; } + } + + internal static class ConvertCommandHandler + { + private const string DefaultMSBuildLogFileName = "msbuild.binlog"; + + public static int ConvertFile(ConvertCommandArguments arguments) + { + if ((int)arguments.Format <= 0) + { + arguments.Console.Error.WriteLine("--format is required."); + return ErrorCodes.ArgumentError; + } + + if (arguments.Format == MSBuildLogFileFormat.MSBuildBinaryLog) + { + arguments.Console.Error.WriteLine("Cannot convert a nettrace file to nettrace format."); + return ErrorCodes.ArgumentError; + } + + if (!arguments.InputFileName.Exists) + { + arguments.Console.Error.WriteLine($"File '{arguments.InputFileName.FullName}' does not exist."); + return ErrorCodes.ArgumentError; + } + + if (arguments.OutputFileName == null) + { + arguments.OutputFileName = arguments.InputFileName; + } + + MSBuildLogFileFormatConverter.ConvertToFormat(arguments.Console, arguments.Format, arguments.InputFileName.FullName, arguments.OutputFileName.FullName); + + return 0; + } + + public static Command ConvertCommand() => + new Command( + name: "convert", + description: "Converts MSBuild binary logs to alternate formats for use with alternate trace analysis tools. Can only convert from the nettrace format") + { + // Handler + CommandHandler.Create(ConvertFile), + + // Arguments and Options + InputFileArgument(), + ConvertFormatOption(), + OutputOption(), + }; + + private static Argument InputFileArgument() => + new Argument( + name: "input-filename", + description: $"Input binary log file to be converted. Defaults to '{ConvertCommandHandler.DefaultMSBuildLogFileName}'.", + getDefaultValue: () => new FileInfo(ConvertCommandHandler.DefaultMSBuildLogFileName)) + .ExistingOnly(); + + public static Option ConvertFormatOption() => + new Option( + alias: "--format", + description: $"Sets the output format for the trace file conversion.") + { + Argument = new Argument(name: "trace-file-format") + }; + + private static Option OutputOption() => + new Option( + aliases: new[] { "-o", "--output" }, + description: "Output filename. Extension of target format will be added.") + { + Argument = new Argument(name: "output-filename") + }; + } +} diff --git a/DotnetMSBuildLog/CommandLine/Commands/ErrorCodes.cs b/DotnetMSBuildLog/CommandLine/Commands/ErrorCodes.cs new file mode 100644 index 0000000..e82b57c --- /dev/null +++ b/DotnetMSBuildLog/CommandLine/Commands/ErrorCodes.cs @@ -0,0 +1,16 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Text; +using System.Threading.Tasks; + +namespace PauloMorgado.DotnetMSBuildLog.CommandLine.Commands +{ + internal static class ErrorCodes + { + public const int SessionCreationError = 1; + public const int TracingError = 2; + public const int ArgumentError = 3; + public const int UnknownError = 4; + } +} diff --git a/DotnetMSBuildLog/Converters/MSBuildLogFileFormatConverter.cs b/DotnetMSBuildLog/Converters/MSBuildLogFileFormatConverter.cs new file mode 100644 index 0000000..c40af7e --- /dev/null +++ b/DotnetMSBuildLog/Converters/MSBuildLogFileFormatConverter.cs @@ -0,0 +1,65 @@ +using System; +using System.Collections.Immutable; +using System.CommandLine; +using System.CommandLine.IO; +using System.IO; +using Microsoft.Build.Logging.StructuredLogger; +using PauloMorgado.DotnetMSBuildLog.Writers; + +namespace PauloMorgado.DotnetMSBuildLog.Converters +{ + internal enum MSBuildLogFileFormat { MSBuildBinaryLog, Speedscope }; + + internal static class MSBuildLogFileFormatConverter + { + private static ImmutableDictionary TraceFileFormatExtensions = GetTraceFileFormatExtensions(); + + private static ImmutableDictionary GetTraceFileFormatExtensions() + { + var builder = ImmutableDictionary.CreateBuilder(); + builder.Add(MSBuildLogFileFormat.MSBuildBinaryLog, "binlog"); + builder.Add(MSBuildLogFileFormat.Speedscope, "speedscope.json"); + return builder.ToImmutable(); + } + + internal static void ConvertToFormat(IConsole console, MSBuildLogFileFormat format, string fileToConvertFilePath, string outputFilePath) + { + if (string.IsNullOrWhiteSpace(outputFilePath)) + { + outputFilePath = fileToConvertFilePath; + } + + outputFilePath = Path.ChangeExtension(outputFilePath, TraceFileFormatExtensions[format]); + console.Out.WriteLine($"Writing:\t{outputFilePath}"); + + switch (format) + { + case MSBuildLogFileFormat.MSBuildBinaryLog: + break; + case MSBuildLogFileFormat.Speedscope: + Convert(format, fileToConvertFilePath, outputFilePath); + break; + default: + // Validation happened way before this, so we shoud never reach this... + throw new ArgumentException($"Invalid TraceFileFormat \"{format}\""); + } + + console.Out.WriteLine("Conversion complete"); + } + + private static void Convert(MSBuildLogFileFormat format, string fileToConvertFilePath, string outputFilePath) + { + var build = Serialization.Read(fileToConvertFilePath); + + switch (format) + { + case MSBuildLogFileFormat.Speedscope: + SpeedscopeMSBuildLogWriter.WriteTo(build, outputFilePath); + break; + default: + // we should never get here + throw new ArgumentException($"Invalid MSBuildLogFileFormat: {format}"); + } + } + } +} diff --git a/DotnetMSBuildLog/DotnetMSBuildLog.csproj b/DotnetMSBuildLog/DotnetMSBuildLog.csproj new file mode 100644 index 0000000..f0a0747 --- /dev/null +++ b/DotnetMSBuildLog/DotnetMSBuildLog.csproj @@ -0,0 +1,18 @@ + + + + Exe + net5.0 + true + dotnet-msbuildlog + enable + dotnet-msbuild + PauloMorgado.DotnetMSBuildLog + + + + + + + + diff --git a/DotnetMSBuildLog/Program.cs b/DotnetMSBuildLog/Program.cs new file mode 100644 index 0000000..b50ad76 --- /dev/null +++ b/DotnetMSBuildLog/Program.cs @@ -0,0 +1,20 @@ +using PauloMorgado.DotnetMSBuildLog.CommandLine.Commands; +using System.CommandLine; +using System.CommandLine.Builder; +using System.CommandLine.Parsing; + +namespace PauloMorgado.DotnetMSBuildLog +{ + static class Program + { + static int Main(string[] args) + { + var parser = new CommandLineBuilder() + .AddCommand(ConvertCommandHandler.ConvertCommand()) + .UseDefaults() + .Build(); + + return parser.Invoke(args); + } + } +} diff --git a/DotnetMSBuildLog/Writers/SpeedscopeMSBuildLogWriter.cs b/DotnetMSBuildLog/Writers/SpeedscopeMSBuildLogWriter.cs new file mode 100644 index 0000000..c99916c --- /dev/null +++ b/DotnetMSBuildLog/Writers/SpeedscopeMSBuildLogWriter.cs @@ -0,0 +1,328 @@ +using Microsoft.Build.Logging.StructuredLogger; +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.IO; +using System.Linq; +using System.Reflection; +using System.Text.Json; + +namespace PauloMorgado.DotnetMSBuildLog.Writers +{ + /// + /// Exports provided StackSource to a https://www.speedscope.app/ format. + /// schema: https://www.speedscope.app/file-format-schema.json + /// + internal static class SpeedscopeMSBuildLogWriter + { + private static JsonWriterOptions jsonWriterOptions = new JsonWriterOptions + { +#if DEBUG + Indented = true, +#else + Indented = false, +#endif + }; + + public static void WriteTo(Build build, string filePath) + { + var frames = new List(); + var buildNodes = new Dictionary>(); + + PopulateSpeedscopeData(build, 0u, build.StartTime.Ticks, frames, buildNodes); + + using var fileStrem = new FileStream(filePath, FileMode.Create, FileAccess.Write, FileShare.Read); + using var jsonWriter = new Utf8JsonWriter(fileStrem, jsonWriterOptions); + + Export(Path.GetFileNameWithoutExtension(filePath), jsonWriter, build.EndTime.Ticks - build.StartTime.Ticks, frames, buildNodes); + + Dump(filePath, build.StartTime.Ticks, build); + } + + private static void PopulateSpeedscopeData(TimedNode node, uint level, long baseTime, List frames, Dictionary> buildNodes) + { + var startTimestamp = node.StartTime.Ticks - baseTime; + var endTimestamp = node.EndTime.Ticks - baseTime; + var duration = endTimestamp - startTimestamp; + + if (startTimestamp >= 0 && duration > 0) // Zero duration has no value for performance analyses and messes up the timeline + { + var frame = frames.Count; +#if DEBUG + node.Index = frame; +#endif + + frames.Add(GetFrameName(node)); + + if (!buildNodes.TryGetValue(node.NodeId, out var events)) + { + events = new LinkedList(); + buildNodes.Add(node.NodeId, events); + } + + insertEvent(events, new SpeedscopeEvent(frame, true, startTimestamp, duration, level)); + insertEvent(events, new SpeedscopeEvent(frame, false, endTimestamp, duration, level)); + } +#if DEBUG + else + { + node.Index = -1; + } +#endif + + if (node.HasChildren) + { + var childLevel = (level + (1u << 16)) & (0xFFFFu << 16); + + foreach (var childNode in node.Children) + { + if (childNode is TimedNode timedChildNode) + { + PopulateSpeedscopeData(timedChildNode, ++childLevel, baseTime, frames, buildNodes); + } + } + } + + static void insertEvent(LinkedList events, SpeedscopeEvent @event) + { + var node = events.Last; + + while (node is not null && node.Value.CompareTo(@event) > 0) + { + node = node.Previous; + } + + if (node is null) + { + events.AddLast(@event); + } + else + { + events.AddAfter(node, @event); + } + } + } + + [Conditional("DEBUG")] + private static void Dump(string filePath, long baseTime, TimedNode node) + { + using var fileStrem = new FileStream(filePath.Replace(".speedscope.json", ".msbuild.json"), FileMode.Create, FileAccess.Write, FileShare.Read); + using var jsonWriter = new Utf8JsonWriter(fileStrem, jsonWriterOptions); + + dump(jsonWriter, baseTime, node); + + static void dump(Utf8JsonWriter jsonWriter, long baseTime, TimedNode node) + { + jsonWriter.WriteStartObject(); + + jsonWriter.WriteString("typeName", node.TypeName); + jsonWriter.WriteString("description", node.ToString()); + jsonWriter.WriteString("name", node.Name); + jsonWriter.WriteNumber("id", node.Id); + jsonWriter.WriteNumber("frame", node.Index); + jsonWriter.WriteNumber("nodeId", node.NodeId); + jsonWriter.WriteString("startTime", node.StartTime.ToString("HH:mm:ss.fffffff")); + jsonWriter.WriteString("endTime", node.EndTime.ToString("HH:mm:ss.fffffff")); + jsonWriter.WriteString("duration", node.Duration.ToString("G")); + jsonWriter.WriteNumber("startTimestamp", (node.StartTime.Ticks - baseTime) / (double)TimeSpan.TicksPerMillisecond); + jsonWriter.WriteNumber("endTimestamp", (node.EndTime.Ticks - baseTime) / (double)TimeSpan.TicksPerMillisecond); + jsonWriter.WriteNumber("durationTime", node.Duration.Ticks / (double)TimeSpan.TicksPerMillisecond); + jsonWriter.WriteString("durationText", node.DurationText); + + if (node.HasChildren) + { + jsonWriter.WriteStartArray("children"); + + foreach (var childNode in node.Children) + { + if (childNode is TimedNode timedChildNode) + { + dump(jsonWriter, baseTime, timedChildNode); + } + } + + jsonWriter.WriteEndArray(); + } + + jsonWriter.WriteEndObject(); + } + } + + static string GetFrameName(BaseNode node) +#if DEBUG + => node switch + { + Project project => $"#{(node as TimedNode)?.Index} {project.TypeName} \"{Path.GetFileName(project.ProjectFile)}\"({string.Join(',', project.EntryTargets)} target(s))@\"{project.ProjectFile}\"", + Task task => $"#{(node as TimedNode)?.Index} {task.TypeName} {task.Name}@[{task.FromAssembly}]", + Target target => $"#{(node as TimedNode)?.Index} {target.TypeName} {target.Name}@\"{target.SourceFilePath}\"", + _ => $"#{(node as TimedNode)?.Index} {node}" + }; +#else + => node switch + { + Project project => $"{project.TypeName} \"{Path.GetFileName(project.ProjectFile)}\"({string.Join(',', project.EntryTargets)} target(s))@\"{project.ProjectFile}\"", + Task task => $"{task.TypeName} {task.Name}@[{task.FromAssembly}]", + Target target => $"{target.TypeName} {target.Name}@\"{target.SourceFilePath}\"", + _ => node.ToString() + }; +#endif + + private static void Export(string name, Utf8JsonWriter jsonWriter, long duration, List frames, Dictionary> buildNodes) + { + jsonWriter.WriteStartObject(); + + ExportHeader(name, jsonWriter); + + ExportShared(jsonWriter, frames); + + ExportProfiles(jsonWriter, duration, buildNodes); + + jsonWriter.WriteEndObject(); + } + + private static void ExportShared(Utf8JsonWriter jsonWriter, List frames) + { + jsonWriter.WriteStartObject("shared"); + + ExportSharedFrames(jsonWriter, frames); + + jsonWriter.WriteEndObject(); + } + + private static void ExportSharedFrames(Utf8JsonWriter jsonWriter, List frames) + { + jsonWriter.WriteStartArray("frames"); + + foreach (var frame in frames) + { + ExportSharedFrame(jsonWriter, frame!); + } + + jsonWriter.WriteEndArray(); + } + + private static void ExportSharedFrame(Utf8JsonWriter jsonWriter, string frame) + { + jsonWriter.WriteStartObject(); + jsonWriter.WriteString("name", frame); + jsonWriter.WriteEndObject(); + } + + private static void ExportProfiles(Utf8JsonWriter jsonWriter, long duration, Dictionary> buildNodes) + { + jsonWriter.WriteStartArray("profiles"); + + foreach (var (buildNodeId, events) in buildNodes.OrderBy(bn => bn.Key)) + { + ExportProfile(jsonWriter, duration, buildNodeId, events); + } + + jsonWriter.WriteEndArray(); + } + + private static void ExportProfile(Utf8JsonWriter jsonWriter, long duration, int buildNodeId, LinkedList events) + { + jsonWriter.WriteStartObject(); + + jsonWriter.WriteString("type", "evented"); + jsonWriter.WriteString("name", $"Node #{buildNodeId}"); + jsonWriter.WriteString("unit", "milliseconds"); + jsonWriter.WriteNumber("startValue", 0.0); + jsonWriter.WriteNumber("endValue", duration / (double)TimeSpan.TicksPerMillisecond); + + jsonWriter.WriteStartArray("events"); + + foreach (var @event in events) + { + ExportProfileBuildNodeEvent(jsonWriter, @event); + } + + jsonWriter.WriteEndArray(); + + jsonWriter.WriteEndObject(); + } + + private static void ExportProfileBuildNodeEvent(Utf8JsonWriter jsonWriter, SpeedscopeEvent @event) + { + jsonWriter.WriteStartObject(); + + jsonWriter.WriteString("type", @event.IsStart ? "O" : "C"); + jsonWriter.WriteNumber("frame", @event.Frame); + jsonWriter.WriteNumber("at", @event.At / (double)TimeSpan.TicksPerMillisecond); + + jsonWriter.WriteEndObject(); + } + + private static void ExportHeader(string name, Utf8JsonWriter jsonWriter) + { + jsonWriter.WriteString("exporter", GetExporterInfo()); + jsonWriter.WriteString("name", name); + jsonWriter.WriteNumber("activeProfileIndex", 0); + jsonWriter.WriteString("$schema", "https://www.speedscope.app/file-format-schema.json"); + } + + internal static string GetExporterInfo() + { + var writer = typeof(SpeedscopeMSBuildLogWriter).GetTypeInfo().Assembly.GetName(); + + return $"{writer.Name}@{writer.Version}"; + } + + private class SpeedscopeEvent : IComparable + { + public readonly bool IsStart; + public readonly int Frame; + public readonly long At; + public readonly long Duration; + public readonly uint Level; + + public SpeedscopeEvent(int frame, bool isStart, long at, long duration, uint level) + { + this.Frame = frame; + this.IsStart = isStart; + this.At = at; + this.Duration = duration; + this.Level = level; + } + + public int CompareTo(SpeedscopeEvent? other) + { + if (other is null) + { + return 1; + } + + var compareAt = this.At.CompareTo(other.At); + + if (compareAt == 0) + { + var compareDuration = this.Duration.CompareTo(other.Duration); + + var compareLevel = this.Level.CompareTo(other.Level); + + if (this.IsStart && other.IsStart) + { + return compareDuration == 0 ? compareLevel : -compareDuration; + } + else if (!(this.IsStart || other.IsStart)) + { + return compareDuration == 0 ? -compareLevel : compareDuration; + } + else + { + int result = this.IsStart ? 1 : -1; + + if (this.Frame == other.Frame) + { + result = -result; + } + + return result; + } + } + + return compareAt; + } + } + } +}