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

Wednesday, November 28, 2012

Components of SQL Server Engine

Four major components:

Protocol layer: interprete betwwen client and relational engine
Relational engine/Query Processor: parse,compile,optimize query.
Storage engine: access data
SQLOS: thread management, deadlock detention, buffer management



Wednesday, November 21, 2012

Examine The Datetime Values

Accuracy of Datetime in SQL Server is 0.00333 millisecond. The millisecond part of value will be converted to a closer times of 0.00333, which is also rounded up to the precision of 1/1000.

0.00333 * 2 = 0.00666
0.00333 * 3 = 0.00999

DECLARE @testDT DATETIME
SET@testDT ='2012-11-11 00:01:00.003'
--this returns  '2012-11-11 00:01:00.003'
SELECT @testDT
SET  @testDT ='2012-11-11 00:01:00.004'
--This returns  '2012-11-11 00:01:00.003'. Because 0.004 is closer to 0.00333 than 0.00666
SELECT @testDT
SET  @testDT ='2012-11-11 00:01:00.005'
-- --This returns  '2012-11-11 00:01:00.007'. Because 0.005 is closer to 0.00666 than 0.00333
--0.00666-0.005=0.00166; 0.005-0.00333= 0.00167
SELECT @testDT
SET  @testDT ='2012-11-11 00:01:00.006'
--SET  @testDT ='2012-11-11 00:01:00.007' 
--SET  @testDT ='2012-11-11 00:01:00.008'  
--above values will all be converted to 0.007 because they are closer to 0.00666 than 0.00999
SELECT @testDT
SET  @testDT ='2012-11-11 00:01:00.009' 
--This returns  '2012-11-11 00:01:00.010'
SELECT @testDT


DBCC IND

Another copy and paste article mainly originated from SQL Server Storage Engine Blog  and SQL Server 2008 internals.

Syntax

DBCC IND ( { 'dbname' | dbid }, { 'objname' | objid },
{ nonclustered indid | 1 | 0 | -1 | -2 } [, partition_number] )

DBCC IND command is used to see which pages have which data, as well as which pages precede and follow various pages in all levels of the index.Basically, examine composition of index.

The first parameter is the database name or the database ID. The second parameter is an
object name or object ID within the database; the object can be either a table or an indexed
view. The third parameter is a specifi c nonclustered index ID (2-250 or 256-1005) or the
values 1, 0, –1, or –2. The values for this parameter have the following meanings:
■ 0 Displays information for in-row data pages and in-row IAM pages of the specifi ed
object.
■ 1 Displays information for all pages, including IAM pages, data pages, and any
existing LOB pages or row-overflow pages of the requested object. If the requested
object has a clustered index, the index pages are included.
■ –1 Displays information for all IAMs, data pages, and index pages for all indexes on
the specifi ed object. This includes LOB and row-overflow data.
■ –2 Displays information for all IAMs for the specified object.
■ Nonclustered index ID Displays information for all IAMs, data pages, and index
pages for one index. This includes LOB and row-overflow data that might be part of
the index’s included columns.

Column Descriptions for DBCC IND Output
  • PageFID - the file ID of the page
  • PagePID - the page number in the file
  • IAMFID - the file ID of the IAM page that maps this page (this will be NULL for IAM pages themselves as they're not self-referential)
  • IAMPID - the page number in the file of the IAM page that maps this page
  • ObjectID - the ID of the object this page is part of
  • IndexID - the ID of the index this page is part of
  • PartitionNumber - the partition number (as defined by the partitioning scheme for the index) of the partition this page is part of
  • PartitionID - the internal ID of the partition this page is part of
  • PageType - the page type. Some common ones are:
    • 1 - data page
    • 2 - index page
    • 3 and 4 - text pages
    • 8 - GAM page
    • 9 - SGAM page
    • 10 - IAM page
    • 11 - PFS page
  • IndexLevel - what level the page is at in the index (if at all). Remember that index levels go from 0 at the leaf to N at the root page (except in clustered indexes in SQL Server 2000 and 7.0 - where there's a 0 at the leaf level (data pages) and a 0 at the next level up (first level of index pages))
  • NextPageFID and NextPagePID - the page ID of the next page in the doubly-linked list of pages at this level of the index
  • PrevPageFID and PrevPagePID - the page ID of the previous page in the doubly-linked list of pages at this level of the index

Create a table to hold result dumped from DBCC IND. This technique is also often used to take snapshot of database status.

CREATE TABLE IndexPages
(PageFID tinyint,
PagePID int,
IAMFID tinyint,
IAMPID int,
ObjectID int,
IndexID tinyint,
PartitionNumber tinyint,
PartitionID bigint,
iam_chain_type varchar(30),
PageType tinyint,
IndexLevel tinyint,
NextPageFID tinyint,
NextPagePID int,
PrevPageFID tinyint,
PrevPagePID int,
Primary Key (PageFID, PagePID));

TRUNCATE TABLE sp_IndexPages;

INSERT INTO sp_IndexPages
EXEC ('DBCC IND (AdventureWorks2008, [Sales.SalesOrderDetail], -1)');

SELECT IndexLevel
, PageFID
, PagePID
, PrevPageFID
, PrevPagePID
, NextPageFID
, NextPagePID
FROM IndexPages
ORDER BY IndexLevel DESC, PrevPagePID;

Note: Use sys.dm_db_index_physical_stats to check the index level and its page numbers in each level.

SELECT index_depth AS D
, index_level AS L
, record_count AS 'Count'
, page_count AS PgCnt
, avg_page_space_used_in_percent AS 'PgPercentFull'
, min_record_size_in_bytes AS 'MinLen'
, max_record_size_in_bytes AS 'MaxLen'
, avg_record_size_in_bytes AS 'AvgLen'
FROM sys.dm_db_index_physical_stats
(DB_ID ('test')
, OBJECT_ID ('test')
, 1, NULL, 'DETAILED');

Tuesday, November 20, 2012

DBCC PAGE

This is copied from http://blogs.msdn.com/b/sqlserverstorageengine/archive/2006/06/10/625659.aspx

dbcc page ( {'dbname' | dbid}, filenum, pagenum [, printopt={0|1|2|3} ])


The printopt parameter has the following meanings:

  • 0 - print just the page header
  • 1 - page header plus per-row hex dumps and a dump of the page slot array (unless its a page that doesn't have one, like allocation bitmaps)
  • 2 - page header plus whole page hex dump
  • 3 - page header plus detailed per-row interpretation

The per-row interpretation work for all page types, including allocation bitmaps.
By default, the output is sent to the errorlog. If you want the output to come back to your current connection, turn on trace flag 3604.

DBCC traceon(3604)
DBCC PAGE (master, 1, 1, 0);