[performance] initial MSBuild project timing (#1569)

"Performance", in various guises, is an ongoing focus. For example,
we track [application startup times][time-plots].

[time-plots]: https://jenkins.mono-project.com/view/Xamarin.Android/job/xamarin-android/plot/Tests%20times/

The next area we want to concentrate on is build and deployment time,
and to do so we need to start collecting information so we know how
we're doing, and whether anything is getting worse.

The first step in tracking our build times is to track the build
times for some of our existing unit tests projects, and plot those
on Jenkins. This is done by using a custom MSBuild logger
`Xamarin.Android.Tools.BootstrapTasks.TimingLogger` which records
detailed timing information into an XML file:

	<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>


These timing XML files from multiple builds are aggregated by the new
`<ProcessMSBuildTiming/>` task, which generates a CSV file containing
the `//*/@elapsed` attribute values for us by the
[Jenkins Plots plugin][jenkins-plots].

[jenkins-plots]: https://wiki.jenkins.io/display/JENKINS/Plot+Plugin

The following projects have their build times collected:

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

Across 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

We are timing the `SignAndroidPackage` and `Install` targets for each
of these build types.

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 Visual Studio 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.

`TimingLogger` is courtesy of @grendello.

Author: jonathanpeppers

Makefile

@@ -197,4 +197,7 @@ run-ji-tests:
 run-apk-tests:
 	$(MSBUILD) $(MSBUILD_FLAGS) $(TEST_TARGETS) /t:RunApkTests
 
+run-performance-tests:
+	$(MSBUILD) $(MSBUILD_FLAGS) $(TEST_TARGETS) /t:RunPerformanceTests
+
 include build-tools/scripts/runtime-helpers.mk

Xamarin.Android-Tests.sln

@@ -1,6 +1,7 @@
-
 Microsoft Visual Studio Solution File, Format Version 12.00
-# Visual Studio 2012
+# Visual Studio 15
+VisualStudioVersion = 15.0.27428.2037
+MinimumVisualStudioVersion = 10.0.40219.1
 Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Mono.Android-Tests", "src\Mono.Android\Test\Mono.Android-Tests.csproj", "{40EAD437-216B-4DF4-8258-3F47E1672C3A}"
 EndProject
 Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "HelloWorld", "samples\HelloWorld\HelloWorld.csproj", "{2305B00D-DE81-4744-B0DA-357835CAFE5A}"
@@ -71,7 +72,15 @@ Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "CodeBehindUnitTests", "test
 EndProject
 Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Xamarin.ProjectTools", "src\Xamarin.Android.Build.Tasks\Tests\Xamarin.ProjectTools\Xamarin.ProjectTools.csproj", "{2DD1EE75-6D8D-4653-A800-0A24367F7F38}"
 EndProject
+Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "Performance-Tests", "Performance-Tests", "{68B8E272-5B12-47AA-8923-550B9CE535C7}"
+EndProject
+Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "timing", "build-tools\timing\timing.csproj", "{37CAA28C-40BE-4253-BA68-CC5D7316A617}"
+EndProject
 Global
+	GlobalSection(SharedMSBuildProjectFiles) = preSolution
+		tests\Xamarin.Forms-Performance-Integration\Xamarin.Forms.Performance.Integration.projitems*{195be9c2-1f91-40dc-bd6d-de860bf083fb}*SharedItemsImports = 13
+		tests\Xamarin.Forms-Performance-Integration\Xamarin.Forms.Performance.Integration.projitems*{576312cc-83ff-48b1-a473-488cdc7121ad}*SharedItemsImports = 4
+	EndGlobalSection
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
 		Release|Any CPU = Release|Any CPU
@@ -181,10 +190,17 @@ Global
 		{2DD1EE75-6D8D-4653-A800-0A24367F7F38}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{2DD1EE75-6D8D-4653-A800-0A24367F7F38}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{2DD1EE75-6D8D-4653-A800-0A24367F7F38}.Release|Any CPU.Build.0 = Release|Any CPU
+		{37CAA28C-40BE-4253-BA68-CC5D7316A617}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{37CAA28C-40BE-4253-BA68-CC5D7316A617}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{37CAA28C-40BE-4253-BA68-CC5D7316A617}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{37CAA28C-40BE-4253-BA68-CC5D7316A617}.Release|Any CPU.Build.0 = Release|Any CPU
+	EndGlobalSection
+	GlobalSection(SolutionProperties) = preSolution
+		HideSolutionNode = FALSE
 	EndGlobalSection
 	GlobalSection(NestedProjects) = preSolution
-		{2305B00D-DE81-4744-B0DA-357835CAFE5A} = {43A4FB09-279A-4138-8027-EC1E1CED2E8A}
 		{40EAD437-216B-4DF4-8258-3F47E1672C3A} = {EFBC4DC0-DBFF-4DAA-B0B8-6D0CB02A25F5}
+		{2305B00D-DE81-4744-B0DA-357835CAFE5A} = {43A4FB09-279A-4138-8027-EC1E1CED2E8A}
 		{05768F39-7BAF-43E6-971E-712F5771E88E} = {D6BFEDF6-2F48-44B2-9553-F2F6F92531BD}
 		{9D5C83B5-70D5-4CC2-9DB7-78B23DC8F255} = {D6BFEDF6-2F48-44B2-9553-F2F6F92531BD}
 		{EF798EB3-D639-4E09-9DB0-233E67F727B0} = {2EFFECF5-1CCA-4005-AE62-1D6F01C88DF4}
@@ -208,5 +224,9 @@ Global
 		{7A5FB23C-6B26-461A-8BBD-02392DCE3C11} = {9B63992C-2201-4BB0-BD00-D637B481A995}
 		{F4DAFD78-BE76-46C9-A1AD-85D8C91CD77B} = {9B63992C-2201-4BB0-BD00-D637B481A995}
 		{2DD1EE75-6D8D-4653-A800-0A24367F7F38} = {9B63992C-2201-4BB0-BD00-D637B481A995}
+		{37CAA28C-40BE-4253-BA68-CC5D7316A617} = {68B8E272-5B12-47AA-8923-550B9CE535C7}
+	EndGlobalSection
+	GlobalSection(ExtensibilityGlobals) = postSolution
+		SolutionGuid = {8643CD20-B195-4919-8135-27549488237E}
 	EndGlobalSection
 EndGlobal

build-tools/Xamarin.Android.Tools.BootstrapTasks/Xamarin.Android.Tools.BootstrapTasks.csproj

@@ -47,8 +47,10 @@
     <Compile Include="Xamarin.Android.Tools.BootstrapTasks\GenerateMonoDroidIncludes.cs" />
     <Compile Include="Xamarin.Android.Tools.BootstrapTasks\GenerateProfile.cs" />
     <Compile Include="Xamarin.Android.Tools.BootstrapTasks\GetNugetPackageBasePath.cs" />
+    <Compile Include="Xamarin.Android.Tools.BootstrapTasks\ProcessMSBuildTiming.cs" />
     <Compile Include="Xamarin.Android.Tools.BootstrapTasks\RenameTestCases.cs" />
     <Compile Include="Xamarin.Android.Tools.BootstrapTasks\StartAndroidEmulator.cs" />
+    <Compile Include="Xamarin.Android.Tools.BootstrapTasks\TimingLogger.cs" />
     <Compile Include="Xamarin.Android.Tools.BootstrapTasks\UnzipDirectoryChildren.cs" />
     <Compile Include="Xamarin.Android.Tools.BootstrapTasks\Zip.cs" />
     <Compile Include="Xamarin.Android.Tools.BootstrapTasks\KillProcess.cs" />

build-tools/Xamarin.Android.Tools.BootstrapTasks/Xamarin.Android.Tools.BootstrapTasks/ProcessMSBuildTiming.cs

@@ -0,0 +1,81 @@
+using System;
+using System.Collections.Generic;
+using System.IO;
+using System.Xml.Linq;
+using Microsoft.Build.Framework;
+using Microsoft.Build.Utilities;
+
+namespace Xamarin.Android.Tools.BootstrapTasks
+{
+	// This tasks takes in XML file output from TimingLogger and aggregates the total build time for each build into a CSV file to be used on Jenkins
+	public class ProcessMSBuildTiming : Task
+	{
+		[Required]
+		public ITaskItem[] InputFiles { get; set; }
+
+		public string ResultsFilename { get; set; }
+
+		public bool AddResults { get; set; }
+
+		public string LabelSuffix { get; set; }
+
+		Dictionary<string, string> results = new Dictionary<string, string> ();
+
+		public override bool Execute ()
+		{
+			foreach (var file in InputFiles) {
+				var element = XElement.Load (file.ItemSpec);
+				var build = element.Element ("build");
+				var id = build.Attribute ("id")?.Value;
+				var elapsed = build.Attribute ("elapsed")?.Value;
+				results [id] = elapsed;
+			}
+			WriteResults ();
+
+			return !Log.HasLoggedErrors;
+		}
+
+		protected void WriteResults ()
+		{
+			if (ResultsFilename != null) {
+				string line1 = null, line2 = null;
+				if (AddResults && File.Exists (ResultsFilename)) {
+					using (var reader = new StreamReader (ResultsFilename)) {
+						try {
+							line1 = reader.ReadLine ();
+							line2 = reader.ReadLine ();
+						} catch (Exception e) {
+							Log.LogWarning ($"unable to read previous results from {ResultsFilename}\n{e}");
+							line1 = line2 = null;
+						}
+					}
+				}
+				using (var resultsFile = new StreamWriter (ResultsFilename)) {
+					WriteValues (resultsFile, results.Keys, line1, LabelSuffix);
+					WriteValues (resultsFile, results.Values, line2);
+					resultsFile.Close ();
+				}
+			}
+		}
+
+		void WriteValues (StreamWriter writer, ICollection<string> values, string line, string suffix = null)
+		{
+			bool first;
+			if (string.IsNullOrEmpty (line))
+				first = true;
+			else {
+				writer.Write (line);
+				first = false;
+			}
+			foreach (var key in values) {
+				if (!first)
+					writer.Write (',');
+				writer.Write (key);
+				if (!string.IsNullOrEmpty (suffix))
+					writer.Write (suffix);
+				first = false;
+			}
+			writer.WriteLine ();
+		}
+	}
+}