One of our production systems has exhibited a problem with a single insertion statement into a temp table from our user database. When I comment out the insert/select, the stored proc in question runs in a timely fashion, so I am confident in my isolation of the problem.
The series of stored procs invoked basically grinds to a halt when I un-comment the insert/select in question. I cannot see anything in Top Transactions by Age in tempdb or any of our user databases. I do not see anything in Activity Monitor that deviates from Activity Monitor's information when the database is "at rest", other than CPU being flatlined at ~20%.
The behavior is as follows: when I setup and then execute the reproduction case, upon arrival at the insert/select in question, I see an SOS_SCHEDULER_YIELD and there is an ENCRYPTION_SCAN. About five hours later, I will see processing of our stored procedure resume and the activity will complete (I put quick and dirty log statements around every distinct operation).
I also replaced the variables in the select portion of the insert with the values as executed, and ran the selection query itself, and it returned in five seconds.
The user database in question has FALSE as its encryption enabled value, as does tempdb. The operation in question happens over about 65k rows of data, and I have tried it with only 1k rows, and the behavior persisted, although the time it took was far less.
A single user database is the only instance of this behavior. I have reproduced it locally over a backup of that user databse. We have about 70 other users of the software that do not exhibit this problem.
Given the above information, my question is, why is processing of our stored procedures stopping? As it is probably optimistic to expect a precise answer, what is the correct step to debugging this? Perhaps there is something in one of the DMVs like dm_tran_locks, dm_exec_requests, dm_tran_database_transactions, dm_os_schedulers, dm_exec_sessions that, while they have provided me with some information, I am not interpreting or understanding the output in a way that points toward a solution.
Below is the insert/select in question:
INSERT INTO #TS_EVENT_DATA
( EVENT_FK,
EVENT_TYPE_CR_FK,
EVENT_ENTITY_CLASS_CR_FK,
userDatabase_ID,
DATA_NAME_FK,
IMPORT_JOB_FK,
PRODUCT_STRUCTURE_FK,
ORG_ENTITY_STRUCTURE_FK,
ENTITY_CLASS_CR_FK,
ENTITY_DATA_NAME_FK,
ENTITY_STRUCTURE_FK,
DATA_SET_FK,
DATA_TYPE_CR_FK,
ORG_IND,
TABLE_NAME,
NET_VALUE1_NEW,
NET_VALUE2_NEW,
NET_VALUE3_NEW,
NET_VALUE4_NEW,
NET_VALUE5_NEW,
NET_VALUE6_NEW,
NET_VALUE1_CUR,
NET_VALUE2_CUR,
NET_VALUE3_CUR,
NET_VALUE4_CUR,
NET_VALUE5_CUR,
NET_VALUE6_CUR,
PERCENT_CHANGE1,
PERCENT_CHANGE2,
PERCENT_CHANGE3,
PERCENT_CHANGE4,
PERCENT_CHANGE5,
PERCENT_CHANGE6,
VALUE_UOM_CODE_FK,
ASSOC_UOM_CODE_FK,
VALUES_SHEET_NAME,
UOM_CONVERSION_FACTOR,
END_DATE_CUR,
END_DATE_NEW,
EFFECTIVE_DATE_CUR,
EVENT_EFFECTIVE_DATE,
EVENT_ACTION_CR_FK,
EVENT_STATUS_CR_FK,
EVENT_CONDITION_CR_FK,
EVENT_SOURCE_CR_FK,
EVENT_PRIORITY_CR_FK,
RESULT_TYPE_CR_FK,
TABLE_ID_FK,
BATCH_NO,
IMPORT_BATCH_NO,
RULES_FK,
RECORD_STATUS_CR_FK,
UPDATE_TIMESTAMP
)
SELECT
A.EVENT_ID,
A.EVENT_TYPE_CR_FK,
A.EVENT_ENTITY_CLASS_CR_FK,
A.userDatabase_ID,
A.DATA_NAME_FK,
A.IMPORT_JOB_FK,
A.PRODUCT_STRUCTURE_FK,
A.ORG_ENTITY_STRUCTURE_FK,
A.ENTITY_CLASS_CR_FK,
A.ENTITY_DATA_NAME_FK,
A.ENTITY_STRUCTURE_FK,
A.DATA_SET_FK,
A.DATA_TYPE_CR_FK,
A.ORG_IND,
A.TABLE_NAME,
A.NET_VALUE1_NEW,
A.NET_VALUE2_NEW,
A.NET_VALUE3_NEW,
A.NET_VALUE4_NEW,
A.NET_VALUE5_NEW,
A.NET_VALUE6_NEW,
A.NET_VALUE1,
A.NET_VALUE2,
A.NET_VALUE3,
A.NET_VALUE4,
A.NET_VALUE5,
A.NET_VALUE6,
CASE ISNULL (A.NET_VALUE1, 0 )
WHEN 0 THEN 0
ELSE ( ( A.NET_VALUE1_NEW - A.NET_VALUE1) / A.NET_VALUE1 )
END,
CASE ISNULL (A.NET_VALUE2, 0 )
WHEN 0 THEN 0
ELSE ( ( A.NET_VALUE2_NEW - A.NET_VALUE2 ) / A.NET_VALUE2 )
END,
CASE ISNULL (A.NET_VALUE3, 0 )
WHEN 0 THEN 0
ELSE ( ( A.NET_VALUE3_NEW - A.NET_VALUE3 ) / A.NET_VALUE3 )
END,
CASE ISNULL (A.NET_VALUE4, 0 )
WHEN 0 THEN 0
ELSE ( ( A.NET_VALUE4_NEW - A.NET_VALUE4 ) / A.NET_VALUE4 )
END,
CASE ISNULL (A.NET_VALUE5, 0 )
WHEN 0 THEN 0
ELSE ( ( A.NET_VALUE5_NEW - A.NET_VALUE5 ) / A.NET_VALUE5 )
END,
CASE ISNULL (A.NET_VALUE6, 0 )
WHEN 0 THEN 0
ELSE ( ( A.NET_VALUE6_NEW - A.NET_VALUE6 ) / A.NET_VALUE6 )
END,
A.VALUE_UOM_CODE_FK,
A.ASSOC_UOM_CODE_FK,
A.VALUES_SHEET_NAME,
( SELECT CASE ISNULL ( A.VALUE_UOM_CODE_FK, 0 )
WHEN 0 THEN 1
ELSE
CASE ISNULL ( A.ASSOC_UOM_CODE_FK, 0 )
WHEN 0 THEN 1
ELSE
( ISNULL (
( SELECT
( SELECT ISNULL (
(SELECT uc.primary_qty
FROM userDatabase.UOM_CODE uc WITH (NOLOCK)
WHERE uc.UOM_CODE_ID = A.VALUE_UOM_CODE_FK ), 1 )
)
/
ISNULL ( (SELECT uc.primary_qty
FROM userDatabase.UOM_CODE uc WITH (NOLOCK)
WHERE uc.UOM_CODE_ID = A.ASSOC_UOM_CODE_FK )
, ISNULL ( (SELECT uc.primary_qty
FROM userDatabase.UOM_CODE uc WITH (NOLOCK)
WHERE uc.UOM_CODE_ID = A.VALUE_UOM_CODE_FK) , 1 )
)
) , 1 ) )
END END
) AS UOM_CONVERSION_FACTOR,
A.END_DATE,
A.END_DATE_NEW,
A.EFFECTIVE_DATE,
A.EVENT_EFFECTIVE_DATE,
A.EVENT_ACTION_CR_FK,
A.EVENT_STATUS_CR_FK,
A.EVENT_CONDITION_CR_FK,
A.EVENT_SOURCE_CR_FK,
A.EVENT_PRIORITY_CR_FK,
A.RESULT_TYPE_CR_FK,
A.SHEET_RESULTS_ID,
A.BATCH_NO,
A.IMPORT_BATCH_NO,
A.RULES_FK,
A.RECORD_STATUS_CR_FK,
@L_SYSDATE
FROM ( SELECT
ED.EVENT_ID,
DS.EVENT_TYPE_CR_FK,
DS.ENTITY_CLASS_CR_FK AS EVENT_ENTITY_CLASS_CR_FK,
ED.PRODUCT_STRUCTURE_FK AS userDatabase_ID,
ED.DATA_NAME_FK,
ED.IMPORT_JOB_FK,
ED.PRODUCT_STRUCTURE_FK,
CASE ISNULL ( DS.ORG_IND, 0 )
WHEN 0 THEN ISNULL ( ED.ORG_ENTITY_STRUCTURE_FK, 1 )
ELSE ED.ORG_ENTITY_STRUCTURE_FK
END AS ORG_ENTITY_STRUCTURE_FK,
DS.ENTITY_STRUCTURE_EC_CR_FK AS ENTITY_CLASS_CR_FK,
DN.ENTITY_DATA_NAME_FK,
ED.ENTITY_STRUCTURE_FK,
DN.DATA_SET_FK,
DS.DATA_TYPE_CR_FK,
DS.ORG_IND,
DS.TABLE_NAME,
ED.NET_VALUE1_NEW,
ED.NET_VALUE2_NEW,
ED.NET_VALUE3_NEW,
ED.NET_VALUE4_NEW,
ED.NET_VALUE5_NEW,
ED.NET_VALUE6_NEW,
SR.NET_VALUE1,
SR.NET_VALUE2,
SR.NET_VALUE3,
SR.NET_VALUE4,
SR.NET_VALUE5,
SR.NET_VALUE6,
ED.VALUE_UOM_CODE_FK,
( SELECT TOP 1 PUC.UOM_CODE_FK
FROM userDatabase.PRODUCT_UOM_CLASS PUC WITH (NOLOCK)
WHERE ( PUC.DATA_NAME_FK = DN.UOM_CLASS_DATA_NAME_FK
AND PUC.PRODUCT_STRUCTURE_FK = ED.PRODUCT_STRUCTURE_FK
AND ( ( DS.ORG_IND = 1
AND PUC.ORG_ENTITY_STRUCTURE_FK = ED.ORG_ENTITY_STRUCTURE_FK )
OR PUC.ORG_ENTITY_STRUCTURE_FK = 1 )
AND ISNULL ( PUC.ENTITY_STRUCTURE_FK, -999 ) = ISNULL ( ED.ENTITY_STRUCTURE_FK, -999 ) )
) AS ASSOC_UOM_CODE_FK,
ED.VALUES_SHEET_NAME,
SR.END_DATE,
ED.END_DATE_NEW,
SR.EFFECTIVE_DATE,
ED.EVENT_EFFECTIVE_DATE,
CASE WHEN ED.EVENT_ACTION_CR_FK = 59
THEN 59
ELSE
CASE WHEN SR.SHEET_RESULTS_ID IS NULL
THEN 51
ELSE 52
END
END AS EVENT_ACTION_CR_FK,
ED.EVENT_STATUS_CR_FK,
ED.EVENT_CONDITION_CR_FK,
ED.EVENT_SOURCE_CR_FK,
ED.EVENT_PRIORITY_CR_FK,
ISNULL ( ED.RESULT_TYPE_CR_FK, 711 ) AS RESULT_TYPE_CR_FK,
SR.SHEET_RESULTS_ID,
ED.BATCH_NO,
ED.IMPORT_BATCH_NO,
ED.RULES_FK,
ED.RECORD_STATUS_CR_FK
FROM SYNCHRONIZER.EVENT_DATA ED WITH (NOLOCK)
INNER JOIN userDatabase.DATA_NAME DN WITH (NOLOCK)
ON ( DN.DATA_NAME_ID = ED.DATA_NAME_FK )
INNER JOIN userDatabase.DATA_SET DS WITH (NOLOCK)
ON ( DS.DATA_SET_ID = DN.DATA_SET_FK )
LEFT JOIN marginmgr.SHEET_RESULTS SR WITH (NOLOCK)
ON ( SR.DATA_NAME_FK = ED.DATA_NAME_FK
AND ISNULL ( SR.PRODUCT_STRUCTURE_FK, 0 ) = ISNULL ( ED.PRODUCT_STRUCTURE_FK, 0 )
AND ISNULL ( SR.ORG_ENTITY_STRUCTURE_FK, 0 ) = ISNULL ( ED.ORG_ENTITY_STRUCTURE_FK, 1 )
AND ISNULL ( SR.ENTITY_STRUCTURE_FK, 0 ) = ISNULL ( ED.ENTITY_STRUCTURE_FK, 0 )
)
WHERE 1 = 1
AND EVENT_STATUS_CR_FK = 88
AND (
( ISNULL ( @in_event_fk, -999 ) = -999
AND ISNULL ( ED.BATCH_NO, -999 ) = ISNULL ( @in_batch_no, -999 )
AND ISNULL ( ED.import_job_fk, -999 ) = ISNULL (@in_import_job_fk, -999 )
AND isnull ( ED.event_priority_cr_fk, -999 ) = isnull (@in_event_priority_cr_fk, -999)
AND ISNULL ( ds.table_name, 'NULL DATA' ) = ISNULL ( @in_table_name, 'NULL DATA' ) )
OR ED.EVENT_ID = ISNULL (@in_event_fk, -999 )
)
AND ( @in_data_name_fk = -999
OR ED.data_name_fk = @in_data_name_fk )
) A
Results of sp_configure:
access check cache bucket count 0 65536 0 0
access check cache quota 0 2147483647 0 0
Ad Hoc Distributed Queries 0 1 0 0
affinity I/O mask -2147483648 2147483647 0 0
affinity mask -2147483648 2147483647 0 0
affinity64 I/O mask -2147483648 2147483647 0 0
affinity64 mask -2147483648 2147483647 0 0
Agent XPs 0 1 1 1
allow updates 0 1 0 0
backup compression default 0 1 0 0
blocked process threshold (s) 0 86400 0 0
c2 audit mode 0 1 0 0
clr enabled 0 1 1 1
common criteria compliance enabled 0 1 0 0
contained database authentication 0 1 0 0
cost threshold for parallelism 0 32767 5 5
cross db ownership chaining 0 1 0 0
cursor threshold -1 2147483647 -1 -1
Database Mail XPs 0 1 1 1
default full-text language 0 2147483647 1033 1033
default language 0 9999 0 0
default trace enabled 0 1 1 1
disallow results from triggers 0 1 0 0
EKM provider enabled 0 1 0 0
filestream access level 0 2 0 0
fill factor (%) 0 100 0 0
ft crawl bandwidth (max) 0 32767 100 100
ft crawl bandwidth (min) 0 32767 0 0
ft notify bandwidth (max) 0 32767 100 100
ft notify bandwidth (min) 0 32767 0 0
index create memory (KB) 704 2147483647 0 0
in-doubt xact resolution 0 2 0 0
lightweight pooling 0 1 0 0
locks 5000 2147483647 0 0
max degree of parallelism 0 32767 0 0
max full-text crawl range 0 256 4 4
max server memory (MB) 128 2147483647 5120 5120
max text repl size (B) -1 2147483647 65536 65536
max worker threads 128 65535 0 0
media retention 0 365 0 0
min memory per query (KB) 512 2147483647 1024 1024
min server memory (MB) 0 2147483647 128 128
nested triggers 0 1 1 1
network packet size (B) 512 32767 4096 4096
Ole Automation Procedures 0 1 0 0
open objects 0 2147483647 0 0
optimize for ad hoc workloads 0 1 0 0
PH timeout (s) 1 3600 60 60
precompute rank 0 1 0 0
priority boost 0 1 0 0
query governor cost limit 0 2147483647 0 0
query wait (s) -1 2147483647 -1 -1
recovery interval (min) 0 32767 0 0
remote access 0 1 1 1
remote admin connections 0 1 0 0
remote login timeout (s) 0 2147483647 10 10
remote proc trans 0 1 0 0
remote query timeout (s) 0 2147483647 600 600
Replication XPs 0 1 0 0
scan for startup procs 0 1 0 0
server trigger recursion 0 1 1 1
set working set size 0 1 0 0
show advanced options 0 1 1 1
SMO and DMO XPs 0 1 1 1
transform noise words 0 1 0 0
two digit year cutoff 1753 9999 2049 2049
user connections 0 32767 0 0
user options 0 32767 0 0
xp_cmdshell 0 1 1 1
Link to XML of Exec Plan (too large to embed).