Merge pull request #439 from Azure/chgagnon/perfFixes

Perf test fixes/improvements

Author: Charles-Gagnon

performance/.editorconfig

@@ -0,0 +1,9 @@
+# See https://github.com/dotnet/roslyn-analyzers/blob/main/.editorconfig for an example on different settings and how they're used
+
+[*.cs]
+
+# Disabled
+dotnet_diagnostic.CA1309.severity = silent # Use ordinal StringComparison - this isn't important for tests and just adds clutter
+dotnet_diagnostic.CA1305.severity = silent # Specify IFormatProvider - this isn't important for tests and just adds clutter
+dotnet_diagnostic.CA1707.severity = silent # Identifiers should not contain underscores - this helps make test names more readable
+dotnet_diagnostic.CA2201.severity = silent # Do not raise reserved exception types - tests can throw whatever they want

performance/SqlTriggerBindingPerformance.cs

@@ -4,17 +4,16 @@
 using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Extensions.Sql.Samples.TriggerBindingSamples;
 using Microsoft.Azure.WebJobs.Extensions.Sql.Tests.Common;
-using Microsoft.Azure.WebJobs.Extensions.Sql.Tests.Integration;
 using BenchmarkDotNet.Attributes;
 
 namespace Microsoft.Azure.WebJobs.Extensions.Sql.Performance
 {
-    public class SqlTriggerBindingPerformance : SqlTriggerBindingIntegrationTests
+    [MemoryDiagnoser]
+    public class SqlTriggerBindingPerformance : SqlTriggerBindingPerformanceTestBase
     {
         [GlobalSetup]
         public void GlobalSetup()
         {
-            this.EnableChangeTrackingForTable("Products");
             this.StartFunctionHost(nameof(ProductsTrigger), SupportedLanguages.CSharp);
         }
 
@@ -34,18 +33,5 @@ await this.WaitForProductChanges(
                 id => id * 100,
                 this.GetBatchProcessingTimeout(1, count));
         }
-
-        [IterationCleanup]
-        public void IterationCleanup()
-        {
-            // Delete all rows in Products table after each iteration
-            this.ExecuteNonQuery("TRUNCATE TABLE Products");
-        }
-
-        [GlobalCleanup]
-        public void GlobalCleanup()
-        {
-            this.Dispose();
-        }
     }
 }

performance/SqlTriggerBindingPerformanceTestBase.cs

@@ -0,0 +1,48 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using Microsoft.Azure.WebJobs.Extensions.Sql.Tests.Integration;
+using BenchmarkDotNet.Attributes;
+
+namespace Microsoft.Azure.WebJobs.Extensions.Sql.Performance
+{
+    public class SqlTriggerBindingPerformanceTestBase : SqlTriggerBindingIntegrationTests
+    {
+        [IterationSetup]
+        public void IterationSetup()
+        {
+            this.SetChangeTrackingForTable("Products", true);
+        }
+
+        [IterationCleanup]
+        public void IterationCleanup()
+        {
+            this.DisposeFunctionHosts();
+            this.SetChangeTrackingForTable("Products", false);
+            // Delete all rows in Products table after each iteration so we start fresh each time
+            this.ExecuteNonQuery("TRUNCATE TABLE Products");
+            // Delete the leases table, otherwise we may end up getting blocked by leases from a previous run
+            this.ExecuteNonQuery(@"DECLARE @cmd varchar(100)
+DECLARE cmds CURSOR FOR
+SELECT 'DROP TABLE az_func.' + Name + ''
+FROM sys.tables
+WHERE Name LIKE 'Leases_%'
+
+OPEN cmds
+WHILE 1 = 1
+BEGIN
+    FETCH cmds INTO @cmd
+    IF @@fetch_status != 0 BREAK
+    EXEC(@cmd)
+END
+CLOSE cmds;
+DEALLOCATE cmds");
+        }
+
+        [GlobalCleanup]
+        public void GlobalCleanup()
+        {
+            this.Dispose();
+        }
+    }
+}

test/Integration/IntegrationTestBase.cs

@@ -394,18 +394,7 @@ public void Dispose()
                 this.LogOutput($"Failed to close connection. Error: {e1.Message}");
             }
 
-            foreach (Process functionHost in this.FunctionHostList)
-            {
-                try
-                {
-                    functionHost.Kill();
-                    functionHost.Dispose();
-                }
-                catch (Exception e2)
-                {
-                    this.LogOutput($"Failed to stop function host, Error: {e2.Message}");
-                }
-            }
+            this.DisposeFunctionHosts();
 
             try
             {
@@ -432,6 +421,26 @@ public void Dispose()
             GC.SuppressFinalize(this);
         }
 
+        /// <summary>
+        /// Disposes all the running function hosts
+        /// </summary>
+        protected void DisposeFunctionHosts()
+        {
+            foreach (Process functionHost in this.FunctionHostList)
+            {
+                try
+                {
+                    functionHost.Kill();
+                    functionHost.Dispose();
+                }
+                catch (Exception ex)
+                {
+                    this.LogOutput($"Failed to stop function host, Error: {ex.Message}");
+                }
+            }
+            this.FunctionHostList.Clear();
+        }
+
         protected async Task<HttpResponseMessage> SendInputRequest(string functionName, string query = "")
         {
             string requestUri = $"http://localhost:{this.Port}/api/{functionName}/{query}";

test/Integration/SqlTriggerBindingIntegrationTests.cs

@@ -29,7 +29,7 @@ public SqlTriggerBindingIntegrationTests(ITestOutputHelper output = null) : base
         [Fact]
         public async Task SingleOperationTriggerTest()
         {
-            this.EnableChangeTrackingForTable("Products");
+            this.SetChangeTrackingForTable("Products");
             this.StartFunctionHost(nameof(ProductsTrigger), SupportedLanguages.CSharp);
 
             int firstId = 1;
@@ -82,7 +82,7 @@ public async Task BatchSizeOverrideTriggerTest()
             const int batchSize = SqlTableChangeMonitor<object>.DefaultBatchSize * 4;
             const int firstId = 1;
             const int lastId = batchSize;
-            this.EnableChangeTrackingForTable("Products");
+            this.SetChangeTrackingForTable("Products");
             var taskCompletionSource = new TaskCompletionSource<bool>();
             DataReceivedEventHandler handler = TestUtils.CreateOutputReceievedHandler(
                 taskCompletionSource,
@@ -120,10 +120,10 @@ public async Task PollingIntervalOverrideTriggerTest()
             const int firstId = 1;
             // Use enough items to require 5 batches to be processed - the test will
             // only wait for the expected time and timeout if the default polling
-            // interval isn't actually modified. 
+            // interval isn't actually modified.
             const int lastId = SqlTableChangeMonitor<object>.DefaultBatchSize * 5;
             const int pollingIntervalMs = SqlTableChangeMonitor<object>.DefaultPollingIntervalMs / 2;
-            this.EnableChangeTrackingForTable("Products");
+            this.SetChangeTrackingForTable("Products");
             var taskCompletionSource = new TaskCompletionSource<bool>();
             DataReceivedEventHandler handler = TestUtils.CreateOutputReceievedHandler(
                 taskCompletionSource,
@@ -160,7 +160,7 @@ public async Task MultiOperationTriggerTest()
         {
             int firstId = 1;
             int lastId = 5;
-            this.EnableChangeTrackingForTable("Products");
+            this.SetChangeTrackingForTable("Products");
             this.StartFunctionHost(nameof(ProductsTrigger), SupportedLanguages.CSharp);
 
             // 1. Insert + multiple updates to a row are treated as single insert with latest row values.
@@ -241,7 +241,7 @@ public async Task MultiFunctionTriggerTest()
             const string Trigger1Changes = "Trigger1 Changes: ";
             const string Trigger2Changes = "Trigger2 Changes: ";
 
-            this.EnableChangeTrackingForTable("Products");
+            this.SetChangeTrackingForTable("Products");
 
             string functionList = $"{nameof(MultiFunctionTrigger.MultiFunctionTrigger1)} {nameof(MultiFunctionTrigger.MultiFunctionTrigger2)}";
             this.StartFunctionHost(functionList, SupportedLanguages.CSharp, useTestFolder: true);
@@ -363,7 +363,7 @@ public async Task MultiFunctionTriggerTest()
         [Fact]
         public async Task MultiHostTriggerTest()
         {
-            this.EnableChangeTrackingForTable("Products");
+            this.SetChangeTrackingForTable("Products");
 
             // Prepare three function host processes.
             this.StartFunctionHost(nameof(ProductsTrigger), SupportedLanguages.CSharp);
@@ -479,11 +479,11 @@ ALTER DATABASE [{this.DatabaseName}]
             ");
         }
 
-        protected void EnableChangeTrackingForTable(string tableName)
+        protected void SetChangeTrackingForTable(string tableName, bool enable = true)
         {
             this.ExecuteNonQuery($@"
                 ALTER TABLE [dbo].[{tableName}]
-                ENABLE CHANGE_TRACKING;
+                {(enable ? "ENABLE" : "DISABLE")} CHANGE_TRACKING;
             ");
         }
 
@@ -559,6 +559,7 @@ void MonitorOutputData(object sender, DataReceivedEventArgs e)
             await actions();
 
             // Now wait until either we timeout or we've gotten all the expected changes, whichever comes first
+            Console.WriteLine("Waiting for product changes");
             await taskCompletion.Task.TimeoutAfter(TimeSpan.FromMilliseconds(timeoutMs), $"Timed out waiting for {operation} changes.");
 
             // Unhook handler since we're done monitoring these changes so we aren't checking other changes done later
@@ -610,7 +611,7 @@ void OutputHandler(object sender, DataReceivedEventArgs e)
 
         /// <summary>
         /// Gets a timeout value to use when processing the given number of changes, based on the
-        /// default batch size and polling interval. 
+        /// default batch size and polling interval.
         /// </summary>
         /// <param name="firstId">The first ID in the batch to process</param>
         /// <param name="lastId">The last ID in the batch to process</param>

test/README.md

@@ -56,7 +56,7 @@ Our integration tests are based on functions from the samples project. To run in
                this.StartFunctionHost(nameof(<FUNCTIONNAME>), lang); // Replace <FUNCTIONNAME> with the class name of the function this test is running against
             // test code here
         }
-   ```  
+   ```
    Ex: When the test has parameters:
 
    ```
@@ -86,4 +86,20 @@ Our integration tests are based on functions from the samples project. To run in
             this.StartFunctionHost(nameof(<FUNCTIONNAME>), lang); // Replace <FUNCTIONNAME> with the class name of the function this test is running against
             // test code here
         }
-   ```
+   ```
+
+## Troubleshooting Tests
+
+This section lists some things to try to help troubleshoot test failures
+
+### Enable debug logging on the Function
+
+Enabling debug logging can greatly increase the information available which can help track down issues or understand at least where the problem may be. To enable debug logging for the Function open [host.json](../samples/samples-csharp/host.json) and add the following property to the `logLevel` section, then rebuild and re-run your test.
+
+```json
+"logLevel": {
+    "default": "Debug"
+}
+```
+
+WARNING : Doing this will add a not-insignificant overhead to the test run duration from writing all the additional content to the log files, which may cause timeouts to occur in tests. If this happens you can temporarily increase those timeouts while debug logging is enabled to avoid having unexpected failures.