Observe Locking Behaviour with SQL Profiler

Setup

 Assuming you have created test table according to definition in a previous post Observing Locking Behaviour With Extended Events, now launch SQL Server Profiler and define a trace that captures Lock:Acquired and Lock:Released. To avoid noises in the captured events, it's better to only capture events from the interested database and filter out the locking events upon the database.

After creating the tace, it can be exported as tracing script so that you can reuse it later.

Then the trace can be started to trace any statement you want to experiment.

Below is a screen shot of monitored locking events on "select c1,c2 from test".

Control the Tracing

When starting a server side SQL Trace with the script exported from the SQL Profiler, it's better to also know these tools to control the trace and view the captured events.

To abserve the tracing informaiton in the system,
in SQL 2000, use
    SELECT * FROM ::fn_trace_getinfo(default),
in SQL 2005 and above, use
    SELECT * FROM  fn_trace_getinfo (default)
    SELECT * FROM sys.traces
To start(1), stop(0) and close(2) a trace, use
exec sp_trace_setstatus @traceId, 2

To get data from tracing file, in SQL 2000, use ::fn_trace_gettable.
    SELECT * into xxx200 FROM ::fn_trace_gettable('c:\temp\mytrace.trc', default)

In SQL 2005 and above, use sys.fn_trace_gettable.
    SELECT * INTO temp_trc FROM fn_trace_gettable('c:\temp\mytrace.trc', default);

Observe Insert Operation

Start trace and Execute this statement:

insert into test default values

This is the events being captured.

We can see it clearly that it puts IX lock on table the first, then IX lock on the page where the record is to be inserted, then X lock on the row where it ends up, then everything goes a backward order, the X lock on the row is released, then the IX on the page is released, at last the IX on the table is released.

Further checking the page content, we can verify the 1:55:4 contains the data just being inserted.

DBCC traceon(3604)
go
dbcc page (19,1,55,3) 
Slot 4 Offset 0xba Length 15

Record Type = PRIMARY_RECORD         Record Attributes =  NULL_BITMAP     Record Size = 15

Memory Dump @0x0000000012D5A0BA

0000000000000000:   10000c00 05000000 40218cb5 030006††††........@!Œµ... 

Slot 4 Column 1 Offset 0x4 Length 4 Length (physical) 4

id = 5                              

Slot 4 Column 2 Offset 0x0 Length 0 Length (physical) 0

c1 = [NULL]                         

Slot 4 Column 3 Offset 0x0 Length 0 Length (physical) 0

c2 = [NULL]                         

Observe Delete Operation

Start tracing and execute this statement.
DELETE FROM test where id=5

Since there's no index created for this table yet, a table scan happens. Below is the captured events.

We can see an IX lock is put on table the first, then it puts IU lock on the page it is accessing, then it puts and releases U locks while searching through each slot in the page, until it finds the slot 4 that contains the row to be deleted. It then changes the IU lock on the page to IX lock, and puts an X lock on the targeted row. It then removes the row. After that, it continues its searching until the end of the table. After the expected operation is done, it goes backward to release the lock gained. It released the X lock on slot 4, then IX lock on page, IX lock on table.

Delete with Clustered Index

Define a clustered primary key on the table:
Alter table test add constraint PK_test_id primary key clustered (id)
After this, the table will be moved to different pages.

Start tracing and issue this statement:

DELETE FROM test where id=3

Oops, it has much more events happening than the last test. An example that table scan is more efficient than the index seek on a small table. I won't post the result here because the tool has been provided.

Major differences are
1. U lock no longer being observed, S lock is used to search the data
2. RID look-up is replaced with Key look-up
3. Index metadata retrieving is extra operation
4. Index operation is extra operation

Exported Tracing Script

Below is a trace script generated by the SQL Profiler for SQL Server 2005 and above.


/****************************************************/
/* Created by: SQL Server 2008 R2 Profiler          */
/* Date: 12/05/2012  12:24:57 AM         */
/****************************************************/


-- Create a Queue
declare @rc int
declare @TraceID int
declare @maxfilesize bigint
set @maxfilesize = 5

-- Please replace the text InsertFileNameHere, with an appropriate
-- filename prefixed by a path, e.g., c:\MyFolder\MyTrace. The .trc extension
-- will be appended to the filename automatically. If you are writing from
-- remote server to local drive, please use UNC path and make sure server has
-- write access to your network share

exec @rc = sp_trace_create @TraceID output, 0, N'InsertFileNameHere', @maxfilesize, NULL
if (@rc != 0) goto error

-- Client side File and Table cannot be scripted

-- Set the events
declare @on bit
set @on = 1
exec sp_trace_setevent @TraceID, 24, 32, @on
exec sp_trace_setevent @TraceID, 24, 56, @on
exec sp_trace_setevent @TraceID, 24, 1, @on
exec sp_trace_setevent @TraceID, 24, 57, @on
exec sp_trace_setevent @TraceID, 24, 3, @on
exec sp_trace_setevent @TraceID, 24, 51, @on
exec sp_trace_setevent @TraceID, 24, 4, @on
exec sp_trace_setevent @TraceID, 24, 12, @on
exec sp_trace_setevent @TraceID, 24, 22, @on
exec sp_trace_setevent @TraceID, 60, 32, @on
exec sp_trace_setevent @TraceID, 60, 56, @on
exec sp_trace_setevent @TraceID, 60, 1, @on
exec sp_trace_setevent @TraceID, 60, 57, @on
exec sp_trace_setevent @TraceID, 60, 3, @on
exec sp_trace_setevent @TraceID, 60, 51, @on
exec sp_trace_setevent @TraceID, 60, 4, @on
exec sp_trace_setevent @TraceID, 60, 12, @on
exec sp_trace_setevent @TraceID, 60, 22, @on
exec sp_trace_setevent @TraceID, 23, 32, @on
exec sp_trace_setevent @TraceID, 23, 56, @on
exec sp_trace_setevent @TraceID, 23, 1, @on
exec sp_trace_setevent @TraceID, 23, 57, @on
exec sp_trace_setevent @TraceID, 23, 22, @on
exec sp_trace_setevent @TraceID, 23, 3, @on
exec sp_trace_setevent @TraceID, 23, 51, @on
exec sp_trace_setevent @TraceID, 23, 4, @on
exec sp_trace_setevent @TraceID, 23, 12, @on


-- Set the Filters
declare @intfilter int
declare @bigintfilter bigint
--Set the database id here
set @intfilter = 19
exec sp_trace_setfilter @TraceID, 3, 0, 0, @intfilter
--filter out database level event
set @intfilter = 2
exec sp_trace_setfilter @TraceID, 57, 0, 1, @intfilter

-- Set the trace status to start
exec sp_trace_setstatus @TraceID, 1

-- display trace id for future references
select TraceID=@TraceID
goto finish

error:
select ErrorCode=@rc

finish:
go

--stop the tracing
exec sp_trace_setstatus @TraceID, 0
--close the tracing
exec sp_trace_setstatus @TraceID, 2

--load trace information into table for further analysis
--SELECT * INTO temp_trc FROM fn_trace_gettable('c:\temp\mytrace.trc', default);

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