Skip to content

Commit

Permalink
Infrastructure for logging build actions to create a log file, then p…
Browse files Browse the repository at this point in the history
…rocessing it to show durations
  • Loading branch information
jskeet committed Oct 12, 2018
1 parent c511a46 commit 734c048
Show file tree
Hide file tree
Showing 7 changed files with 198 additions and 0 deletions.
3 changes: 3 additions & 0 deletions .gitignore
Expand Up @@ -48,3 +48,6 @@ AllTests.txt

# Benchmarks
BenchmarkDotNet.Artifacts

# Log files
build_timing_log.txt
6 changes: 6 additions & 0 deletions 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
@@ -0,0 +1,15 @@
<Project Sdk="Microsoft.NET.Sdk">

<PropertyGroup>
<IsPackable>false</IsPackable>
<Description>Console app to process a build timing log</Description>
<OutputType>Exe</OutputType>
<TargetFramework>netcoreapp2.0</TargetFramework>
<TreatWarningsAsErrors>True</TreatWarningsAsErrors>
</PropertyGroup>

<ItemGroup>
<PackageReference Include="NodaTime" Version="2.4.0" />
</ItemGroup>

</Project>
46 changes: 46 additions & 0 deletions 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
{
/// <summary>
/// The separated parts of a raw log line.
/// </summary>
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);
}
}
}
108 changes: 108 additions & 0 deletions 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
{
/// <summary>
/// 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.
/// </summary>
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<LogEntry> 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}");
}
}
}
}
14 changes: 14 additions & 0 deletions tools/Google.Cloud.Tools.sln
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
6 changes: 6 additions & 0 deletions toolversions.sh
Expand Up @@ -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
}

0 comments on commit 734c048

Please sign in to comment.