Skip to content

Commit

Permalink
test: Fix a MySql flicker by introducing an intentional delay (#2348)
Browse files Browse the repository at this point in the history
  • Loading branch information
tippmar-nr authored Mar 19, 2024
1 parent 49cec88 commit 620a932
Show file tree
Hide file tree
Showing 2 changed files with 36 additions and 18 deletions.
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
// Copyright 2020 New Relic, Inc. All rights reserved.
// Copyright 2020 New Relic, Inc. All rights reserved.
// SPDX-License-Identifier: Apache-2.0


Expand Down Expand Up @@ -39,6 +39,28 @@ public void ExecuteReader()
});
}

[LibraryMethod]
[Transaction]
[MethodImpl(MethodImplOptions.NoOptimization | MethodImplOptions.NoInlining)]
public void ExecuteReaderWithDelay()
{
ExecuteCommand(command =>
{
var dates = new List<string>();
using (var reader = command.ExecuteReader())
{
while (reader.Read())
{
dates.Add(reader.GetString(reader.GetOrdinal("_date")));
}
}
string res = string.Join(",", dates);
ConsoleMFLogger.Info(res);
return res;
}, true); // add a delay to the query to make sure this is the slowest one that executes, helps test reliability
}


[LibraryMethod]
[Transaction]
[MethodImpl(MethodImplOptions.NoOptimization | MethodImplOptions.NoInlining)]
Expand Down Expand Up @@ -206,13 +228,14 @@ await ExecuteDbCommandAsync(async command =>
}

private const string Query = "SELECT _date FROM dates WHERE _date LIKE '2%' ORDER BY _date DESC LIMIT 1";
private const string QueryWithDelay = "SELECT SLEEP(2), _date FROM dates WHERE _date LIKE '2%' ORDER BY _date DESC LIMIT 1";

private string ExecuteCommand(Func<MySqlCommand, string> action)
private string ExecuteCommand(Func<MySqlCommand, string> action, bool delay = false)
{
string result;

using (var connection = new MySqlConnection(MySqlTestConfiguration.MySqlConnectionString))
using (var command = new MySqlCommand(Query, connection))
using (var command = new MySqlCommand(delay ? QueryWithDelay : Query, connection))
{
connection.Open();
result = action(command);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,7 @@ public abstract class MySqlConnectorTestBase<TFixture> : NewRelicIntegrationTest

private readonly List<string> commandList = new List<string>()
{
"ExecuteReader",
"ExecuteReaderWithDelay",
"ExecuteScalar",
"ExecuteNonQuery",
"ExecuteReaderAsync",
Expand Down Expand Up @@ -56,9 +56,9 @@ protected MySqlConnectorTestBase(TFixture fixture, ITestOutputHelper output) : b
var configModifier = new NewRelicConfigModifier(configPath);

configModifier
.ConfigureFasterMetricsHarvestCycle(10)
.ConfigureFasterTransactionTracesHarvestCycle(10)
.ConfigureFasterSqlTracesHarvestCycle(10)
.ConfigureFasterMetricsHarvestCycle(30)
.ConfigureFasterTransactionTracesHarvestCycle(30)
.ConfigureFasterSqlTracesHarvestCycle(30)
.ForceTransactionTraces()
.SetLogLevel("finest");

Expand All @@ -74,8 +74,7 @@ protected MySqlConnectorTestBase(TFixture fixture, ITestOutputHelper output) : b
exerciseApplication: () =>
{
// Confirm transaction transform has completed before moving on to host application shutdown, and final sendDataOnExit harvest
_fixture.AgentLog.WaitForLogLine(AgentLogBase.TransactionTransformCompletedLogLineRegex,
TimeSpan.FromMinutes(2)); // must be 2 minutes since this can take a while.
_fixture.AgentLog.WaitForLogLine(AgentLogBase.TransactionTransformCompletedLogLineRegex, TimeSpan.FromMinutes(2));
_fixture.AgentLog.WaitForLogLine(AgentLogBase.SqlTraceDataLogLineRegex, TimeSpan.FromMinutes(1));
}
);
Expand Down Expand Up @@ -146,7 +145,7 @@ public void Test()
});
}

var query = "SELECT _date FROM dates WHERE _date LIKE ? ORDER BY _date DESC LIMIT ?";
var queryWithDelay = "SELECT SLEEP(?), _date FROM dates WHERE _date LIKE ? ORDER BY _date DESC LIMIT ?";

var expectedTransactionTraceSegments = new List<string> { "Datastore/statement/MySQL/dates/select" };

Expand All @@ -158,7 +157,7 @@ public void Test()
{
segmentName = "Datastore/statement/MySQL/dates/select",
parameterName = "sql",
parameterValue = query
parameterValue = queryWithDelay
},
new Assertions.ExpectedSegmentParameter
{
Expand Down Expand Up @@ -186,15 +185,11 @@ public void Test()

var metrics = _fixture.AgentLog.GetMetrics().ToList();

// there should be only a single trace but we've found that the TransactionName isn't predictable enough
// (it's supposed to be the first query, but the assumption that the first query is always the slowest one doesn't
// hold universally). So we'll make sure there's just one trace and that the query, metricName and ExplainPlan properties are
// what we expect.
// there may be multiple traces, but we want the slowest one (by total call time) which is always the result of ExecuteReaderWithDelay
var sqlTraces = _fixture.AgentLog.GetSqlTraces().ToList();
Assert.Single(sqlTraces);
var sqlTrace = sqlTraces.OrderByDescending(t => t.TotalCallTime).First();

var sqlTrace = sqlTraces.First();
Assert.Equal( query, sqlTrace.Sql );
Assert.Equal( queryWithDelay, sqlTrace.Sql );
Assert.Equal("Datastore/statement/MySQL/dates/select", sqlTrace.DatastoreMetricName);
Assert.True(sqlTrace.ParameterData.GetValueOrDefault("explain_plan") != null);

Expand Down

0 comments on commit 620a932

Please sign in to comment.