THE SQL Server Blog Spot on the Web

Welcome to SQLblog.com - The SQL Server blog spot on the web Sign in | |
in Search

The Rambling DBA: Jonathan Kehayias

The random ramblings and rantings of frazzled SQL Server DBA

An XEvent a Day (15 of 31) – Tracking Ghost Cleanup

If you don’t know anything about Ghost Cleanup, I recommend highly that you go read Paul Randal’s blog posts Inside the Storage Engine: Ghost cleanup in depth, Ghost cleanup redux, and Turning off the ghost cleanup task for a performance gain.  To my knowledge Paul’s posts are the only things that cover Ghost Cleanup at any level online.

In this post we’ll look at how you can use Extended Events to track the activity of Ghost Cleanup inside of your SQL Server.  To do this, we’ll first take a look at the ghost_cleanup Event and what it returns.

-- Find the Event
SELECT 
    p.name, 
    o.name, 
    o.description
FROM sys.dm_xe_packages AS p
JOIN sys.dm_xe_objects AS o
    ON p.guid = o.package_guid
WHERE o.name = 'ghost_cleanup'

-- Get the data columns for the Event
SELECT 
    name, 
    TYPE_NAME
FROM sys.dm_xe_object_columns
WHERE OBJECT_NAME = 'ghost_cleanup'
  AND column_type = 'data'

image

The ghost_cleanup Event is in the sqlserver Package and returns the file_id and page_id that the ghost cleanup process is working on.  Since most SQL Servers have multiple databases, we probably will want to track the database_id through an Action as well.  Since ghost cleanup is a background process, and we don’t know much about how it works, or how many Events are going to be generated, we could start off with the synchronous_event_counter Target, but in this case, I just want to capture Events and all of them, so we will just go with the asynchronous_file_target.

CREATE EVENT SESSION TrackGhostCleanup
ON SERVER
ADD EVENT sqlserver.ghost_cleanup
( ACTION(sqlserver.database_id))
ADD TARGET package0.asynchronous_file_target(
     SET filename='C:\SQLBlog\TrackGhostCleanup.xel',
         metadatafile='C:\SQLBlog\TrackGhostCleanup.xem')
WITH (MAX_MEMORY = 4MB, EVENT_RETENTION_MODE = NO_EVENT_LOSS )
GO
ALTER EVENT SESSION TrackGhostCleanup
ON SERVER
STATE=START

This is a really basic Event Session, it captures one Event, sqlserver.ghost_cleanup and collects the sqlserver.database_id Action when the Event fires.  The Event data is captured by the package0.asynchronous_file_target, and the Event Session is configured to not allow Event Loss.  After the starting the Event Session and allowing it to run, we can query the files for the captured events and see how ghost_cleanup is running on our instance.

-- Query the Event data from the Target.
SELECT 
    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    event_data.value('(event/@package)[1]', 'varchar(50)') AS package_name,
    event_data.value('(event/@id)[1]', 'int') AS id,
    event_data.value('(event/@version)[1]', 'int') AS version,
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    event_data.value('(event/action[@name="database_id"]/value)[1]', 'int') as database_id,
    event_data.value('(event/data[@name="file_id"]/value)[1]', 'int') as file_id,
    event_data.value('(event/data[@name="page_id"]/value)[1]', 'int') as page_id
FROM 
(SELECT
    CAST(event_data AS XML) AS event_data
 FROM sys.fn_xe_file_target_read_file('C:\SQLBlog\TrackGhostCleanup*.xel', 'C:\SQLBlog\TrackGhostCleanup*xem', null, null)
) as tab

From around 15 minutes of runtime on one of my development servers, over 17.5K Events have fired, much more than I initially anticipated, and after nearly 30 minutes of runtime, I had just over 37K Events. 

image

Some interesting information can be found in the Events.  In SQL Server 2008, the Ghost Cleanup process runs every 10 seconds, just as Paul has documented in his blog posts, which was a change from every 5 seconds in SQL Server 2005.

image

The process in 2008 cleans up 200 pages at a time, something Paul hasn’t specifically blogged about for SQL Server 2008.  Before anyone debates this, Paul’s statement “It will check through or cleanup a limited number of pages each time it wakes up - I remember the limit is 10 pages - to ensure it doesn't swamp the system.” from his Inside the Storage Engine: Ghost cleanup in depth is based on SQL Server 2005, which also ran ghost cleanup every 5 seconds instead of 10 seconds.  We can look at the Event information over subsequent 10 second intervals and see that 200 pages are cleaned up each time ghost_cleanup runs.

image

image

This has to be one of my favorite aspects of Extended Events.  You get to really learn about SQL Server Internals by just playing with SQL Server.  I have a couple more blog posts that show how you can learn about SQL Server Internals using Extended Events for this series, and if you are interested in a previous post on the subject check out TSQL Tuesday #11 – Physical IO’s Don’t Always Accumulate Wait Times.

Until tomorrow….

Published Wednesday, December 15, 2010 10:45 PM by Jonathan Kehayias

Comments

 

Suresh Kandoth said:

It looks like even SQL 2005 was performing Ghost processing at 10 sec interval. You can see this using the SQL Profiler Transaction events which shows the Ghost Cleanup tran name. So it looks like both version have the same frequency.

January 17, 2011 6:01 PM
 

Jonathan Kehayias said:

What specific EventSubClass are you tracking in the Profiler TransactionLog Event for this?  I spent about two hours tonight working back through my Ghost Cleanup Demo's and sample code to figure out what Log_op or Context you could be trying to key on and I give up.  I can't see anyway that you can accurately track ghost cleanup operations through the TransactionLog Event in Profiler, or the sqlserver.transaction_log Event in Denali CTP1 Extended Events either.  Each ghost_cleanup event fires off multiple Log operations and in tracing those out I see them occuring in non-ghost cleanup operations in the database as well.

January 17, 2011 10:34 PM
 

Suresh Kandoth said:

Sorry, I was not specific. The profiler event is "SQLTransaction" and ObjectName is "GhostCleanupTask".

January 26, 2011 6:55 PM
Anonymous comments are disabled

This Blog

Syndication

Powered by Community Server (Commercial Edition), by Telligent Systems
  Privacy Statement