diff --git a/tests/MSBuildDeviceIntegration/Tests/PerformanceTest.cs b/tests/MSBuildDeviceIntegration/Tests/PerformanceTest.cs index 58597ec4c70..e867dfb13ac 100644 --- a/tests/MSBuildDeviceIntegration/Tests/PerformanceTest.cs +++ b/tests/MSBuildDeviceIntegration/Tests/PerformanceTest.cs @@ -5,6 +5,7 @@ using System.Runtime.CompilerServices; using Microsoft.Build.Framework; using Microsoft.Build.Logging.StructuredLogger; +using StructuredBuild = Microsoft.Build.Logging.StructuredLogger.Build; using NUnit.Framework; using Xamarin.Android.Tasks; using Xamarin.Android.Tools; @@ -18,6 +19,7 @@ namespace Xamarin.Android.Build.Tests public class PerformanceTest : DeviceTest { const int Retry = 2; + const int MaxEvaluationTimeInMs = 500; static readonly Dictionary csv_values = new Dictionary (); [OneTimeSetUp] @@ -60,9 +62,11 @@ void Profile (ProjectBuilder builder, int iterations, Action act } double total = 0; + StructuredBuild build = null; for (int i=0; i < iterations; i++) { action (builder); - var actual = GetDurationFromBinLog (builder); + build = ReadBinLog (builder); + var actual = GetDuration (build, builder); TestContext.Out.WriteLine ($"run {i} took: {actual}ms"); total += actual; if (afterRun is not null) @@ -71,6 +75,7 @@ void Profile (ProjectBuilder builder, int iterations, Action act total /= iterations; TestContext.Out.WriteLine ($"expected: {expected}ms, actual: {total}ms"); if (total > expected) { + AssertSlowMachine (build, expected, total); Assert.Fail ($"Exceeded expected time of {expected}ms, actual {total}ms"); } } @@ -81,47 +86,63 @@ void ProfileTask (ProjectBuilder builder, string task, int iterations, Action expected) { + AssertSlowMachine (build, expected, total); Assert.Fail ($"Exceeded expected time of {expected}ms, actual {total}ms"); } } - double GetTaskDurationFromBinLog (ProjectBuilder builder, string task) + void AssertSlowMachine (StructuredBuild build, int expected, double actual) + { + var evaluations = build.FindChildrenRecursive (); + var maxEval = evaluations.Any () ? evaluations.Max (e => e.Duration.TotalMilliseconds) : 0; + TestContext.Out.WriteLine ($"max evaluation time: {maxEval}ms (threshold: {MaxEvaluationTimeInMs}ms)"); + if (maxEval > MaxEvaluationTimeInMs) { + Assert.Inconclusive ($"Exceeded expected time of {expected}ms, actual {actual}ms, but evaluation time was {maxEval:F0}ms (threshold: {MaxEvaluationTimeInMs}ms), indicating a slow CI machine."); + } + } + + StructuredBuild ReadBinLog (ProjectBuilder builder) { var binlog = Path.Combine (Root, builder.ProjectDirectory, $"{Path.GetFileNameWithoutExtension (builder.BuildLogFile)}.binlog"); FileAssert.Exists (binlog); + return BinaryLog.ReadBuild (binlog); + } - var build = BinaryLog.ReadBuild (binlog); + double GetTaskDuration (StructuredBuild build, ProjectBuilder builder, string task) + { var duration = build .FindChildrenRecursive (t => t.Name == task) .Aggregate (TimeSpan.Zero, (duration, target) => duration + target.Duration); - if (duration == TimeSpan.Zero) + if (duration == TimeSpan.Zero) { + var binlog = Path.Combine (Root, builder.ProjectDirectory, $"{Path.GetFileNameWithoutExtension (builder.BuildLogFile)}.binlog"); throw new InvalidDataException ($"No task build duration found in {binlog}"); + } return duration.TotalMilliseconds; } - double GetDurationFromBinLog (ProjectBuilder builder) + double GetDuration (StructuredBuild build, ProjectBuilder builder) { - var binlog = Path.Combine (Root, builder.ProjectDirectory, $"{Path.GetFileNameWithoutExtension (builder.BuildLogFile)}.binlog"); - FileAssert.Exists (binlog); - - var build = BinaryLog.ReadBuild (binlog); var duration = build .FindChildrenRecursive () .Aggregate (TimeSpan.Zero, (duration, project) => duration + project.Duration); - if (duration == TimeSpan.Zero) + if (duration == TimeSpan.Zero) { + var binlog = Path.Combine (Root, builder.ProjectDirectory, $"{Path.GetFileNameWithoutExtension (builder.BuildLogFile)}.binlog"); throw new InvalidDataException ($"No project build duration found in {binlog}"); + } return duration.TotalMilliseconds; }