From 80fcbeab61fa16b7924f3db61c642f35f7fb452c Mon Sep 17 00:00:00 2001 From: Roman Artiukhin Date: Fri, 15 May 2020 23:37:28 +0300 Subject: [PATCH 1/2] Refactor debug logging in AbstractBatcher --- src/NHibernate/AdoNet/AbstractBatcher.cs | 101 +++++++++-------------- 1 file changed, 39 insertions(+), 62 deletions(-) diff --git a/src/NHibernate/AdoNet/AbstractBatcher.cs b/src/NHibernate/AdoNet/AbstractBatcher.cs index a243571ce0d..520b4e152a3 100644 --- a/src/NHibernate/AdoNet/AbstractBatcher.cs +++ b/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,13 +238,24 @@ 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) { @@ -256,23 +263,6 @@ public virtual DbDataReader ExecuteReader(DbCommand cmd) 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; } /// @@ -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() From 747d5413867e1b9399a5978ffa04054ccadb8fb8 Mon Sep 17 00:00:00 2001 From: Roman Artiukhin Date: Sat, 16 May 2020 09:27:38 +0300 Subject: [PATCH 2/2] Async regen --- .../Async/AdoNet/AbstractBatcher.cs | 43 ++++++++----------- 1 file changed, 19 insertions(+), 24 deletions(-) diff --git a/src/NHibernate/Async/AdoNet/AbstractBatcher.cs b/src/NHibernate/Async/AdoNet/AbstractBatcher.cs index 50110b4d6d5..ed60b6c704c 100644 --- a/src/NHibernate/Async/AdoNet/AbstractBatcher.cs +++ b/src/NHibernate/Async/AdoNet/AbstractBatcher.cs @@ -141,7 +141,7 @@ public async Task 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 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 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 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; } /// @@ -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);