Ok. Here's what I try to run:
USE tempdb;
SELECT TOP 1000000 IDENTITY(INT, 1, 1) Number
INTO Numbers
FROM sys.objects s1
CROSS JOIN sys.objects s2
CROSS JOIN sys.objects s3
CROSS JOIN sys.objects s4;
This is one of those "make me a numbers table" queries.
Here's the problem. If I run this immediately after the SQL Server service is (re)started, it takes forever. Not forever as in ten seconds and I want it faster. Forever as in, I let it go over two hours once by accident and still had to kill it. I'm thinking it just never ever comes back. And ordinarily it takes under two seconds on my machine to run this.
However, if I do this instead:
USE tempdb;
SELECT TOP 1000000 IDENTITY(INT, 1, 1) Number
INTO Numbers
FROM sys.objects s1
CROSS JOIN sys.objects s2
CROSS JOIN sys.objects s3;
DROP TABLE Numbers;
SELECT TOP 1000000 IDENTITY(INT, 1, 1) Number
INTO Numbers
FROM sys.objects s1
CROSS JOIN sys.objects s2
CROSS JOIN sys.objects s3
CROSS JOIN sys.objects s4;
Then it works as you would expect — the first SELECT
runs in under two seconds, as does the second. Why don't I just use the three-table version? Because there aren't enough entries in sys.objects
for that number cubed to equal a million result rows. But that's not even the point anymore.
Anyway, from here on, I can repeat that second DROP
/ SELECT…INTO
as much as I want, no problem. Somehow that first three-table version made it ok forever. At least, till the next time the service is restarted and/or the machine rebooted. At which point, running that last SELECT
again never comes back. Again.
Here's where it starts getting even weirder. If I pare that first SELECT
back to a two-table version:
USE tempdb;
SELECT TOP 1000000 IDENTITY(INT, 1, 1) Number
INTO Numbers
FROM sys.objects s1
CROSS JOIN sys.objects s2;
DROP TABLE Numbers;
SELECT TOP 1000000 IDENTITY(INT, 1, 1) Number
INTO Numbers
FROM sys.objects s1
CROSS JOIN sys.objects s2
CROSS JOIN sys.objects s3
CROSS JOIN sys.objects s4;
This also makes the second SELECT
run forever. As does a one-table version. Somehow, that three-table version is magical!
What is going on here? Why is this slow?
(And before anyone points out that I'm creating a permanent table in tempdb
, yes, I know. Changing to actual temp tables doesn't make any difference.)
Added info:
EXEC sp_WhoIsActive @find_block_leaders = 1, @sort_order = '[blocked_session_count] DESC'
(scripted as XML so it can be read here) is:<?xml version="1.0" ?> <RESULTS1> <RECORD> <dd hh:mm:ss.mss>00 00:10:45.066</dd hh:mm:ss.mss> <session_id>52</session_id> <sql_text><?query -- SELECT TOP 1000000 IDENTITY(INT, 1, 1) Number INTO Numbers FROM sys.objects s1 CROSS JOIN sys.objects s2 CROSS JOIN sys.objects s3 CROSS JOIN sys.objects s4; --?></sql_text> <login_name>my own login name redacted</login_name> <wait_info>(99ms)LCK_M_X</wait_info> <CPU> 9,750</CPU> <tempdb_allocations> 713</tempdb_allocations> <tempdb_current> 702</tempdb_current> <blocking_session_id>NULL</blocking_session_id> <blocked_session_count> 0</blocked_session_count> <reads> 583,273</reads> <writes> 537</writes> <physical_reads> 50</physical_reads> <used_memory> 3</used_memory> <status>suspended</status> <open_tran_count> 2</open_tran_count> <percent_complete>NULL</percent_complete> <host_name>my own machine name redacted</host_name> <database_name>tempdb</database_name> <program_name>Microsoft SQL Server Management Studio - Query</program_name> <start_time>2013-11-23 23:48:19.473</start_time> <login_time>2013-11-23 23:47:47.060</login_time> <request_id>0</request_id> <collection_time>2013-11-23 23:59:04.560</collection_time> </RECORD> </RESULTS1>
More added info:
Why I'm putting this in tempdb is that it's part of a script intended to be run on virgin installations, and tempdb is guaranteed to be there. As I said, changing to global temp tables does no different.
Slow queries can mean your database does more work than it needs to, which means it's using more resources than it needs to. When limited resources like CPU or I/O run out, everything can start to slow down. Inefficient use of resources is also a problem when you're not using the resources you have.
Here's one way to track down the cause of the problem: Find out the most expensive queries running in SQL Server, over the period of slowdown. Review the query plan and query execution statistics and wait types for the slowest query. Review the Query History over the period where performance changed.
When you run your query for the first time and the data is not in cache, the server read the data from disk. It is time-comsuming. The second time you execute the same query data is already in cache so it requires less time.
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
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.
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)
Rather than chase this problem, why don't you just create the table once in the model
database, then it will be created for you in tempdb
automatically?
For the actual problem, we don't know. My first guess would be that your initial size for your tempdb file(s) is very small (like, 1MB). So, when you create the table, it has to expand the file(s) to accommodate it. This can be quite expensive especially if you don't have instant file initialization enabled, and it can also be very expensive to grow the log to accommodate the activity required there as well.
Other than that, we could keep guessing, but you will be better suited to investigate what is actually happening. Questions you'll want to ask:
sys.dm_exec_requests
say for wait_type
? blocking_session_id
?If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With