fix: When sql explain plan generation fails, don't attempt to generate an explain plan on future invocations of the same query. (#3075)

Author: tippmar-nr

src/Agent/NewRelic/Agent/Core/Database/CacheByDatastoreVendor.cs

@@ -10,7 +10,7 @@ namespace NewRelic.Agent.Core.Database
 {
     public class CacheByDatastoreVendor<TKey, TValue> where TValue : class
     {
-        // The capcity defaults to 1000 but can be configured using the SqlStatementCacheMaxSize setting in the local newrelic.config.
+        // The capacity defaults to 1000 but can be configured using the SqlStatementCacheMaxSize setting in the local newrelic.config.
         private int _capacity = 1000;
         private readonly SimpleCache<TKey, TValue>[] _caches;
 
@@ -29,13 +29,22 @@ public TValue GetOrAdd(DatastoreVendor vendor, TKey key, Func<TValue> valueFunc)
             return _caches[(int)vendor].GetOrAdd(key, valueFunc);
         }
 
+        public bool TryAdd(DatastoreVendor vendor, TKey key, Func<TValue> valueFunc)
+        {
+            return _caches[(int)vendor].TryAdd(key, valueFunc);
+        }
+        public bool Contains(DatastoreVendor vendor, TKey key)
+        {
+            return _caches[(int)vendor].Contains(key);
+        }
+
         public void SetCapacity(int capacity)
         {
             if (capacity != Capacity)
             {
                 var oldCapacity = Capacity;
                 Capacity = capacity;
-                Log.Info($"The capcity of cache type ({GetType()}) has been modified from {oldCapacity} to {Capacity}. Agent's memory allocation will be affected by this change so use with precaution.");
+                Log.Info($"The capacity of cache type ({GetType()}) has been modified from {oldCapacity} to {Capacity}. Agent's memory allocation will be affected by this change so use with caution.");
             }
         }
 
@@ -51,5 +60,13 @@ private int Capacity
                 }
             }
         }
+
+        public void Reset()
+        {
+            for (var i = 0; i < Enum.GetValues(typeof(DatastoreVendor)).Length; i++)
+            {
+                _caches[i].Reset();
+            }
+        }
     }
 }

src/Agent/NewRelic/Agent/Core/Segments/DatastoreSegmentData.cs

@@ -17,6 +17,7 @@
 using System;
 using System.Collections.Generic;
 using System.Text;
+using NewRelic.Agent.Extensions.Collections;
 using static NewRelic.Agent.Core.WireModels.MetricWireModel;
 
 namespace NewRelic.Agent.Core.Segments
@@ -51,8 +52,17 @@ public class DatastoreSegmentData : AbstractSegmentData, IDatastoreSegmentData
         public ExplainPlan ExplainPlan => _explainPlan;
 
         private readonly IDatabaseService _databaseService;
+        private static CacheByDatastoreVendor<string, string> _failedExplainPlanQueryCacheByDatastoreVendor;
 
-        public DatastoreSegmentData(IDatabaseService databaseService, ParsedSqlStatement parsedSqlStatement, string commandText = null, ConnectionInfo connectionInfo = null, IDictionary<string, IConvertible> queryParameters = null)
+        static DatastoreSegmentData()
+        {
+            _failedExplainPlanQueryCacheByDatastoreVendor = new CacheByDatastoreVendor<string, string>("FailedExplainPlanQueryCache");
+            _failedExplainPlanQueryCacheByDatastoreVendor.SetCapacity(1000);
+        }
+
+        public DatastoreSegmentData(IDatabaseService databaseService,
+            ParsedSqlStatement parsedSqlStatement, string commandText = null, ConnectionInfo connectionInfo = null,
+            IDictionary<string, IConvertible> queryParameters = null)
         {
             _databaseService = databaseService;
             _connectionInfo = connectionInfo ?? EmptyConnectionInfo;
@@ -120,11 +130,15 @@ internal override IEnumerable<KeyValuePair<string, object>> Finish()
         }
 
 
-        public void ExecuteExplainPlan(SqlObfuscator obfuscator)
+        public bool ExecuteExplainPlan(SqlObfuscator obfuscator)
         {
+            // don't attempt to generate an explain plan if this query has failed previously
+            if (_failedExplainPlanQueryCacheByDatastoreVendor.Contains(DatastoreVendorName, CommandText))
+                return false;
+
             // Don't re-run an explain plan if one already exists
             if (_explainPlan != null)
-                return;
+                return false;
 
             try
             {
@@ -145,10 +159,15 @@ public void ExecuteExplainPlan(SqlObfuscator obfuscator)
                         _explainPlan = new ExplainPlan(explainPlan.ExplainPlanHeaders, explainPlan.ExplainPlanDatas, explainPlan.ObfuscatedHeaders);
                     }
                 }
+
+                return true;
             }
             catch (Exception exception)
             {
-                Log.Debug(exception, "Unable to execute explain plan");
+                Log.Debug(exception, "Unable to execute explain plan for query: {Query}. This query will be ignored for future explain plan execution.",
+                    obfuscator.GetObfuscatedSql(CommandText, DatastoreVendorName) ?? "[redacted]");
+                _failedExplainPlanQueryCacheByDatastoreVendor.TryAdd(DatastoreVendorName, CommandText, () => string.Empty); // all we really want to cache is the query text
+                return false;
             }
         }
 
@@ -239,5 +258,21 @@ public void SetConnectionInfo(ConnectionInfo connInfo)
         {
             _connectionInfo = connInfo;
         }
+
+        /// <summary>
+        /// FOR UNIT TESTING ONLY
+        /// </summary>
+        public static void ClearFailedExplainPlanCache()
+        {
+            _failedExplainPlanQueryCacheByDatastoreVendor.Reset();
+        }
+
+        /// <summary>
+        /// FOR UNIT TESTING ONLY
+        /// </summary>
+        public CacheByDatastoreVendor<string, string> GetFailedExplainPlanCache()
+        {
+            return _failedExplainPlanQueryCacheByDatastoreVendor;
+        }
     }
 }

src/Agent/NewRelic/Agent/Extensions/NewRelic.Agent.Extensions/Caching/SimpleCache.cs

@@ -69,6 +69,11 @@ public TValue Peek(TKey key)
             return node;
         }
 
+        /// <summary>
+        /// Checks whether the specified key exists in the cache without updating stats or affecting the priority of items in the cache.
+        /// </summary>
+        public bool Contains(TKey key) => PeekInternal(key) != null;
+
         /// <summary>
         /// Allows searching of the cache.  If found, returns the existing item and updates the statistics.
         /// If not found, returns NULL.
@@ -106,6 +111,17 @@ public TValue GetOrAdd(TKey key, Func<TValue> valueFx)
             return result ?? _cacheMap.GetOrAdd(key, x => valueFx());
         }
 
+        /// <summary>
+        /// Attempts to add an item to the cache.  If the item already exists, returns false. Otherwise, returns true.
+        /// </summary>
+        /// <param name="key"></param>
+        /// <param name="valueFunc">Function to call to obtain the value if the key is not present in the cache.</param>
+        /// <returns></returns>
+        public bool TryAdd(TKey key, Func<TValue> valueFunc)
+        {
+            return _cacheMap.TryAdd(key, valueFunc());
+        }
+
         /// <summary>
         /// Allows resetting of the Hit, Miss, and Ejection counters
         /// </summary>

tests/Agent/IntegrationTests/IntegrationTestHelpers/AgentLogBase.cs

@@ -86,6 +86,9 @@ public abstract class AgentLogBase
         public const string WrapperExceptionLogLineRegex = ErrorLogLinePrefixRegex + "An exception occurred in a wrapper";
         public const string ApplicationErrorLogLineRegex = DebugLogLinePrefixRegex + "Noticed application error";
 
+        // explain plan failure
+        public const string ExplainPlainFailureLogLineRegex = DebugLogLinePrefixRegex + "Unable to execute explain plan for query: (.*)";
+
         public AgentLogBase(ITestOutputHelper testLogger)
         {
             _testLogger = testLogger;

tests/Agent/IntegrationTests/SharedApplications/Common/MultiFunctionApplicationHelpers/NetStandardLibraries/MsSql/MicrosoftDataSqlClientExerciser.cs

@@ -12,6 +12,7 @@
 using NewRelic.Agent.IntegrationTests.Shared.ReflectionHelpers;
 using NewRelic.Api.Agent;
 using System.Threading;
+using System;
 
 namespace MultiFunctionApplicationHelpers.NetStandardLibraries.MsSql
 {
@@ -265,6 +266,63 @@ public void Wait(int millisecondsTimeOut)
             Thread.Sleep(millisecondsTimeOut);
         }
 
+#if NET9_0
+        [LibraryMethod]
+        public async Task MsSqlCreateStoredProcWithTempTable(string procedureName)
+        {
+            var createProcedure = $@"
+                CREATE OR ALTER PROCEDURE {procedureName}
+                AS
+                BEGIN
+                    -- Create a temporary table and insert data into it using SELECT INTO
+                    SELECT 
+                        Id,
+                        FirstName
+                    INTO #TempTable
+                    FROM 
+                        TeamMembers;
+
+                    -- Select all rows from the temporary table
+                    SELECT * FROM #TempTable;
+                END;";
+
+            await using var connection = new SqlConnection(_connectionString);
+            await connection.OpenAsync();
+
+            await using var command = new SqlCommand(createProcedure, connection);
+            await command.ExecuteNonQueryAsync();
+
+        }
+
+        [LibraryMethod]
+        [Transaction]
+        [MethodImpl(MethodImplOptions.NoOptimization | MethodImplOptions.NoInlining)]
+        public async Task MsSqlStoredProcWithTempTable(string procedureName)
+        {
+            await using var connection = new SqlConnection(_connectionString);
+            await connection.OpenAsync();
+
+            await using var command = connection.CreateCommand();
+            command.CommandText = procedureName;
+            command.CommandType = System.Data.CommandType.StoredProcedure;
+
+            // execute the command
+            await using var reader = await command.ExecuteReaderAsync();
+
+        }
+
+        [LibraryMethod]
+        public async Task MsSqlDropStoredProcWithTempTable(string procedureName)
+        {
+            var dropProcedureSql = string.Format(DropProcedureSql, procedureName);
+            await using var connection = new SqlConnection(_connectionString);
+            await connection.OpenAsync();
+
+            await using var command = new SqlCommand(dropProcedureSql, connection);
+            await command.ExecuteNonQueryAsync();
+        }
+#endif
+
         private void EnsureProcedure(string procedureName, DbParameter[] dbParameters)
         {
             var parameters = string.Join(", ", dbParameters.Select(x => $"{x.ParameterName} {x.DbTypeName}"));

tests/Agent/IntegrationTests/UnboundedIntegrationTests/MsSql/MsSqlFailedExplainPlanTests.cs

@@ -0,0 +1,70 @@
+// Copyright 2020 New Relic, Inc. All rights reserved.
+// SPDX-License-Identifier: Apache-2.0
+
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Text;
+using System.Threading.Tasks;
+using Microsoft.VisualStudio.TestPlatform.Utilities;
+using NewRelic.Agent.IntegrationTestHelpers;
+using NewRelic.Agent.IntegrationTestHelpers.RemoteServiceFixtures;
+using Xunit;
+using Xunit.Abstractions;
+
+namespace NewRelic.Agent.UnboundedIntegrationTests.MsSql
+{
+    public class MsSqlFailedExplainPlanTests : NewRelicIntegrationTest<ConsoleDynamicMethodFixtureCoreLatest>
+    {
+        private readonly ConsoleDynamicMethodFixtureCoreLatest _fixture;
+
+        public MsSqlFailedExplainPlanTests(ConsoleDynamicMethodFixtureCoreLatest fixture, ITestOutputHelper outputHelper) : base(fixture)
+        {
+            var exerciserName = "MicrosoftDataSqlClientExerciser";
+
+            _fixture = fixture;
+            _fixture.TestLogger = outputHelper;
+
+            var procedureName = Utilities.GenerateProcedureName();
+
+            _fixture.AddCommand($"{exerciserName} MsSqlCreateStoredProcWithTempTable {procedureName}");
+            _fixture.AddCommand($"{exerciserName} MsSqlStoredProcWithTempTable {procedureName}");
+            _fixture.AddCommand($"{exerciserName} MsSqlStoredProcWithTempTable {procedureName}");
+            _fixture.AddCommand($"{exerciserName} MsSqlDropStoredProcWithTempTable {procedureName}");
+
+            _fixture.AddActions
+            (
+                setupConfiguration: () =>
+                {
+                    var configPath = fixture.DestinationNewRelicConfigFilePath;
+                    var configModifier = new NewRelicConfigModifier(configPath);
+                    configModifier.ConfigureFasterMetricsHarvestCycle(15);
+                    configModifier.ConfigureFasterTransactionTracesHarvestCycle(15);
+                    configModifier.ConfigureFasterSqlTracesHarvestCycle(15);
+
+                    configModifier.ForceTransactionTraces();
+                    configModifier.SetLogLevel("finest");       //This has to stay at finest to ensure parameter check security
+
+                    CommonUtils.ModifyOrCreateXmlAttributeInNewRelicConfig(configPath, new[] { "configuration", "transactionTracer" }, "explainEnabled", "true");
+                    CommonUtils.ModifyOrCreateXmlAttributeInNewRelicConfig(configPath, new[] { "configuration", "transactionTracer" }, "recordSql", "raw");
+                    CommonUtils.ModifyOrCreateXmlAttributeInNewRelicConfig(configPath, new[] { "configuration", "transactionTracer" }, "explainThreshold", "1");
+                    CommonUtils.ModifyOrCreateXmlAttributeInNewRelicConfig(configPath, new[] { "configuration", "datastoreTracer", "queryParameters" }, "enabled", "true");
+                },
+                exerciseApplication: () =>
+                {
+                    _fixture.AgentLog.WaitForLogLine(AgentLogBase.ExplainPlainFailureLogLineRegex, TimeSpan.FromMinutes(1));
+                }
+            );
+
+            _fixture.Initialize();
+
+        }
+
+        [Fact]
+        public void Test()
+        {
+            // verify that the log contains one explain plan failure log line - second call to the stored proc doesn't try to generate an explain plan
+            Assert.Single(_fixture.AgentLog.TryGetLogLines(AgentLogBase.ExplainPlainFailureLogLineRegex));
+        }
+    }
+}