SSIS 2012 fail to start – execution timed out

I’ve recently upgraded to SQL Server 2012 and created a centralized ETL server. Things were fine until I enabled the scheduled jobs. Jobs started to fail randomly after reporting the error below:

Started:  1:10:01 AM  Failed to execute IS server package because of error 0x80131904.
Description: The operation failed because the execution timed out.  Source: .Net SqlClient Data Provider  Started:  1:10:01 AM  Finished: 1:10:07 AM  Elapsed:  5.6 seconds.  The package execution failed.  The step failed.

I searched the web and found that I wasn’t the only one. Furthermore, MS has yet to release a patch for this issue. The relevant reported MS Connect post:

SSIS package fails to start – application lock timeout in SSISDB.catalog.create_execution

My environment

Name	Value
Product	Microsoft SQL Server Standard (64bit)
Operating System	Microsoft Windows NT 6.1 (7601)
Platform	NT x64
Version	11.0.3368.0
Memory	8191 (MB)
Processors	1

What I did

I started my investigation by checking dmv and ended up modifying one of the SPs in SSISDB. I know that this isn’t a good choice but did that to fix quickly.

Process Monitoring

I ran a query against sys.dm_exec_requests and got the following results. I noticed that there was a lot of blocking going on and the execution timed out error had occurred because of this.

I was able to track down that xp_userlock was being called by sp_getapplock in catalog.create_execution SP.

Index creation

Many have pointed out the problem of missing indexes on SSISDB. Phil Brammer shared a missing index creation script via SSIS 2012 – Catalog Indexing Recommendations. I was hoping this error was due to the missing indexes, so I simply applied Phil Brammer’s script instead of spending more time investigating. Unfortunately, it didn’t help and I still got an execution timed out error. At this point I thought it’d be better to use a different approach. I started to review the logic of catalog.create_execution SP thoroughly.

catalog.create_execution modification

Since I needed to fix this timeout issue in a single day, I decided to take an extreme route by modifying the catalog.create_execution SP. I will explain what I changed shortly, but first, the sys.dm_exec_requests query result. As you can see, the blocking issue has been resolved.

You can download the modified code here : [catalog].[create_execution_new].

catalog.create_execution

Looking at the big picture, this SP generates data on four tables: operations, operation_permissions, executions and execution_parameter_values.

Logic flow

The developer of this SP took a procedural and very conservative approach to ensure the following two things: first, that data don’t change until insertion to execution and execution_parameter_values and second, that there was an assurance that different error messages can be returned for each step.

Transaction	Lock	Step No	Main step	Sub Step
		1	Check if the sp(catalog.create_execution) is called using windows Authentication	Returns an error if it’s called using SQL Server Authentication.
		2	Insert data into operation table	[internal].[insert_operation]
		3	Insert data into operation_permissions table	[internal].[init_object_permissions]
T	X	4	SET TRANSACTION ISOLATION LEVEL SERIALIZABLE
T	X	5	Begin transaction
T	X	6	Start application lock	EXEC sp_getapplock @Resource = ‘MS_ISServer_Create_Execution’, @LockTimeOut= 5000, @LockMode = ‘Exclusive’
T	X	7	Get project_id and version
T	X	8	Get environment information	Get environment information using reference_id Check if there’s any discrepancy in data type or sensitivity between parameter and environment variable
T	X	9	Update operations.object_id to project_id
T	X	10	Insert data into executions table	INSERT into [internal].[executions]
T	X	11	Create key to decrypt and encrypt sensitive data	CREATE CERTIFICATE CREATE SYMMETRIC KEY
T	X	12	Insert execution_parameter_values	1) insert non-sensitive parameter doesn’t reference environment variable 2) insert sensitive parameter doesn’t reference environment variable 3) Insert records for object_type=50(instance of execution) 4) insert non-sensitive parameter referencing environment variable 5) insert sensitive parameter referencing environment variable 6) update sensitive parameter value after converting data type if it’s date, double or decimal 7) insert any missing parameter from project level object parameter 8) insert any missing parameter from package level object parameter 9) update parameter value to object_parameters.design_default_value if sensitive=0 and required=0 and value_set=0
T	X	13	close symmetric keys
T	X	14	commit

Now, the Code

I modified the original code to assure the following principals.

1. Keep SERIALIZABLE isolation level as short as possible
   • I assumed the developer wanted to guarantee that the same meta information for the package is retrieved until he finishes the data insert.
   • You don’t need to keep the SERIALIZABLE isolation level once you have necessary data
2. Take out application locking
   • I assumed the SERIALIZABLE isolation level is enough to guarantee that meta data wouldn’t be changed during retrieval.
3. Keep transactions as short as possible
   • A transaction is used only when DML is executed.
4. Convert the procedural approach to a set-based approach

Transaction	Lock	Step No	Main step	Sub Step
		1	Check if the sp(catalog.create_execution) is called using windows Authentication	Returns an error if it’s called using SQL Server Authentication.
		2	Insert data into operation table	[internal].[insert_operation]
		3	Insert data into operation_permissions table	[internal].[init_object_permissions]
	X	4	SET TRANSACTION ISOLATION LEVEL SERIALIZABLE
	X	5	Get project_id, version and environment information	convert logic to single SQL statement
	X	6	Create key to decrypt and encrypt sensitive data	CREATE CERTIFICATE CREATE SYMMETRIC KEY
	X	7	Generate data for execution_parameter_values and insert into temp table	convert logic to single SQL statement
	X	8	SET TRANSACTION ISOLATION LEVEL READ COMMITTED
T		9	Begin transaction
		10	Update operations.object_id to project_id
T		11	Insert data into executions table	INSERT into [internal].[executions]
T		12	Insert execution_parameter_values	INSERT INTO [internal].[execution_parameter_values]
T		13	close symmetric keys
T		14	commit

Things that you should know:

1. I took out the permission check logic. As for the reasons:
   • I worried that permission check logic might make the modified query too complicated.
   • In my environment I don’t have any need to set different permission settings for SSISDB objects
2. I used base tables instead of views.
   • I wanted to be able to predict the execution plan and control access path.

Testing

If you capture what’s been called when you execute a package in an Integration Services Catalogs using the profiler, we will find that three SPs, [catalog].[create_execution], [catalog].[set_execution_parameter_value] and [catalog].[start_execution], are called. Below is the trace that I captured:

Declare @execution_id bigint
EXEC [SSISDB].[catalog].[create_execution] @package_name=N’Package.dtsx’, @execution_id=@execution_id OUTPUT, @folder_name=N’DEV’
, @project_name=N’Test2′, @use32bitruntime=False, @reference_id=1
Select @execution_id

exec sp_executesql N’DECLARE @var0 smallint = 1
EXEC [SSISDB].[catalog].[set_execution_parameter_value] @execution_id,  @object_type=50, @parameter_name=N”LOGGING_LEVEL”, @parameter_value=@var0
‘,N’@execution_id bigint’,@execution_id=10010
go
exec sp_executesql N’EXEC [SSISDB].[catalog].[start_execution] @execution_id’,N’@execution_id bigint’,@execution_id=10010
go

I created my SP [catalog].[create_execution_new] and checked if both [catalog].[create_execution] and [catalog].[create_execution_new] generates the same result. I also checked if the execution result of both were identical, and they were. I then created a backup copy of [catalog].[create_execution] and replaced [catalog].[create_execution] with my SP. It’s been several days since I made the replacement and it’s still working well.

Summary

I’m afraid that I had to choose an extreme workaround. However, it was a good chance to peek at both how the SSIS catalog works and what the developer was thinking. I hope this helps those who are experiencing the same issue and that a fix from MS is coming soon.