more small fixes

pwelter34 · pwelter34 · commit f92367a39f77 · 2023-09-11T21:51:25.000-05:00
diff --git a/src/FluentCommand.Caching/DistributedDataCache.cs b/src/FluentCommand.Caching/DistributedDataCache.cs
@@ -196,17 +196,15 @@ public async Task RemoveAsync(string key, CancellationToken cancellationToken =
     }
 
 
-    [LoggerMessage(0, LogLevel.Information, "Cache Hit; Key: '{cacheKey}'")]
+    [LoggerMessage(0, LogLevel.Debug, "Cache Hit; Key: '{cacheKey}'")]
     static partial void LogCacheHit(ILogger logger, string cacheKey);
 
-    [LoggerMessage(1, LogLevel.Information, "Cache Miss; Key: '{cacheKey}'")]
+    [LoggerMessage(1, LogLevel.Debug, "Cache Miss; Key: '{cacheKey}'")]
     static partial void LogCacheMiss(ILogger logger, string cacheKey);
 
-    [LoggerMessage(2, LogLevel.Information, "Cache Insert; Key: '{cacheKey}'")]
+    [LoggerMessage(2, LogLevel.Debug, "Cache Insert; Key: '{cacheKey}'")]
     static partial void LogCacheInsert(ILogger logger, string cacheKey);
 
-    [LoggerMessage(3, LogLevel.Information, "Cache Remove; Key: '{cacheKey}'")]
+    [LoggerMessage(3, LogLevel.Debug, "Cache Remove; Key: '{cacheKey}'")]
     static partial void LogCacheRemove(ILogger logger, string cacheKey);
-
-
 }
diff --git a/src/FluentCommand/DataCommand.cs b/src/FluentCommand/DataCommand.cs
@@ -1,5 +1,6 @@
 using System.Data;
 using System.Data.Common;
+using System.Diagnostics;
 
 using FluentCommand.Extensions;
 using FluentCommand.Internal;
@@ -556,8 +557,7 @@ private TResult QueryFactory<TResult>(Func<TResult> query, bool supportCache)
 
         AssertDisposed();
 
-        var watch = SharedStopwatch.StartNew();
-        var logged = false;
+        var startingTimestamp = Stopwatch.GetTimestamp();
 
         try
         {
@@ -579,16 +579,14 @@ private TResult QueryFactory<TResult>(Func<TResult> query, bool supportCache)
         }
         catch (Exception ex)
         {
-            LogCommand(watch.Elapsed, ex);
-            logged = true;
+            LogCommand(startingTimestamp, ex);
+            startingTimestamp = 0;
 
             throw;
         }
         finally
         {
-            // if catch block didn't already log
-            if (!logged)
-                LogCommand(watch.Elapsed);
+            LogCommand(startingTimestamp);
 
             _dataSession.ReleaseConnection();
             Dispose();
@@ -605,8 +603,7 @@ private async Task<TResult> QueryFactoryAsync<TResult>(
 
         AssertDisposed();
 
-        var watch = SharedStopwatch.StartNew();
-        var logged = false;
+        var startingTimestamp = Stopwatch.GetTimestamp();
 
         try
         {
@@ -628,16 +625,14 @@ private async Task<TResult> QueryFactoryAsync<TResult>(
         }
         catch (Exception ex)
         {
-            LogCommand(watch.Elapsed, ex);
-            logged = true;
+            LogCommand(startingTimestamp, ex);
+            startingTimestamp = 0;
 
             throw;
         }
         finally
         {
-            // if catch block didn't already log
-            if (!logged)
-                LogCommand(watch.Elapsed);
+            LogCommand(startingTimestamp);
 
 #if NETCOREAPP3_0_OR_GREATER
 
@@ -751,8 +746,22 @@ await cache
     }
 
 
-    private void LogCommand(TimeSpan duration, Exception exception = null)
+    private void LogCommand(long startingTimestamp, Exception exception = null)
     {
+        // indicates already logged
+        if (startingTimestamp == 0)
+            return;
+
+        var endingTimestamp = Stopwatch.GetTimestamp();
+
+#if NET7_0_OR_GREATER
+        var duration = Stopwatch.GetElapsedTime(startingTimestamp, endingTimestamp);
+#else
+        var duration = new TimeSpan((long)((endingTimestamp - startingTimestamp) * _tickFrequency));
+#endif
+
         _dataSession.QueryLogger?.LogCommand(Command, duration, exception, _logState);
     }
+
+    private static readonly double _tickFrequency = (double)TimeSpan.TicksPerSecond / Stopwatch.Frequency;
 }
diff --git a/src/FluentCommand/Internal/SharedStopwatch.cs b/src/FluentCommand/Internal/SharedStopwatch.cs
diff --git a/test/FluentCommand.PostgreSQL.Tests/DatabaseFixture.cs b/test/FluentCommand.PostgreSQL.Tests/DatabaseFixture.cs
@@ -4,6 +4,7 @@
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.DependencyInjection.Extensions;
 using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
 
 using Npgsql;
 
@@ -13,9 +14,15 @@ namespace FluentCommand.PostgreSQL.Tests;
 
 public class DatabaseFixture : TestHostFixture
 {
+    protected override void ConfigureLogging(HostBuilderContext context, ILoggingBuilder builder)
+    {
+        base.ConfigureLogging(context, builder);
+        builder.SetMinimumLevel(LogLevel.Debug);
+    }
+
     protected override void ConfigureServices(HostBuilderContext context, IServiceCollection services)
     {
-        var trackerConnnection = context.Configuration.GetConnectionString("Tracker");
+        var trackerConnection = context.Configuration.GetConnectionString("Tracker");
         var cacheConnection = context.Configuration.GetConnectionString("DistributedCache");
 
         services.AddHostedService<DatabaseInitializer>();
@@ -26,7 +33,7 @@ protected override void ConfigureServices(HostBuilderContext context, IServiceCo
         services.TryAddSingleton<IDataConfiguration>(sp =>
             new DataConfiguration(
                 NpgsqlFactory.Instance,
-                trackerConnnection,
+                trackerConnection,
                 sp.GetService<IDataCache>(),
                 sp.GetService<IQueryGenerator>(),
                 sp.GetService<IDataQueryLogger>()
diff --git a/test/FluentCommand.SQLite.Tests/DatabaseFixture.cs b/test/FluentCommand.SQLite.Tests/DatabaseFixture.cs
@@ -6,16 +6,23 @@
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.DependencyInjection.Extensions;
 using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
 
 using XUnit.Hosting;
 
 namespace FluentCommand.SQLite.Tests;
 
 public class DatabaseFixture : TestHostFixture
 {
+    protected override void ConfigureLogging(HostBuilderContext context, ILoggingBuilder builder)
+    {
+        base.ConfigureLogging(context, builder);
+        builder.SetMinimumLevel(LogLevel.Debug);
+    }
+
     protected override void ConfigureServices(HostBuilderContext context, IServiceCollection services)
     {
-        var trackerConnnection = context.Configuration.GetConnectionString("Tracker");
+        var trackerConnection = context.Configuration.GetConnectionString("Tracker");
         var cacheConnection = context.Configuration.GetConnectionString("DistributedCache");
 
         services.AddHostedService<DatabaseInitializer>();
@@ -26,7 +33,7 @@ protected override void ConfigureServices(HostBuilderContext context, IServiceCo
         services.TryAddSingleton<IDataConfiguration>(sp =>
             new DataConfiguration(
                 SqliteFactory.Instance,
-                trackerConnnection,
+                trackerConnection,
                 sp.GetService<IDataCache>(),
                 sp.GetService<IQueryGenerator>(),
                 sp.GetService<IDataQueryLogger>()
diff --git a/test/FluentCommand.SqlServer.Tests/DatabaseFixture.cs b/test/FluentCommand.SqlServer.Tests/DatabaseFixture.cs
@@ -6,13 +6,20 @@
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.DependencyInjection.Extensions;
 using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
 
 using XUnit.Hosting;
 
 namespace FluentCommand.SqlServer.Tests;
 
 public class DatabaseFixture : TestHostFixture
 {
+    protected override void ConfigureLogging(HostBuilderContext context, ILoggingBuilder builder)
+    {
+        base.ConfigureLogging(context, builder);
+        builder.SetMinimumLevel(LogLevel.Debug);
+    }
+
     protected override void ConfigureServices(HostBuilderContext context, IServiceCollection services)
     {
         var trackerConnection = context.Configuration.GetConnectionString("Tracker");

Original file line number	Diff line number	Diff line change
`@@ -1,5 +1,6 @@`
`1`	`1`	`using System.Data;`
`2`	`2`	`using System.Data.Common;`
	`3`	`+using System.Diagnostics;`
`3`	`4`
`4`	`5`	`using FluentCommand.Extensions;`
`5`	`6`	`using FluentCommand.Internal;`
`@@ -556,8 +557,7 @@ private TResult QueryFactory<TResult>(Func<TResult> query, bool supportCache)`
`556`	`557`
`557`	`558`	`AssertDisposed();`
`558`	`559`
`559`		`- var watch = SharedStopwatch.StartNew();`
`560`		`- var logged = false;`
	`560`	`+ var startingTimestamp = Stopwatch.GetTimestamp();`
`561`	`561`
`562`	`562`	`try`
`563`	`563`	`{`
`@@ -579,16 +579,14 @@ private TResult QueryFactory<TResult>(Func<TResult> query, bool supportCache)`
`579`	`579`	`}`
`580`	`580`	`catch (Exception ex)`
`581`	`581`	`{`
`582`		`- LogCommand(watch.Elapsed, ex);`
`583`		`- logged = true;`
	`582`	`+ LogCommand(startingTimestamp, ex);`
	`583`	`+ startingTimestamp = 0;`
`584`	`584`
`585`	`585`	`throw;`
`586`	`586`	`}`
`587`	`587`	`finally`
`588`	`588`	`{`
`589`		`- // if catch block didn't already log`
`590`		`- if (!logged)`
`591`		`- LogCommand(watch.Elapsed);`
	`589`	`+ LogCommand(startingTimestamp);`
`592`	`590`
`593`	`591`	`_dataSession.ReleaseConnection();`
`594`	`592`	`Dispose();`
`@@ -605,8 +603,7 @@ private async Task<TResult> QueryFactoryAsync<TResult>(`
`605`	`603`
`606`	`604`	`AssertDisposed();`
`607`	`605`
`608`		`- var watch = SharedStopwatch.StartNew();`
`609`		`- var logged = false;`
	`606`	`+ var startingTimestamp = Stopwatch.GetTimestamp();`
`610`	`607`
`611`	`608`	`try`
`612`	`609`	`{`
`@@ -628,16 +625,14 @@ private async Task<TResult> QueryFactoryAsync<TResult>(`
`628`	`625`	`}`
`629`	`626`	`catch (Exception ex)`
`630`	`627`	`{`
`631`		`- LogCommand(watch.Elapsed, ex);`
`632`		`- logged = true;`
	`628`	`+ LogCommand(startingTimestamp, ex);`
	`629`	`+ startingTimestamp = 0;`
`633`	`630`
`634`	`631`	`throw;`
`635`	`632`	`}`
`636`	`633`	`finally`
`637`	`634`	`{`
`638`		`- // if catch block didn't already log`
`639`		`- if (!logged)`
`640`		`- LogCommand(watch.Elapsed);`
	`635`	`+ LogCommand(startingTimestamp);`
`641`	`636`
`642`	`637`	`#if NETCOREAPP3_0_OR_GREATER`
`643`	`638`
`@@ -751,8 +746,22 @@ await cache`
`751`	`746`	`}`
`752`	`747`
`753`	`748`
`754`		`- private void LogCommand(TimeSpan duration, Exception exception = null)`
	`749`	`+ private void LogCommand(long startingTimestamp, Exception exception = null)`
`755`	`750`	`{`
	`751`	`+ // indicates already logged`
	`752`	`+ if (startingTimestamp == 0)`
	`753`	`+ return;`
	`754`	`+`
	`755`	`+ var endingTimestamp = Stopwatch.GetTimestamp();`
	`756`	`+`
	`757`	`+#if NET7_0_OR_GREATER`
	`758`	`+ var duration = Stopwatch.GetElapsedTime(startingTimestamp, endingTimestamp);`
	`759`	`+#else`
	`760`	`+ var duration = new TimeSpan((long)((endingTimestamp - startingTimestamp) * _tickFrequency));`
	`761`	`+#endif`
	`762`	`+`
`756`	`763`	`_dataSession.QueryLogger?.LogCommand(Command, duration, exception, _logState);`
`757`	`764`	`}`
	`765`	`+`
	`766`	`+ private static readonly double _tickFrequency = (double)TimeSpan.TicksPerSecond / Stopwatch.Frequency;`
`758`	`767`	`}`