I can speak SQL

Fluent SQL speaker

SSIS 2012 fail to start – execution timed out

Posted by kulmam92 on June 27, 2013

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.

Before_Change_Lock

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.

after_Change_Lock

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.

Advertisements

7 Responses to “SSIS 2012 fail to start – execution timed out”

  1. […] SSIS Castalog – SSIS 2012 fail to start – execution timed out […]

  2. mbourgon said

    Howdy – came across this via the connect item. I wanted to see how this was holding up and whether you’d still recommend it. We’re adding processes and hitting this issue now. My main concern is that we need to take it into account when we patch, and making sure that it is working well and not causing problems.

    Thanks!

    • kulmam92 said

      Hi Michael

      I think that’s a really good question. I haven’t had any issue with the changes that I made. My plan for the patch is to apply patch to the test environment first and validate it there. I think you also need to compare original version of SP if there’s any change in it.

  3. daveballantyne said

    As it happens i have run into the same symptom, not necessarily the same problem though.

    Like you my jobs were failing with the timeout but when i captured the activity i could see that the ‘lead blocker’ was executing :

    UPDATE [internal].[execution_parameter_values]
    SET [sensitive_parameter_value] = EncryptByKey(KEY_GUID(@key_name),CONVERT(varbinary(4000),[parameter_value])),
    [parameter_value] = NULL
    WHERE [execution_id] = @operation_id
    AND [sensitive] = 1
    AND [parameter_value] IS NOT NULL
    AND [sensitive_parameter_value] IS NULL
    AND [parameter_data_type] NOT IN (‘datetime’, ‘double’, ‘single’, ‘decimal’)

    Looking at the plan it was scanning [internal].[execution_parameter_values], a quick FREEPROCACHE was all that was needed to stop the timeouts on the applock as this statement was executing in a timely fashion.

    • daveballantyne said

      Me again 🙂

      So , that didnt 100% solve the problem, but to solve i did something else , use the sp_getapplock to serialize access to the create_execution proc. Now the proc never timesout 🙂
      Seems simpler and more portable than creating a new procedure….

      BEGIN TRANSACTION
      EXEC sp_getapplock @Resource = ‘JobStartLock’,
      @LockMode = ‘Exclusive’;

      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_releaseapplock @Resource = ‘JobStartLock’;

      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
      COMMIT

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

 
%d bloggers like this: