Archive

Archive for the ‘SQL Server 2012’ Category

Tracking Transaction Log Records With SQL Server 2012 Extended Events

29/01/2013 Leave a comment

Last week I tested sqlserver.transaction_log event in SQL Server 2012 SP1 CU2. I wanted to compere results from fn_dblog() and transaction_log event. Jonathan Kehayias (blog|twitter) wrote here about this event while SQL Server 2012 was in CTP1.
At that time, there were 70 Log Operations and 29 Contexts for those operations available in SQL Server Denali CTP1. (Information taken from Jonathan’s post)

 In SQL Server 2012 SP1 CU2 there are 73 Log Operations and 32 Contexts for those operations.
Description for transaction_log event is: “Occurs when a record is added to the SQL Server transaction log. This is a very high volume event that will affect the performance of the server. Therefore, you should use appropriate filtering to reduce the number of events, and only use this event for targeted troubleshooting during a short time period.”

From description transaction_log event should capture all log records that will be written to transaction log file. So I expected same number of log operations returned from transaction_log event and fn_dblog() function. Let’s confirm that.

For testing I will create database TruncateDb and set database to simple recovery mode so the log clears out on CHECKPOINT. Then I will create a table and insert 1 record in it. I will create event session named TransactionLog to capture the sqlserver.transaction_log event for the database TruncateDb and to store events to the file C:\XELogs\TransactionLog.xel.

CREATE DATABASE TruncateDb;
GO
USE TruncateDb;
GO
ALTER DATABASE TruncateDb SET RECOVERY SIMPLE;
GO

-- Create table
CREATE TABLE dbo.t1 (c1 INT IDENTITY(1,1), c2 CHAR (8000));
GO
-- Insert 1 record
INSERT INTO dbo.t1(c2)
SELECT 'a';
GO

-- Create Xevent session
DECLARE @sqlcmd nvarchar(2000) = '
CREATE EVENT SESSION [TransactionLog] ON SERVER
ADD EVENT sqlserver.transaction_log(
    ACTION(package0.event_sequence)
    WHERE ([database_id]=('+ cast(DB_ID() as varchar(3))+')))
ADD TARGET package0.event_file(SET filename=N''C:\XELogs\TransactionLog.xel'')
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,
STARTUP_STATE=OFF)'
EXEC (@sqlcmd)
GO

When the event session is created, I will execute CHECKPOINT on the database so that transaction log clears out and fn_dblog() function will return only 3 records.

-- clear the log
CHECKPOINT;
GO
-- returns only 3 records
SELECT * FROM fn_dblog (NULL, NULL);
GO

checkpoint

Then I’ll start event session, truncate table t1 and stop event session TransactionLog.

--Start session
ALTER EVENT SESSION TransactionLog
ON SERVER
STATE=START;
GO
USE TruncateDb;
GO
-- Truncate table
TRUNCATE TABLE t1;
GO
--Stop session
ALTER EVENT SESSION TransactionLog
ON SERVER
STATE=STOP
GO

Now I can query data from event file and compare it with records from fn_dblog().

-- records from fn_dblog()
SELECT [Current LSN], Operation, Context, [Xact ID], [Transaction ID], [Log Record Fixed Length],
[Log Record Length], [Log Reserve], AllocUnitId
FROM fn_dblog (NULL, NULL);

-- records from transaction_log event
SELECT 
    XEvent.value('(event/@name)[1]', 'varchar(50)') AS event_name,
	XEvent.value('(event/data[@name="operation"]/text)[1]', 'nvarchar(100)') as log_op_name,
    XEvent.value('(event/data[@name="transaction_id"]/value)[1]', 'int') as transaction_id,
	XEvent.value('(event/data[@name="log_record_size"]/value)[1]', 'nvarchar(100)') as log_record_size,
	XEvent.value('(event/data[@name="context"]/text)[1]', 'nvarchar(20)') as context,
	XEvent.value('(event/data[@name="replication_command"]/value)[1]', 'int') as replication_command,
	XEvent.value('(event/data[@name="alloc_unit_id"]/value)[1]', 'nvarchar(100)') as alloc_unit_id,
	XEvent.value('(event/data[@name="transaction_start_time"]/value)[1]', 'datetime2') as transaction_start_time
FROM (
	SELECT CAST(event_data AS XML) AS XEvent
	FROM sys.fn_xe_file_target_read_file('C:\XELogs\TransactionLog*.xel',null,null,null) )as src 
ORDER BY XEvent.value('(event/action[@name="event_sequence"]/value)[1]', 'int')

fn_dblog()

transaction_log

First 3 records from fn_dblog() are generated by CHECKPOINT and they aren’t included in event session file because I started event session after checkpoint. The first record from event file is LOP_BEGIN_XACT with transaction_id = 74018. It correspond to the [Xact ID] of LOP_BEGIN_XACT log record returned in row 4 of the fn_dblog().

We can see that event session file returns only 12 records while we have 16 records from fn_dblog() after checkpoint. We can see that LOP_COUNT_DELTA operations missing from event session file.

If we select only LOP_COUNT_DELTA operations from fn_dblog() we can see that LOP_COUNT_DELTA operations are used for updating system catalog and that Transaction ID is different (0000:00000000).

SELECT [Current LSN], Operation, Context, [Transaction ID], 
AllocUnitId, AllocUnitName
FROM fn_dblog (NULL, NULL)
WHERE Operation ='LOP_COUNT_DELTA'

LP_COUNT_DELTA

Although descriptions says that transaction_log event capture all log records that will be written to transaction log file it isn’t true. I also tested transaction_log event with INSERT statements and noticed that transaction_log event didn’t capture:

non-transactional updates

It seems that transaction_log event doesn’t capture log records with Transaction ID=0000:00000000. These log records are not part of transactional updates (called being non-transactional – thanks Paul Randal for naming it here).

How to remove “Server name” entry from “Connect to Server” dialog in SSMS

20/11/2012 Leave a comment

If you connect to a lot of different SQL servers with SQL Server Tools (SSMS, SQL Profiler etc.), the list of servers in “Connect to Server” dialog become large. Before SQL Server 2012 there was no way to delete individual server entry from the list or supported way to delete the list.

Some time ago, somewhere on the web I found a way how to delete the list of servers in “Connect to Server” dialog.
For SQL Server 2005 method is to close SSMS and then delete mru.dat file. On windows 2003 server file is located at %UserProfile%\Application Data\Microsoft\Microsoft SQL Server\90\Tools\Shell .
For SQL Server 2008/2008R2 method is to close SSMS and then delete SqlStudio.bin file. On windows 2003 server file is located at %UserProfile%\Application Data\Microsoft\Microsoft SQL Server\100\Tools\Shell. On Windows 7 and Windows 2008 server file is located at %UserProfile%\AppData\Roaming\Microsoft\Microsoft SQL Server\100\Tools\Shell.
A few days ago, I used the same method for SSMS 2012 by deleting SqlStudio.bin file from %UserProfile%\AppData\Roaming\Microsoft\SQL Server Management Studio\11.0.

But the problem in using these methods is that it’s unsupported by Microsoft and we lose user specific settings in SSMS.

Today I found that with SQL Server 2012 we have a supported way to delete server name from the list of servers in “Connect to Server” dialog by simply selecting the server name from the drop down list and then pressing the delete button.
It is documented in this blog post.

Reads in Read Committed Isolation Level

23/07/2012 Leave a comment

I’ll start this blog post with a question: “What kinds of locks in SQL Server are acquired during simple select statement in read committed isolation level (READ_COMMITTED_SNAPSHOT database option is set to OFF)?”

Few days ago, I would answer: “Intent-Shared locks at table and pages level and shared locks on a row by row basis.”

But, I found out that it’s not correct.  In some situations shared locks are not issued at all. Let’s demonstrate that. First let’s create a database and table with 3 rows.

 CREATE DATABASE TestLocks
GO
ALTER DATABASE TestLocks SET READ_COMMITTED_SNAPSHOT OFF
GO
USE TestLocks
GO
-- Create table
CREATE TABLE dbo.DemoTable ( id int, col1 varchar(4000))
GO
-- Insert 3 rows = 2 pages
INSERT INTO dbo.DemoTable
SELECT 1, REPLICATE('a',4000) UNION ALL
SELECT 2, REPLICATE('a',4000) UNION ALL
SELECT 3, REPLICATE('a',4000) 

If we run DBCC IND we can see that table contains 2 data pages (in my case page 78 and 80).

DBCC IND('TestLocks','DemoTable',1)

Let’s run simple select statement.

SET TRANSACTION ISOLATION LEVEL READ COMMITTED
GO
SELECT * FROM dbo.DemoTable
GO

I used SQL Profiler to check acquired lock.

We can see that only Intent-Shared (IS) locks at the table and page levels are issued. There are no row-level shared (S) locks.

I was very surprised when I noticed that. I thought that shared locks are always acquired and that optimizer only decides about granularity of locks (row or page level shared lock).

I searched about this lock behavior in SQL Server and found Paul White’s post “The Case of the Missing Shared Locks” where he wrote about locking optimization.

It seems that SQL Server avoids acquiring row-level shared (S) locks when it knows that no data has changed on a page. I didn’t find more information about shared lock optimization. If you know more you can leave a comment.

SQL Server 2012 RTM has released to manufacturing

07/03/2012 Leave a comment

Microsoft announced that SQL Server 2012 RTM has released to manufacturing and general availability is scheduled for 1 April 2012.

You can download an evaluation of the SQL Server 2012 RTM today. 

Microsoft SQL Server 2012 Feature Pack is available here.

Today, don’t forget to attend the SQL Server 2012 Virtual Launch Event.

SQL Server 2012: Page restore from the SSMS UI

13/01/2012 1 comment

In my last blog post I wrote about various ways to detect damaged pages in the database and how to perform page restores in SQL Server 2005/2008. Same apply to SQL Server 2012. SQL Server 2008 doesn’t have UI support for page restore but SQL Server 2012 Management Studio (SSMS) brings us a nice UI support for page restore. If you prefer to do page restores with UI here are the steps:

    1. In SSMS Object Explorer right click on database -> Tasks -> Restore then click on Page…PR2012_1

Restore Page window will be opened.

2. In Restore Page window, chosen database is selected (1) and Pages grid (2) is automatically populated with damaged pages from msdb.dbo.suspect_pages table (see picture below).

PR2012_2

From Restore Page window you can run DBCC CHECKDB (3) to find if there are more damaged pages in the database or you can add additional pages if you want using Add (4) button. You also need to set the location for the log backup (5). Backup sets part (6) shows all backups that will be used to bring data pages up to date with the current log file.

3. Final step is to click OK button and damaged pages are restored. Open-mouthed smile

SQL Server 2012: Detecting Sort Warnings with Extended Events (sort_warning event) – Part 2

07/12/2011 Leave a comment

In my last post, SQL Server 2012: Detecting Sort Warnings with Extended Events (sort_warning event) I showed how to use sort_warning event with sql_text action to detect sort warnings in database with statements sent to SQL server instance. We also saw that using sql_text action we know what stored procedure or batch are causing sort warnings. But sometimes that isn’t enough.

If we have a stored procedure or a batch with more statements that use sort operator we would like to know the information about the exact statement inside stored procedure or batch that caused sort_warning event. In SQL Server 2012 that can be achieved using tsql_stack or tsql_frame actions. Action tsql_stack is available in SQL Server 2008 (R2) while tsql_frame action is new in SQL Server 2012.

Below is description for tsql_stack and tsql_frame actions from metadata DMV:

In this post I will use tsql_frame action. To run all examples from this post we need TestSortWarnings database I used in my last post. This time I will create Extended Events session SortWarning with event_file target and it will capture sqlserver.sort_warning event with sqlserver.sql_text and sqlserver.tsql_frame actions. Event session is configured with a predicate on the sqlserver.database_id to track sort warnings only on TestSortWarnings database. Before you execute the script, you need to replace a value for database_id with a value returned by SELECT DB_ID(‘TestSortWarnings’) statement. Next script will create and start Event session SortWarning.

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='SortWarning')
DROP EVENT SESSION [MultipleDataFiles] ON SERVER;
-- Create Event Session SortWarning
CREATE EVENT SESSION SortWarning ON SERVER
ADD EVENT sqlserver.sort_warning(
ACTION(sqlserver.sql_text,sqlserver.tsql_frame)
WHERE (sqlserver.database_id=(7))) -- replace database_id
ADD TARGET package0.event_file(SET filename = N'C:\Log\SortWarning.xel',max_file_size=(100))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS)
GO
-- Start the Event Session
ALTER EVENT SESSION SortWarning
ON SERVER
STATE=START
GO

With the event session created and started we can run next script which will generate sort warning event.

USE TestSortWarnings
GO
DECLARE @T1 TABLE (Col1 int, Col2 varchar(8000))
-- Insert data to table variable
INSERT INTO @T1 SELECT * FROM dbo.TestTable
-- Return data sorted on Col2 column
SELECT * FROM @T1
ORDER BY Col2 ASC
GO

Let’s read the data from the extended events log file.

SELECT CAST(event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file('C:\Log\SortWarning*.xel',null,null,null)

Here is the result:

Sort_warning_type and sql_text are collected (1) and we see information collected with tsq_frame action (2). We can use sql_handle and offset information (offsetStart and offsetEnd) from tsql_frame action element and sys.dm_exec_sql_text DMF to return the specific statement which caused sort_warning. Here is the script to retrieve data we need:

SELECT
x.object_name AS event_name,
DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), vent_data.value('(event/@timestamp)[1]', 'datetime')) AS timestamp,
event_data.value('(event/data[@name="sort_warning_type"]/text)[1]', 'varchar(20)') AS sort_warning_type,
event_data.value('(event/action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text,
frame_data.value('./@level','int') AS frame_level,
OBJECT_NAME(st.objectid, st.dbid) AS objectname,
SUBSTRING(st.text, (frame_data.value('./@offsetStart','int')/2)+1,
((CASE frame_data.value('./@offsetEnd','int')
WHEN -1 THEN DATALENGTH(st.text)
ELSE frame_data.value('./@offsetEnd','int')
END - frame_data.value('./@offsetStart','int'))/2) + 1) AS sort_warning_statement
FROM (SELECT object_name, CAST(event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file('C:\Log\SortWarning*.xel',null,null,null)) x
CROSS APPLY x.event_data.nodes('event/action[@name="tsql_frame"]/value/frame') Frame(frame_data)
OUTER APPLY sys.dm_exec_sql_text(CONVERT(varbinary(max), frame_data.value('./@handle','varchar(max)'),1)) st

The results:

From the result we can see that frame_level for batch is 0 and objectname is NULL. Sort_warning_statement column shows us what specific statement from the batch is causing sort warning while sql_text column returns complete batch sent to a SQL server instance. It gives us all information about sort warnings to the statement level.

Now let’s execute 2 stored procedures dbo.Test and dbo.Test1.

EXEC dbo.test
GO
EXEC dbo.test1
GO

If we retrieve the event data from the event session target again we will see 3 new records.

The output from event_file target:

We see that frame_level for stored procedure is 1 and we have the name of stored procedure and exact statement inside the stored procedure which caused sort warning. That’s all we need.

Let’s see what will happened if we encounter stored procedure nesting. In the next script I will create and execute stored procedure dbo.test2 which calls dbo.test1 procedure.

CREATE PROCEDURE dbo.Test2
AS
SET NOCOUNT ONEXEC dbo.Test1
GO

EXEC dbo.Test2
GO

The output from event_file target:

We can see that even with stored procedure nesting we have all necessary information about sort warnings event. Frame_level column is 2 and it tells us the nesting level for the stored procedure responsible for sort warning event.

I like how much information we can get with SQL Server 2012 extended events. Open-mouthed smile In this post I tried to show how easily we can track sort warnings to the statement level in SQL Server 2012.

I hope that you have learned something new. 🙂

SQL Server 2012: Detecting Sort Warnings with Extended Events (sort_warning event)

05/12/2011 1 comment

Sort warnings events will rise when sort operation is performed in a query and it doesn’t fit into memory. In this case, SQL Server needs to spill the sort operation into tempdb which can result in a very slow physical operation especially if multiple passes to tempdb is needed for sorting the data. Ideally, there shouldn’t be any sort warnings on a server.

How to detect Sort Warnings in SQL Server 2008 (R2)?

In SQL Server 2008 (R2), sort warning event can be detected using SQL Profiler. SQL Server default trace has this event included by default. But using Sort Warning event in SQL Profiler we can’t capture what statements are causing these warnings because TextData column isn’t available.  Solomon Rutzky presented a way of finding statements by using profiler trace, trigger and DBCC INPUTBUFFER.

SQL Server 2008 (R2) doesn’t provide an event through Extended Events to track sort warnings. In SQL Server 2012 this will change.

How to detect Sort Warnings in SQL Server 2012 RC0?

In SQL Server 2012 RC0, the number of event has expanded to 616 and one of these new events is sort_warning event. Extended Events Sort_warning event can be used to detect what statements are causing sort warnings.  I will show how to use sort_warning event to detect sort warnings in database. Let’s create a new database with a simple table and stored procedures for testing.

-- Create TestSortWarnings database
CREATE DATABASE TestSortWarnings
GO
USE TestSortWarnings
GO
-- Create TestTable
CREATE TABLE dbo.TestTable (Col1 int IDENTITY(1,1), Col2 varchar(8000))
GO
-- Insert data into table
INSERT INTO dbo.TestTable (Col2)
SELECT REPLICATE('A','8000')
GO 200

CREATE PROCEDURE dbo.Test
AS
SET NOCOUNT ON

-- Declare table variable
DECLARE @T1 TABLE (Col1 int, Col2 varchar(8000))
-- Insert data to table variable
INSERT INTO @T1
SELECT * FROM dbo.TestTable

-- Return data sorted on Col2 column
SELECT * FROM @T1
ORDER BY Col2 ASC
GO

CREATE PROCEDURE dbo.Test1
AS
SET NOCOUNT ON

-- Declare table variable
DECLARE @T1 TABLE (Col1 int, Col2 varchar(8000))
-- Insert data to table variable
INSERT INTO @T1
SELECT * FROM dbo.TestTable
-- Return data sorted on Col2 column
SELECT * FROM @T1
ORDER BY Col2 ASC
OPTION (RECOMPILE)

-- Example with DINSTINCT
SELECT DISTINCT Col2 FROM @T1
-- Example with GROUP BY
SELECT Col2, COUNT(*) FROM @T1
GROUP BY Col2

Table TestTable has 2 columns, no indexes and has 200 rows. Two stored procedures will generate sort warnings during execution. I will use this database, table and stored procedures in all my examples.

Detecting Sort Warnings with Extended Events

SQL Server 2012 management studio (SSMS) has UI for creating and managing Extended Events and it will be much easier to use it. Great thing is that SSMS includes an event session data viewer for all targets except the ETW file target. If you want to learn more about it you can read a post “Introducing the Extended Events User Interface” written by SQL Team. Post is focused on the mechanisms for creating event sessions and displaying event session data.

In this post I will use T-SQL but everything from this post can be done with UI. Next script will create event session SortWarning with ring_buffer target. It will capture sqlserver.sort_warning event with sqlserver.sql_text action. Event session is configured with a predicate on the sqlserver.database_id to track sort warnings only on TestSortWarnings database. Before you execute the script, you need to replace a value for database_id with a value returned by SELECT DB_ID(‘TestSortWarnings’) statement.


CREATE EVENT SESSION SortWarning ON SERVER
ADD EVENT sqlserver.sort_warning(
  ACTION(sqlserver.sql_text)
  WHERE (sqlserver.database_id=(7))) -- Replace database_id
ADD TARGET package0.ring_buffer
GO

-- Start the Event Session
ALTER EVENT SESSION SortWarning
ON SERVER
STATE=START
GO

I will use prepared test data to simulate sort warnings. I will also include Actual Execution Plan to demonstrate new warnings information in it.

USE TestSortWarnings
GO
DECLARE @T1 TABLE (Col1 int, Col2 varchar(8000))
-- Insert data to table variable
INSERT INTO @T1 SELECT * FROM dbo.TestTable

-- Return data sorted on Col2 column
SELECT * FROM @T1
ORDER BY Col2 ASC
GO

If we look at Active Execution Plan we can see a warning on sort operator.

Let’s execute the stored procedure Test:

 EXEC dbo.Test
GO 

Let’s retrieve the event data from the event session target:

DECLARE @XEvent XML
SELECT @XEvent = CAST(target_data AS XML)
FROM sys.dm_xe_sessions s
INNER JOIN sys.dm_xe_session_targets t
  ON s.address = t.event_session_address
WHERE s.name = 'SortWarning'
AND t.target_name = 'ring_buffer'

SELECT
  event_data.value('(./@name)[1]', 'varchar(20)') AS event_name,
  DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), event_data.value('(./@timestamp)[1]', 'datetime')) AS timestamp,
  event_data.value('(./data[@name="sort_warning_type"]/text)[1]', 'varchar(20)') AS sort_warning_type,
  event_data.value('(./action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text
FROM @XEvent.nodes('RingBufferTarget[1]/event') XE(event_data)
 

Results:

Sort_warning event is raised 2 times. We see that singe pass over the data are required to sort the data and statements which caused spill to tempdb.  Let’s now execute stored procedure dbo.Test1 (with included Actual Execution plan).

 EXEC dbo.Test1
GO 

If we look at Actual Execution Plan we can see that stored procedure Test1 caused 2 sort warnings. (1) Second statement in stored procedure with ORDER BY didn’t cause sort warnings because of OPTION (RECOMPILE). Statements with DISTINCT (2) and GROUP BY (3) caused sort warnings.

If we retrieve the event data from the event session target again we will see 2 new records.

As we can see, by capturing only sqlserver.sort_warning event and sqlserver.sql_text action in event session we have information about the statement sent from a client to an SQL Server. Sometimes, that can be enough, but in some situations we need more information. If we have a stored procedure, which can be nested for example, with more statements that use sort operator (like Test1 stored procedure from our example), we will not know exactly which statements inside a stored procedure are causing sort warning events.

My next post will show how we can track sort warnings to the statement level inside a stored procedure.