Skip to content

Refactor debug logging in AbstractBatcher #2382

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
May 17, 2020
Merged

Refactor debug logging in AbstractBatcher #2382

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
80fcbea
Refactor debug logging in AbstractBatcher
bahusoid May 15, 2020
747d541
Async regen
bahusoid May 16, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
101 changes: 39 additions & 62 deletions src/NHibernate/AdoNet/AbstractBatcher.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Moved to LogOpenPreparedCommand

{
Log.Debug("Building an DbCommand object for the SqlString: {0}", sql);
}
LogOpenPreparedCommand(sql);
_commandsToClose.Add(cmd);
return cmd;
}
Expand Down Expand Up @@ -232,7 +228,7 @@ public int ExecuteNonQuery(DbCommand cmd)
}
finally
{
if (Log.IsDebugEnabled() && duration != null)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

duration is created only under Debug logging. I see no point in additional code cluttering with Log.IsDebugEnabled()

if (duration != null)
Log.Debug("ExecuteNonQuery took {0} ms", duration.ElapsedMilliseconds);
}
}
Expand All @@ -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
Copy link
Member Author

@bahusoid bahusoid May 16, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Useless finally block (as in case exception reader is null). Moved logic to LogOpenReader

{
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>
Expand Down Expand Up @@ -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
{
Expand All @@ -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()
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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)
Expand All @@ -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()
Expand Down
43 changes: 19 additions & 24 deletions src/NHibernate/Async/AdoNet/AbstractBatcher.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
Expand All @@ -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)
Expand All @@ -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>
Expand Down Expand Up @@ -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);
Expand Down