Archive

Archive for the ‘Immersion Events’ Category

Using dm_tran_database_transactions and a First Step to Converting LSNs

June 1, 2012 1 comment

In my last post, I showed how to use fn_dblog to read the transaction log. In this post, I will demonstrate using sys.dm_tran_database_transactions DMO to get information about executing transactions. You can find the complete result set for the DMO at this Books Online entry. For this post, I am interested in the following results:

SELECT DB_NAME(database_id),                                                -- Return the database name
database_transaction_log_bytes_used,                                        -- Log bytes used
database_transaction_log_bytes_reserved,                                    -- Log bytes reserved
master.dbo.fn_convertnumericlsntobinary(database_transaction_begin_lsn),    -- Beginning lsn of the transaction
master.dbo.fn_convertnumericlsntobinary(database_transaction_last_lsn)      -- Last lsn of the transaction
FROM sys.dm_tran_database_transactions 
WHERE database_transaction_begin_lsn IS NOT NULL                            -- Confirm that the transaction has 
AND database_transaction_last_lsn IS NOT NULL                               -- a start and end lsn
AND database_transaction_state = 4                                          -- Indicates a transaction that has written to the transaction log
AND database_id = DB_ID()                                                   -- Return rows for the current database

The results look like this:

dm_tran_database_transactions results

 

You will notice that the lsns are being converted using fn_convertnumericlsntobinary. The code for this function is available here at step 3 of alternative approach 1. This is the first in a magical, multi-step odyssey to join the results of sys.dm_tran_database_transactions to fn_dblog.

My initial attempt was a straight join between the function and the DMO on transaction_id, which exists in both. I ran an explicit transaction without a commit, and compared the transaction_ids. The DMO returned the value 1200932 while the function returned 0005602A, the first decimal and the second hex. No big deal, just convert one of them. However, 1200932 converts to 125324 in hex. So, I was stumped but tried to make sense of it. Do I double it and add 30? After spending too much time trying to figure it out, I wrote Paul Randal (b|t) and explained my problem. His response? “The transaction IDs don’t match – annoyingly.”

So, with that bit of wisdom I set out to try another method. This involved using the lsn information from the DMO as input parameters to fn_dblog. My next post will show you more than you ever wanted to know about converting lsns.

Reading the Transaction Log Using fn_dblog

May 25, 2012 3 comments

One of my favorite sections of the SQLskills Internals Immersion Event was logging and recovery. I’ve enjoyed internals since I started working as a COBOL programmer. Figuring out what SQL Server is doing under the covers makes me happy.

We covered a number of methods of interrogating the transaction log, and I have been working to put them together. In my next few blog posts, I will cover two of them and detail the challenges I faced joining the results.

I was familiar with the table-based function fn_dblog from reading SQL Server 2008 Internals. It takes two optional parameters, start and end log sequence number (lsn). Running this code:

SELECT * FROM fn_dblog(NULL,NULL)

will return the entire contents of the transaction log. Replacing the NULLs with an lsn will limit the result set. That query returns 116 columns, which is much more information than I need. Adding the following select list returned the data I was interested in:

SELECT 
SPID,                         -- The process ID for the transaction
[Begin Time],                 -- The start time for the transaction
[Current LSN],                -- The lsn of this record            
[Previous LSN],               -- Previous lsn for this record
Operation,                    -- The operation performed by the log record
Context,                      -- The resource affected by the operation
[Log Reserve],                -- The space reserved for rollback in bytes
AllocUnitName,                -- The name a the affected allocation unit
[Page ID],                    -- The page ID of the affected page
[Number of Locks],            -- The number of locks held by the transaction
[Lock Information]            -- Information about the locks held and the resources locked
FROM fn_dblog(NULL, NULL) 

To generate the result set below, I ran a CHECKPOINT on a database in SIMPLE recovery model to clear out the transaction log. I then ran the following query:

INSERT INTO loginsert
VALUES
(1
,'abcdefghij')
GO

I’ve split the results into two parts. The first set contains everything up to the lock information:

fn_dblog results part one

 

You can see that SPID and Begin Time are only be populated for a BEGIN TRANSACTION (LOP_BEGIN_XACT in the log). The LOP_INSERT_ROWS operation shows the table inserted to and the page affected.

Finally, the Lock Information column demonstrates SQL Server’s lock escalation behavior. In the second half of the result set:

fn_dblog result part two

 

you can see SQL Server acquiring three locks. First, an intent exclusive lock is taken on a table. Second, an intent exclusive lock on a page. Finally, an exclusive lock is taken on a key. I thought this was a very cool representation of lock escalation.

My next posts will cover the following topics:

  • Using sys.dm_tran_database_transactions to see what transactions are executing on the system
  • More information than you thought possible about convert lsns
  • Joining those results to fn_dblog to the log records associated with each active transaction

SQL Server Log Space Reservation – Part II

April 30, 2012 2 comments

In my last post, I wrote about SQL Server reserving space for open transactions to account for potential rollback. This reserved space is released once the transaction commits. You can track the amount of space reserved using the sys.dm_tran_database_transactions DMO. In this post, I will demonstrate how expensive this space reservation can be for long-running transactions.

I created two databases to allow me to track log space reservation for two processes. The first will update all values in a 100,000-row tables 10 times, running all updates within single transaction. The second will run each update in an explicit transaction. Here is the script to create the database:

CREATE DATABASE [DUDLOOPTRAN]
 CONTAINMENT = NONE
 ON  PRIMARY 
( NAME = N'DUDLOOPTRAN_Data', FILENAME = N'D:\Data\DUDLOOPTRAN_01.mdf' , SIZE = 2097152KB , FILEGROWTH = 1048576KB )
 LOG ON 
( NAME = N'DUDLOOPTRAN_log', FILENAME = N'D:\Data\DUDLOOPTRAN_01.ldf' , SIZE = 8388608KB , FILEGROWTH = 2097152KB )
GO
ALTER DATABASE [DUDLOOPTRAN] SET COMPATIBILITY_LEVEL = 110
GO
ALTER DATABASE [DUDLOOPTRAN] SET ANSI_NULL_DEFAULT OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET ANSI_NULLS OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET ANSI_PADDING OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET ANSI_WARNINGS OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET ARITHABORT OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET AUTO_CLOSE OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET AUTO_CREATE_STATISTICS ON 
GO
ALTER DATABASE [DUDLOOPTRAN] SET AUTO_SHRINK OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET AUTO_UPDATE_STATISTICS ON 
GO
ALTER DATABASE [DUDLOOPTRAN] SET CURSOR_CLOSE_ON_COMMIT OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET CURSOR_DEFAULT  GLOBAL 
GO
ALTER DATABASE [DUDLOOPTRAN] SET CONCAT_NULL_YIELDS_NULL OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET NUMERIC_ROUNDABORT OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET QUOTED_IDENTIFIER OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET RECURSIVE_TRIGGERS OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET  DISABLE_BROKER 
GO
ALTER DATABASE [DUDLOOPTRAN] SET AUTO_UPDATE_STATISTICS_ASYNC OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET DATE_CORRELATION_OPTIMIZATION OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET PARAMETERIZATION SIMPLE 
GO
ALTER DATABASE [DUDLOOPTRAN] SET READ_COMMITTED_SNAPSHOT OFF 
GO
ALTER DATABASE [DUDLOOPTRAN] SET  READ_WRITE 
GO
ALTER DATABASE [DUDLOOPTRAN] SET RECOVERY FULL 
GO
ALTER DATABASE [DUDLOOPTRAN] SET  MULTI_USER 
GO
ALTER DATABASE [DUDLOOPTRAN] SET PAGE_VERIFY CHECKSUM  
GO
ALTER DATABASE [DUDLOOPTRAN] SET TARGET_RECOVERY_TIME = 0 SECONDS 
GO
USE [DUDLOOPTRAN]
GO
IF NOT EXISTS (SELECT name FROM sys.filegroups WHERE is_default=1 AND name = N'PRIMARY') ALTER DATABASE [DUDLOOPTRAN] MODIFY FILEGROUP [PRIMARY] DEFAULT
GO

CREATE DATABASE [DUDONETRAN]
 CONTAINMENT = NONE
 ON  PRIMARY 
( NAME = N'DUDONETRAN_Data', FILENAME = N'D:\Data\DUDONETRAN_01.mdf' , SIZE = 2097152KB , FILEGROWTH = 1048576KB )
 LOG ON 
( NAME = N'DUDONETRAN_log', FILENAME = N'D:\Data\DUDONETRAN_01.ldf' , SIZE = 8388608KB , FILEGROWTH = 2097152KB )
GO
ALTER DATABASE [DUDONETRAN] SET COMPATIBILITY_LEVEL = 110
GO
ALTER DATABASE [DUDONETRAN] SET ANSI_NULL_DEFAULT OFF 
GO
ALTER DATABASE [DUDONETRAN] SET ANSI_NULLS OFF 
GO
ALTER DATABASE [DUDONETRAN] SET ANSI_PADDING OFF 
GO
ALTER DATABASE [DUDONETRAN] SET ANSI_WARNINGS OFF 
GO
ALTER DATABASE [DUDONETRAN] SET ARITHABORT OFF 
GO
ALTER DATABASE [DUDONETRAN] SET AUTO_CLOSE OFF 
GO
ALTER DATABASE [DUDONETRAN] SET AUTO_CREATE_STATISTICS ON 
GO
ALTER DATABASE [DUDONETRAN] SET AUTO_SHRINK OFF 
GO
ALTER DATABASE [DUDONETRAN] SET AUTO_UPDATE_STATISTICS ON 
GO
ALTER DATABASE [DUDONETRAN] SET CURSOR_CLOSE_ON_COMMIT OFF 
GO
ALTER DATABASE [DUDONETRAN] SET CURSOR_DEFAULT  GLOBAL 
GO
ALTER DATABASE [DUDONETRAN] SET CONCAT_NULL_YIELDS_NULL OFF 
GO
ALTER DATABASE [DUDONETRAN] SET NUMERIC_ROUNDABORT OFF 
GO
ALTER DATABASE [DUDONETRAN] SET QUOTED_IDENTIFIER OFF 
GO
ALTER DATABASE [DUDONETRAN] SET RECURSIVE_TRIGGERS OFF 
GO
ALTER DATABASE [DUDONETRAN] SET  DISABLE_BROKER 
GO
ALTER DATABASE [DUDONETRAN] SET AUTO_UPDATE_STATISTICS_ASYNC OFF 
GO
ALTER DATABASE [DUDONETRAN] SET DATE_CORRELATION_OPTIMIZATION OFF 
GO
ALTER DATABASE [DUDONETRAN] SET PARAMETERIZATION SIMPLE 
GO
ALTER DATABASE [DUDONETRAN] SET READ_COMMITTED_SNAPSHOT OFF 
GO
ALTER DATABASE [DUDONETRAN] SET  READ_WRITE 
GO
ALTER DATABASE [DUDONETRAN] SET RECOVERY FULL 
GO
ALTER DATABASE [DUDONETRAN] SET  MULTI_USER 
GO
ALTER DATABASE [DUDONETRAN] SET PAGE_VERIFY CHECKSUM  
GO
ALTER DATABASE [DUDONETRAN] SET TARGET_RECOVERY_TIME = 0 SECONDS 
GO
USE [DUDONETRAN]
GO
IF NOT EXISTS (SELECT name FROM sys.filegroups WHERE is_default=1 AND name = N'PRIMARY') ALTER DATABASE [DUDONETRAN] MODIFY FILEGROUP [PRIMARY] DEFAULT
GO

And this is the code to create the tables:

USE DUDLOOPTRAN
GO

-- Create an populate a table in each database to use in the update loops

CREATE TABLE looptranu
(runnumber INT
,rundate DATETIME
,vartext VARCHAR(10)
,chartext CHAR(10))

USE DUDONETRAN
GO

CREATE TABLE onetranu
(runnumber INT
,rundate DATETIME
,vartext VARCHAR(10)
,chartext CHAR(10))

USE DUDLOOPTRAN
GO

INSERT INTO looptranu
VALUES
(1
,GETDATE()
,REPLICATE('a',10)
,REPLICATE('b',10))
GO 100000

USE DUDONETRAN
GO

INSERT INTO onetranu
VALUES
(1
,GETDATE()
,REPLICATE('a',10)
,REPLICATE('b',10))
GO 100000

After creating the databases and tables, I ran the following scripts. First, this script runs the updates in a single transaction:

USE DUDONETRAN
GO

-- Declare @loopcount variable to run the loop
-- Declare @textlen to vary the length of the text fields

DECLARE @loopcount INT
DECLARE @textlen TINYINT
SET @loopcount = 1

-- Begin an explicit transaction that will remain open for the duration of the loop
BEGIN TRAN

WHILE @loopcount <= 10
BEGIN

	-- Use the modulus operator to set text length to the remainder of @loopcount / 10

	SET @textlen = (@loopcount % 10)
	
	-- Update onetranu using the values described below
	UPDATE onetranu
	-- Set runnumber equal to @loopcount
	SET runnumber = @loopcount, 
	-- Set rundate equal the current datetime
	rundate = GETDATE(), 
	-- Set vartext to a string of a's, with the length determined by the @textlen variable
	vartext = REPLICATE('a',@textlen), 
	-- Set chartext to a string of b's, with the length determined by the @textlen variable
	chartext = REPLICATE('b',@textlen)

	-- Increment @loopcount
	SET @loopcount = @loopcount + 1

END

COMMIT

This code does each update in an explicit transaction:

USE DUDLOOPTRAN
GO

-- Declare @loopcount variable to run the loop
-- Declare @textlen to vary the length of the text fields

DECLARE @loopcount INT
DECLARE @textlen TINYINT
SET @loopcount = 1

-- Begin an explicit transaction that will remain open for the duration of the loop


WHILE @loopcount <= 10
BEGIN
	
	BEGIN TRAN
	-- Use the modulus operator to set text length to the remainder of @loopcount / 10

	SET @textlen = (@loopcount % 10)
	
	-- Update onetranu using the values described below
	UPDATE looptranu
	-- Set runnumber equal to @loopcount
	SET runnumber = @loopcount, 
	-- Set rundate equal the current datetime
	rundate = GETDATE(), 
	-- Set vartext to a string of a's, with the length determined by the @textlen variable
	vartext = REPLICATE('a',@textlen), 
	-- Set chartext to a string of b's, with the length determined by the @textlen variable
	chartext = REPLICATE('b',@textlen)

	-- Increment @loopcount
	SET @loopcount = @loopcount + 1
	
	COMMIT
	
END

Finally, this code will insert the contents of sys.dm_tran_database_transactions into a temp table for analysis. Run this while the update scripts are running:

USE master
GO

-- Create a temp table to hold the result set from sys.dm_tran_database_transactions

CREATE TABLE #transactions
(tranid BIGINT
,databaseid INT
,trantype INT
,transtate INT
,recordcount INT
,bytesused BIGINT
,bytesreserved BIGINT)

-- Run an infinite loop for the duration of each update script
-- stopping it when the script completes

WHILE 1 = 1
BEGIN

	INSERT INTO #transactions
	SELECT transaction_id AS [Tran ID], 
	database_id AS [Database ID], 
	database_transaction_type AS [Tran Type], 
	database_transaction_state AS [Tran State], 
	database_transaction_log_record_count AS [Log Record Count],
	database_transaction_log_bytes_used AS [Log Bytes Used],
	database_transaction_log_bytes_reserved AS [Log Bytes Reserved]
	FROM sys.dm_tran_database_transactions

END

-- Use the select statement below to see the results
-- This query will return a single row per transaction
-- for read/write activity (trantype = 1)
-- that has generated log records (transtate = 4)

SELECT tranid, 
MAX(recordcount) AS [Record Count], 
(MAX(bytesused)/1045876) AS [MB Used], 
(MAX(bytesreserved)/1045876) AS [MB Reserved] 
FROM #transactions
WHERE databaseid = DB_ID('DUDONETRAN')  -- Make sure to use the correct database name
AND trantype = 1
AND transtate = 4
GROUP BY tranid

-- Clean up the temp table after the run

--DROP TABLE #transactions

Here are the results of the single transaction:

DUDONETRAN Results

And here are the results of the explicit transactions in the loop:
DUDLOOPTRAN Results

 
As you can see, the total space used and reserved is approximately the same. The difference is the updates running in explicit transactions release the reserved space when each transaction commits. While the total reserved space for the explicit transaction is 344mb, 36mb is the most space reserved at any one time. However, the 342mb reserved for the single transaction is held for the duration of the transaction.

The examples I’ve shown here update 100,000 narrow rows 10 times. The cost of running updates or inserts to much wider rows millions of times would be exponentially greater. I hope these examples have demonstrated this.

SQL Server Log Space Reservation – Part I

April 27, 2012 1 comment

My biggest challenge in blogging about the SQLskills Internals Immersion Event is picking a topic to start with. I am going to choose log file space consumption because of an issue that occurred this week in our test environment.

An application ran a job that inserted over 400 million in a single transaction. After the job ran for more than 24 hours, the application requested the job be killed because it was “taking too long.” Go figure. The app was advised the rollback could take as long as the initial job run, and they decided to have the process killed. The rollback ended up taking about the same amount of time. When SQL Server rolls back a transaction, it generates and executes an anti-operation for each record in the log. In the case of 400 million inserts, 400 million deletes needed to be generated and executed.

While I was aware of this behavior going into the class, I learned that this scenario is even more costly because SQL Server reserves space in the log for any potential rollback activity. This means all of the log records for the inserts are written into the log and SQL reserves additional space for the rollback, more than doubling the amount of space needed. You can see the amount space reserved by a transaction in the sys.dm_tran_database_transactions dynamic management object in column database_transaction_log_space_reserved. The reserved space is released once the transaction commits. Additionally, because all of the log records for the large transaction are needed for a rollback, SQL Server cannot reuse the log file and it will continue to grow.

Both of these problems can be solved by running the single transaction in smaller batches. Committing more frequently will release the reserved undo space. It will also increase the probability SQL Server can reuse the existing log file. In my next post I will compare the log file use and reservation single long-running transaction to shorter, batched transactions performing the same activity.

Using an UPDATE Statement to Update a Column and Set a Variable

April 17, 2012 1 comment

I am a day and a half into the SQLskills Internals Immersion Event and I expect to have a lot more to post once I’ve recovered. Kimberly Tripp (blog | twitter) covered a feature of the UPDATE statement that I was unaware of. It allows you to update a column and set a variable with the updated value in a single statement. Here is an example:


-- Create a test table
CREATE TABLE UpdateTest
(id INT
,firstname VARCHAR(30)
,lastname VARCHAR(30)
,balance MONEY)

-- Insert a row into the test table
INSERT INTO UpdateTest
VALUES
(1
,'Skreeby'
,'Looby'
,1234.56)

-- Declare variables for use below
DECLARE @balance MONEY
DECLARE @debit MONEY
SET @debit = 500.00

-- Update table, updating the balance column equal to balance - @debit and setting
-- the @balance at the same time
-- NOTE: If more than one row is updated, your variable will contain the column value 
-- from the last row updated

UPDATE UpdateTest
SET @balance = balance = balance - @debit
WHERE id = 1

-- Select the variable and table
SELECT @balance AS [Balance]

SELECT * FROM UpdateTest

Here are the results:

Balance Results

 
I had no idea you could do this with an update statement and wanted to get it out there.