From 734c048e6a7f9a0c09462fa05fb9ff27c246dc14 Mon Sep 17 00:00:00 2001 From: Jon Skeet Date: Fri, 12 Oct 2018 12:07:21 +0100 Subject: [PATCH] Infrastructure for logging build actions to create a log file, then processing it to show durations --- .gitignore | 3 + processbuildtiminglog.sh | 6 + ...e.Cloud.Tools.ProcessBuildTimingLog.csproj | 15 +++ .../LogEntry.cs | 46 ++++++++ .../Program.cs | 108 ++++++++++++++++++ tools/Google.Cloud.Tools.sln | 14 +++ toolversions.sh | 6 + 7 files changed, 198 insertions(+) create mode 100755 processbuildtiminglog.sh create mode 100644 tools/Google.Cloud.Tools.ProcessBuildTimingLog/Google.Cloud.Tools.ProcessBuildTimingLog.csproj create mode 100644 tools/Google.Cloud.Tools.ProcessBuildTimingLog/LogEntry.cs create mode 100644 tools/Google.Cloud.Tools.ProcessBuildTimingLog/Program.cs diff --git a/.gitignore b/.gitignore index 3c3e7b467590..7bffda14a549 100644 --- a/.gitignore +++ b/.gitignore @@ -48,3 +48,6 @@ AllTests.txt # Benchmarks BenchmarkDotNet.Artifacts + +# Log files +build_timing_log.txt diff --git a/processbuildtiminglog.sh b/processbuildtiminglog.sh new file mode 100755 index 000000000000..bfd48b4f4ee2 --- /dev/null +++ b/processbuildtiminglog.sh @@ -0,0 +1,6 @@ +#!/bin/bash + +echo ---------------- +echo Build timing log +echo ---------------- +dotnet run -p tools/Google.Cloud.Tools.ProcessBuildTimingLog -- build_timing_log.txt diff --git a/tools/Google.Cloud.Tools.ProcessBuildTimingLog/Google.Cloud.Tools.ProcessBuildTimingLog.csproj b/tools/Google.Cloud.Tools.ProcessBuildTimingLog/Google.Cloud.Tools.ProcessBuildTimingLog.csproj new file mode 100644 index 000000000000..bf2cad5ea633 --- /dev/null +++ b/tools/Google.Cloud.Tools.ProcessBuildTimingLog/Google.Cloud.Tools.ProcessBuildTimingLog.csproj @@ -0,0 +1,15 @@ + + + + false + Console app to process a build timing log + Exe + netcoreapp2.0 + True + + + + + + + diff --git a/tools/Google.Cloud.Tools.ProcessBuildTimingLog/LogEntry.cs b/tools/Google.Cloud.Tools.ProcessBuildTimingLog/LogEntry.cs new file mode 100644 index 000000000000..f0f490520b5f --- /dev/null +++ b/tools/Google.Cloud.Tools.ProcessBuildTimingLog/LogEntry.cs @@ -0,0 +1,46 @@ +// Copyright 2018 Google LLC +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using NodaTime; +using NodaTime.Text; +using System; +using System.Collections.Generic; +using System.Text; + +namespace Google.Cloud.Tools.ProcessBuildTimingLog +{ + /// + /// The separated parts of a raw log line. + /// + public class LogEntry + { + private static readonly char[] s_separators = { ' ' }; + public string Action { get; } + public Instant Timestamp { get; } + + private LogEntry(string action, Instant timestamp) => + (Action, Timestamp) = (action, timestamp); + + public static LogEntry FromLogLine(string line) + { + string[] bits = line.Split(s_separators, 2); + if (bits.Length != 2) + { + throw new ArgumentException("Invalid log line: {line}"); + } + var instant = OffsetDateTimePattern.ExtendedIso.Parse(bits[0]).Value.ToInstant(); + return new LogEntry(bits[1], instant); + } + } +} diff --git a/tools/Google.Cloud.Tools.ProcessBuildTimingLog/Program.cs b/tools/Google.Cloud.Tools.ProcessBuildTimingLog/Program.cs new file mode 100644 index 000000000000..e2ac70ee478d --- /dev/null +++ b/tools/Google.Cloud.Tools.ProcessBuildTimingLog/Program.cs @@ -0,0 +1,108 @@ +// Copyright 2018 Google LLC +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +using NodaTime; +using NodaTime.Text; +using System; +using System.Collections.Generic; +using System.IO; +using System.Linq; + +namespace Google.Cloud.Tools.ProcessBuildTimingLog +{ + /// + /// Processes a build timing log created by the log_build_action function in toolversions.sh. + /// This makes it easy to see how long each part of the build takes. + /// + class Program + { + private static readonly DurationPattern s_durationPattern = DurationPattern.CreateWithInvariantCulture("-HH:mm:ss"); + // The text to use instead of a duration for entries with no duration + private const string NoDurationText = "--------"; + + private const string StartPrefix = "(Start) "; + private const string EndPrefix = "(End) "; + + private static int Main(string[] args) + { + if (args.Length != 1) + { + Console.WriteLine("Required single argument: log file path"); + return 1; + } + string[] lines = File.ReadAllLines(args[0]); + + var logEntries = lines.Where(line => line.Length > 0).Select(LogEntry.FromLogLine).ToList(); + + for (int i = 0; i < logEntries.Count; i++) + { + ProcessEntry(logEntries, i); + } + + return 0; + } + + private static void ProcessEntry(List entries, int index) + { + LogEntry entry = entries[index]; + + // Ignore any "end" actions. Assume they've already been handled (or are useless if they're orphans) + if (entry.Action.StartsWith(EndPrefix)) + { + return; + } + + // If we have a "start" action, find the next matching "start" or "end", and handle appropriately + if (entry.Action.StartsWith(StartPrefix)) + { + string unprefixedAction = entry.Action.Substring(StartPrefix.Length); + string expectedEndAction = EndPrefix + unprefixedAction; + + // Note: in theory we should probably do this by index rather than timing, but it's very unlikely + // to cause issues. + var nextStart = entries.Skip(index + 1).FirstOrDefault(e => e.Action.StartsWith(entry.Action)); + var nextEnd = entries.Skip(index + 1).FirstOrDefault(e => e.Action.StartsWith(expectedEndAction)); + if (nextEnd == null) + { + PrintEntry(entry.Timestamp, null, $"No matching end: {unprefixedAction}"); + return; + } + if (nextStart != null && nextStart.Timestamp < nextEnd.Timestamp) + { + PrintEntry(entry.Timestamp, null, $"Matching start before end: {unprefixedAction}"); + return; + } + // We report the action in parentheses as a simple indication that it's a compound action. + PrintEntry(entry.Timestamp, nextEnd.Timestamp, $"({unprefixedAction})"); + return; + } + // Simple case: just one line for this action. Use the next entry if we have one. + if (index == entries.Count) + { + PrintEntry(entry.Timestamp, null, $"Final line of file: {entry.Action}"); + } + else + { + PrintEntry(entry.Timestamp, entries[index + 1].Timestamp, entry.Action); + } + + void PrintEntry(Instant start, Instant? end, string action) + { + string formattedDuration = end != null + ? s_durationPattern.Format(end.Value - start) + : NoDurationText; + Console.WriteLine($"{InstantPattern.General.Format(start)} {formattedDuration} {action}"); + } + } + } +} diff --git a/tools/Google.Cloud.Tools.sln b/tools/Google.Cloud.Tools.sln index 47cad18e9e82..4ebb7da42536 100644 --- a/tools/Google.Cloud.Tools.sln +++ b/tools/Google.Cloud.Tools.sln @@ -42,6 +42,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Google.Cloud.Tools.Generate EndProject Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Google.Cloud.AnalyzersTesting", "Google.Cloud.AnalyzersTesting\Google.Cloud.AnalyzersTesting.csproj", "{5608BDB2-A160-49C0-A545-C08787534B18}" EndProject +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Google.Cloud.Tools.ProcessBuildTimingLog", "Google.Cloud.Tools.ProcessBuildTimingLog\Google.Cloud.Tools.ProcessBuildTimingLog.csproj", "{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}" +EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|Any CPU = Debug|Any CPU @@ -292,6 +294,18 @@ Global {5608BDB2-A160-49C0-A545-C08787534B18}.Release|x64.Build.0 = Release|Any CPU {5608BDB2-A160-49C0-A545-C08787534B18}.Release|x86.ActiveCfg = Release|Any CPU {5608BDB2-A160-49C0-A545-C08787534B18}.Release|x86.Build.0 = Release|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|Any CPU.Build.0 = Debug|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|x64.ActiveCfg = Debug|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|x64.Build.0 = Debug|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|x86.ActiveCfg = Debug|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|x86.Build.0 = Debug|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|Any CPU.ActiveCfg = Release|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|Any CPU.Build.0 = Release|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|x64.ActiveCfg = Release|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|x64.Build.0 = Release|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|x86.ActiveCfg = Release|Any CPU + {E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|x86.Build.0 = Release|Any CPU EndGlobalSection GlobalSection(SolutionProperties) = preSolution HideSolutionNode = FALSE diff --git a/toolversions.sh b/toolversions.sh index ff7e153aaffb..3a4c8d549da0 100755 --- a/toolversions.sh +++ b/toolversions.sh @@ -82,3 +82,9 @@ install_docfx() { ) fi } + +# Logs to both stdout and a build timing log, allowing +# post-processing to see how long each part of the build takes. +log_build_action() { + echo "$(date -u -Iseconds) $1" | tee -a $REPO_ROOT/build_timing_log.txt +}