Creating alerts for custom errors with auditing and Log Analytics

Errors are an inherent part of any application. As a database professional managing an Azure SQL Managed Instance, you may be interested in understanding when specific errors occur and how to leverage user-generated errors to respond swiftly when particular scenarios arise.

On this post we will see how we can setup alerts for scenarios like query blocking and long open transactions.

This will be an extend of what is described on How to setup alerts for deadlocks using Log Analytics | Microsoft Community Hub

Step 1 - Setup Log Analytics and auditing

Follow steps 1, 2, 3 and 4 described on How to setup alerts for deadlocks using Log Analytics | Microsoft Community Hub

Step 2 - Create a table to save the details of the blocking chain / long open transaction

Getting an alert itself is not useful if you don`t have a way of getting details for later analysis.

Create the table on a database of your choice.

If you are interested on blocking:

CREATE TABLE [dbo].[blocking_report] (
	[DateTime] [datetime] NULL
	,[HeadBlocker] [varchar](1) NOT NULL
	,[SessionID] [smallint] NOT NULL
	,[Login] [nvarchar](128) NOT NULL
	,[Database] [nvarchar](128) NULL
	,[BlockedBy] [smallint] NULL
	,[OpenTransactions] [int] NULL
	,[Status] [nvarchar](30) NOT NULL
	,[WaitType] [nvarchar](60) NULL
	,[WaitTime_ms] [bigint] NULL
	,[WaitResource] [nvarchar](256) NULL
	,[WaitResourceDesc] [nvarchar](3072) NULL
	,[Command] [nvarchar](32) NULL
	,[Application] [nvarchar](128) NULL
	,[TotalCPU_ms] [int] NOT NULL
	,[TotalPhysicalIO_MB] [bigint] NULL
	,[MemoryUse_KB] [int] NULL
	,[LoginTime] [datetime] NOT NULL
	,[LastRequestStartTime] [datetime] NOT NULL
	,[HostName] [nvarchar](128) NULL
	,[QueryHash] [binary](8) NULL
	,[BlockerQuery_or_MostRecentQuery] [nvarchar](max) NULL
	)

If you are interested on open transactions:

CREATE TABLE [dbo].[opentransactions](
	[CapturedTime] [datetime] NOT NULL,
	[tran_elapsed_time_seconds] [int] NULL,
	[transaction_begin_time] [datetime] NOT NULL,
	[session_id] [int] NOT NULL,
	[database_name] [nvarchar](128) NULL,
	[open_transaction_count] [int] NOT NULL,
	[host_name] [nvarchar](128) NULL,
	[program_name] [nvarchar](128) NULL,
	[login_name] [nvarchar](128) NULL,
	[status] [nvarchar](30) NULL,
	[text] [nvarchar](max) NULL
) 

Step 3 - Create a SQL Agent job 

Schedule the two SQL Agent jobs using the queries below. You might be interested on schedule that runs every X amount of seconds/minutes. Describing very briefly what each query does:

• if a query is being blocked for more than 60 seconds, save the blocking chain on a table and raise an error
• if a transaction is open for more than 120 seconds, save the query details on a table and raise an error

Make the necessary adjustments according to your goals.

Query for blocking:

IF (
		SELECT count(*)
		FROM sys.dm_exec_requests
		WHERE wait_type LIKE 'LCK%'
			AND wait_time > 60000
		) > 0 -- checks for queries waiting to obtain a lock for more than 30 seconds
BEGIN
	INSERT INTO database_name.dbo.Blocking_report
	-- make sure that you change the database_name value 
	SELECT (
			SELECT getdate()
			)
		,[HeadBlocker] = CASE 
			WHEN r2.session_id IS NOT NULL
				AND (
					r.blocking_session_id = 0
					OR r.session_id IS NULL
					)
				THEN '1'
			ELSE ''
			END
		,[SessionID] = s.session_id
		,[Login] = s.login_name
		,[Database] = db_name(p.dbid)
		,[BlockedBy] = w.blocking_session_id
		,[OpenTransactions] = r.open_transaction_count
		,[Status] = s.STATUS
		,[WaitType] = w.wait_type
		,[WaitTime_ms] = w.wait_duration_ms
		,[WaitResource] = r.wait_resource
		,[WaitResourceDesc] = w.resource_description
		,[Command] = r.command
		,[Application] = s.program_name
		,[TotalCPU_ms] = s.cpu_time
		,[TotalPhysicalIO_MB] = (s.reads + s.writes) * 8 / 1024
		,[MemoryUse_KB] = s.memory_usage * 8192 / 1024
		,[LoginTime] = s.login_time
		,[LastRequestStartTime] = s.last_request_start_time
		,[HostName] = s.host_name
		,[QueryHash] = r.query_hash
		,[BlockerQuery_or_MostRecentQuery] = txt.TEXT
	FROM sys.dm_exec_sessions s
	LEFT OUTER JOIN sys.dm_exec_connections c ON (s.session_id = c.session_id)
	LEFT OUTER JOIN sys.dm_exec_requests r ON (s.session_id = r.session_id)
	LEFT OUTER JOIN sys.dm_os_tasks t ON (
			r.session_id = t.session_id
			AND r.request_id = t.request_id
			)
	LEFT OUTER JOIN (
		SELECT *
			,ROW_NUMBER() OVER (
				PARTITION BY waiting_task_address ORDER BY wait_duration_ms DESC
				) AS row_num
		FROM sys.dm_os_waiting_tasks
		) w ON (t.task_address = w.waiting_task_address)
		AND w.row_num = 1
	LEFT OUTER JOIN sys.dm_exec_requests r2 ON (s.session_id = r2.blocking_session_id)
	LEFT OUTER JOIN sys.sysprocesses p ON (s.session_id = p.spid)
	OUTER APPLY sys.dm_exec_sql_text(ISNULL(r.[sql_handle], c.most_recent_sql_handle)) AS txt
	WHERE s.is_user_process = 1
		AND (
			r2.session_id IS NOT NULL
			AND (
				r.blocking_session_id = 0
				OR r.session_id IS NULL
				)
			)
		OR blocked > 0
	ORDER BY [HeadBlocker] DESC
		,s.session_id;

	THROW 50000
		,'There are queries being blocked for more than 60 seconds'
		,1;
END

Query for open transactions:

DECLARE @count INT = (
		SELECT count(*)
		FROM sys.dm_tran_active_transactions at
		INNER JOIN sys.dm_tran_session_transactions st ON st.transaction_id = at.transaction_id
		LEFT OUTER JOIN sys.dm_exec_sessions sess ON st.session_id = sess.session_id
		LEFT OUTER JOIN sys.dm_exec_connections conn ON conn.session_id = sess.session_id
		OUTER APPLY sys.dm_exec_sql_text(conn.most_recent_sql_handle) AS txt
		WHERE DATEDIFF(SECOND, transaction_begin_time, GETDATE()) > 120 -- 120 seconds
		)

IF @count > 0
BEGIN
	INSERT INTO database_name.dbo.opentransactions -- change database_name to where the table was created
	SELECT GETDATE() AS CapturedTime
		,DATEDIFF(SECOND, transaction_begin_time, GETDATE()) AS tran_elapsed_time_seconds
		,at.transaction_begin_time
		,st.session_id
		,DB_NAME(sess.database_id) AS database_name
		,st.open_transaction_count
		,sess.host_name
		,sess.program_name
		,sess.login_name
		,sess.STATUS
		,txt.TEXT
	FROM sys.dm_tran_active_transactions at
	INNER JOIN sys.dm_tran_session_transactions st ON st.transaction_id = at.transaction_id
	LEFT OUTER JOIN sys.dm_exec_sessions sess ON st.session_id = sess.session_id
	LEFT OUTER JOIN sys.dm_exec_connections conn ON conn.session_id = sess.session_id
	OUTER APPLY sys.dm_exec_sql_text(conn.most_recent_sql_handle) AS txt
	WHERE DATEDIFF(SECOND, transaction_begin_time, GETDATE()) > 120 --120 seconds
	ORDER BY tran_elapsed_time_seconds DESC;

	THROW 50000
		,'There are open transactions for more than 120 seconds'
		,1;
END

Step 4 - Create the alert based on a Log Analytics query

Just as described on steps 6 and 7 of How to setup alerts for deadlocks using Log Analytics | Microsoft Community Hub, you can create the two separate alerts using the queries below.

For blocking:

AzureDiagnostics
| where TimeGenerated > ago(15m) //last 15 minutes 
| where LogicalServerName_s == "server_name" //server name
| where Category == "SQLSecurityAuditEvents"
| where additional_information_s contains "There are queries being blocked for more"
| project TimeGenerated, LogicalServerName_s, database_name_s, additional_information_s

For open transactions:

AzureDiagnostics
| where TimeGenerated > ago(15m) //last 15 minutes 
| where LogicalServerName_s == "server_name" //server name
| where Category == "SQLSecurityAuditEvents"
| where additional_information_s contains "There are open transactions for more than"
| project TimeGenerated, LogicalServerName_s, database_name_s, additional_information_s