Refactor debug logging in AbstractBatcher (#2382)

Author: bahusoid

src/NHibernate/AdoNet/AbstractBatcher.cs

@@ -93,11 +93,7 @@ private DbCommand Generate(CommandType type, SqlString sqlString, SqlType[] para
 			}
 
 			var cmd = _factory.ConnectionProvider.Driver.GenerateCommand(type, sql, parameterTypes);
-			LogOpenPreparedCommand();
-			if (Log.IsDebugEnabled())
-			{
-				Log.Debug("Building an DbCommand object for the SqlString: {0}", sql);
-			}
+			LogOpenPreparedCommand(sql);
 			_commandsToClose.Add(cmd);
 			return cmd;
 		}
@@ -232,7 +228,7 @@ public int ExecuteNonQuery(DbCommand cmd)
 			}
 			finally
 			{
-				if (Log.IsDebugEnabled() && duration != null)
+				if (duration != null)
 					Log.Debug("ExecuteNonQuery took {0} ms", duration.ElapsedMilliseconds);
 			}
 		}
@@ -242,37 +238,31 @@ public virtual DbDataReader ExecuteReader(DbCommand cmd)
 			CheckReaders();
 			LogCommand(cmd);
 			Prepare(cmd);
-			Stopwatch duration = null;
-			if (Log.IsDebugEnabled())
-				duration = Stopwatch.StartNew();
-			DbDataReader reader = null;
+
+			var duration = Log.IsDebugEnabled() ? Stopwatch.StartNew() : null;
+
+			var reader = DoExecuteReader(cmd);
+
+			_readersToClose.Add(reader);
+			LogOpenReader(duration , reader);
+			return reader;
+		}
+
+		private DbDataReader DoExecuteReader(DbCommand cmd)
+		{
 			try
 			{
-				reader = cmd.ExecuteReader();
+				var reader = cmd.ExecuteReader();
+				return _factory.ConnectionProvider.Driver.SupportsMultipleOpenReaders
+					? reader
+					: NHybridDataReader.Create(reader);
 			}
 			catch (Exception e)
 			{
 				e.Data["actual-sql-query"] = cmd.CommandText;
 				Log.Error(e, "Could not execute query: {0}", cmd.CommandText);
 				throw;
 			}
-			finally
-			{
-				if (Log.IsDebugEnabled() && duration != null && reader != null)
-				{
-					Log.Debug("ExecuteReader took {0} ms", duration.ElapsedMilliseconds);
-					_readersDuration[reader] = duration;
-				}
-			}
-
-			if (!_factory.ConnectionProvider.Driver.SupportsMultipleOpenReaders)
-			{
-				reader = NHybridDataReader.Create(reader);
-			}
-
-			_readersToClose.Add(reader);
-			LogOpenReader();
-			return reader;
 		}
 
 		/// <summary>
@@ -388,8 +378,7 @@ public void CloseReader(DbDataReader reader)
 			var rsw = reader as ResultSetWrapper;
 			var actualReader = rsw == null ? reader : rsw.Target;
 			_readersToClose.Remove(actualReader);
-
-			var duration = GetReaderStopwatch(actualReader);
+			_readersDuration.Remove(actualReader, out var duration);
 
 			try
 			{
@@ -401,24 +390,7 @@ public void CloseReader(DbDataReader reader)
 				Log.Warn(e, "exception closing reader");
 			}
 
-			LogCloseReader();
-			LogDuration(duration);
-		}
-
-		private Stopwatch GetReaderStopwatch(DbDataReader reader)
-		{
-			var nhReader = reader as NHybridDataReader;
-			var actualReader = nhReader == null ? reader : nhReader.Target;
-
-			_readersDuration.Remove(actualReader, out var duration);
-			return duration;
-		}
-
-		private static void LogDuration(Stopwatch duration)
-		{
-			if (!Log.IsDebugEnabled() || duration == null) return;
-
-			Log.Debug("DataReader was closed after {0} ms", duration.ElapsedMilliseconds);
+			LogCloseReader(duration);
 		}
 
 		public void ExecuteBatch()
@@ -447,7 +419,7 @@ protected void ExecuteBatchWithTiming(DbCommand ps)
 				duration = Stopwatch.StartNew();
 			var countBeforeExecutingBatch = CountOfStatementsInCurrentBatch;
 			DoExecuteBatch(ps);
-			if (Log.IsDebugEnabled() && duration != null)
+			if (duration != null)
 				Log.Debug("ExecuteBatch for {0} statements took {1} ms",
 					countBeforeExecutingBatch,
 					duration.ElapsedMilliseconds);
@@ -504,12 +476,13 @@ protected void LogCommand(DbCommand command)
 			_factory.Settings.SqlStatementLogger.LogCommand(command, FormatStyle.Basic);
 		}
 
-		private void LogOpenPreparedCommand()
+		private void LogOpenPreparedCommand(SqlString sql)
 		{
 			if (Log.IsDebugEnabled())
 			{
 				int currentOpenCommandCount = Interlocked.Increment(ref _openCommandCount);
 				Log.Debug("Opened new DbCommand, open DbCommands: {0}", currentOpenCommandCount);
+				Log.Debug("Building an DbCommand object for the SqlString: {0}", sql);
 			}
 
 			if (_factory.Statistics.IsStatisticsEnabled)
@@ -532,22 +505,26 @@ private void LogClosePreparedCommand()
 			}
 		}
 
-		private static void LogOpenReader()
+		private void LogOpenReader(Stopwatch duration, DbDataReader reader)
 		{
-			if (Log.IsDebugEnabled())
-			{
-				int currentOpenReaderCount = Interlocked.Increment(ref _openReaderCount);
-				Log.Debug("Opened DbDataReader, open DbDataReaders: {0}", currentOpenReaderCount);
-			}
+			if (duration == null)
+				return;
+
+			Log.Debug("ExecuteReader took {0} ms", duration.ElapsedMilliseconds);
+			_readersDuration[reader] = duration;
+
+			int currentOpenReaderCount = Interlocked.Increment(ref _openReaderCount);
+			Log.Debug("Opened DbDataReader, open DbDataReaders: {0}", currentOpenReaderCount);
 		}
 
-		private static void LogCloseReader()
+		private static void LogCloseReader(Stopwatch duration)
 		{
-			if (Log.IsDebugEnabled())
-			{
-				int currentOpenReaderCount = Interlocked.Decrement(ref _openReaderCount);
-				Log.Debug("Closed DbDataReader, open DbDataReaders :{0}", currentOpenReaderCount);
-			}
+			if (duration == null)
+				return;
+
+			int currentOpenReaderCount = Interlocked.Decrement(ref _openReaderCount);
+			Log.Debug("Closed DbDataReader, open DbDataReaders :{0}", currentOpenReaderCount);
+			Log.Debug("DataReader was closed after {0} ms", duration.ElapsedMilliseconds);
 		}
 
 		public void CancelLastQuery()

src/NHibernate/Async/AdoNet/AbstractBatcher.cs

@@ -141,7 +141,7 @@ public async Task<int> ExecuteNonQueryAsync(DbCommand cmd, CancellationToken can
 			}
 			finally
 			{
-				if (Log.IsDebugEnabled() && duration != null)
+				if (duration != null)
 					Log.Debug("ExecuteNonQuery took {0} ms", duration.ElapsedMilliseconds);
 			}
 		}
@@ -152,13 +152,25 @@ public virtual async Task<DbDataReader> ExecuteReaderAsync(DbCommand cmd, Cancel
 			await (CheckReadersAsync(cancellationToken)).ConfigureAwait(false);
 			LogCommand(cmd);
 			await (PrepareAsync(cmd, cancellationToken)).ConfigureAwait(false);
-			Stopwatch duration = null;
-			if (Log.IsDebugEnabled())
-				duration = Stopwatch.StartNew();
-			DbDataReader reader = null;
+
+			var duration = Log.IsDebugEnabled() ? Stopwatch.StartNew() : null;
+
+			var reader = await (DoExecuteReaderAsync(cmd, cancellationToken)).ConfigureAwait(false);
+
+			_readersToClose.Add(reader);
+			LogOpenReader(duration , reader);
+			return reader;
+		}
+
+		private async Task<DbDataReader> DoExecuteReaderAsync(DbCommand cmd, CancellationToken cancellationToken)
+		{
+			cancellationToken.ThrowIfCancellationRequested();
 			try
 			{
-				reader = await (cmd.ExecuteReaderAsync(cancellationToken)).ConfigureAwait(false);
+				var reader = await (cmd.ExecuteReaderAsync(cancellationToken)).ConfigureAwait(false);
+				return _factory.ConnectionProvider.Driver.SupportsMultipleOpenReaders
+					? reader
+					: await (NHybridDataReader.CreateAsync(reader, cancellationToken)).ConfigureAwait(false);
 			}
 			catch (OperationCanceledException) { throw; }
 			catch (Exception e)
@@ -167,23 +179,6 @@ public virtual async Task<DbDataReader> ExecuteReaderAsync(DbCommand cmd, Cancel
 				Log.Error(e, "Could not execute query: {0}", cmd.CommandText);
 				throw;
 			}
-			finally
-			{
-				if (Log.IsDebugEnabled() && duration != null && reader != null)
-				{
-					Log.Debug("ExecuteReader took {0} ms", duration.ElapsedMilliseconds);
-					_readersDuration[reader] = duration;
-				}
-			}
-
-			if (!_factory.ConnectionProvider.Driver.SupportsMultipleOpenReaders)
-			{
-				reader = await (NHybridDataReader.CreateAsync(reader, cancellationToken)).ConfigureAwait(false);
-			}
-
-			_readersToClose.Add(reader);
-			LogOpenReader();
-			return reader;
 		}
 
 		/// <summary>
@@ -234,7 +229,7 @@ protected async Task ExecuteBatchWithTimingAsync(DbCommand ps, CancellationToken
 				duration = Stopwatch.StartNew();
 			var countBeforeExecutingBatch = CountOfStatementsInCurrentBatch;
 			await (DoExecuteBatchAsync(ps, cancellationToken)).ConfigureAwait(false);
-			if (Log.IsDebugEnabled() && duration != null)
+			if (duration != null)
 				Log.Debug("ExecuteBatch for {0} statements took {1} ms",
 					countBeforeExecutingBatch,
 					duration.ElapsedMilliseconds);