Thursday, November 29, 2012

Observing Locking Behaviour With Extended Events (SQL Server 2008 +)

Tracking extended events is similar to SQL Trace, but it runs at a much lower level than SQL Trace, so that much more lower level events can be tracked and revealed. For example, it can be used to troubleshoot excessive CPU usage,deadlocks and examine how the locks are used inside SQL Server.

The code samples listed here are typical steps of using extended events.

--Assuming I have a database called TestDB and its ID is 19
--You can use dynamic SQL to avoid doing this step
select DB_ID('TestDB')
-- Perform cleanup.
IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='ObservingLocking') 
    DROP EVENT SESSION FindBlockers ON SERVER 
    GO

-- create extended event
CREATE EVENT SESSION ObservingLocking
ON SERVER
ADD EVENT sqlserver.lock_acquired(where database_id = 19),
ADD EVENT sqlserver.lock_released(where database_id = 19 )
ADD TARGET package0.asynchronous_file_target(set filename = 'c:\temp\ObservingLocking.log')
WITH
(
    MAX_MEMORY = 4096KB,
    EVENT_RETENTION_MODE = NO_EVENT_LOSS ,
    MAX_DISPATCH_LATENCY = 1 SECONDS,
    MEMORY_PARTITION_MODE = NONE,
    TRACK_CAUSALITY = ON,
    STARTUP_STATE = OFF
);
go

--start the event capturing 
ALTER EVENT SESSION ObservingLocking ON SERVER STATE = START
-- experiments workload here
--begin transaction
--xxxxxxxx
--rollback

--stop event capturing
ALTER EVENT SESSION ObservingLocking ON SERVER STATE = STOP
go

--remove extended event
DROP EVENT SESSION ObservingLocking ON SERVER
GO


--Read the captured event tracing data. I usually remove the trace files before a new test
declare @Temp table (ID int identity(1,1), EventData xml)
insert into @Temp(EventData)
select  cast(event_data as xml) event_data
 from sys.fn_xe_file_target_read_file ('c:\temp\ObservingLocking_0*', 'c:\temp\ObservingLocking0_*.xem', null, null) a;

 with x as (
        select
                a.ID, x.value('../@name', 'varchar(128)') EventName, x.value('../@timestamp', 'datetime') EventTime,
                x.value('@name','varchar(128)') [Col], case when isnull(rtrim(x.value('(./text)[1]', 'varchar(128)')), '') = '' then x.value('(.)[1]', 'varchar(128)') else x.value('(./text)[1]', 'varchar(128)') end [Value]
        from @Temp a
            cross apply EventData.nodes('//data') ed(x)
    )
select *
from(
    select ID, EventName, resource_type ResourceType,
            mode Mode, resource_0 Res0, resource_1 Res1,
            resource_2 Res2, lockspace_workspace_id, lockspace_sub_id,
            lockspace_nest_id, owner_type OwnerType,transaction_id TransID,
            database_id DBID, EventTime
    from x
    pivot( MAX([Value]) for Col in ([resource_type], [mode], [owner_type], [transaction_id], [database_id], [lockspace_workspace_id], [lockspace_sub_id], [lockspace_nest_id], [resource_0], [resource_1], [resource_2])) pvt
    ) y
where ResourceType not in ('METADATA') and Mode not in ('NL')
go

Then let's do some experiments in a new Query window.

--create test table in TestDB
create table test(id int identity,c1 varchar(10),c2 int);
--insert some data
insert into test (c1,c2)values('Tired',1),('Exciting',2),('Happy',3);
--go back to another query window and start event capturing
--issue a simple select statement
select c1,c2 from test
--go back to another window and stop the tracing
--now load the log and examine it

How to understand the result?

It says first the SQL Server acquired a shared lock on database, then it got released, then it acquired IS lock on object 2105058535 that is test table in this example, it went further to put an IS lock on a page in test table, then it was released, then the shared lock was acquired and release couple time on database.

Wait, why there is no expected S lock on the rows being retrieved?

Theoretically, when SQL Server tries to read with SELECT statement, it starts to apply an IS lock on the table, then page, then issue an S lock on a record that it is going to read, then release the S lock, then put S lock onto next record, it does so until all the records are accessed then release IS lock on the page, then the table. An exceptions here is if all the records in a page have not been changed since last time the page is written to disk, SQL Server will only apply IS lock on the page without having to use S locks on the records. This reduces the overhead of getting/releasing locks.


Note: IS lock never goes to ROW level, it follows a patch of database then table and then page.
It is an intention of S lock on lower level.

Credit of this post is going to MVP John Huang, as well as MSDN.
http://msdn.microsoft.com/en-us/library/ff878413.aspx
http://msdn.microsoft.com/en-us/library/bb630340%28v=sql.105%29.aspx

No comments: