Skip to content

Commit cbf4248

Browse files
tippmar-nrtippmar-nr
authored
test: MySql test performance improvements (#2336)
1 parent ee488e3 commit cbf4248

File tree

12 files changed

+212
-158
lines changed

12 files changed

+212
-158
lines changed

‎.github/workflows/all_solutions.yml

Lines changed: 7 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -440,10 +440,13 @@ jobs:
440440
run: |
441441
Write-Host "Installing HostableWebCore Feature"
442442
Enable-WindowsOptionalFeature -Online -FeatureName IIS-HostableWebCore
443-
Write-Host "Installing Msmq Features"
444-
Enable-WindowsOptionalFeature -Online -FeatureName MSMQ-Server -All
445-
Enable-WindowsOptionalFeature -Online -FeatureName MSMQ-HTTP -All
446-
Enable-WindowsOptionalFeature -Online -FeatureName MSMQ-Triggers -All
443+
444+
if ("${{ matrix.namespace }}" -eq "Msmq") {
445+
Write-Host "Installing Msmq Features"
446+
Enable-WindowsOptionalFeature -Online -FeatureName MSMQ-Server -All
447+
Enable-WindowsOptionalFeature -Online -FeatureName MSMQ-HTTP -All
448+
Enable-WindowsOptionalFeature -Online -FeatureName MSMQ-Triggers -All
449+
}
447450
448451
if ("${{ matrix.namespace }}" -eq "MsSql") {
449452
Write-Host "Installing MSSQL CLI"

‎tests/Agent/IntegrationTests/IntegrationTestHelpers/AgentLogBase.cs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -157,22 +157,22 @@ public IEnumerable<Match> WaitForLogLines(string regularExpression, TimeSpan? ti
157157

158158
var timeout = timeoutOrZero ?? TimeSpan.Zero;
159159

160-
_testLogger?.WriteLine($"{Timestamp} WaitForLogLines Waiting for expression: {regularExpression}. Duration: {timeout.TotalSeconds} seconds. Minimum count: {minimumCount}");
160+
_testLogger?.WriteLine($"{Timestamp} WaitForLogLines Waiting for expression: {regularExpression}. Duration: {timeout.TotalSeconds:N0} seconds. Minimum count: {minimumCount}");
161161

162162
var timeTaken = Stopwatch.StartNew();
163163
do
164164
{
165165
var matches = TryGetLogLines(regularExpression).ToList();
166166
if (matches.Count >= minimumCount)
167167
{
168-
_testLogger?.WriteLine($"{Timestamp} WaitForLogLines Matched expression: {regularExpression}.");
168+
_testLogger?.WriteLine($"{Timestamp} WaitForLogLines Matched expression: {regularExpression} in {timeTaken.Elapsed.TotalSeconds:N1}s.");
169169
return matches;
170170
}
171171

172172
Thread.Sleep(TimeSpan.FromMilliseconds(100));
173173
} while (timeTaken.Elapsed < timeout);
174174

175-
var message = $"{Timestamp} Log line did not appear a minimum of {minimumCount} times within {timeout.TotalSeconds} seconds. Expected line expression: {regularExpression}";
175+
var message = $"{Timestamp} Log line did not appear a minimum of {minimumCount} times within {timeout.TotalSeconds:N0} seconds. Expected line expression: {regularExpression}";
176176
_testLogger?.WriteLine(message);
177177
throw new Exception(message);
178178
}

‎tests/Agent/IntegrationTests/IntegrationTestHelpers/IntegrationTestHelpers.csproj

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,6 @@
1414
<PackageReference Include="xunit" version="2.6.6" />
1515
<PackageReference Include="xunit.assert" Version="2.6.6" />
1616
<PackageReference Include="xunit.core" Version="2.6.6" />
17-
<PackageReference Include="xunit.extensibility.core" Version="2.6.6" />
1817
</ItemGroup>
1918
<ItemGroup>
2019
<ProjectReference Include="..\Shared\Shared.csproj" />

‎tests/Agent/IntegrationTests/IntegrationTestHelpers/RemoteServiceFixtures/RemoteApplicationFixture.cs

Lines changed: 115 additions & 37 deletions
Original file line numberDiff line numberDiff line change
@@ -4,10 +4,12 @@
44

55
using System;
66
using System.Collections.Generic;
7+
using System.Diagnostics;
78
using System.IO;
89
using System.Net;
910
using System.Net.Http;
1011
using System.Threading;
12+
using System.Threading.Tasks;
1113
using NewRelic.Agent.IntegrationTests.Shared;
1214
using Newtonsoft.Json;
1315
using Xunit;
@@ -255,19 +257,28 @@ public virtual void Initialize()
255257

256258
RemoteApplication.TestLogger = new XUnitTestLogger(TestLogger);
257259

258-
RemoteApplication.DeleteWorkingSpace();
260+
var captureStandardOutput = RemoteApplication.CaptureStandardOutput;
259261

260-
RemoteApplication.CopyToRemote();
262+
var timer = new ExecutionTimer();
263+
timer.Aggregate(() =>
264+
{
265+
RemoteApplication.DeleteWorkingSpace();
261266

262-
SetupConfiguration();
267+
RemoteApplication.CopyToRemote();
263268

264-
var captureStandardOutput = RemoteApplication.CaptureStandardOutput;
269+
SetupConfiguration();
265270

266-
RemoteApplication.Start(CommandLineArguments, EnvironmentVariables, captureStandardOutput);
271+
RemoteApplication.Start(CommandLineArguments, EnvironmentVariables, captureStandardOutput);
272+
});
273+
274+
TestLogger?.WriteLine($"Remote application build/startup time: {timer.Total:N4} seconds");
267275

268276
try
269277
{
270-
ExerciseApplication();
278+
timer = new ExecutionTimer();
279+
timer.Aggregate(ExerciseApplication);
280+
TestLogger?.WriteLine($"ExerciseApplication execution time: {timer.Total:N4} seconds");
281+
271282
}
272283
catch (Exception ex)
273284
{
@@ -276,50 +287,56 @@ public virtual void Initialize()
276287
}
277288
finally
278289
{
290+
timer = new ExecutionTimer();
279291

280-
ShutdownRemoteApplication();
281-
282-
if (captureStandardOutput)
292+
timer.Aggregate(() =>
283293
{
284-
RemoteApplication.CapturedOutput.WriteProcessOutputToLog("RemoteApplication:");
285294

286-
// Most of our tests run in HostedWebCore, but some don't, e.g. the self-hosted
287-
// WCF tests. For the HWC tests we carefully validate the console output in order
288-
// to detect process-level failures that may cause test flickers. For the self-
289-
// hosted tests, unfortunately, we just punt that.
290-
if (RemoteApplication.ValidateHostedWebCoreOutput)
295+
ShutdownRemoteApplication();
296+
297+
if (captureStandardOutput)
291298
{
292-
SubprocessLogValidator.ValidateHostedWebCoreConsoleOutput(RemoteApplication.CapturedOutput.StandardOutput, TestLogger);
299+
RemoteApplication.CapturedOutput.WriteProcessOutputToLog("RemoteApplication:");
300+
301+
// Most of our tests run in HostedWebCore, but some don't, e.g. the self-hosted
302+
// WCF tests. For the HWC tests we carefully validate the console output in order
303+
// to detect process-level failures that may cause test flickers. For the self-
304+
// hosted tests, unfortunately, we just punt that.
305+
if (RemoteApplication.ValidateHostedWebCoreOutput)
306+
{
307+
SubprocessLogValidator.ValidateHostedWebCoreConsoleOutput(RemoteApplication.CapturedOutput.StandardOutput, TestLogger);
308+
}
309+
else
310+
{
311+
TestLogger?.WriteLine("Note: child process is not required for log validation because _remoteApplication.ValidateHostedWebCoreOutput = false");
312+
}
293313
}
294314
else
295315
{
296-
TestLogger?.WriteLine("Note: child process is not required for log validation because _remoteApplication.ValidateHostedWebCoreOutput = false");
316+
TestLogger?.WriteLine("Note: child process application does not redirect output because _remoteApplication.CaptureStandardOutput = false. HostedWebCore validation cannot take place without the standard output. This is common for non-web and self-hosted applications.");
297317
}
298-
}
299-
else
300-
{
301-
TestLogger?.WriteLine("Note: child process application does not redirect output because _remoteApplication.CaptureStandardOutput = false. HostedWebCore validation cannot take place without the standard output. This is common for non-web and self-hosted applications.");
302-
}
303318

304-
RemoteApplication.WaitForExit();
319+
RemoteApplication.WaitForExit();
305320

306-
applicationHadNonZeroExitCode = RemoteApplication.ExitCode != 0;
307-
var formattedExitCode = FormatExitCode(RemoteApplication.ExitCode);
321+
applicationHadNonZeroExitCode = RemoteApplication.ExitCode != 0;
322+
var formattedExitCode = FormatExitCode(RemoteApplication.ExitCode);
308323

309-
TestLogger?.WriteLine($"Remote application exited with a {(applicationHadNonZeroExitCode ? "failure" : "success")} exit code of {formattedExitCode}.");
324+
TestLogger?.WriteLine($"Remote application exited with a {(applicationHadNonZeroExitCode ? "failure" : "success")} exit code of {formattedExitCode}.");
310325

311-
if (applicationHadNonZeroExitCode && _errorsToRetryOn.Contains((uint)RemoteApplication.ExitCode.Value))
312-
{
313-
retryMessage = $"{formattedExitCode} is a known error.";
314-
retryTest = true;
315-
}
326+
if (applicationHadNonZeroExitCode && _errorsToRetryOn.Contains((uint)RemoteApplication.ExitCode.Value))
327+
{
328+
retryMessage = $"{formattedExitCode} is a known error.";
329+
retryTest = true;
330+
}
316331

317-
if (retryTest && (numberOfTries < MaxTries))
318-
{
319-
TestLogger?.WriteLine(retryMessage + " Retrying test.");
320-
Thread.Sleep(1000);
321-
numberOfTries++;
322-
}
332+
if (retryTest && (numberOfTries < MaxTries))
333+
{
334+
TestLogger?.WriteLine(retryMessage + " Retrying test.");
335+
Thread.Sleep(1000);
336+
numberOfTries++;
337+
}
338+
});
339+
TestLogger?.WriteLine($"Remote application shutdown time: {timer.Total:N4} seconds");
323340
}
324341

325342
} while (retryTest && numberOfTries < MaxTries);
@@ -544,4 +561,65 @@ protected void GetAndAssertSuccessStatus(string address, bool expectedSuccessSta
544561
}
545562
}
546563
}
564+
565+
566+
// borrowed from XUnit.Sdk.ExecutionTimer, as using their implementation caused a runtime error looking for xunit.execution.dotnet.dll
567+
/// <summary>
568+
/// Measures and aggregates execution time of one or more actions.
569+
/// </summary>
570+
public class ExecutionTimer
571+
{
572+
TimeSpan total;
573+
574+
/// <summary>
575+
/// Returns the total time aggregated across all the actions.
576+
/// </summary>
577+
public decimal Total
578+
{
579+
get { return (decimal)total.TotalSeconds; }
580+
}
581+
582+
/// <summary>
583+
/// Executes an action and aggregates its run time into the total.
584+
/// </summary>
585+
/// <param name="action">The action to measure.</param>
586+
public void Aggregate(Action action)
587+
{
588+
var stopwatch = Stopwatch.StartNew();
589+
try
590+
{
591+
action();
592+
}
593+
finally
594+
{
595+
total += stopwatch.Elapsed;
596+
}
597+
}
598+
599+
/// <summary>
600+
/// Executes an asynchronous action and aggregates its run time into the total.
601+
/// </summary>
602+
/// <param name="asyncAction">The action to measure.</param>
603+
public async Task AggregateAsync(Func<Task> asyncAction)
604+
{
605+
var stopwatch = Stopwatch.StartNew();
606+
try
607+
{
608+
await asyncAction();
609+
}
610+
finally
611+
{
612+
total += stopwatch.Elapsed;
613+
}
614+
}
615+
616+
/// <summary>
617+
/// Aggregates a time span into the total time.
618+
/// </summary>
619+
/// <param name="time">The time to add.</param>
620+
public void Aggregate(TimeSpan time)
621+
{
622+
total += time;
623+
}
624+
}
547625
}

‎tests/Agent/IntegrationTests/SharedApplications/Common/MultiFunctionApplicationHelpers/MultiFunctionApplicationHelpers.csproj

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -81,7 +81,6 @@
8181
<!-- MySql.Data .NET/Core references -->
8282
<PackageReference Include="MySql.Data" Version="6.10.7" Condition="'$(TargetFramework)' == 'net6.0'" />
8383
<!-- MySql.Data v8.0.33 is a breaking change for the agent and requires agent version 10.11.1 or greater -->
84-
<PackageReference Include="MySql.Data" Version="8.3.0" Condition="'$(TargetFramework)' == 'net7.0'" />
8584
<PackageReference Include="MySql.Data" Version="8.3.0" Condition="'$(TargetFramework)' == 'net8.0'" />
8685

8786
<!-- MongoDB.Driver .NET Framework references -->

‎tests/Agent/IntegrationTests/SharedApplications/Common/MultiFunctionApplicationHelpers/NetStandardLibraries/MySql/MySqlExerciser.cs

Lines changed: 13 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,8 @@
1-
// Copyright 2020 New Relic, Inc. All rights reserved.
1+
// Copyright 2020 New Relic, Inc. All rights reserved.
22
// SPDX-License-Identifier: Apache-2.0
33

4+
#if !NET7_0 // there is no .NET 7 test for MySql
5+
46
using System.Collections.Generic;
57
using System.Linq;
68
using System.Runtime.CompilerServices;
@@ -46,7 +48,7 @@ public async Task SingleDateQueryAsync()
4648
var dates = new List<string>();
4749

4850
using (var connection = new MySqlConnection(MySqlTestConfiguration.MySqlConnectionString))
49-
using (var command = new MySqlCommand("SELECT _date FROM dates WHERE _date LIKE '2%' ORDER BY _date DESC LIMIT 10000", connection))
51+
using (var command = new MySqlCommand("SELECT _date FROM dates WHERE _date LIKE '2%' ORDER BY _date DESC LIMIT 1", connection))
5052
{
5153
await connection.OpenAsync();
5254
using (var reader = await command.ExecuteReaderAsync())
@@ -64,10 +66,16 @@ public async Task SingleDateQueryAsync()
6466
[LibraryMethod]
6567
[Transaction]
6668
[MethodImpl(MethodImplOptions.NoOptimization | MethodImplOptions.NoInlining)]
67-
public void CreateAndExecuteStoredProcedure(string procedureName, bool paramsWithAtSigns)
69+
public void CreateAndExecuteStoredProcedures(string procedureNameWith, string procedureNameWithout)
6870
{
69-
CreateProcedure(procedureName);
71+
CreateProcedure(procedureNameWith);
72+
ExecuteProcedure(procedureNameWith, true);
73+
CreateProcedure(procedureNameWithout);
74+
ExecuteProcedure(procedureNameWithout, false);
75+
}
7076

77+
private static void ExecuteProcedure(string procedureName, bool paramsWithAtSigns)
78+
{
7179
using (var connection = new MySqlConnection(MySqlTestConfiguration.MySqlConnectionString))
7280
using (var command = new MySqlCommand(procedureName, connection))
7381
{
@@ -101,3 +109,4 @@ private void CreateProcedure(string procedureName)
101109
}
102110
}
103111
}
112+
#endif

‎tests/Agent/IntegrationTests/UnboundedIntegrationTests/MySql/MySqlAsyncTests.cs

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -35,9 +35,9 @@ public MySqlAsyncTestsBase(TFixture fixture, ITestOutputHelper output, bool asyn
3535
{
3636
var configPath = fixture.DestinationNewRelicConfigFilePath;
3737
var configModifier = new NewRelicConfigModifier(configPath);
38-
configModifier.ConfigureFasterMetricsHarvestCycle(45);
39-
configModifier.ConfigureFasterTransactionTracesHarvestCycle(45);
40-
configModifier.ConfigureFasterSqlTracesHarvestCycle(45);
38+
configModifier.ConfigureFasterMetricsHarvestCycle(10);
39+
configModifier.ConfigureFasterTransactionTracesHarvestCycle(10);
40+
configModifier.ConfigureFasterSqlTracesHarvestCycle(10);
4141

4242
configModifier.ForceTransactionTraces()
4343
.SetLogLevel("finest");
@@ -205,9 +205,9 @@ public MySqlAsyncTestsCoreOldest(ConsoleDynamicMethodFixtureCoreOldest fixture,
205205
}
206206

207207
[NetCoreTest]
208-
public class MySqlAsyncTestsCore : MySqlAsyncTestsBase<ConsoleDynamicMethodFixtureCoreLatest>
208+
public class MySqlAsyncTestsCoreLatest : MySqlAsyncTestsBase<ConsoleDynamicMethodFixtureCoreLatest>
209209
{
210-
public MySqlAsyncTestsCore(ConsoleDynamicMethodFixtureCoreLatest fixture, ITestOutputHelper output) : base(fixture, output, true)
210+
public MySqlAsyncTestsCoreLatest(ConsoleDynamicMethodFixtureCoreLatest fixture, ITestOutputHelper output) : base(fixture, output, true)
211211
{
212212

213213
}

‎tests/Agent/IntegrationTests/UnboundedIntegrationTests/MySql/MySqlConnectorTests.cs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -56,9 +56,9 @@ protected MySqlConnectorTestBase(TFixture fixture, ITestOutputHelper output) : b
5656
var configModifier = new NewRelicConfigModifier(configPath);
5757

5858
configModifier
59-
.ConfigureFasterMetricsHarvestCycle(45)
60-
.ConfigureFasterTransactionTracesHarvestCycle(45)
61-
.ConfigureFasterSqlTracesHarvestCycle(45)
59+
.ConfigureFasterMetricsHarvestCycle(10)
60+
.ConfigureFasterTransactionTracesHarvestCycle(10)
61+
.ConfigureFasterSqlTracesHarvestCycle(20)
6262
.ForceTransactionTraces()
6363
.SetLogLevel("finest");
6464

0 commit comments

Comments
 (0)