Skip to content

Commit 734c048

Browse files
committed
Infrastructure for logging build actions to create a log file, then processing it to show durations
1 parent c511a46 commit 734c048

File tree

7 files changed

+198
-0
lines changed

7 files changed

+198
-0
lines changed

.gitignore

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -48,3 +48,6 @@ AllTests.txt
4848

4949
# Benchmarks
5050
BenchmarkDotNet.Artifacts
51+
52+
# Log files
53+
build_timing_log.txt

processbuildtiminglog.sh

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
#!/bin/bash
2+
3+
echo ----------------
4+
echo Build timing log
5+
echo ----------------
6+
dotnet run -p tools/Google.Cloud.Tools.ProcessBuildTimingLog -- build_timing_log.txt
Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
<Project Sdk="Microsoft.NET.Sdk">
2+
3+
<PropertyGroup>
4+
<IsPackable>false</IsPackable>
5+
<Description>Console app to process a build timing log</Description>
6+
<OutputType>Exe</OutputType>
7+
<TargetFramework>netcoreapp2.0</TargetFramework>
8+
<TreatWarningsAsErrors>True</TreatWarningsAsErrors>
9+
</PropertyGroup>
10+
11+
<ItemGroup>
12+
<PackageReference Include="NodaTime" Version="2.4.0" />
13+
</ItemGroup>
14+
15+
</Project>
Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,46 @@
1+
// Copyright 2018 Google LLC
2+
//
3+
// Licensed under the Apache License, Version 2.0 (the "License");
4+
// you may not use this file except in compliance with the License.
5+
// You may obtain a copy of the License at
6+
//
7+
// https://www.apache.org/licenses/LICENSE-2.0
8+
//
9+
// Unless required by applicable law or agreed to in writing, software
10+
// distributed under the License is distributed on an "AS IS" BASIS,
11+
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12+
// See the License for the specific language governing permissions and
13+
// limitations under the License.
14+
15+
using NodaTime;
16+
using NodaTime.Text;
17+
using System;
18+
using System.Collections.Generic;
19+
using System.Text;
20+
21+
namespace Google.Cloud.Tools.ProcessBuildTimingLog
22+
{
23+
/// <summary>
24+
/// The separated parts of a raw log line.
25+
/// </summary>
26+
public class LogEntry
27+
{
28+
private static readonly char[] s_separators = { ' ' };
29+
public string Action { get; }
30+
public Instant Timestamp { get; }
31+
32+
private LogEntry(string action, Instant timestamp) =>
33+
(Action, Timestamp) = (action, timestamp);
34+
35+
public static LogEntry FromLogLine(string line)
36+
{
37+
string[] bits = line.Split(s_separators, 2);
38+
if (bits.Length != 2)
39+
{
40+
throw new ArgumentException("Invalid log line: {line}");
41+
}
42+
var instant = OffsetDateTimePattern.ExtendedIso.Parse(bits[0]).Value.ToInstant();
43+
return new LogEntry(bits[1], instant);
44+
}
45+
}
46+
}
Lines changed: 108 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,108 @@
1+
// Copyright 2018 Google LLC
2+
//
3+
// Licensed under the Apache License, Version 2.0 (the "License");
4+
// you may not use this file except in compliance with the License.
5+
// You may obtain a copy of the License at
6+
//
7+
// https://www.apache.org/licenses/LICENSE-2.0
8+
//
9+
// Unless required by applicable law or agreed to in writing, software
10+
// distributed under the License is distributed on an "AS IS" BASIS,
11+
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12+
// See the License for the specific language governing permissions and
13+
// limitations under the License.
14+
using NodaTime;
15+
using NodaTime.Text;
16+
using System;
17+
using System.Collections.Generic;
18+
using System.IO;
19+
using System.Linq;
20+
21+
namespace Google.Cloud.Tools.ProcessBuildTimingLog
22+
{
23+
/// <summary>
24+
/// Processes a build timing log created by the log_build_action function in toolversions.sh.
25+
/// This makes it easy to see how long each part of the build takes.
26+
/// </summary>
27+
class Program
28+
{
29+
private static readonly DurationPattern s_durationPattern = DurationPattern.CreateWithInvariantCulture("-HH:mm:ss");
30+
// The text to use instead of a duration for entries with no duration
31+
private const string NoDurationText = "--------";
32+
33+
private const string StartPrefix = "(Start) ";
34+
private const string EndPrefix = "(End) ";
35+
36+
private static int Main(string[] args)
37+
{
38+
if (args.Length != 1)
39+
{
40+
Console.WriteLine("Required single argument: log file path");
41+
return 1;
42+
}
43+
string[] lines = File.ReadAllLines(args[0]);
44+
45+
var logEntries = lines.Where(line => line.Length > 0).Select(LogEntry.FromLogLine).ToList();
46+
47+
for (int i = 0; i < logEntries.Count; i++)
48+
{
49+
ProcessEntry(logEntries, i);
50+
}
51+
52+
return 0;
53+
}
54+
55+
private static void ProcessEntry(List<LogEntry> entries, int index)
56+
{
57+
LogEntry entry = entries[index];
58+
59+
// Ignore any "end" actions. Assume they've already been handled (or are useless if they're orphans)
60+
if (entry.Action.StartsWith(EndPrefix))
61+
{
62+
return;
63+
}
64+
65+
// If we have a "start" action, find the next matching "start" or "end", and handle appropriately
66+
if (entry.Action.StartsWith(StartPrefix))
67+
{
68+
string unprefixedAction = entry.Action.Substring(StartPrefix.Length);
69+
string expectedEndAction = EndPrefix + unprefixedAction;
70+
71+
// Note: in theory we should probably do this by index rather than timing, but it's very unlikely
72+
// to cause issues.
73+
var nextStart = entries.Skip(index + 1).FirstOrDefault(e => e.Action.StartsWith(entry.Action));
74+
var nextEnd = entries.Skip(index + 1).FirstOrDefault(e => e.Action.StartsWith(expectedEndAction));
75+
if (nextEnd == null)
76+
{
77+
PrintEntry(entry.Timestamp, null, $"No matching end: {unprefixedAction}");
78+
return;
79+
}
80+
if (nextStart != null && nextStart.Timestamp < nextEnd.Timestamp)
81+
{
82+
PrintEntry(entry.Timestamp, null, $"Matching start before end: {unprefixedAction}");
83+
return;
84+
}
85+
// We report the action in parentheses as a simple indication that it's a compound action.
86+
PrintEntry(entry.Timestamp, nextEnd.Timestamp, $"({unprefixedAction})");
87+
return;
88+
}
89+
// Simple case: just one line for this action. Use the next entry if we have one.
90+
if (index == entries.Count)
91+
{
92+
PrintEntry(entry.Timestamp, null, $"Final line of file: {entry.Action}");
93+
}
94+
else
95+
{
96+
PrintEntry(entry.Timestamp, entries[index + 1].Timestamp, entry.Action);
97+
}
98+
99+
void PrintEntry(Instant start, Instant? end, string action)
100+
{
101+
string formattedDuration = end != null
102+
? s_durationPattern.Format(end.Value - start)
103+
: NoDurationText;
104+
Console.WriteLine($"{InstantPattern.General.Format(start)} {formattedDuration} {action}");
105+
}
106+
}
107+
}
108+
}

tools/Google.Cloud.Tools.sln

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -42,6 +42,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Google.Cloud.Tools.Generate
4242
EndProject
4343
Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Google.Cloud.AnalyzersTesting", "Google.Cloud.AnalyzersTesting\Google.Cloud.AnalyzersTesting.csproj", "{5608BDB2-A160-49C0-A545-C08787534B18}"
4444
EndProject
45+
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Google.Cloud.Tools.ProcessBuildTimingLog", "Google.Cloud.Tools.ProcessBuildTimingLog\Google.Cloud.Tools.ProcessBuildTimingLog.csproj", "{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}"
46+
EndProject
4547
Global
4648
GlobalSection(SolutionConfigurationPlatforms) = preSolution
4749
Debug|Any CPU = Debug|Any CPU
@@ -292,6 +294,18 @@ Global
292294
{5608BDB2-A160-49C0-A545-C08787534B18}.Release|x64.Build.0 = Release|Any CPU
293295
{5608BDB2-A160-49C0-A545-C08787534B18}.Release|x86.ActiveCfg = Release|Any CPU
294296
{5608BDB2-A160-49C0-A545-C08787534B18}.Release|x86.Build.0 = Release|Any CPU
297+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
298+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|Any CPU.Build.0 = Debug|Any CPU
299+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|x64.ActiveCfg = Debug|Any CPU
300+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|x64.Build.0 = Debug|Any CPU
301+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|x86.ActiveCfg = Debug|Any CPU
302+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Debug|x86.Build.0 = Debug|Any CPU
303+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|Any CPU.ActiveCfg = Release|Any CPU
304+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|Any CPU.Build.0 = Release|Any CPU
305+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|x64.ActiveCfg = Release|Any CPU
306+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|x64.Build.0 = Release|Any CPU
307+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|x86.ActiveCfg = Release|Any CPU
308+
{E47C244F-96BC-4753-BFE1-7A54A3C3AA3E}.Release|x86.Build.0 = Release|Any CPU
295309
EndGlobalSection
296310
GlobalSection(SolutionProperties) = preSolution
297311
HideSolutionNode = FALSE

toolversions.sh

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -82,3 +82,9 @@ install_docfx() {
8282
)
8383
fi
8484
}
85+
86+
# Logs to both stdout and a build timing log, allowing
87+
# post-processing to see how long each part of the build takes.
88+
log_build_action() {
89+
echo "$(date -u -Iseconds) $1" | tee -a $REPO_ROOT/build_timing_log.txt
90+
}

0 commit comments

Comments
 (0)