How to log all SQL statements with their duration (C#.NET MSSQL/delphi SDAC)

Data Abstract
1

How can we easily log all SQL statements with as much as possible info

I would like to log the actual SQL with the execution duration (~SQL server time) with (custom) info from the RO client (PC, application, process id)

Talk issue

speaks about demo server application but I cannot find this sample code after a quick scan of C:\Users\Public\Documents\RemObjects Samples\Data Abstract for .NET

DASchema GetSQL event does not give me duration
BusinessProcessor.OnGenerate does not give me duration and is only called for update/insert
ProcessorAfterExecuteCommand not always called (after update/insert and some selects?) and ElapsedMilliseconds always seems 0 (delphi SDAC)

Our main focus is C#.NET code with MSSQL DB connections

3

Hello

The best way to log all MS SQL server activity is their SQL Server Profiler tool. However this tool won’t show application-level data like name of the user connected to the DA server etc. Also profiler tool might not be available for some databases supported by Data Abstract.

It is possible to add custom logging to the server app itself. Data Abstract server uses only 2 methods to access and update data and 1 additional to execute Schema command. The logging code would look like this:

	[RemObjects.SDK.Server.Service]
	public class DataService : RemObjects.DataAbstract.Server.DataAbstractService
	{
		public DataService()
		{
			this.InitializeComponent();

			this.BeforeExecutingGetDataReader += DataService_BeforeExecutingGetDataReader;
			this.BeforeExecuteCommand += DataService_BeforeExecuteCommand;
		}

		// Required for designer support
		private void InitializeComponent()
		{
			RemObjects.DataAbstract.Bin2DataStreamer dataStreamer;
			dataStreamer = new RemObjects.DataAbstract.Bin2DataStreamer();
			this.AcquireConnection = true;
			this.ServiceDataStreamer = dataStreamer;
			this.ServiceSchemaName = "....";
		}

		private IList<String> _log;
		private Stopwatch _executionTime;

		private void InitLog(String operationName)
		{
			this._executionTime = new Stopwatch();
			this._executionTime.Start();

			this._log = new List<String>();
			this._log.Add($"{DateTime.UtcNow}: Operation started ({operationName})");
		}

		private void FlushLog()
		{
			this._executionTime.Stop();
			this._log.Add($"{DateTime.UtcNow}: Operation completed ({this._executionTime.ElapsedMilliseconds} ticks)");

			foreach (var message in this._log)
			{
				Console.WriteLine(message);
			}
		}

		private void DataService_BeforeExecuteCommand(DataAbstractService sender, DataAbstractServiceExecuteCommandEventArgs e)
		{
			this.LogDatabaseCommand(e.Command);
		}

		private void DataService_BeforeExecutingGetDataReader(RemObjects.DataAbstract.Schema.ServiceSchema sender, RemObjects.DataAbstract.Schema.BeforeExecutingGetDataReaderEventArgs e)
		{
			this.LogDatabaseCommand(e.Command);
		}
		
		private void LogDatabaseCommand(IDbCommand command)
		{
			this._log.Add($"Connection: {this.Connection.Name}");
			this._log.Add("SQL: ");
			this._log.Add(command.CommandText);

			if (command.Parameters.Count == 0)
			{
				return;
			}

			this._log.Add($"Parameters");
			foreach (IDbDataParameter parameter in command.Parameters)
			{
				var parameterName = parameter.ParameterName;
				var parameterValue = ((parameter.Value == null) || (parameter.Value == DBNull.Value) ?  "NULL" :  parameter.Value.ToString());
				this._log.Add($"    {parameterName}: {parameterValue}");
			}
		}

		public override Binary GetData(string[] tableNames, TableRequestInfo[] requestInfo)
		{
			this.InitLog("GetData");
			try
			{
				return base.GetData(tableNames, requestInfo);
			}
			catch (Exception ex)
			{
				this._log.Add(ex.ToString());
				throw;
			}
			finally
			{
				this.FlushLog();
			}
		}

		public override Binary UpdateData(Binary serializedDelta)
		{
			this.InitLog("UpdateData");
			try
			{
				return base.UpdateData(serializedDelta);
			}
			catch (Exception ex)
			{
				this._log.Add(ex.ToString());
				throw;
			}
			finally
			{
				this.FlushLog();
			}
		}

		public override int ExecuteCommandEx(string commandName, DataParameter[] inputParameters, out DataParameter[] outputParameters)
		{
			this.InitLog("ExecuteCommand");
			try
			{
				return base.ExecuteCommandEx(commandName, inputParameters, out outputParameters);
			}
			catch (Exception ex)
			{
				this._log.Add(ex.ToString());
				throw;
			}
			finally
			{
				this.FlushLog();
			}
		}
	}

Hope this helps

4

Can the duration be added? It is very useful to see which queries took a long time.
SQL profiler is not an option for us for the reasons you mentioned.

5

The FlushLog method already displays elapsed time. This time also includes data serialization time, however for long-running queries this additional time won’t matter much. F.e. if a query runs for 5 seconds then 10 additional milliseconds won’t change the overall picture.

Regards

6

Sorry, missed the duration info.
This works as needed, thanks

7

I will log an issue to investigate if it is possible to add such feature to Data Abstract core without affecting performance.

8

Logged as bugs://D19122.

9

Do you have a similar solution for delphi? I don’t see the BeforeExecutingGetDataReader and GetData event in delphi.
How can we log all the SQL statements for a delphi RO dataabstract server?

10

Hi,

you can assign events to aDataSet in the DataAbstractService.OnBeforeGetDatasetData or to aCommand / Sender in the DataAbstractService.OnBeforeExecuteCommand or TDABusinessProcessor.OnBeforeExecuteCommand events:

(aDataset as IDAServerDataset).OnBeforeOpen := MyBeforeOpen;
(aDataset as IDAServerDataset).OnAfterOpen := MyAfterOpen;

aCommand.OnBeforeExecute := MyBeforeExecute;
aCommand.OnAfterExecute := MyAfterExecute;

in this events you can log SQL, time stamps, etc

11

It looks like the OnBeforeGetDatasetData does not get called for custom GetDataCall functions
So I assume we add our logging directly in our own server call in this case.
Do we have all the SQL traffic then or are there other cases where the events aren’t triggered

12

Hi,

For custom GetDataCall functions you also should assign OnBeforeOpen/OnAfterOpen events in your custom functions.