I can could also reproduce this 100% of the time on my machine. (see note at end)
The gist of the problem is that you are taking out S locks on system table rows in tempdb that can conflict with the locks needed for internal tempdb cleanup transactions.
When this clean up work is allocated to the same session that owns the S lock an indefinite hang can occur.
To avoid this problem for certain you need to stop referencing the system objects inside tempdb.
It is possible to create a numbers table without referencing any external tables at all. The following needs to read no base table rows and thus also takes no locks.
WITH Ten(N) AS
(
SELECT 1 UNION ALL SELECT 1 UNION ALL SELECT 1 UNION ALL
SELECT 1 UNION ALL SELECT 1 UNION ALL SELECT 1 UNION ALL
SELECT 1 UNION ALL SELECT 1 UNION ALL SELECT 1 UNION ALL SELECT 1
)
SELECT TOP 1000000 IDENTITY(INT, 1, 1) Number
INTO Numbers
FROM Ten T10,
Ten T100,
Ten T1000,
Ten T10000,
Ten T100000,
Ten T1000000
Steps to Reproduce
First create a procedure
CREATE PROC P
AS
SET NOCOUNT ON;
DECLARE @T TABLE (X INT)
GO
Then restart the SQL Service and in one connection execute
WHILE NOT EXISTS(SELECT *
FROM sys.dm_os_waiting_tasks
WHERE session_id = blocking_session_id)
BEGIN
/*This will cause the problematic droptemp transactions*/
EXEC sp_recompile 'P'
EXEC P
END;
SELECT *
FROM sys.dm_os_waiting_tasks
WHERE session_id = blocking_session_id
Then in another connection run
USE tempdb;
SELECT TOP 1000000 IDENTITY(INT, 1, 1) Number
INTO #T
FROM sys.objects s1
CROSS JOIN sys.objects s2
CROSS JOIN sys.objects s3
CROSS JOIN sys.objects s4;
DROP TABLE #T
The query populating the Numbers table seems to manage to get into a live lock situation with the internal system transactions that clean up temporary objects such as table variables.
I managed to get session id 53 blocked in this manner. It is blocked indefinitely. The output of sp_WhoIsActive shows that this spid spends almost all of the time suspended. In consecutive runs the numbers in the reads column increases but the values in the other columns remain largely the same.
The wait duration doesn't show an increasing pattern though indicating that it must get unblocked periodically before getting blocked again.
SELECT *
FROM sys.dm_os_waiting_tasks
WHERE session_id = blocking_session_id
Returns
+----------------------+------------+-----------------+------------------+-----------+--------------------+-----------------------+---------------------+--------------------------+--------------------------------------------------------------------------------------------------+
| waiting_task_address | session_id | exec_context_id | wait_duration_ms | wait_type | resource_address | blocking_task_address | blocking_session_id | blocking_exec_context_id | resource_description |
+----------------------+------------+-----------------+------------------+-----------+--------------------+-----------------------+---------------------+--------------------------+--------------------------------------------------------------------------------------------------+
| 0x00000002F2C170C8 | 53 | 0 | 86 | LCK_M_X | 0x00000002F9B13040 | 0x00000002F2C170C8 | 53 | NULL | keylock hobtid=281474978938880 dbid=2 id=lock2f9ac8880 mode=U associatedObjectId=281474978938880 |
+----------------------+------------+-----------------+------------------+-----------+--------------------+-----------------------+---------------------+--------------------------+--------------------------------------------------------------------------------------------------+
Using the id in the resource description
SELECT o.name
FROM sys.allocation_units au WITH (NOLOCK)
INNER JOIN sys.partitions p WITH (NOLOCK)
ON au.container_id = p.partition_id
INNER JOIN sys.all_objects o WITH (NOLOCK)
ON o.object_id = p.object_id
WHERE allocation_unit_id = 281474978938880
Returns
+------------+
| name |
+------------+
| sysschobjs |
+------------+
Running
SELECT resource_description,request_status
FROM sys.dm_tran_locks
WHERE request_session_id = 53 AND request_status <> 'GRANT'
Returns
+----------------------+----------------+
| resource_description | request_status |
+----------------------+----------------+
| (246708db8c1f) | CONVERT |
+----------------------+----------------+
Connecting via the DAC and running
SELECT id,name
FROM tempdb.sys.sysschobjs WITH (NOLOCK)
WHERE %%LOCKRES%% = '(246708db8c1f)'
Returns
+-------------+-----------+
| id | name |
+-------------+-----------+
| -1578606288 | #A1E86130 |
+-------------+-----------+
Curious about what that is
SELECT name,user_type_id
FROM tempdb.sys.columns
WHERE object_id = -1578606288
Returns
+------+--------------+
| name | user_type_id |
+------+--------------+
| X | 56 |
+------+--------------+
This is the column name in the table variable used by the stored proc.
Running
SELECT request_mode,
request_status,
request_session_id,
request_owner_id,
lock_owner_address,
t.transaction_id,
t.name,
t.transaction_begin_time
FROM sys.dm_tran_locks l
JOIN sys.dm_tran_active_transactions t
ON l.request_owner_id = t.transaction_id
WHERE resource_description = '(246708db8c1f)'
Returns
+--------------+----------------+--------------------+------------------+--------------------+----------------+-------------+-------------------------+
| request_mode | request_status | request_session_id | request_owner_id | lock_owner_address | transaction_id | name | transaction_begin_time |
+--------------+----------------+--------------------+------------------+--------------------+----------------+-------------+-------------------------+
| U | GRANT | 53 | 227647 | 0x00000002F1EF6800 | 227647 | droptemp | 2013-11-24 18:36:28.267 |
| S | GRANT | 53 | 191790 | 0x00000002F9B16380 | 191790 | SELECT INTO | 2013-11-24 18:21:30.083 |
| X | CONVERT | 53 | 227647 | 0x00000002F9B12FC0 | 227647 | droptemp | 2013-11-24 18:36:28.267 |
+--------------+----------------+--------------------+------------------+--------------------+----------------+-------------+-------------------------+
So the SELECT INTO transaction is holding an S lock on the row in tempdb.sys.sysschobjs pertaining to the table variable #A1E86130. The droptemp transaction cannot get an X lock on this row because of this conflicting S lock.
Running this query repeatedly reveals that the transaction_id for the droptemp transaction repeatedly changes.
I speculate that SQL Server must allocate these internal transactions on user spids and prioritise them before doing the user work. So the session id 53 is stuck in a constant cycle where it starts up a droptemp transaction, is blocked by the user transaction running on the same spid. Rolls back the internal transaction then repeats the process indefinitely.
This is borne out by tracing the various locking and transaction events in SQL Server Profiler after the spid becomes hung.
I also traced the locking events prior to that.
Lock Events Blocking
Most of the shared key locks taken out by the SELECT INTO transaction on keys in sysschobjs get released immediately. The exception is the first lock on (246708db8c1f).
This makes some sense as the plan shows nested loops scans of [sys].[sysschobjs].[clst] [o] and because temporary objects get given negative objectids they will be the first rows encountered in scan order.
I also encountered the situation described in the OP where running a three way cross join first seems to allow the four way one to succeed.
The first few events in the trace for the SELECT INTO transaction there are an entirely different pattern.
This was after a service restart so the lock resource values in the text data column are not directly comparable.
Instead of retaining the lock on the first key and then a pattern of acquiring and releasing subsequent keys it seems to acquire a lot more locks without releasing them initially.
I presume there must be some variance in execution strategy that avoids the issue.
Update
The Connect Item I raised about this has not been marked as fixed but I am now on SQL Server 2012 SP2 and can now only reproduce temporary self blocking rather than permanent. I still get the self blocking but after some amount of failed attempts to execute the droptemp transaction successfully it appears to go back to processing the user transaction. After that commits the system transaction then is executed successfully. Still on the same spid. (eight attempts in one example run. I'm not sure if this will be consistently repeated)
