I was asked by a colleague that when he runs a create database statement with large initial sizes for database files , he was able to find the ghost clean-up process with SPID less than 50 ( system process) blocked by the create database statement by simply running the query sp_who2.
Though I did not have a straight answer for this, I was sure this must be due to the locking behaviour. In SQL server troubleshooting most of the time the answer is always in SQL server but it’s up to DBAs get that out from the engine. To kick off things here, we will go through what ghost clean-up process is and then look at my test environment I setup for figuring out the reason. I use extended events too
Ghost clean-up process:
For guys working with SQL server for a while, I’m sure they must know what ghost clean-up process is. In a simple way, this is a background task that runs at frequent intervals to delete the records physically from the data file pages which was marked as ghost records by the actual delete command. I’m not going any further with this explanation, as SQL server guru Paul Randal (Blog|Twitter) has written some high quality and much informative blogs about it here http://www.sqlskills.com/BLOGS/PAUL/post/Inside-the-Storage-Engine-Ghost-cleanup-in-depth.aspx , http://www.sqlskills.com/BLOGS/PAUL/post/Inside-the-Storage-Engine-Ghost-cleanup-in-depth.aspx and http://www.sqlskills.com/BLOGS/PAUL/post/Turning-off-the-ghost-cleanup-task-for-a-performance-gain.aspx.
Starting from SQL server 2008 SP1, it’s a known fact that Ghost cleans-up process in SQL server was modified to run once in 10 seconds as a background task. Prior to SQL server 2008 SP1, it used to run once in 5 secs. Jonathan Kehayias (Blog | Twitter), has blogged about this and was able to prove to that ghost clean-up process runs once in 10 seconds – http://www.sqlskills.com/blogs/jonathan/post/An-XEvent-a-Day-(15-of-31)-Tracking-Ghost-Cleanup.aspx. He uses extended events to show us this and I’m a big fan of extended events too as it gives you a lot of internal information that another tracing tools doesn’t give.
Playing with it:
I quickly sat down and started creating a database with 30GB size, I scripted the NEW database wizard and executed this command in a session and opened up another session to run sp_who2. There by I found what my colleague was explaining
-- Keep this running in session 1 -- In my case this session id or spid is 52 -- Do not question my practice of creating databases on C:\drive, this is my laptop CREATE DATABASE [GHOST_DB] ON PRIMARY ( NAME = N'GHOST_DB', FILENAME = N'C:\Program Files\Microsoft SQL Server\MSSQL10.SQL2008\MSSQL\DATA\GHOST_DB.mdf' , SIZE = 25600000KB , FILEGROWTH = 1024KB ) LOG ON ( NAME = N'GHOST_DB_log', FILENAME = N'C:\Program Files\Microsoft SQL Server\MSSQL10.SQL2008\MSSQL\DATA\GHOST_DB_log.ldf' , SIZE = 5120000KB , FILEGROWTH = 10%) GO --Execute SP_who2 in another session sp_who2
From the figure you can see that ghost clean-up process 22 is blocked by session id 52 which is my create database command
See above pic 1, the spid 22 is blocked by 52.
Meanwhile I also started an extended event to track Ghost clean-up process as explained by Jonathan in his blog, and below are the scripts that I used for it.
-- create an extended event to capture Ghost_cleanup process CREATE EVENT SESSION GhostCleanup ON SERVER ADD EVENT sqlserver.ghost_cleanup ( ACTION(sqlserver.database_id)) ADD TARGET package0.asynchronous_file_target( SET filename='C:\temp\GhostCleanup.xel', metadatafile='C:\temp\GhostCleanup.xem') WITH (MAX_MEMORY = 8MB, EVENT_RETENTION_MODE = NO_EVENT_LOSS ) GO -- Start the session once created ALTER EVENT SESSION GhostCleanup ON SERVER STATE=START -- Use this query to read the Event data from the Target file SELECT evt_data.value('(event/@name)', 'varchar(100)') AS event_name, evt_data.value('(event/@package)', 'varchar(100)') AS package_name, evt_data.value('(event/@id)', 'int') AS id, evt_data.value('(event/@version)', 'int') AS version, DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), evt_data.value('(event/@timestamp)', 'datetime2')) AS [timestamp], evt_data.value('(event/action[@name="database_id"]/value)', 'int') as database_id, evt_data.value('(event/data[@name="file_id"]/value)', 'int') as file_id, evt_data.value('(event/data[@name="page_id"]/value)', 'int') as page_id FROM (SELECT CAST(event_data AS XML) AS evt_data FROM sys.fn_xe_file_target_read_file('C:\temp\GhostCleanup*.xel','C:\temp\GhostCleanup*.xem', null, null) ) as a
Using the above query, we should be able to track the ghost clean-up process and its frequency.
As we could see a blockingbetween these two statements from Pic 1, I’m sure there must be locking going on for these command so I came up with this small TSQL which helped me understand the process
select a.resource_type,a.resource_associated_entity_id,object_name(b.object_id), a.request_mode,a.request_status,a.request_session_id from sys.dm_tran_locks a, sys.partitions b where a.resource_associated_entity_id = b.hobt_id
This query indeed helped me figure out what’s going behind the scenes and that justified the blocking that we were seeing
Pic 2 – green circles indicate the locks taken i.e., granted locks and red indicates the locks that are put on wait.
Looking at this picture closely, session 52 (create database stmt) has acquired an exclusive(X) lock on the key value on the table “SYSDBREG” for the new database creation and this lock will be held until the time the database is completely created, the lock time here will directly relate to the amount of time taken to initialize the database files and creating the database. As we have seen before, the ghost clean-up process (that pops-up once in 10secs) has been waiting for SHARED (S) locks to be acquired on the same KEY resource that create database statement has acquired. To add much more concrete meaning to this discussion, I monitored the extended event that we created and it really tells us that the ghost clean-up process did not happen in SQL server until the database creation completed. Database creation in this case took 2:27 mins and ghost clean-up did not run until this finished
From this picture 3 (I have truncated lot of information), it is very evident the ghost clean-up did not run from 16:05:03 to 16:07:29 unlike the earlier shown in green circles which just correlates the duration when my new database GHOST_DB was created. Also to note is that the ghost clean-up process when it runs the next time, it runs on the new database that we just created.
Now I had a very good explanation that I can give my colleague. But wait what is SYSDBREG table? This table is a system base table on top of which various catalog views are built in SQL server. Look at the BOL link – http://msdn.microsoft.com/en-us/library/ms179503.aspx and http://sqlblog.com/blogs/kalen_delaney/archive/2007/09/13/geek-city-the-resource-database.aspx
So this is just a default behaviour, ghost clean-up is trying to acquire a shared lock on each of the row (entries) in the sysdbreg base table and cannot acquire for that KEY value which is exclusively locked by create database statement. This not only applies to create database statement, it might well be the case to all the database changes that are done which in-turn acquires an exclusive locks on the sysdbreg table for more than 10 secs.
Don’t worry or panic when you see this behaviour, hope this article will help us to understand about why this happens!! These tests were done on SQL server 2008 SP1 and ghost clean-up process was coded in SQL server to run every 5 seconds in SQL server 2008 RTM and SQL server 2005.
As always, do not try this on a production server.