[performance] initial MSBuild project timing #1569

jonathanpeppers · 2018-04-17T16:43:08Z

[performance] initial MSBuild project timing

The first step in tracking our build times is to at least some of our
existing projects' build times recorded as plots on Jenkins. This works
by running a custom MSBuild logger (written by Grendel) that records
detailed timing information down to even each MSBuild task. For now, I
am aggregating these results to a single CSV file to be ingested by
Jenkins plots.

The new TimingLogger emits XML in the following format:

<builds>
    <build start-ticks="636607852701529939" start-threadid="1" id="HelloWorld-FreshBuild" commit="8dcd59e" description="A fresh build after a clean checkout for HelloWorld" end-ticks="636607852899547509" end-threadid="1" elapsed="00:00:19.8017570" succeeded="True">
        <toolsets>
            <toolset version="15.0" path="C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\MSBuild\15.0\Bin" />
        </toolsets>
        <files>
            <file id="1" path="C:\Users\myuser\Desktop\Git\xamarin-android\samples\HelloWorld\HelloWorld.csproj" />
        </files>
        <project start-ticks="636607852707145402" start-threadid="6" file-id="1" end-ticks="636607852899326841" end-threadid="6" elapsed="00:00:19.2181439" succeeded="True">
            <target start-ticks="636607852707365985" start-threadid="6" name="RedirectMonoAndroidSdkPaths" file-id="2" end-ticks="636607852708932958" end-threadid="6" elapsed="00:00:00.1566973" succeeded="True">
                <task start-ticks="636607852708755105" start-threadid="6" name="SetVsMonoAndroidRegistryKey" file-id="2" end-ticks="636607852708895478" end-threadid="6" elapsed="00:00:00.0140373" succeeded="True" />
            </target>
        </project>
    </build>
</builds>

The total elapsed time of the build is aggregated into the CSV file.

Projects built:

samples/HelloWorld
tests/Xamarin.Forms-Performance-Integration

Four types of builds:

Fresh build (simulated fresh checkout)
Second build (no changes)
Touch C# file, build again
Touch Android resource XML file, build again

I am timing the SignAndroidPackage and Install targets for each of
these cases.

Results are aggregated into TestResult-MSBuild-times.csv for
processing on Jenkins. After this gets merged into master, there will be
some configuration needed to setup the new plot.

Example results, in the aggregated CSV file:

HelloWorld-FreshBuild-Debug	HelloWorld-FreshInstall-Debug	XF-FreshBuild-Debug	XF-FreshInstall-Debug
00:00:16.3538291	00:00:04.7940071	00:00:27.5263076	00:00:22.6720137

Also included in the table, will be the TouchCSharp and
TouchAndroidResource builds for both of the HelloWorld and XF
projects for both SignAndroidPackage and Install targets.

Other changes:

I let VS 2017 re-sort/fixup Xamarin.Android.sln
Split up timing.csproj into timing.targets and timing.projitems
Updated Makefile to include a run-performance-tests target.
A new ProcessMSBuildTimings task to aggregate the results

Upstream in monodroid:

Since it is not built on Jenkins, these timings need to go somewhere
else TBD
Plans are to test more "real world" apps here, and inject as many
<XamarinAndroidProject /> items as needed during the timings
We should also leverage the more detailed timings collected, timing
specific MSBuild tasks could be useful

jonathanpeppers · 2018-04-17T21:05:27Z

build-tools/timing/timing.targets

+      <_ID>%(XamarinAndroidProject.ShortName)-FreshBuild</_ID>
+      <_Description>A fresh build after a clean checkout for %(XamarinAndroidProject.Name)</_Description>
+      <_Target>SignAndroidPackage</_Target>
+      <_ProjectDir>$([System.IO.Path]::GetDirectoryName(%(XamarinAndroidProject.Identity)))</_ProjectDir>


xbuild is calculating $(_ProjectDir) as an empty string.

Is there some workaround I need here? It works for msbuild, even on macOS.

I don't see how it could be evaluated as non-empty on msbuild. %(XamarinAndroidProject.Identity) is evaluated to "%(XamarinAndroidProject.Identity)" (as is). You'd need @(XamarinAndroidProject->'%(Identity)'). It equally failed on both msbuild and xbuild.

<Project xmlns="http://schemas.microsoft.com/developer/msbuild/2003"> <ItemGroup> <XamarinAndroidProject Include="/sources/xamarin-android/Xamarin.Android.sln" /> </ItemGroup> <PropertyGroup> <_V>%(XamarinAndroidProject.Identity)</_V> <_W>@(XamarinAndroidProject->'%(Identity)')</_W> </PropertyGroup> <Target Name="Build"> <Message Text="V: $(_V)" /> <Message Text="W: $(_W)" /> </Target> </Project> $ msbuild x.targets </snip> V: %(XamarinAndroidProject.Identity) W: /sources/xamarin-android/Xamarin.Android.sln

I still couldn't find a valid solution, but you might find it with this hint.

Yeah it must be an xbuild bug, if you make the target "batch" by adding an Outputs it works:

<Project xmlns="http://schemas.microsoft.com/developer/msbuild/2003"> <ItemGroup> <XamarinAndroidProject Include="/sources/xamarin-android/Xamarin.Android.sln" /> </ItemGroup> <Target Name="Build" Outputs="%(XamarinAndroidProject.Identity)"> <PropertyGroup> <_V>%(XamarinAndroidProject.Identity)</_V> <_W>@(XamarinAndroidProject->'%(Identity)')</_W> </PropertyGroup> <Message Text="V: $(_V)" /> <Message Text="W: $(_W)" /> </Target> </Project>

msbuild:

V: /sources/xamarin-android/Xamarin.Android.sln W: /sources/xamarin-android/Xamarin.Android.sln

xbuild:

V: %(XamarinAndroidProject.Identity) W: /sources/xamarin-android/Xamarin.Android.sln

Anyway, thanks for your example, I see how to fix it now.

jonpryor · 2018-04-18T18:08:46Z

build-tools/scripts/RunTests.targets

+  <Target Name="RunPerformanceTests">
+    <MSBuild Projects="$(MSBuildThisFileDirectory)..\timing\timing.csproj" Targets="MSBuildTiming" />
+  </Target>
+  <Target Name="RunAllTests" DependsOnTargets="RunNUnitTests;RunJavaInteropTests;RunApkTests;RunPerformanceTests" />


Let's move the DependsOnTargets values into a new $(RunAllTestsDependsOn) property, so that every time we add a new target we don't need to repeat quite so much.

jonpryor · 2018-04-18T18:11:32Z

build-tools/timing/timing.csproj

    <TargetFrameworkVersion>v4.5</TargetFrameworkVersion>
  </PropertyGroup>
  <Import Project="..\..\Configuration.props" />
+  <Import Project="timing.targets" />


This file should probably follow build-tools/dependencies/dependencies.csproj in spirit and:

<Import Project="$(MSBuildBinPath)\Microsoft.CSharp.targets" />

Override/set $(BuildDependsOn).

That way the @(ProjectReference) values will actually mean something. (Without a call to the ResolveReferences target, @(ProjectReference) is meaningless.

jonpryor · 2018-04-18T18:13:45Z

build-tools/timing/timing.projitems

+    <_TopDir>$(MSBuildThisFileDirectory)..\..\</_TopDir>
+  </PropertyGroup>
+  <ItemGroup>
+    <XamarinAndroidProject Include="$(_TopDir)samples\HelloWorld\HelloWorld.csproj">


We should pick a more semantically meaningful name here than @(XamarinAndroidProject). What is a "Xamarin Android Project" such that src/Mono.Android, tests/locales/Xamarin.Android.Locale-Tests, and many more don't apply?

I would suggest @(XACaptureBuildTimingProject).

jonpryor · 2018-04-18T18:16:31Z

build-tools/timing/timing.targets

+      <_FilesToDelete Include="$(_OutputDir)Timing_*" />
+    </ItemGroup>
+    <Delete Files="@(_FilesToDelete)"/>
+    <GitCommitHash


Why not use the GetXAVersionInfo target from build-tools/scripts/XAVersionInfo.targets, which populates $(XAVersionHash)?

jonpryor · 2018-04-18T18:22:53Z

build-tools/timing/timing.targets

+      <_Target>Install</_Target>
+      <_OutputFile>$(_OutputDir)Timing_$(_ID)_$(Configuration)_@(XamarinAndroidProject->'%(Name)')</_OutputFile>
+    </PropertyGroup>
+    <Exec Command="$(_XABuild) /fl /flp:LogFile=$(_OutputFile).log &quot;/logger:$(_TimingLogger);ID=$(_ID);Description=$(_Description);Commit=$(_XAHash);OutputPath=$(_OutputFile).xml&quot; /p:Configuration=$(Configuration) %(XamarinAndroidProject.Identity) /t:$(_Target)" />


Given that Windows has somewhat limited lengths to command-lines, and I don't know how long this command-line will be, perhaps we should instead use use @ResponseFiles?

<WriteLinesToFile File="fresh.rsp" Lines="/fl;/flp:LogFile=$(_OutputFile).log;"/logger:$(_TimingLogger)%3bID=$(_ID)%3bDescription=$(_Description)..." /> <Exec Command="$(_XABuild) @fresh.rsp" /> <Delete Files="fresh.rsp" />

jonpryor · 2018-04-18T18:25:03Z

build-tools/xa-prep-tasks/Xamarin.Android.BuildTools.PrepTasks/ProcessMSBuildTiming.cs

+		{
+			foreach (var file in InputFiles) {
+				using (var stream = File.OpenRead (file.ItemSpec)) {
+					var element = XElement.Load (stream);


Why not use XElement.Load(string)? This would remove a level of indentation for the using block.

jonpryor · 2018-04-18T18:25:37Z

build-tools/xa-prep-tasks/Xamarin.Android.BuildTools.PrepTasks/ProcessMSBuildTiming.cs

+		{
+			if (ResultsFilename != null) {
+				string line1 = null, line2 = null;
+				if (AddResults && File.Exists (ResultsFilename))


This if block should have braces.

jonpryor · 2018-04-18T18:27:21Z

build-tools/xa-prep-tasks/Xamarin.Android.BuildTools.PrepTasks/ProcessMSBuildTiming.cs

+
+namespace Xamarin.Android.BuildTools.PrepTasks
+{
+	public class ProcessMSBuildTiming : Task


Some kind of comment description of what this does might be useful. :-)

I suspect this should go into Xamarin.Android.Tools.BootstrapTasks, not xa-prep-tasks. xa-prep-tasks is the "bare minimum" needed to prepare the entire repo, meaning external dependencies are potentially problematic. (This is why xa-prep-tasks doesn't have a dependency on libZipSharp, for example.)

jonpryor · 2018-04-18T18:30:59Z

tests/Xamarin.Android.Timing/TimingLogger.cs

+			eventSource.TaskFinished += OnTaskFinished;
+
+			events = new Stack<LogEvent> ();
+			doc = new XmlDocument ();


XmlDocument?! I feel gross. :-/

HHOS?

This is the only one I didn't address, I agree I would rather use System.Xml.Linq, too.

I just didn't think it was worth rewriting all this code--but if we were going to change the file drastically or something it might be worth it.

jonpryor · 2018-04-18T18:33:01Z

tests/Xamarin.Android.Timing/TimingLogger.cs

+
+namespace Xamarin.Android.Timing
+{
+	public class TimingLogger : Logger


Should this just go into build-tools/Xamarin.Android.Tools.BootstrapTasks? That project already has Microsoft.Build.Framework/etc. dependencies.

jonpryor · 2018-04-18T18:34:19Z

Xamarin.Android.sln


 Microsoft Visual Studio Solution File, Format Version 12.00
-# Visual Studio 2012
+# Visual Studio 15


As mentioned on the call, I think Xamarin.Android.sln can be left unchanged, and this should instead modify Xamarin.Android-Tests.sln, as the timing-related functionality is only useful alongside the tests.

jonathanpeppers · 2018-04-19T14:18:39Z

Needs more fixes on xbuild:

/Users/builder/jenkins/workspace/xamarin-android-pr-builder/xamarin-android/build-tools/timing/timing.targets: error : Error executing task WriteLinesToFile: Error converting Property named 'File' with value '$(_ID).rsp' to type Microsoft.Build.Framework.ITaskItem: Can't concatenate Item list with other strings where an item list is expected ('@(XACaptureBuildTimingProject->'%(ShortName)')', '-FreshBuild'). Use semi colon to separate items.
    14 Warning(s)
    1 Error(s)

jonathanpeppers · 2018-04-19T14:40:17Z

xbuild is killing me, if I use a plain filename for <WriteLinesToFile File="" /> I get a new issue:

~/Desktop/Git/xamarin-android/build-tools/timing/timing.targets (FreshBuild target) ->
~/Desktop/Git/xamarin-android/build-tools/timing/timing.targets: error : Error executing task WriteLinesToFile: Error converting Property named 'Lines' with value '/fl;/flp:LogFile=$(_OutputFile).log;"/logger:$(_TimingLogger)%3bID=$(_ID)%3bDescription=$(_Description)%3bCommit=$(XAVersionHash)%3bOutputPath=$(_OutputFile).xml";/p:Configuration=$(Configuration);%(XACaptureBuildTimingProject.Identity);/t:$(_Target)' to type Microsoft.Build.Framework.ITaskItem[]: Can't concatenate Item list with other strings where an item list is expected ('~/Desktop/Git/xamarin-android/build-tools/timing/../../bin/TestDebug/Timing_', '@(XACaptureBuildTimingProject->'%(ShortName)')'). Use semi colon to separate items.
    4 Warning(s)
    1 Error(s)

jonathanpeppers · 2018-04-19T18:38:57Z

So my thoughts to finish this up are to either:

Wait for msbuild to be the default, detect xbuild and just skip the build in timing.csproj
Remove the "response file" logic, as I think the plain <Exec /> commands were working everywhere

@jonpryor which do you think?

jonpryor · 2018-04-19T21:17:09Z

which do you think?

I want to know how long of a command-line we're currently generating. The Windows command-line length is 8191 characters.

(My bad, I thought it was closer to 2048! Which it was...18 years ago. Doh.)

Go for the <Exec/> and skip the response file idea.

jonathanpeppers · 2018-04-19T21:36:02Z

Without the reponse file the command is ~978 chars:

C:\Users\myuser\Desktop\Git\xamarin-android\build-tools\timing\..\..\bin\Debug\bin\xabuild /fl /flp:LogFile=C:\Users\myuser\Desktop\Git\xamarin-android\build-tools\timing\..\..\bin\TestDebug\Timing_XF-TouchAndroidResourceInstall_Debug_Xamarin.Forms-Integration.log "/logger:Xamarin.Android.Tools.BootstrapTasks.TimingLogger,C:\Users\myuser\Desktop\Git\xamarin-android\build-tools\timing\..\..\bin\BuildDebug\Xamarin.Android.Tools.BootstrapTasks.dll;ID=XF-TouchAndroidResourceInstall;Description=An install after touching an Android resource XML file for Xamarin.Forms-Integration;Commit=67d4ad9;OutputPath=C:\Users\myuser\Desktop\Git\xamarin-android\build-tools\timing\..\..\bin\TestDebug\Timing_XF-TouchAndroidResourceInstall_Debug_Xamarin.Forms-Integration.xml" /p:Configuration=Debug C:\Users\myuser\Desktop\Git\xamarin-android\build-tools\timing\..\..\tests\Xamarin.Forms-Performance-Integration\Droid\Xamarin.Forms.Performance.Integration.Droid.csproj /t:Install

This is with a reasonably long path to the xamarin-android source, since I check stuff out into Deskop\Git, so I think we're good.

jonpryor · 2018-05-01T15:34:48Z

build-tools/timing/timing.targets

+    </PropertyGroup>
+    <Exec Command="$(_XABuild) /fl /flp:LogFile=$(_OutputFile).log &quot;/logger:$(_TimingLogger);ID=$(_ID);Description=$(_Description);Commit=$(XAVersionHash);OutputPath=$(_OutputFile).xml&quot; /p:Configuration=$(Configuration) %(XACaptureBuildTimingProject.Identity) /t:$(_Target)" />
+  </Target>
+  <Target Name="TouchCSharpBuild"


I see a target TouchCSharpBuild. Should the timing collected by this target be mentioned in the commit message?

jonpryor · 2018-05-01T15:39:06Z

One last thing I'd like is "documentation" for the commit message. The <TimingLogger/> task generates an XML file; an example file with comments for semantics of the file would be helpful, so that we don't need to read the task source to determine it. (Again, this "documentation" need not live in Documentation, but it should be in the commit message.)

These changes seem to mostly be sorting/fixups for VS 2017. I found it best to include these in a separate commit, prior to adding new projects.

This is the original source written by Grendel. The only thing I changed here was namespace/project name.

The first step in tracking our build times is to at least some of our existing projects' build times recorded as plots on Jenkins. This works by running a custom MSBuild logger (written by Grendel) that records detailed timing information down to even each MSBuild task. For now, I am aggregating these results to a single CSV file to be ingested by Jenkins plots. The new `TimingLogger` emits XML in the following format: <builds> <build start-ticks="636607852701529939" start-threadid="1" id="HelloWorld-FreshBuild" commit="8dcd59e" description="A fresh build after a clean checkout for HelloWorld" end-ticks="636607852899547509" end-threadid="1" elapsed="00:00:19.8017570" succeeded="True"> <toolsets> <toolset version="15.0" path="C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\MSBuild\15.0\Bin" /> </toolsets> <files> <file id="1" path="C:\Users\jopepper\Desktop\Git\xamarin-android\samples\HelloWorld\HelloWorld.csproj" /> </files> <project start-ticks="636607852707145402" start-threadid="6" file-id="1" end-ticks="636607852899326841" end-threadid="6" elapsed="00:00:19.2181439" succeeded="True"> <target start-ticks="636607852707365985" start-threadid="6" name="RedirectMonoAndroidSdkPaths" file-id="2" end-ticks="636607852708932958" end-threadid="6" elapsed="00:00:00.1566973" succeeded="True"> <task start-ticks="636607852708755105" start-threadid="6" name="SetVsMonoAndroidRegistryKey" file-id="2" end-ticks="636607852708895478" end-threadid="6" elapsed="00:00:00.0140373" succeeded="True" /> </target> </project> </build> </builds> The total `elapsed` time of the build is aggregated into the CSV file. Projects built: - `samples/HelloWorld` - `tests/Xamarin.Forms-Performance-Integration` Four types of builds: - Fresh build (simulated fresh checkout) - Second build (no changes) - Touch C# file, build again - Touch Android resource XML file, build again I am timing the `SignAndroidPackage` and `Install` targets for each of these cases. Results are aggregated into `TestResult-MSBuild-times.csv` for processing on Jenkins. After this gets merged into master, there will be some configuration needed to setup the new plot. Example results, in the aggregated CSV file: | HelloWorld-FreshBuild-Debug | HelloWorld-FreshInstall-Debug | XF-FreshBuild-Debug | XF-FreshInstall-Debug | | ---: | ---: | ---: | ---: | | 00:00:16.3538291 | 00:00:04.7940071 | 00:00:27.5263076 | 00:00:22.6720137 | Also included in the table, will be the `TouchCSharp` and `TouchAndroidResource` builds for both of the `HelloWorld` and `XF` projects for both `SignAndroidPackage` and `Install` targets. Other changes: - I let VS 2017 re-sort/fixup `Xamarin.Android.sln` - Split up `timing.csproj` into `timing.targets` and `timing.projitems` - Updated `Makefile` to include a `run-performance-tests` target. - A new `ProcessMSBuildTimings` task to aggregate the results Upstream in `monodroid`: - Since it is not built on Jenkins, these timings need to go somewhere else TBD - Plans are to test more "real world" apps here, and inject as many `<XamarinAndroidProject />` items as needed during the timings - We should also leverage the more detailed timings collected, timing specific MSBuild tasks could be useful

jonathanpeppers requested review from grendello and jonpryor April 17, 2018 16:43

jonathanpeppers commented Apr 17, 2018

View reviewed changes

jonpryor reviewed Apr 18, 2018

View reviewed changes

jonathanpeppers force-pushed the profile-build-times branch from bdc7750 to 39137dc Compare April 19, 2018 03:03

jonathanpeppers force-pushed the profile-build-times branch from 40fd6b2 to 67d4ad9 Compare April 19, 2018 21:33

jonathanpeppers force-pushed the profile-build-times branch 4 times, most recently from 6170d1a to 0d7c7ed Compare April 27, 2018 20:18

jonpryor reviewed May 1, 2018

View reviewed changes

jonathanpeppers force-pushed the profile-build-times branch from 0d7c7ed to 8bda6aa Compare May 1, 2018 20:39

jonathanpeppers and others added 2 commits May 2, 2018 09:17

[Xamarin.Android-Tests.sln] VS 2017

e2129ca

These changes seem to mostly be sorting/fixups for VS 2017. I found it best to include these in a separate commit, prior to adding new projects.

[Xamarin.Android.Timing] a new MSBuild logger for profiling

c7426b2

This is the original source written by Grendel. The only thing I changed here was namespace/project name.

jonathanpeppers force-pushed the profile-build-times branch from 8bda6aa to 4b750e5 Compare May 2, 2018 14:32

jonpryor merged commit b0efc6a into dotnet:master May 2, 2018

jonathanpeppers deleted the profile-build-times branch August 9, 2018 19:02

github-actions bot locked and limited conversation to collaborators Feb 3, 2024

[performance] initial MSBuild project timing #1569

[performance] initial MSBuild project timing #1569

Uh oh!

Conversation

jonathanpeppers commented Apr 17, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

atsushieno Apr 18, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jonathanpeppers commented Apr 19, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jonathanpeppers commented Apr 19, 2018

Uh oh!

jonathanpeppers commented Apr 19, 2018

Uh oh!

jonpryor commented Apr 19, 2018

Uh oh!

jonathanpeppers commented Apr 19, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jonpryor commented May 1, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

jonathanpeppers commented Apr 17, 2018 •

edited

Loading

atsushieno Apr 18, 2018 •

edited

Loading

jonathanpeppers commented Apr 19, 2018 •

edited

Loading