July 18, 2013 at 9:00 am
I'm fighting with a very naughty leading application that likes to open transactions and orphan them which is preventing the transaction log from truncating. For various reasons it is impractical to solve the bad code in the leading app. <Sigh>.
I have been diligently monitoring log growth to detect when this happens so I can intervene with trusty KILL, and have setup a SQL Agent performance alert for long running transactions, but I'm hoping to get a bit more surgical with a custom agent script.
DBCC OPENTRAN gives me the orphaned SPID, and it's pretty obvious when it began say more than 30 minutes ago. I'm trying to recreate this using DMV's. This was my first attempt, and it didn't send me a notification when things got stuck.
DECLARE@timeout INT;
SET@timeout = 1800;
SELECT
s_er.[session_id]
,s_es.[login_name]
,DB_NAME(s_tdt.database_id) AS [Database]
,s_er.start_time AS [Start Time]
,datediff(SS,s_er.start_time,GETDATE()) as [Duration]
,DATEDIFF( ss, [s_tdt].[database_transaction_begin_time], CURRENT_TIMESTAMP ) AS [Transaction Begin Time]
FROM sys.dm_exec_requests s_er
JOIN sys.dm_tran_database_transactions s_tdt ON s_er.[transaction_id] = s_tdt.[transaction_id]
JOIN sys.dm_exec_sessions s_es ON s_es.[session_id] = s_er.[session_id]
JOIN sys.dm_exec_connections s_ec ON s_ec.[session_id] = s_er.[session_id]
WHERE s_tdt.database_id > 4 --filter system databases
AND s_tdt.[database_transaction_begin_time] IS NOT NULL
AND DATEDIFF( ss, s_tdt.[database_transaction_begin_time], CURRENT_TIMESTAMP ) >= @timeout
I think filtering out NULL [database_transaction_begin_time] is the problem. I did some experiments by executing just a BEGIN TRANSACTION, and the [database_transaction_begin_time] is NULL. I also tried looking at sys.dm_exec_requests.start_time, but there is not a row here for my orphaned transaction.
I'm starting to think maybe I need to be a bit more clever decoding [database_transaction_state], possibly look for connections with no active requests, or look at [last_read] or [last_write] in sys.dm_exec_connections? Hoping some really smart people out there can clue me in on an easier way.
So my question is what DMV column to look for to detect the oldest open transaction similar to DBCC OPENTRAN?
Thanks!
July 18, 2013 at 9:34 am
The reason you're getting odd results is that BEGIN TRANSACTION alone is not enough to actually start a transaction. The transaction will start when the next command is run.
So
BEGIN TRANSACTION
SELECT <stuff> ...
that will get you the rows in the query that you're using (which is about as close to opentran as you can get)
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
July 18, 2013 at 10:52 am
Thanks! So that would explain my busted testing methodology.
Maybe I've made some faulty assumptions about the root cause of the lack of log truncation. What I was seeing is the transaction log growing, and if I run a DBCC LOGINFO I see most of the VLFs with an active status. So pretty clearly the log is not truncating, thus the growth.
It was an assumption on my part that an open transaction was preventing the truncation, but in terms of evidence, DBCC OPENTRAN was showing a SPID many many hours old. I'll have to confirm next time it happens, but I think when I followed that up with sp_who2, it was showing the command for the problem SPID as "AWAITING COMMAND".
It seems pretty clear I need to look for cases where sys.dm_tran_active_transactions.[transaction_state] = 2 (active), but can I trust the time component of this DMV?
EDIT: I found most of what I need here http://www.sqlservercentral.com/articles/Stairway+Series/94579/[/url]
Is it possible to tie a SPID with an open transaction to a specific VLF?
July 18, 2013 at 12:24 pm
If DBCC OPENTRAN is showing a session, then that session has an open transaction. If it's AWAITING COMMAND, that just means that the transaction has been started and not committed.
The sys.dm_tran_database_transactions DMV is correct.
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
July 18, 2013 at 12:24 pm
I think I have it figured out. I needed to understand that sys.dm_tran_active_transactions shows logical transactions, and sys.dm_tran_database_transactions is showing actual "physical presence" of transactions. As such I need to use the transaction_begin_time from sys.dm_tran_active_transactions.
This free ebook was invaluable in clarifying the transaction log related DMV. https://www.simple-talk.com/books/sql-books/performance-tuning-with-sql-server-dynamic-management-views/[/url]
July 18, 2013 at 12:27 pm
Err... there's no such thing as a 'logical' or 'physical' transaction. There are just transactions.
sys.dm_tran_active_transactions reports at an instance level, so if you're trying it ID transactions within a single database it's probably not a good choice, whereas sys.dm_tran_database_transactions reports at a database level, so you can filter on database_id. There will be multiple entries in there if the transaction is cross-database (one row for each database involved in the transaction)
Edit: I was slightly wrong in my earlier example, the BEGIN TRAN and the SELECT are not enough, has to be a BEGIN TRAN and some form of data modification. Without a data modification, there isn't a begin tran log record written and hence the log won't be retained due to active tran.
Hence, if you have something like this:
BEGIN TRANSACTION
SELECT ...
SELECT ....
SELECT ...
UPDATE ...
It's only when the update starts that the transaction actually starts for the purposes of log reuse (which is what you're interested in)
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
July 18, 2013 at 1:21 pm
I think we're now saying the same thing, and admittedly I am probably abusing the word "logical", but here's what I mean.
If I open a new query window and run the following statement:
BEGIN TRANSACTION
SELECT @@SPID
Then in another query window I run this:
SELECT
tst.[session_id]
,es.[login_name]
,DB_NAME(es.database_id) AS [Database]
,DATEDIFF( ss, tat.[transaction_begin_time], CURRENT_TIMESTAMP ) AS [Duration s]
,tat.[transaction_begin_time]
,tdt.database_transaction_begin_time
,tat.[transaction_type] AS [Transaction Type]
,tat.[transaction_state] AS [Transaction State]
,tdt.[database_transaction_type] AS [Transaction Type]
,tdt.[database_transaction_state] AS [Transaction State]
,database_transaction_log_bytes_used
,database_transaction_log_bytes_reserved
FROM sys.dm_tran_active_transactions tat
INNER JOIN sys.dm_tran_session_transactions tst ON tst.[transaction_id] = tat.[transaction_id]
INNER JOIN sys.dm_exec_sessions es ON es.[session_id] = tst.[session_id]
LEFT JOIN sys.dm_exec_requests er ON er.[session_id] = es.[session_id]
LEFT JOIN sys.dm_tran_database_transactions tdt ON er.[transaction_id] = tdt.[transaction_id]
INNER JOIN sys.dm_exec_connections ec ON ec.[session_id] = es.[session_id]
WHERE tst.[is_user_transaction] = 1
ORDER BY tat.[transaction_begin_time] ASC;
Note I have intentionally duplicated similar begin_time, transaction_type, and transaction_state columns from both sys.dm_tran_database_transactions and sys.dm_tran_active_transactions.
For the SPID of my example, database_transaction_begin_time and the last 4 columns will be NULL. As accurately pointed out I'm not actually using any log with a SELECT.
So "logically" I have begun a transaction, but I am not actually burning any log. Clear as mud?
Probably a lack of understanding of instance level and database level transaction events on my part, but I grant Microsoft partial credit for some confusing column nomenclature.
The short of it is, in my previous attempt I was trying to queue off sys.dm_tran_database_transactions.database_transaction_begin_time which apparently will not get me what I'm after.
July 18, 2013 at 1:27 pm
jallmond (7/18/2013)
So "logically" I have begun a transaction, but I am not actually burning any log. Clear as mud?
The transaction has been initiated but no log records reflecting that transaction have been written, hence there is nothing preventing log truncation. The transaction has started for the purposes of things like snapshot isolation level, but not for logging purposes
The short of it is, in my previous attempt I was trying to queue off sys.dm_tran_database_transactions.database_transaction_begin_time which will not get me what I'm after.
Actually it will.
You're interested in long running transactions that are preventing log truncation. Hence you're only interested in transactions that have written log records. Transactions that have been initiated but have not written any log entries are not holding the log active and hence you don't need to see them.
Querying sys.dm_tran_database_transactions and filtering for database_transaction_begin_time IS NOT NULL will get you transactions that have written log records and not committed or rolled back, which is what you were initially asking for.
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
July 18, 2013 at 1:33 pm
Got it, thanks for clarifying. I was missing the fact my simple test is not actually reproducing the problem behavior.
Viewing 9 posts - 1 through 8 (of 8 total)
You must be logged in to reply to this topic. Login to reply