Archive

Archive for June, 2012

Tracking and Calculating Wait Times – Part I

June 20, 2012 1 comment

Several weeks ago, I took a call from a vended application investigating slowness that occurred on a regular basis on Wednesdays. Members of my team had looked at the performance of the app from a SQL Server perspective during the slow period and could not find anything out of line. The app had also worked with the Windows, Storage and Network teams, and no red flags were found. The vendor had asked if we could provide information about SQL Server wait times.

The data they were interested in is available from sys.dm_os_waiting_tasks, but the wait time values are cumulative so the raw values are not very useful. Fortunately, one of my former co-workers (I owe him a beer) set up a process that created the table scripted below:

USE [Your Database Name]
GO

/****** Object:  Table [dbo].[Your Table Name]    Script Date: 06/18/2012 21:27:17 ******/
SET ANSI_NULLS ON
GO

SET QUOTED_IDENTIFIER ON
GO

CREATE TABLE [dbo].[Your Table Name]
([WAT_WAIT_TYPE_NM] [nvarchar](120) NOT NULL,
 [WAT_WAITING_TASKS_NBR] [bigint] NOT NULL,
 [WAT_WAIT_TM_MS_NBR] [bigint] NOT NULL,
 [WAT_MAX_WAIT_TIME_MS_NBR] [bigint] NOT NULL,
 [WAT_SIGNAL_WAIT_TIME_MS_NBR] [bigint] NOT NULL,
 [WAT_CAPTURE_DT] [datetime] NOT NULL
) ON [PRIMARY]
GO

ALTER TABLE [dbo].[Your Table Name] ADD  DEFAULT (getdate()) FOR [WAT_CAPTURE_DT]
GO

The process runs the following stored procedure hourly from an agent job:

USE [Your Database Name]
GO
/****** Object:  StoredProcedure [dbo].[Your Procedure Name]    Script Date: 06/18/2012 21:28:15 ******/
SET ANSI_NULLS ON
GO

SET QUOTED_IDENTIFIER ON
GO

CREATE PROCEDURE [dbo].[Your Procedure Name]
AS
SET NOCOUNT ON ;

        INSERT INTO [dbo].[DUT_WAIT_STATS] (
                        WAT_WAIT_TYPE_NM,
                        WAT_WAITING_TASKS_NBR,
                        WAT_WAIT_TM_MS_NBR,
                        WAT_MAX_WAIT_TIME_MS_NBR,
                        WAT_SIGNAL_WAIT_TIME_MS_NBR,
                        WAT_CAPTURE_DT)

		SELECT  [wait_type],
		        [waiting_tasks_count],
				[wait_time_ms],
                [max_wait_time_ms],
		        [signal_wait_time_ms],
				GETDATE()
		FROM sys.dm_os_wait_stats

GO

I would recommend using a process like this to provide the ability to troubleshoot wait times historically as it is simple to set up and is very lightweight. We are storing 6 months’ worth of data and the table is less than 4mb in size.

This gave me the data I was looking for, but because the wait times are cumulative I still needed to calculate the deltas. I will cover the process I put together in my next post.

Joining sys.dm_tran_database_transactions to fn_dblog Results

June 11, 2012 Leave a comment

In my previous two posts, Reading the Transaction Log Using fn_dblog and Using dm_tran_database_transactions and a First Step to Converting LSNs, I demonstrated using these DMOs to see what transactions are executing and to read the transaction log. In this post, I’ll show how to join those results together. Here is the script I used:

USE [Your Database Name Here]
GO

--  Declare variables
DECLARE @startlsn VARBINARY(15)
DECLARE @lastlsn VARBINARY(15)
DECLARE @LSN_START NVARCHAR(50)
DECLARE @LSN_END NVARCHAR(50)
DECLARE @dbname NVARCHAR(100)
DECLARE @bytesused BIGINT
DECLARE @bytesreserved BIGINT
DECLARE @loopcount INT
DECLARE @looplimit INT

-- Initialize the loop counter
SET @loopcount = 1

-- Create a temp table to hold all of the active transactions from
-- sys.dm_tran_database_transactions
CREATE TABLE #tranresults
(dbname NVARCHAR(100)
,bytesused BIGINT
,bytesreserved BIGINT
,startlsn VARBINARY(15)
,endlsn VARBINARY(15))

-- Create a temp table to hold data about each transaction and the associated log records
CREATE TABLE #logresults
(dbname NVARCHAR(100)
,bytesused BIGINT
,bytesreserved BIGINT
,spid INT
,begintime NVARCHAR(48)
,currentlsn VARCHAR(46)
,previouslsn VARCHAR(46)
,transactionid VARCHAR(28)
,operation NVARCHAR(62)
,context VARCHAR(62)
,logreserve INT
,allocunitname NVARCHAR(774)
,pageid NVARCHAR(28)
,numberoflocks SMALLINT
,lockinformation NVARCHAR(512))

-- Insert data from sys.dm_tran_database_transaction for all transactions that have
-- generated log records
-- Notice the use of the fn_convertnumericlsntobinary function
-- This is necessary for subsequent SUBSTRING operations
INSERT INTO #tranresults
SELECT DB_NAME(database_id),
database_transaction_log_bytes_used,
database_transaction_log_bytes_reserved,
master.dbo.fn_convertnumericlsntobinary(database_transaction_begin_lsn),
master.dbo.fn_convertnumericlsntobinary(database_transaction_last_lsn)
FROM sys.dm_tran_database_transactions
WHERE database_transaction_begin_lsn IS NOT NULL
AND database_transaction_last_lsn IS NOT NULL
AND database_transaction_state = 4
AND database_id = DB_ID()

-- Set the @looplimit variable to the number of rows selected from
-- sys.dm_tran_database_transactions
SET @looplimit = @@ROWCOUNT

-- Run through this loop once for each row selected from
-- sys.dm_tran_database_transactions
WHILE @loopcount <= @looplimit
BEGIN

-- Select data from the first row into variables for later use
	SELECT TOP 1
	@dbname = dbname,
	@bytesused = bytesused,
	@bytesreserved = bytesreserved,
	@startlsn = startlsn,
	@lastlsn = endlsn
	FROM #tranresults

-- Convert the starting and ending lsn for use in the fn_dblog function below
-- The following code is necessary because fn_dblog expects the lsn as colon-delimited
-- numeric values, represented as VARCHAR
-- I initially thought I could get away with converting the numeric lsn to VARCHAR and
-- running the SUBSTRING operations on it, but the numeric value is variable in length

	SET @LSN_START = CONVERT(VARCHAR(10),CONVERT(INT,SUBSTRING(@startlsn,1,4))) + ':' +
	CONVERT(VARCHAR(10),CONVERT(INT,SUBSTRING(@startlsn,5,4))) + ':' +
	CONVERT(VARCHAR(10),CONVERT(INT,SUBSTRING(@startlsn,9,2)))

	SET @LSN_END = CONVERT(VARCHAR(10),CONVERT(INT,SUBSTRING(@lastlsn,1,4))) + ':' +
	CONVERT(VARCHAR(10),CONVERT(INT,SUBSTRING(@lastlsn,5,4))) + ':' +
	CONVERT(VARCHAR(10),CONVERT(INT,SUBSTRING(@lastlsn,9,2)))

	SELECT @LSN_START
	SELECT @LSN_END

-- Now having re-reconverted the lsns, exit our hero, stage left
-- For transactions with a non-null start and end lsn, insert required data into
-- the #logresults temp table
	IF (@LSN_START IS NOT NULL) AND (@LSN_END IS NOT NULL)
	BEGIN
	INSERT INTO #logresults
	SELECT
	@dbname AS [Database],
	@bytesused AS [Bytes Used],
	@bytesreserved AS [Bytes Reserved],
	SPID,
	[Begin Time],
	[Current LSN],
	[Previous LSN],
	[Transaction ID],
	Operation,
	Context,
	[Log Reserve],
	AllocUnitName,
	[Page ID],
	[Number of Locks],
	[Lock Information]
	FROM ::fn_dblog(@LSN_START, @LSN_END)
	END

-- Delete the top row from the #tranresults temp table
	DELETE TOP (1) FROM #tranresults
	SET @loopcount = @loopcount + 1

END

SELECT * FROM #logresults
ORDER BY currentlsn

-- Clean up the temp tables
DROP TABLE #logresults
DROP TABLE #tranresults

The comments do a good job of explaining what the script is doing, but I want to clarify a few things. Because I was unable to join the DMOs on transaction ID, I decided to use the begin and end lsn values from the DMV as input parameters to fn_dblog. And here’s where the fun began. The DMV stores the lsns as numeric values. The function expects a colon-delimited VARCHAR string made up of numbers. For example, if the DMV stores an lsn value of 4242000000012300002, fn_dblog will expect 4242:123:2.

To do the the conversion, I followed these steps:

  1. Converted the values to hex using fn_convertnumericlsntobinary;
  2. Substringed each of the colon-delimited parts of the lsn, converted to INT;
  3. Converted the INT values to VARCHAR;
  4. Concatenated the VARCHAR values with colons.

And so, having re-reconverted the lsns, our hero is ready to pass them into fn_dblog. The results of fn_dblog are inserted to the temp table for each set of lsns, which is selected from at the end of the script.

A few points about the result set: fn_dblog is database-specific and the result set only contains log records for currently active transactions. Because the tran log acts like a stream of consciousness for the database, you may see additional LOP_BEGIN_XACT records following the LOP_BEGINXACT for the first transaction returned. Here is an example showing a transaction beginning and committing (highlighted in yellow) while another transaction is open. Notice that the currentlsn values are sequential while the previouslsn values are grouped by transactionid.


I hope this series of posts provides insight into the transaction log and how to relate it to active transactions on an instance.

It Was Twenty Years Ago Today, Approximately…

June 8, 2012 1 comment

I am hoping to have the final installment in the Saga of the Transaction Log up on Monday. In the meantime, here’s a clip that I hope brightens your day.

Please to enjoy Driver Has No Cash, featuring Bill Whitmer on ukulele, Bob Rising on Noble and Cooley’s finest toy drum set and yours truly clutching a mike stand for dear life.

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.