HangFire – SQLServer – “Lock Timeouts”

Background

When running an Application that relies on SQL Server has a backend it is a good idea to profile the application.

Profiling Tools

We use SQL Server Activity Monitor, Extended Events, and SQL Server Profiler to do so.

Activity Monitor

Image

 

Explanation

  1. Resource Waits
    • Lock = 46742
    • Network I/O = 2429
    • Backup = 1467
    • Buffer I/O = 1151
    • Logging = 705
    • Buffer Latch = 216

 

Extended Events

Live Data

Image

 

Tabulate

Field Value
 sql_text (@queues1 nvarchar(4000))
delete top (1) JQ output DELETED.Id, DELETED.JobId, DELETED.Queue
from [HangFire].JobQueue JQ with (readpast, updlock, rowlock, forceseek)
where Queue in (@queues1)

 

 

Explanation

  1. Fetch data from HangFire.JobQueue
  2. Hint
    • Hint Locks
      • readpast
        • If another session has the row locked, then skip it and go on to the next one
      • updlock
        • Request an Update Lock
      • rowlock
        • The lock granularity should be Row
      • forceseek
        • Seek rather than scan

Findings

  1. In an hour, 60 Minutes, session
    • We identified the following errors
      • error_reported=12
      • lock_timeout=78

TroubleShooting

Query

The identified query

(@queues1 nvarchar(4000))
delete top (1) JQ output DELETED.Id, DELETED.JobId, DELETED.Queue
from [HangFire].JobQueue JQ with (readpast, updlock, rowlock, forceseek)
where Queue in (@queues1)

is used to poll the Queue.

By default it runs 15 seconds.

 

Remediation

Polling Interval

Increase Pooling Interval

Configuration

app.config
   <appSettings>
   
    <add key="maxDurationInMinutes" value="60" />

    <add key="queuePollInterval" value="60" />
		
  </appSettings>

c# – Read Configuration file

Read queuePollInterval entry from App.Config file


static private void getAppConfigQueuePollInterval()
{
	
	String strQueuePollInterval;
	bool    bRC = false;
	
	
	if (ConfigurationManager.AppSettings["queuePollInterval"] != null)
	{
		
		strQueuePollInterval = ConfigurationManager.AppSettings["queuePollInterval"];
		
		try
		{
			bRC = Int32.TryParse(strQueuePollInterval, out iQueuePollInterval);
			
			Console.WriteLine("queuePollInterval :- " + strQueuePollInterval);					
			
		}
		catch			
		{
		
		}
		
	} //if (ConfigurationManager.AppSettings["queuePollInterval"] != null)
	
} //getAppConfigQueuePollInterval()

c# – Change Polling Interval from default of 15 seconds to value indicated in configuration file

Read queuePollInterval entry from App.Config file



SqlServerStorageOptions optSqlServerStorageOptions = new SqlServerStorageOptions();
{

   if (iQueuePollInterval != queuePollIntervalDefault)
   {
		
	//Documentation Configuration Using SQL Server
	//http://docs.hangfire.io/en/latest/configuration/using-sql-server.html
	//QueuePollInterval = TimeSpan.FromSeconds(15) // Default value
	optSqlServerStorageOptions.QueuePollInterval
		= TimeSpan.FromSeconds(iQueuePollInterval);
			
   }	
	
};
		
GlobalConfiguration.Configuration.UseSqlServerStorage
(
	  connectionStringHFID
	, optSqlServerStorageOptions
);

 

Results – Output

Results – Extended Events

Interpretation

We reduced our lockouts to 78 to 65.

And, all our tasks were still completed successfully.

 

Source Control

GitHub

Updated the gitHub repository and here is the URL.

 

Summary

1 test does not make a science, will run numerous tests and come back and update our post.

Changing the Polling Interval came Googling and as always test everything out.

References

  1. Hangfire keeps running SQL queries even when inactive
    Link
  2. Handling long running tasks (+ long invisibility timeout) + server restarts
    Link

HangFire – SQL Server – “Warning: Null value is eliminated by an aggregate or other SET operation.”

Background

In our first two posts, we introduced HangFire using two sample codes.

The Sample codes are :-

  1. Hangfire.io – Installation & Hello World Application
    Link
  2. Hangfire.IO – More Complex Application
    Link

 

In this Post

In this post, we will start exploring the data we captured through Extended Events.

 

Extended Event

Category :- Error Reported

Image

 

Tabulated

 Field Value
 error_number  8153
 message  Warning: Null value is eliminated by an aggregate or other SET operation.
 severity  10
 sql_text  sql_text (@count int)DECLARE @RecordsToAggregate TABLE ( [Key] NVARCHAR(100) NOT NULL, [Value] SMALLINT NOT NULL, [ExpireAt] DATETIME NULL ) SET TRANSACTION ISOLATION LEVEL READ COMMITTED BEGIN TRAN DELETE TOP (@count) C OUTPUT DELETED.[Key], DELETED.[Value], DELETED.[ExpireAt] INTO @RecordsToAggregate FROM [HangFire].[Counter] C WITH (READPAST, XLOCK, INDEX(0)) SET NOCOUNT ON ;MERGE [HangFire].[AggregatedCounter] WITH (HOLDLOCK) AS [Target] USING ( SELECT [Key], SUM([Value]) as [Value], MAX([ExpireAt]) AS [ExpireAt] FROM @RecordsToAggregate GROUP BY [Key]) AS [Source] ([Key], [Value], [ExpireAt]) ON [Target].[Key] = [Source].[Key] WHEN MATCHED THEN UPDATE SET [Target].[Value] = [Target].[Value] + [Source].[Value], [Target].[ExpireAt] = (SELECT MAX([ExpireAt]) FROM (VALUES ([Source].ExpireAt), ([Target].[ExpireAt])) AS MaxExpireAt([ExpireAt])) WHEN NOT MATCHED THEN INSERT ([Key], [Value], [ExpireAt]) VALUES ([Source].[Key], [Source].[Value], [Source].[ExpireAt]); COMMIT TRAN
 state  1
 user_defined  False

 

 

TroubleShooting

Add Test Data


set nocount on;
set XACT_ABORT on;
go

declare @commit bit
declare @strLog varchar(100)

set @commit =0
set @commit =1

begin tran

	insert into [HangFire].[Counter]
	(
		  [Key]
		, [Value]
		, [ExpireAt]
	)
	select
		1
		, rand() * 100
		, null --rand() * 1000
	union all
	select
		2
		, rand() * 100
		, null --rand() * 1000

	select top 5 *
	from   [HangFire].[Counter] C 


while (@@trancount > 0)
begin

	if (@commit =1)
	begin

		print 'commit'
		commit tran;

	end
	else
	begin

		print 'rollback'
	
		rollback tran;
	
	end

end
go


Original Code

Script


declare @count int

set @count = 10


DECLARE @RecordsToAggregate TABLE 
(  
	   [Key] NVARCHAR(100) NOT NULL
	,  [Value] SMALLINT NOT NULL
	,  [ExpireAt] DATETIME NULL 
)  
SET TRANSACTION ISOLATION LEVEL READ COMMITTED 

BEGIN TRAN  

	DELETE TOP (@count) C 
	OUTPUT DELETED.[Key], DELETED.[Value], DELETED.[ExpireAt] 
	INTO @RecordsToAggregate 
	FROM [HangFire].[Counter] C WITH (READPAST, XLOCK, INDEX(0))  
	
	SET NOCOUNT ON  
	;MERGE [HangFire].[AggregatedCounter] WITH (HOLDLOCK) AS [Target] 
	USING 
	(  
		SELECT 
				  [Key]
				, SUM([Value]) as [Value]
				, MAX([ExpireAt]) AS [ExpireAt] 

		FROM @RecordsToAggregate  

		GROUP BY 
				[Key]

	) AS [Source] 
	(
		  [Key]
		, [Value]
		, [ExpireAt]
	) 
		ON [Target].[Key] = [Source].[Key] 
		
	WHEN MATCHED THEN 
		UPDATE SET   
				   [Target].[Value] = [Target].[Value] + [Source].[Value]
				,  [Target].[ExpireAt] = 
		(
				SELECT MAX([ExpireAt]) 
				FROM 
				(
					VALUES 
					  ([Source].ExpireAt)
					, ([Target].[ExpireAt])
				) 
				AS MaxExpireAt
				(
					[ExpireAt]
				)
		) 
				
	WHEN NOT MATCHED THEN 
		INSERT ([Key], [Value], [ExpireAt]) 
		VALUES ([Source].[Key], [Source].[Value], [Source].[ExpireAt])
		;  
		
--COMMIT TRAN 
ROLLBACK TRAN

Output

Image


Textual

Warning: Null value is eliminated by an aggregate or other SET operation.

 

Revised Code

Script


set nocount on;
set XACT_ABORT on;

declare @count int

set @count = 10


DECLARE @RecordsToAggregate TABLE 
(  
	   [Key] NVARCHAR(100) NOT NULL
	,  [Value] SMALLINT NOT NULL
	,  [ExpireAt] DATETIME NULL 
)  
SET TRANSACTION ISOLATION LEVEL READ COMMITTED 

BEGIN TRAN  

	DELETE TOP (@count) C 
	OUTPUT DELETED.[Key], DELETED.[Value], DELETED.[ExpireAt] 
	INTO @RecordsToAggregate 
	FROM [HangFire].[Counter] C WITH (READPAST, XLOCK, INDEX(0))  
	
	SET NOCOUNT ON  
	;MERGE [HangFire].[AggregatedCounter] WITH (HOLDLOCK) AS [Target] 
	USING 
	(  
		SELECT 
				  [Key]
				, SUM([Value]) as [Value]
				-- dadeniji - when ExpiryAt is null, replace with 1900-01-01
				--, MAX([ExpireAt]) AS [ExpireAt] 
				, MAX(isNull([ExpireAt], '1900-01-01')) AS [ExpireAt] 

		FROM @RecordsToAggregate  

		GROUP BY 
				[Key]

	) AS [Source] 
	(
		  [Key]
		, [Value]
		, [ExpireAt]
	) 
		ON [Target].[Key] = [Source].[Key] 
		
	WHEN MATCHED THEN 
		UPDATE SET   
				   [Target].[Value] = [Target].[Value] + [Source].[Value]
				,  [Target].[ExpireAt] = 
		(
				SELECT MAX([ExpireAt]) 
				FROM 
				(
					VALUES 
					  ([Source].ExpireAt)
					, ([Target].[ExpireAt])
				) 
				AS MaxExpireAt
				(
					[ExpireAt]
				)
		) 
				
	WHEN NOT MATCHED THEN 
		INSERT ([Key], [Value], [ExpireAt]) 
		VALUES ([Source].[Key], [Source].[Value], [Source].[ExpireAt])
		;  
		
--COMMIT TRAN 
ROLLBACK TRAN

The basic change is us replacing

with

Hangfire.IO – More Complex Application

Background

With our first Application out of the way, let us develop a slightly more involved console App.

Why?

Why such a fascination with HangFire.IO?

One of the tools that we use to monitor SQL Server is Sql Server Management Studio – Activity Monitor.

SQL Server Management Studio ( SSMS )

Activity Monitor

Image

Explanation

  1. delete top (1) from [HangFire].JobQueue with (readpast, updlock, rowlock)
    output DELETED.Id, DELETED.JobId, DELETED.Queue
    where (FetchedAt is null or FetchedAt < DATEADD(second, @timeout, GETUTCDATE()))
    and Queue in (@queues1)

    • 286 per minute
  2. update [HangFire].Server set LastHeartbeat = @now where Id = @id
    • 48 per minute

 

Lab

Data Model

Outline

We have two tables, homework.task and homework.taskDetail.

The homework.task will have the following columns

  1. taskID
  2. taskLabel
  3. interval
  4. cronExpression

And, the homework.taskDetail column will have

  1. taskID
  2. processedCount

The application will store task information in the homework.task table.

Based on time schedule, we increment the processedCount column in the homework.taskDetail table.

 

Database Diagram

SQL Script

Table

Table – homework.task


if schema_id('homework') is null
begin

	exec('create schema [homework] authorization [dbo]')


end
go

if object_id('[homework].[task]') is null
begin

	create table [homework].[task]
	(

		  [taskID]			int not null
		, [taskLabel]		varchar(60) not null
		, [interval]		int not null

		, [cronExpression]  varchar(60) not null

		, [dateAdded]		datetime not null
			constraint [constraintHWTaskDefaultDateAdded] 
				default getdate()

		, [dateUpdated]		datetime null

		, constraint [PK_HWTask] primary key
			(
				[taskID]
			)
			 			
	)

end
go



 

Table – homework.taskDetail


if schema_id('homework') is null
begin

	exec('create schema [homework] authorization [dbo]')

end
go

if object_id('[homework].[taskDetail]') is null
begin

	create table [homework].[taskDetail]
	(

		  [taskID]			int not null
		
		, [processedCount]  int not null

		, [dateAdded]		datetime not null
			constraint [constraintHWTaskDetailDefaultDateAdded] 
				default getdate()

		, [dateUpdated]		datetime null

		, constraint [PK_HWTaskDetail] primary key
			(
				[taskID]
			)

		, constraint [FK_HWTaskDetail] foreign key
			(
				[taskID]
			)
			references [homework].[task]
			(
				[taskID]
			)
			 			
	)


end
go



Stored Procedure

SP – homework.ups_taskInit



if schema_id('homework') is null
begin

	exec('create schema [homework] authorization [dbo]')


end
go


if object_id('[homework].[usp_taskInit]') is null
begin

	exec('create procedure [homework].[usp_taskInit] as ')


end
go

alter procedure [homework].[usp_taskInit]
as

begin

	set nocount on;
	set XACT_ABORT on;

	truncate table [homework].[taskDetail]
	
	delete from [homework].[task]

end
go



 

SP – homework.ups_taskAdd


if schema_id('homework') is null
begin

	exec('create schema [homework] authorization [dbo]')


end
go

if object_id('[homework].[usp_taskAdd]') is null
begin

	exec('create procedure [homework].[usp_taskAdd] as ')


end
go

alter procedure [homework].[usp_taskAdd]
	  @taskID		   int 
	, @taskLabel	   varchar(60)
	, @interval		   int 

	, @cronExpression  varchar(60)

as

begin

	set nocount on;
	set XACT_ABORT on;

	MERGE [homework].[task] AS tblTarget
    USING 
			(
				SELECT 
						  [taskID] = @taskID
						, [taskLabel] = @taskLabel
						, [interval] = @interval
						, [cronExpression] = @cronExpression
						, [dateAdded] = getdate()
			) AS tblSource
	ON 
			(
				    (tblTarget.taskID = tblSource.taskID )
			)
	WHEN MATCHED THEN
    UPDATE 
	SET 
		  tblTarget.[taskLabel] = tblSource.[taskLabel]
		, [interval]= tblSource.[interval]
		, [cronExpression] = tblSource.[cronExpression]
		, tblTarget.[dateUpdated] = getdate()

	WHEN NOT MATCHED BY TARGET THEN
		INSERT 
		(
			  [taskID]
			, [taskLabel]
			, [interval]
			, [cronExpression]
			, [dateAdded]
		)
		VALUES 
		(
			  [taskID]
			, [taskLabel]
			, [interval]
			, [cronExpression]
			, [dateAdded]

		)
	
	;
end
go




SP – homework.ups_taskDetailAdd



if schema_id('homework') is null
begin

	exec('create schema [homework] authorization [dbo]')


end
go

if object_id('[homework].[usp_taskDetailAdd]') is null
begin

	exec('create procedure [homework].[usp_taskDetailAdd] as ')


end
go

alter procedure [homework].[usp_taskDetailAdd]
	  @taskID		   int 

as

begin

	set nocount on;
	set XACT_ABORT on;

	MERGE [homework].[taskDetail] AS tblTarget
    USING 
			(
				SELECT [taskID] = @taskID
			) AS tblSource
	ON 
			(
				    (tblTarget.taskID = tblSource.taskID )
			)
	WHEN MATCHED THEN
    UPDATE 
	SET 
		  tblTarget.[processedCount] = isNull(tblTarget.[processedCount], 0) + 1
		, tblTarget.[dateUpdated] = getdate()

	WHEN NOT MATCHED BY TARGET THEN
		INSERT 
		(
			  [taskID]
			, [processedCount]
		)
		VALUES 
		(
			  [taskID]
			, 1
		)
	
	;

end
go



Function

Function – homework.itvf_taskDetail


if schema_id('homework') is null
begin

	exec('create schema [homework] authorization [dbo]')


end
go

if object_id('[homework].[itvf_taskDetail]') is null
begin

	exec('create function [homework].[itvf_taskDetail]() returns table return ( select [shell] = 1/0 ) ')


end
go

alter function [homework].[itvf_taskDetail]()
returns TABLE
return
(
	select	
	
			  tblT.[taskID]
			, tblT.[taskLabel]
			, tblT.[interval]
			, tblT.[cronExpression]

			, tblTD.[processedCount]
			, tblTD.[dateAdded]
			, tblTD.[dateUpdated]

	from    [homework].[task] tblT

	left outer join [homework].[taskDetail] tblTD

		on tblT.[taskID] = tblTD.[taskID]

)
go


C# Code


using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using System.Threading;

using System.Data;
using System.Data.SqlClient;
using System.Configuration;

using Hangfire;
using Hangfire.SqlServer;


namespace consoleApp
{
    class Program
    {
		static Thread  t;
		static DateTime dtStartTime;
		static DateTime dtCurrent;
		static TimeSpan tsElapsed;
		static String strLog;

		static DateTime dtExpectedEndTS;
			
		const int MAX_TIME_ELAPSED_MINUTES = 60;
		
		const string FORMAT_MAX_TIME_ELAPSED = "Exiting after {0} seconds";
		const string FORMAT_CRONTAB_DISPLAY = "TASK ID {0}, CRON EXPRESSION {1}";
		
		static int iMaxDurationInMinutes = MAX_TIME_ELAPSED_MINUTES ;
			
		// 1 second
		static TimeSpan	tsPeriodicCheck = new TimeSpan(0, 0, 1);
		
		static public bool IsCancelled { get; set; } 

		const String connectionStringDemoID = "connectionStringDemo";
		static String conStringDemo = null;
			
		const String connectionStringHFID = "connectionStringHF";
		
		static DateTime dtStartTS = (DateTime.Now);
			
		static String dtStartTSAsString = (dtStartTS).ToString(@"hh\:mm\:ss"); 

			
        static void Main(string[] args)
        {
			
			getDBConnectionString();
			
			getAppConfig();
			
			IsCancelled = false;
			
			//Instanciate Thread
			t = new Thread(threadBackgroundJobScheduler);
			
			//Start Thread
			t.Start();
		
			Console.WriteLine("Hangfire Server started.");			
			
			Console.WriteLine("On Main thread, wait 30 seconds");			
			
			Thread.Sleep(30);
				
    	
			//wait for thread to finish
			if (t != null)
			{
			
				t.Join();
				
			}		
			
			
            
		}

		static void threadBackgroundJobScheduler()
		{
						
			useHangFire();
	
		}	

		static void scheduledTaskInitDB()
		{	
		
			string dbSQL = "[homework].[usp_taskInit]";
			using(SqlConnection sqlConnection = new SqlConnection(conStringDemo))
			using(SqlCommand sqlCommand = new SqlCommand(dbSQL , sqlConnection))
			{

				sqlCommand.CommandType = CommandType.StoredProcedure;    

				sqlConnection.Open();
				sqlCommand.ExecuteNonQuery();
			}

		}
		
		static void scheduledTaskIndividualDB(scheduleTask objScheduleTask )
		{	
		
			string dbSQL = "[homework].[usp_taskAdd]";
			using(SqlConnection sqlConnection = new SqlConnection(conStringDemo))
			using(SqlCommand sqlCommand = new SqlCommand(dbSQL , sqlConnection))
			{

				sqlCommand.CommandType = CommandType.StoredProcedure;    
				
				sqlCommand.Parameters.Add("@taskID", SqlDbType.Int).Value = objScheduleTask.taskID;
				sqlCommand.Parameters.Add("@taskLabel", SqlDbType.VarChar).Value = objScheduleTask.taskLabel;
				sqlCommand.Parameters.Add("@interval", SqlDbType.Int).Value = objScheduleTask.interval;
				sqlCommand.Parameters.Add("@cronExpression", SqlDbType.VarChar).Value = objScheduleTask.cronExpression;
				
				sqlConnection.Open();
				sqlCommand.ExecuteNonQuery();
			}

		}
		
        static void scheduleTaskIndividual(int id, int interval)
        {
			

			String strCronExpression;
			String taskLabel;
			scheduleTask objScheduleTask;
			String strTaskEntry;
		
			objScheduleTask = new scheduleTask(id, interval);
			taskLabel = objScheduleTask.taskLabel;
			strCronExpression = objScheduleTask.cronExpression;
		
			strTaskEntry = String.Format(FORMAT_CRONTAB_DISPLAY, taskLabel, strCronExpression);
			
			Console.WriteLine(strTaskEntry);
			
			scheduledTaskIndividualDB(objScheduleTask );
			
			RecurringJob.AddOrUpdate
				(
					  taskLabel
					, () => backgroundTask.processTask(id)
					, strCronExpression
				);
				
			
		}
		
        static void scheduleTasks()
        {
			scheduledTaskInitDB();
			
			scheduleTaskIndividual(1, 1);
			
			scheduleTaskIndividual(2, 3);
			
			scheduleTaskIndividual(3, 5);
			
			scheduleTaskIndividual(4, 10);
			
			scheduleTaskIndividual(5, 15);
			
			scheduleTaskIndividual(6, 30);
			
			scheduleTaskIndividual(7, 45);
			
			scheduleTaskIndividual(8, 60);
			
			
		}
		
        static void useHangFire()
        {

			//get Current Time
			dtStartTime = DateTime.Now;
					
            GlobalConfiguration.Configuration.UseSqlServerStorage(connectionStringHFID);
			
            using (var server = new BackgroundJobServer())
            {

		
				BackgroundJob.Schedule(() => backgroundTask.sayHello(), TimeSpan.FromSeconds(2));
				
				scheduleTasks();
				
			
				while 
				(
					IsCancelled==false
				) 
				{ 
					
					dtCurrent = DateTime.Now;

					tsElapsed = dtCurrent - dtStartTime;
				
					if (dtCurrent >= dtExpectedEndTS)
					{
						
						IsCancelled=true;
						
						strLog = String.Format(FORMAT_MAX_TIME_ELAPSED, tsElapsed.TotalSeconds);  
						
						Console.WriteLine(strLog);
						
						
						break;
						
					}
				
					//wait a little longer
					Thread.Sleep(tsPeriodicCheck); 
			
				} //while not cancelled
			
			}//using	
			

		} // useHangFire()
	 
	 
		static private void getDBConnectionString()
		{
			
			if (ConfigurationManager.ConnectionStrings[connectionStringDemoID] != null)
			{
				
				conStringDemo = ConfigurationManager.ConnectionStrings[connectionStringDemoID].ConnectionString;
			
			}
			else
			{
				 throw new System.Exception("connectionStringDemoID not found in app.config");
				
			}
			
		} //getDBConnectionString()
		

		static private void getAppConfig()
		{
			
			String strMaxDurationInMinutes;
			bool    bRC = false;

			String   dtExpectedEndTSAsString;
			
			System.TimeSpan tsDurationInMins;
			
			iMaxDurationInMinutes = MAX_TIME_ELAPSED_MINUTES;
			
			Console.WriteLine("Start Date :- " + dtStartTSAsString);
			
			
			if (ConfigurationManager.AppSettings["maxDurationInMinutes"] != null)
			{
				
				strMaxDurationInMinutes = ConfigurationManager.AppSettings["maxDurationInMinutes"];
				
				try
				{
					bRC = Int32.TryParse(strMaxDurationInMinutes, out iMaxDurationInMinutes);
				}
				catch			
				{
					iMaxDurationInMinutes = MAX_TIME_ELAPSED_MINUTES;
				}
				
				tsDurationInMins = new System.TimeSpan(0, iMaxDurationInMinutes, 0);
				
				dtExpectedEndTS = dtStartTS.Add(tsDurationInMins);
				
				dtExpectedEndTSAsString = (dtExpectedEndTS).ToString(@"hh\:mm\:ss"); 
				
				Console.WriteLine("Expected End Date :- " + dtExpectedEndTSAsString);

				
			}
			else
			{
				
				iMaxDurationInMinutes = MAX_TIME_ELAPSED_MINUTES;
				
				tsDurationInMins = new System.TimeSpan(0, iMaxDurationInMinutes, 0);
				
				dtExpectedEndTS = (DateTime.Now).Add(tsDurationInMins);
				
			}
			
		} //getAppConfig()
				
		
    } // class program
	
	
	class backgroundTask
	{
		
		static String FORMAT_DATETIME = "{0:ddd, MMM d, yyyy  hh:mm tt}";
		
		static String connectionStringDemoID = "connectionStringDemo";
		static String conStringDemo = null;
				
		
		[AutomaticRetry(Attempts = 0)]
		static public void sayHello()
		{
			
			String strTimeStamp;
			String strLog;
			
			strTimeStamp = String.Format(FORMAT_DATETIME, DateTime.Now);
			
			strLog = "At " + strTimeStamp + " ... Saying Hello";

			//Say Time
			Console.WriteLine(strLog);
		
			
		} //sayHello
		
		static private void getDBConnectionString()
		{
			
			if (conStringDemo == null)
			{
				
				
				if (ConfigurationManager.ConnectionStrings[connectionStringDemoID] != null)
				{
					
					conStringDemo = ConfigurationManager.ConnectionStrings[connectionStringDemoID].ConnectionString;
				
				}
				else
				{
					 throw new System.Exception("connectionStringDemoID not found in app.config");
					
				}
			}
			
		} //getDBConnectionString()
		
		
		[AutomaticRetry(Attempts = 0)]
		[DisableConcurrentExecution(timeoutInSeconds: 10 * 60)]
		static public void processTask(int taskID)
		{
	
			string dbSQL = "[homework].[usp_taskDetailAdd]";
			
			
			if(conStringDemo == null)
			{
				getDBConnectionString();
			}
			
			using(SqlConnection sqlConnection = new SqlConnection(conStringDemo))
			using(SqlCommand sqlCommand = new SqlCommand(dbSQL , sqlConnection))
			{

				sqlCommand.CommandType = CommandType.StoredProcedure;    
				
				sqlCommand.Parameters.Add("@taskID", SqlDbType.Int).Value = taskID;
				
				sqlConnection.Open();
				sqlCommand.ExecuteNonQuery();
			}
			
		} //processTask
		
		
	}
	
}




 

 

Run

Here is the output from running the app..

Run Output

 

SQL Track

Code


select *

from   [homework].[itvf_taskDetail]()

SQL Output

 

Source Code

GitHub

As alway posted to GitHub.

Here is the URL.

 

Summary

Will come back and share our findings in terms of reliability and performance.

It will be a bit long and so will save it for another post.

Reference

  1. How to write your first multi-threaded application with c#
    Link
  2. How do I get the time difference between two DateTime objects using C#?
    Link

 

Hangfire.io – Installation & Hello World Application

Background

One of the applications that we are hosting relies on Hangfire to perform some background processing.

It is time to get smart quick!

What Are we going To Do

We will take the minimalist approach.

Checklist

  1. No Visual Studio IDE.
  2. Just an editor, notepad++
  3. Nuget, Packet Manager
  4. Hangfire packages
  5. Validate that MSBuild is installed
    • If not download and install it
  6. Create Source Files
    • Simple File
    • Build File
  7. Invoke Build
  8. Trial Runs

Installation

Hangfire is based on Microsoft .Net and we can install it by laying down Nuget and Hangfire specific packages.

Nuget

Outline

  1. Download nuget

 

Download nuget

Download nuget.exe from here.

The current version is 3.5.

And, we reached for the file under the “Windows x86 CommandLine” section.

 

Hangfire

Outline

  1. Download Hangfire packages
    • Install Hangfire.core
    • Install Hangfire.sqlserver

hangfire.core

Code


rem installHangFireCore

set _folderNuget=N:\downloads\nuget\v3.5\
set _logger=N:\downloads\wtee\wtee.exe

if not exist log mkdir log

%_folderNuget%\nuget.exe install Hangfire.Core | %_logger% log\Hangfire.core.log

Output

hangfire.SqlServer

Code


rem installHangFire.SqlServer

set _folderNuget=N:\downloads\nuget\v3.5\
set _logger=N:\downloads\wtee\wtee.exe

if not exist log mkdir log

%_folderNuget%\nuget.exe install Hangfire.SqlServer | %_logger% log\Hangfire.sqlserver.log

Output

 

Files

 

Package Description Links  Files
 Hangfire.core Core components for Hangfire (background job system for ASP.NET applications). Link (Nuget Gallery )  a) Hangfire.Core
b) Owin
c) Newtonsoft.Json
 Hangfire.sqlServer  SQL Server 2008+ (including Express), SQL Server LocalDB and SQL Azure storage support for Hangfire (background job system for ASP.NET applications).  Link ( Nuget Gallery )  a) Hangfire.Core
b) Hangfire.SqlServer
c) Owin
d) Microsoft.Owin
e) Microsoft.Owin.Host.SystemWeb
f) Newtonsoft.Json

 

 

 

MS Build

Download Build

Microsoft Build Tools 2015

Download Site

Download MSBuild from here.

Install
Welcome

Installing

Setup Completed

 

Source Code

Source File

Source File

hfSimple.cs

Code

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;

using Hangfire;
using Hangfire.SqlServer;


namespace consoleApp
{
    class Program
    {
        static void Main(string[] args)
        {
            useHangFire();
        }


        static void useHangFire()
        {


            GlobalConfiguration.Configuration.UseSqlServerStorage("connectionString");
			
			
            using (var server = new BackgroundJobServer())
            {

		
				BackgroundJob.Schedule(() => backgroundTask.sayHello(), TimeSpan.FromSeconds(2));
				
				RecurringJob.AddOrUpdate("IDStopClock", () => backgroundTask.sayTime(), Cron.Minutely);
				
				Console.WriteLine("Hangfire Server started. Press any key to exit...");			
				
                Console.ReadKey();
            }
			

	 }
	 
	 


    } // class program
	
	
	class backgroundTask
	{
		
		static String FORMAT_DATETIME = "{0:ddd, MMM d, yyyy  hh:mm tt}";
		
		
		static long lIteration = 0;
		

		static public void sayHello()
		{
			
			String strTimeStamp;
			String strLog;
			
			strTimeStamp = String.Format(FORMAT_DATETIME, DateTime.Now);
			
			strLog = "At " + strTimeStamp + " ... Saying Hello";

			//Say Time
			Console.WriteLine(strLog);
		
			
		} //sayHello
		
		[AutomaticRetry(Attempts = 5)]
		[DisableConcurrentExecution(timeoutInSeconds: 10 * 60)]
		static public void sayTime()
		{
			
			String strTimeStamp;
			String strLog;
			
			strTimeStamp = String.Format(FORMAT_DATETIME, DateTime.Now);
			
			strLog = lIteration + ")" + strTimeStamp;

			//Say Time
			Console.WriteLine(strLog);
		
			lIteration = lIteration + 1;
			
		} //sayTime
		
		
	}
	
}


 

Configuration

App.config

Code


<?xml version="1.0" encoding="utf-8" ?>
<configuration>
    <startup> 
        <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.5.2" />
    </startup>

  <connectionStrings>
    <add name="connectionString" connectionString="Trusted_Connection=Yes;Server=.;Application Name=hangfire;database=labHangFire;" />

  </connectionStrings>
</configuration>
Explanation
  1. ConnectionStrings
    • Trusted_Connection=Yes
      • Integrated Security; as opposed to SQL Server username/password combination
    • Application Name
      • Given name for the Application
    • database
      • Name of the database on the specified SQL Instance

 

Build Files

Build Configuration File

hfsimple.csproj

Code

<?xml version="1.0" encoding="utf-8"?>
<Project ToolsVersion="14.0" DefaultTargets="Build" xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
  <Import Project="$(MSBuildExtensionsPath)\$(MSBuildToolsVersion)\Microsoft.Common.props" Condition="Exists('$(MSBuildExtensionsPath)\$(MSBuildToolsVersion)\Microsoft.Common.props')" />
  <PropertyGroup>
    <Configuration Condition=" '$(Configuration)' == '' ">Debug</Configuration>
    <Platform Condition=" '$(Platform)' == '' ">AnyCPU</Platform>
    <ProjectGuid>{2957BCCD-03ED-4FF3-868D-8A07226516D7}</ProjectGuid>
    <OutputType>Exe</OutputType>
    <AppDesignerFolder>Properties</AppDesignerFolder>
    <RootNamespace>hfsimple</RootNamespace>
    <AssemblyName>hfsimple</AssemblyName>
    <TargetFrameworkVersion>v4.5.2</TargetFrameworkVersion>
    <FileAlignment>512</FileAlignment>
    <AutoGenerateBindingRedirects>true</AutoGenerateBindingRedirects>
  </PropertyGroup>
  <PropertyGroup Condition=" '$(Configuration)|$(Platform)' == 'Debug|AnyCPU' ">
    <PlatformTarget>AnyCPU</PlatformTarget>
    <DebugSymbols>true</DebugSymbols>
    <DebugType>full</DebugType>
    <Optimize>false</Optimize>
    <OutputPath>bin\Debug\</OutputPath>
    <DefineConstants>DEBUG;TRACE</DefineConstants>
    <ErrorReport>prompt</ErrorReport>
    <WarningLevel>4</WarningLevel>
  </PropertyGroup>
  <PropertyGroup Condition=" '$(Configuration)|$(Platform)' == 'Release|AnyCPU' ">
    <PlatformTarget>AnyCPU</PlatformTarget>
    <DebugType>pdbonly</DebugType>
    <Optimize>true</Optimize>
    <OutputPath>bin\Release\</OutputPath>
    <DefineConstants>TRACE</DefineConstants>
    <ErrorReport>prompt</ErrorReport>
    <WarningLevel>4</WarningLevel>
  </PropertyGroup>
  <ItemGroup>
  
    <Reference Include="Hangfire.Core">
      <HintPath>package\Hangfire.Core.1.6.12\lib\net45\Hangfire.Core.dll</HintPath>
      <Private>True</Private>
    </Reference>
	
	<Reference Include="Hangfire.SqlServer">
	  <HintPath>package\Hangfire.SqlServer.1.6.12\lib\net45\Hangfire.SqlServer.dll</HintPath>
	  <Private>True</Private>
	</Reference>
	<Reference Include="Newtonsoft.Json">
      <HintPath>package\Newtonsoft.Json.5.0.1\lib\net45\Newtonsoft.Json.dll</HintPath>
      <Private>True</Private>
    </Reference>
    
	<Reference Include="System" />
    <Reference Include="System.Core" />
    <Reference Include="System.Xml.Linq" />
    <Reference Include="System.Data.DataSetExtensions" />
    <Reference Include="Microsoft.CSharp" />
    <Reference Include="System.Data" />
    <Reference Include="System.Net.Http" />
    <Reference Include="System.Xml" />
  
  </ItemGroup>
  
  <ItemGroup>
    <Compile Include="hfSimple.cs" />
    <Compile Include="Properties\AssemblyInfo.cs" />
  </ItemGroup>
  
  <ItemGroup>
    <None Include="App.config" />
    <None Include="packages.config" />
  </ItemGroup>
  
  <Import Project="$(MSBuildToolsPath)\Microsoft.CSharp.targets" />
  <!-- 
  
	  To modify your build process, add your task inside one of the targets below and uncomment it. 
      Other similar extension points exist, see Microsoft.Common.targets.
	
	  <Target Name="BeforeBuild">
	  </Target>
	  <Target Name="AfterBuild">
	  </Target>
	  
  -->
</Project>

Build Script

buildhf.cmd

Code

set "_appFolder=C:\Program Files (x86)\MSBuild\14.0\Bin\"

"%_appFolder%\msbuild" hfSimple.csproj /t:Rebuild 

 

Usage

Sample Run

Explanation

  1. Each minute, we display the current time on the console

 

Review

SQL Server

Upon initial run, Hangfire creates its tables.

Object Explorer

Image

Explanation

  1. Objects / Tables created

 

Errors

Error Signature Error Sample Resolution
Unhandled Exception: System.Data.SqlClient.SqlException: Cannot open database Unhandled Exception: System.Data.SqlClient.SqlException: Cannot open database “labHangFire” requested by the login. The login failed.
Login failed for user ‘dadeniji’.
Create database referenced for hangfire

 

 

Source Code Version Control

GitHub

DanielAdeniji/hangfireConsoleSimple
Link

Summary

What we have is a simple, console application.

In later posts, we will dig more into profiling.

Extended Events – Lock Timeouts

Background

Back to Extended Events, let us start looking at what we have been collecting.

 

Lock Timeouts

We are noticing quite a bit of lock timeouts, and so created an Extended Event Trace to collect them.

Outline

Saved events are saved in binary files.

We need the SQL Engine to extract the compressed XML files and parse its data into elements and attributes.

Query

Table Value Function – extendedEvent.itvf_EventsReview

Script


use master
go

if schema_id('extendedEvent') is null
begin

	exec('create schema [extendedEvent] authorization [dbo]');

end
go


/*

	drop function [extendedEvent].[itvf_EventsReviewFull]

*/

if object_id('[extendedEvent].[itvf_EventsReview]') is null
begin

	exec('create function [extendedEvent].[itvf_EventsReview]() returns table return select [shell] = 1/0 ')

end
go

alter function [extendedEvent].[itvf_EventsReview] 
(
	  @folderXEL sysname
	, @folderXEM sysname = null
	, @maxNumberofRecords int = 1E6
)
returns table

return

	with cte
	(
		  [objectName] 
		, [eventData] 
	)
	as
	(
		SELECT
 
			  [objectName] = tblFNXE.[object_name]
			, [eventData] = cast(tblFNXE.event_data as xml)
 
		FROM sys.fn_xe_file_target_read_file
			(
				  @folderXEL + '\' + '*.xel'
				, isNull(@folderXEM, @folderXEL) + '\' + '*.xem'
				, null
				, null
		   ) tblFNXE
	)
	select top ( 
				  @maxNumberofRecords
			   )
 
			  [objectName] = isNull(cte.[objectName], '')
 
			, [eventData] = cast(cte.eventData as xml)
			--, [XMLFragment] = [event].[node].query('.')
 
			--timestamp on root node
			--, [tsAsDateTimeUTC] 
			--	= [event].[node].value('@timestamp', 'datetimeoffset')     
 
			--collect system time
			, [systemTSAsValueUTC]
				 = cast
				   (
						cast
						(
								([event].[node].query('/event/action[@name="collect_system_time"]/value/text()'))
									as varchar(60)
						)
						as datetime
					)

			-- collect system time to locale time
			, [systemTSAsLocale] 
				 = cast
				   (
						cast
						(

							dateadd
							(
								 minute
							   , [dbo].[udfn_getTimeDifferenceBetweenUTCAndSystemTimeInMinutes]() * -1
 							   , cast
								 (
								   cast
								   (
									  ([event].[node].query('/event/action[@name="collect_system_time"]/value/text()')) 
									   as varchar(60)
								   )
								   as datetime
								)
							)
							as varchar(40)
					)
					as datetime
				)

			--is system
			, [isSystem] 
				= case 
						cast
						(
							([event].[node].query('/event/action[@name="is_system"]/value/text()'))
							as varchar(5)
                        )
						when 'true' then 'Y'
						else 'N'
                  end
				
			--session ID
			, [sessionID] 
				= cast
					(	
						cast
						(
							[event].[node].query('/event/action[@name="session_id"]/value/text()')
							as varchar(60)
						)
						as int
					)

 
			-- client Host Name
			, [clientHostName] 
				= cast
					(
						[event].[node].query('/event/action[@name="client_hostname"]/value/text()')
						as sysname
					)
 
			-- username
			, [username] 
				--= [event].[node].query('/event/action[@name="username"]/value/text()')
				= cast
					(
						[event].[node].query('/event/action[@name="session_server_principal_name"]/value/text()')
						as sysname
					)

			-- client App Name
			, [clientAppName] 
				= cast
					(
						[event].[node].query('/event/action[@name="client_app_name"]/value/text()')
						as sysname
					)
 
			-- SQL Text
			, [sqlText] 
				= cast
					(
						[event].[node].query('/event/action[@name="sql_text"]/value/text()')
						as nvarchar(max)
					)

			, [errorNumber]
				 = cast
					(
						[event].[node].value('(/event/data[@name="error_number"]/value)[1]', 'int')
						as int
					)

			, [result]
				 = cast
					(
						[event].[node].value('(/event/data[@name="result"]/text)[1]', 'nvarchar(30)')
						 as nvarchar(30)
					)

			-- Message
			, [message] 
				= cast
					(
						[event].[node].value('(/event/data[@name="message"]/value)[1]', 'nvarchar(4000)')
						as nvarchar(600)
					)
 
	from   cte
 
	cross apply cte.eventData.nodes(N'//event') event(node)


go


grant select on [extendedEvent].[itvf_EventsReview] to [public]
go

Invoke


select *

from   [extendedEvent].[itvf_EventsReview] 
	(
	    'C:\Assist\ExtendedEvents\TraceFiles\Prod'
	  , 'C:\Assist\ExtendedEvents\TraceFiles\Prod'
	  , default
       )

 

Output

lockTimeouts_20170411_0802PM

 

Persist Data

It is a lot less expensive to parse the XML data once and store the extracted data into an actual SQL Server table.

All queries will thereafter query the relational table.

Relational Table

extendedEvent.events

Create Table

if schema_id('extendedEvent') is null
begin

	exec('create schema [extendedEvent] authorization [dbo]; ')

end
go

if object_id('[extendedEvent].[events]') is null
begin

	create table [extendedEvent].[events]
	(

		  [id]							   bigint		not null identity(1,1)

		, [objectName]                     nvarchar(120) not null 
		, [eventData]                      xml not null 
		, [systemTSAsValueUTC]             datetime not null 
		, [systemTSAsLocale]               datetime not null 
		, [isSystem]                       varchar(1)  null 
		, [sessionID]                      int not null 
		, [clientHostName]                 sysname not null 
		, [username]                       sysname not null 
		, [clientAppName]                  sysname not null 
		, [sqlText]                        nvarchar(max)  not null 
		, [errorNumber]                    int null 
		, [result]                         nvarchar(600)  null 
		, [message]                        nvarchar(1200) null 


	)

end
go

if not exists
(
	select *
	from   sys.objects tblSO
	where   tblSO.parent_object_id = object_id('[extendedEvent].[events]')
)
begin

	alter table [extendedEvent].[events]
		add constraint [PK_ExtendedEvent.events]
			primary key
				(
					  [systemTSAsLocale] 
					, [objectName]
					, [sessionID]
					, [id]
				)
end
go

if not exists
(
	select *
	from   sys.indexes tblSI
	where  tblSI.object_id = object_id('[extendedEvent].[events]')
	and    tbLSI.[name] = 'INDX_ObjectName'
)
begin

	create index [INDX_ObjectName]
	on [extendedEvent].[events]
	(
		  [objectName]
		, [isSystem]
	)

end
go



Load Table

set nocount on;
go

use [AdminDB]
go

truncate table [extendedEvent].[events]
go

insert into [extendedEvent].[events]
(
       [objectName]
      ,[eventData]
      ,[systemTSAsValueUTC]
      ,[systemTSAsLocale]
      ,[isSystem]
      ,[sessionID]
      ,[clientHostName]
      ,[username]
      ,[clientAppName]
      ,[sqlText]
      ,[errorNumber]
      ,[result]
      ,[message]
)
select 
       [objectName]
      ,[eventData]
      ,[systemTSAsValueUTC]
      ,[systemTSAsLocale]
      ,[isSystem]
      ,[sessionID]
      ,[clientHostName]
      ,[username]
      ,[clientAppName]
      ,[sqlText]
      ,[errorNumber]
      ,[result]
      ,[message]
from   [master].[extendedEvent].[itvf_EventsReview] 
	(
		  'C:\Assist\ExtendedEvents\TraceFiles\Prod'
		, 'C:\Assist\ExtendedEvents\TraceFiles\Prod'
		, default
	)

Analyze Data
Script
; with cteCategory
as
(
	select 
			  tblEE.objectName
			, [count] = count(*)

	from   [extendedEvent].[events] tblEE

	group by
			  tblEE.objectName
)
select 
		  tblEE.objectName
		, tblEE.isSystem
		, tblEE.[sqlText]
		, tblEE.[message]		    
		, [count] = count(*)
		, [%] =
				cast
				(
					(
						  ( count(*) * 100)
						/ tblEEC.[count]
					)
					as decimal(6, 2)
				)
			

from   [extendedEvent].[events] tblEE

inner join cteCategory tblEEC

	on tblEE.[objectName] = tblEEC.[objectName]

group by
		  tblEE.objectName
		, tblEE.isSystem
		, tblEE.[sqlText]    
		, tblEE.[message]
		, tblEEC.[count]

order by
	      count(*) desc
		, tblEE.objectName
		, tblEE.isSystem
		, tblEE.[sqlText]    

Output

Explanation
  1. Lock TimeOut
    • 60% of the timeouts are system timeouts
      • They have is System=true
      • Username is sa
    • 36% of the timeouts are user and application timeouts attributed to HangFire
      • An easy way to perform background processing in .NET and .NET Core applications.
        No Windows Service or separate process required.

        Backed by persistent storage. Open and free for commercial use.
        Link
  2. Error Reported
    • Cannot drop the table ‘#CourseSequence’, because it does not exist or you do not have permission.
    • Invalid or Expired Session: nvjpqa3efiy3nrajzhpf1kud
    • The query processor ran out of internal resources and could not produce a query plan.
      This is a rare event and only expected for extremely complex queries or queries that reference a very large number of tables or partitions. Please simplify the query. If you believe you have received this message in error, contact Customer Support Services for more information.