SQL Timings Not Displaying

[jknopp]

I am implementing MiniProfiler based on the Samples.Mvc5 project included in the repo and am having an issue with the display of SQL timings. I am curious if something might be off in my setup, but I am not sure exactly what that might be.

Here is an example of loading the homepage, and I am confused why the SQL timings and percentage all show as 0.0:

However, if I actually click on the sql timings I get this view, which does seem to indicate that each SQL call does have timings associated with it:

Can you help direct me as to why I might not be seeing them aggregated in the initial view, or where I might start looking to gather more info?

[jknopp]

The DataConnection class I am using to define ProfileDbConnection and other related objects is in a separate CSPROJ, here are some relevant configuration methods:

/// <summary>
/// Creates a new native connection
/// </summary>
protected override IDbConnection CreateNativeConnection()
{
	var connection = new SqlConnection(ConnectionString);
	return new ProfiledDbConnection(connection, MiniProfiler.Current);
}

/// <summary>
/// Creates a new SQL command
/// </summary>
/// <param name="cmdText">Command text</param>
protected override DbCommand CreateCommand(string cmdText)
{
	var command = new SqlCommand(cmdText, null, (SqlTransaction)Transaction);
	return new ProfiledDbCommand(command, (DbConnection)NativeConnection, MiniProfiler.Current);
}

/// <summary>
/// Creates a new command parameter
/// </summary>
/// <param name="name">Parameter name</param>
/// <param name="value">Parameter value</param>
protected override DbParameter CreateParameter(string name, object value)
{
	return new SqlParameter(name, value);
}

/// <summary>
/// Creates a data adapter
/// </summary>
protected override DbDataAdapter CreateDataAdapter()
{
	return new ProfiledDbDataAdapter(new SqlDataAdapter(), MiniProfiler.Current);
}

In the MVC app's Global.asax.cs:

public MvcApplication()
{
	AuthenticateRequest += (sender, e) =>
	{
		var app = (HttpApplication) sender;
		if (Request.IsLocal || app.User != null && app.User.Identity.IsAuthenticated && app.User.Identity.Name == "administrator")
		{
			MiniProfiler.StartNew();
		}
	};
	EndRequest += (sender, e) =>
	{
		MiniProfiler.Current?.Stop();
	};
}

[NickCraver]

Are you using a custom ProfiledDbConnection, or the included? (I'm taking your code to mean it's custom and not illustrating...but checking!)

It seems from your screenshots we're getting the fact the command started, when the result came in, but not the end of the command (for the overall timing). Normally, this happens when the data reader is closed (here:

dotnet/src/MiniProfiler.Shared/Data/ProfiledDbDataReader.cs

Line 235 in 3eb4385

_profiler?.ReaderFinish(this);

). Something is funny about that here - does any part of your setup stand out that makes sense as to why data readers would be different? If you're doing custom bits, it looks like .Close() isn't being overridden on the command. Note that the hookup generally happens here

[NickCraver]

@jknopp any word here?

[jknopp]

@NickCraver sorry about that, hadn't gotten time to circle back. I am using the included ProfiledDbConnection. I don't use ProfiledDbDataReader directly anywhere and am using only classes provided by the NuGet, however, I am integrating it with a DataConnection class from our CMS which may be why the snippet above appears customized.

I will include the whole class for context below. The commands overrides like ExecuteQuery, ExecuteNonQuery do call Close() is it possible I need to update how that is handled?

using System;
using System.Data;
using System.Data.Common;
using System.Data.SqlClient;
using System.Threading;
using System.Threading.Tasks;
using CMS.DataEngine;
using CMS.Helpers;
using StackExchange.Profiling;
using StackExchange.Profiling.Data;

// TODO Test and update this class
namespace KickstartTemplate.WebApp.Kentico
{
	/// <summary>
	/// Represents SQL Server data connection.
	/// </summary>
	public class DataConnection : AbstractDataConnection
	{
		#region "Methods"

		/// <summary>
		/// Constructor.
		/// </summary>
		/// <param name="connectionString">Connection string</param>
		internal DataConnection(string connectionString)
			: base(connectionString)
		{
		}


		/// <summary>
		/// Performs a bulk insert of the data into a target database table
		/// </summary>
		/// <param name="sourceData">Source data table</param>
		/// <param name="targetTable">Name of the target DB table</param>
		/// <param name="insertSettings">Bulk insert configuration</param>
		public override void BulkInsert(DataTable sourceData, string targetTable, BulkInsertSettings insertSettings = null)
		{
			if (insertSettings == null)
			{
				// Ensure default settings
				insertSettings = new BulkInsertSettings();
			}

			// Check the thread safety
			CheckThreadSafety();

			bool closeConnection = false;

			try
			{
				// Open the connection
				if (!IsOpen())
				{
					Open();
					closeConnection = true;
				}

				var conn = ((ProfiledDbConnection)NativeConnection).WrappedConnection as SqlConnection;

				// Perform the bulk insert
				using (SqlBulkCopy sbc = new SqlBulkCopy(conn, insertSettings.Options, Transaction as SqlTransaction))
				{
					// Set timeout for insert operation
					sbc.BulkCopyTimeout = insertSettings.BulkCopyTimeout;

					// Set newsletter queue table as destination table
					sbc.DestinationTableName = targetTable;

					// Map the Source Column from DataTable to the Destination Columns in SQL Server
					if (insertSettings.Mappings != null)
					{
						foreach (var item in insertSettings.Mappings)
						{
							sbc.ColumnMappings.Add(item.Key, item.Value);
						}
					}

					// Finally write to server
					sbc.WriteToServer(sourceData);

					sbc.Close();
				}
			}
			catch (Exception ex)
			{
				if (!HandleError("BulkInsert to table '" + targetTable + "'", ex))
				{
					throw;
				}
			}
			finally
			{
				// Close connection if necessary
				if (closeConnection)
				{
					Close();
				}
			}
		}

		public override void BeginTransaction(IsolationLevel isolation)
		{
			if (this.IsTransaction())
				return;
			this.LogConnectionOperation("BeginTransaction(" + (object)isolation + ")", true, (IDataConnection)this);
			this.Transaction = new ProfiledDbTransaction(this.NativeConnection.BeginTransaction(isolation) as DbTransaction, this.NativeConnection as ProfiledDbConnection);
		}

		/// <summary>Returns result of the query.</summary>
		/// <param name="queryText">Query or stored procedure to be run</param>
		/// <param name="queryParams">Query parameters</param>
		/// <param name="queryType">Indicates it query is a SQL query or stored procedure</param>
		/// <param name="requiresTransaction">If true, the query should run within transaction</param>
		public override DataSet ExecuteQuery(string queryText,
			QueryDataParameters queryParams,
			QueryTypeEnum queryType,
			bool requiresTransaction)
		{
			CheckThreadSafety();
			bool closeConnection = false;
			bool commitTransaction = false;
			DataSet dataSet = null;
			if (queryParams != null)
				dataSet = queryParams.FillDataSet;
			if (dataSet == null)
				dataSet = new DataSet();
			else
				dataSet.Clear();
			try
			{
				ProfiledDbCommand dbCommand = PrepareCommand(queryText, queryParams, queryType, requiresTransaction, ref closeConnection, ref commitTransaction);
				ProfiledDbDataAdapter dataAdapter = CreateDataAdapter() as ProfiledDbDataAdapter;
				dataAdapter.SelectCommand = dbCommand;
				dataAdapter.Fill(dataSet);

				if (IsLocalCmsDatabase())
				{
					foreach (DataTable table in dataSet.Tables)
					{
						table.ExtendedProperties["IsFromCMSDatabase"] = true;
						void MarkExternal() => table.ExtendedProperties["CMSHasExternalData"] = true;
						table.TableNewRow += (sender, args) => MarkExternal();
						table.RowChanged += (sender, args) => MarkExternal();
						table.ColumnChanged += (sender, args) => MarkExternal();
					}
				}
				if (commitTransaction)
				{
					CommitTransaction();
					commitTransaction = false;
				}
			}
			catch (Exception ex)
			{
				if (!HandleError(queryText, ex))
					throw;
			}
			finally
			{
				if (commitTransaction)
					RollbackTransaction();
				if (closeConnection)
					Close();
			}
			return dataSet;
		}

		/// <summary>
		/// Returns true, if the given connection string represents a connection to the local CMS database.
		/// </summary>
		private bool IsLocalCmsDatabase()
		{
			if (!string.IsNullOrEmpty(ConnectionString) && !ConnectionString.Equals(ConnectionHelper.ConnectionString, StringComparison.OrdinalIgnoreCase))
				return ConnectionString.Equals(DatabaseSeparationHelper.ConnStringSeparate, StringComparison.OrdinalIgnoreCase);
			return true;
		}

		/// <summary>Prepares the SQL command for the query.</summary>
		/// <param name="queryText">Query or stored procedure to be run</param>
		/// <param name="queryParams">Query parameters</param>
		/// <param name="queryType">Indicates it query is a SQL query or stored procedure</param>
		/// <param name="allowTransaction">Allow transaction for the command</param>
		/// <param name="closeConnection">Close connection</param>
		/// <param name="commitTransaction">Commit transaction</param>
		protected new ProfiledDbCommand PrepareCommand(
			string queryText,
			QueryDataParameters queryParams,
			QueryTypeEnum queryType,
			bool allowTransaction,
			ref bool closeConnection,
			ref bool commitTransaction)
		{
			if (!IsOpen())
			{
				Open();
				closeConnection = true;
			}
			if (allowTransaction && Transaction == null)
			{
				BeginTransaction(ConnectionHelper.TransactionIsolationLevel);
				commitTransaction = true;
			}
			ProfiledDbCommand command = CreateCommand(queryText) as ProfiledDbCommand;
			command.CommandType = queryType == QueryTypeEnum.StoredProcedure ? CommandType.StoredProcedure : CommandType.Text;
			command.CommandTimeout = CommandTimeout;
			AddParameters(command, queryParams);
			return command;
		}

		/// <summary>
		/// <para>
		/// An asynchronous version of <see cref="M:CMS.DataEngine.AbstractDataConnection.ExecuteNonQuery(System.String,CMS.DataEngine.QueryDataParameters,CMS.DataEngine.QueryTypeEnum,System.Boolean)" /> which executes the query asynchronously and returns the number of rows affected.
		/// </para>
		/// <para>
		/// The cancellation token can be used to request that the operation be abandoned before the command timeout elapses.
		/// Exceptions will be reported via the returned Task object.
		/// </para>
		/// </summary>
		/// <param name="queryText">Query or stored procedure to be run.</param>
		/// <param name="queryParams">Query parameters.</param>
		/// <param name="queryType">Indicates if query is a SQL query or stored procedure.</param>
		/// <param name="requiresTransaction">If true, the query should run within transaction.</param>
		/// <param name="cancellationToken">The cancellation instruction.</param>
		/// <returns>A task representing the asynchronous operation.</returns>
		public override async Task<int> ExecuteNonQueryAsync(
		 string queryText,
		 QueryDataParameters queryParams,
		 QueryTypeEnum queryType,
		 bool requiresTransaction,
		 CancellationToken cancellationToken)
		{
			CheckThreadSafety();
			bool closeConnection = false;
			bool commitTransaction = false;
			int result = 0;
			try
			{
				result = await PrepareCommand(queryText, queryParams, queryType, requiresTransaction, ref closeConnection, ref commitTransaction).ExecuteNonQueryAsync(cancellationToken);
				if (commitTransaction)
				{
					CommitTransaction();
					commitTransaction = false;
				}
			}
			catch (Exception ex)
			{
				if (!HandleError(queryText, ex))
					throw;
			}
			finally
			{
				if (commitTransaction)
					RollbackTransaction();
				if (closeConnection)
					Close();
			}
			return result;
		}

		/// <summary>
		/// Executes the query and returns the number of rows affected.
		/// </summary>
		/// <param name="queryText">Query or stored procedure to be run.</param>
		/// <param name="queryParams">Query parameters.</param>
		/// <param name="queryType">Indicates if query is a SQL query or stored procedure.</param>
		/// <param name="requiresTransaction">If true, the query should run within transaction.</param>
		public override int ExecuteNonQuery(
		  string queryText,
		  QueryDataParameters queryParams,
		  QueryTypeEnum queryType,
		  bool requiresTransaction)
		{
			CheckThreadSafety();
			bool closeConnection = false;
			bool commitTransaction = false;
			int num = 0;
			try
			{
				num = PrepareCommand(queryText, queryParams, queryType, requiresTransaction, ref closeConnection, ref commitTransaction).ExecuteNonQuery();
				if (commitTransaction)
				{
					CommitTransaction();
					commitTransaction = false;
				}
			}
			catch (Exception ex)
			{
				if (!HandleError(queryText, ex))
					throw;
			}
			finally
			{
				if (commitTransaction)
					RollbackTransaction();
				if (closeConnection)
					Close();
			}
			return num;
		}

		/// <summary>
		/// <para>
		/// An asynchronous version of <see cref="M:CMS.DataEngine.AbstractDataConnection.ExecuteReader(System.String,CMS.DataEngine.QueryDataParameters,CMS.DataEngine.QueryTypeEnum,System.Data.CommandBehavior)" /> which executes the query asynchronously and returns result as a <see cref="T:System.Data.Common.DbDataReader" />.
		/// </para>
		/// <para>
		/// The cancellation token can be used to request that the operation be abandoned before the command timeout elapses.
		/// Exceptions will be reported via the returned Task object.
		/// </para>
		/// </summary>
		/// <param name="queryText">Query or stored procedure to be run.</param>
		/// <param name="queryParams">Query parameters.</param>
		/// <param name="queryType">Indicates if query is a SQL query or stored procedure.</param>
		/// <param name="commandBehavior">Command behavior.</param>
		/// <param name="cancellationToken">The cancellation instruction.</param>
		/// <returns>A task representing the asynchronous operation.</returns>
		/// <remarks>
		/// The method executes the query with command behavior <see cref="F:System.Data.CommandBehavior.CloseConnection" /> if passed <paramref name="commandBehavior" /> is set to <see cref="F:System.Data.CommandBehavior.Default" /> and connection is not opened.
		/// </remarks>
		public override async Task<DbDataReader> ExecuteReaderAsync(
		  string queryText,
		  QueryDataParameters queryParams,
		  QueryTypeEnum queryType,
		  CommandBehavior commandBehavior,
		  CancellationToken cancellationToken)
		{
			CheckThreadSafety();
			bool closeConnection = false;
			bool commitTransaction = false;
			try
			{
				ProfiledDbCommand dbCommand = PrepareCommand(queryText, queryParams, queryType, false, ref closeConnection, ref commitTransaction);
				if (closeConnection && commandBehavior == CommandBehavior.Default)
					commandBehavior = CommandBehavior.CloseConnection;
				return await dbCommand.ExecuteReaderAsync(commandBehavior, cancellationToken);
			}
			catch (Exception ex)
			{
				if (closeConnection)
					Close();
				if (HandleError(queryText, ex))
					return null;
				throw;
			}
		}

		/// <summary>
		/// Executes the query and returns result of the query as a <see cref="T:System.Data.Common.DbDataReader" />.
		/// </summary>
		/// <param name="queryText">Query or stored procedure to be run.</param>
		/// <param name="queryParams">Query parameters.</param>
		/// <param name="queryType">Indicates if query is a SQL query or stored procedure.</param>
		/// <param name="commandBehavior">Command behavior.</param>
		/// <remarks>
		/// The method executes the query with command behavior <see cref="F:System.Data.CommandBehavior.CloseConnection" /> if passed <paramref name="commandBehavior" /> is set to <see cref="F:System.Data.CommandBehavior.Default" /> and connection is not opened.
		/// </remarks>
		public override DbDataReader ExecuteReader(
		  string queryText,
		  QueryDataParameters queryParams,
		  QueryTypeEnum queryType,
		  CommandBehavior commandBehavior)
		{
			CheckThreadSafety();
			bool closeConnection = false;
			bool commitTransaction = false;
			try
			{
				ProfiledDbCommand dbCommand = PrepareCommand(queryText, queryParams, queryType, false, ref closeConnection, ref commitTransaction);
				if (closeConnection && commandBehavior == CommandBehavior.Default)
					commandBehavior = CommandBehavior.CloseConnection;
				return dbCommand.ExecuteReader(commandBehavior);
			}
			catch (Exception ex)
			{
				if (closeConnection)
					Close();
				if (HandleError(queryText, ex))
					return null;
				throw;
			}
		}

		/// <summary>
		/// <para>
		/// An asynchronous version of <see cref="M:CMS.DataEngine.AbstractDataConnection.ExecuteScalar(System.String,CMS.DataEngine.QueryDataParameters,CMS.DataEngine.QueryTypeEnum,System.Boolean)" />, which executes the query asynchronously
		/// and returns the first column of the first row in the result set returned by the query.
		/// Additional columns or rows are ignored.
		/// </para>
		/// <para>
		/// The cancellation token can be used to request that the operation be abandoned before the command timeout elapses.
		/// Exceptions will be reported via the returned Task object.
		/// </para>
		/// </summary>
		/// <param name="queryText">Query or stored procedure to be run.</param>
		/// <param name="queryParams">Query parameters.</param>
		/// <param name="queryType">Indicates if query is a SQL query or stored procedure</param>
		/// <param name="requiresTransaction">If true, the query should run within transaction.</param>
		/// <param name="cancellationToken">The cancellation instruction.</param>
		/// <returns>A task representing the asynchronous operation.</returns>
		public override async Task<object> ExecuteScalarAsync(
		  string queryText,
		  QueryDataParameters queryParams,
		  QueryTypeEnum queryType,
		  bool requiresTransaction,
		  CancellationToken cancellationToken)
		{
			CheckThreadSafety();
			bool closeConnection = false;
			bool commitTransaction = false;
			object result = null;
			try
			{
				result = await PrepareCommand(queryText, queryParams, queryType, requiresTransaction, ref closeConnection, ref commitTransaction).ExecuteScalarAsync(cancellationToken);
				if (commitTransaction)
				{
					CommitTransaction();
					commitTransaction = false;
				}
			}
			catch (Exception ex)
			{
				if (!HandleError(queryText, ex))
					throw;
			}
			finally
			{
				if (commitTransaction)
					RollbackTransaction();
				if (closeConnection)
					Close();
			}
			return result;
		}

		/// <summary>
		/// Executes the query and returns the first column of the first row in the result set returned by the query.
		/// Additional columns or rows are ignored.
		/// </summary>
		/// <param name="queryText">Query or stored procedure to be run.</param>
		/// <param name="queryParams">Query parameters.</param>
		/// <param name="queryType">Indicates if query is a SQL query or stored procedure.</param>
		/// <param name="requiresTransaction">If true, the query should run within transaction.</param>
		public override object ExecuteScalar(
		  string queryText,
		  QueryDataParameters queryParams,
		  QueryTypeEnum queryType,
		  bool requiresTransaction)
		{
			CheckThreadSafety();
			bool closeConnection = false;
			bool commitTransaction = false;
			object obj = null;
			try
			{
				obj = PrepareCommand(queryText, queryParams, queryType, requiresTransaction, ref closeConnection, ref commitTransaction).ExecuteScalar();
				if (commitTransaction)
				{
					CommitTransaction();
					commitTransaction = false;
				}
			}
			catch (Exception ex)
			{
				if (!HandleError(queryText, ex))
					throw;
			}
			finally
			{
				if (commitTransaction)
					RollbackTransaction();
				if (closeConnection)
					Close();
			}
			return obj;
		}

		/// <summary>
		/// Creates a new native connection
		/// </summary>
		protected override IDbConnection CreateNativeConnection()
		{
			var connection = new SqlConnection(ConnectionString);
			return new ProfiledDbConnection(connection, MiniProfiler.Current);
		}

		/// <summary>
		/// Creates a new SQL command
		/// </summary>
		/// <param name="cmdText">Command text</param>
		protected override DbCommand CreateCommand(string cmdText)
		{
			var command = new SqlCommand(cmdText, null, (SqlTransaction)Transaction);
			return new ProfiledDbCommand(command, (DbConnection)NativeConnection, MiniProfiler.Current);
		}

		/// <summary>
		/// Creates a new command parameter
		/// </summary>
		/// <param name="name">Parameter name</param>
		/// <param name="value">Parameter value</param>
		protected override DbParameter CreateParameter(string name, object value)
		{
			return new SqlParameter(name, value);
		}

		/// <summary>
		/// Creates a data adapter
		/// </summary>
		protected override DbDataAdapter CreateDataAdapter()
		{
			return new ProfiledDbDataAdapter(new SqlDataAdapter(), MiniProfiler.Current);
		}

		/// <summary>
		/// Handles the database error. Returns false, if the error was not handled
		/// </summary>
		/// <param name="message">Error message</param>
		/// <param name="ex">Database exception</param>
		protected override bool HandleDbError(string message, DbException ex)
		{
			// Log track for deadlock exception
			if (ex is SqlException sqlEx && sqlEx.Number == 1205)
			{
				Trackable<CMSTransactionScope>.TrackAllOpen(ex.Message);
			}

			return base.HandleDbError(message, ex);
		}

		#endregion
	}
}

[urbanekv]

@NickCraver
I'am currently trying to integrate MiniProfiler into our project. I did experience the same problem as @jknopp - not correctly closing timers and thus having 0.00ms in total SQL values.

In my case, I am trying to use ProfiledDbDataAdapter the simillar way as at @jknopp code in the comment above.

ProfiledDbDataAdapter dataAdapter = CreateDataAdapter() as ProfiledDbDataAdapter;
				dataAdapter.SelectCommand = dbCommand;
				dataAdapter.Fill(dataSet);

I tried to debug from VS and step into ProfiledDbDataAdapter::Fill().
It's possible to step up to ExecuteStart - https://github.com/MiniProfiler/dotnet/blob/main/src/MiniProfiler.Shared/Data/ProfiledDbDataAdapter.cs#L82
And then it all of the sudden jumps to return result line - https://github.com/MiniProfiler/dotnet/blob/main/src/MiniProfiler.Shared/Data/ProfiledDbDataAdapter.cs#L97

So it skips ExecuteFinish. On the other hand, internal fill was called. Debugging in VS behaves weird probably because the MiniProfiler code is optimized out. I tried to build DEBUG version of MiniProfiler, but had troubles with that (either by build.cmd or from withing VS).

[urbanekv]

In the end, ExecuteFinish() is called in our use case well, but Stop() is skipped. I have just sent a fix proposal above - just don't sending the dummy reader into ExecuteFinish(). On the other hand we might not use SQL profiling the intended way... I tried to use profiled db connection first but I hit several data type issues during runtime, so ProfiledDbDataAdapter seemed to be the best level for us.