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);