info@techdevops.com
TechDevOps.com
Explore Tools
Experts in Microsoft SQL Server Operations, Performance, Replication, Cloud & Migrations



Find the root cause of a TEMPDB LOG growth issue
by BF (Senior MSSQL Operations - Enterprise, Cloud, Strategy)
2018-06-13









Using Extended Events, DBCC OPENTRAN, INPUTBUFFER & SYSPROCESSES to help find the root cause of TEMPDB LOG growth issue




Step 1: Create New Extended Events Session to capture file growth events for database_file_size_change and database_log_file_used_size_changes


CREATE EVENT SESSION [EE_DB_File_Growth] ON SERVER
ADD EVENT [sqlserver].[database_file_size_change] (
ACTION ( [sqlserver].[session_id], [sqlserver].[database_id],
[sqlserver].[client_hostname], [sqlserver].[sql_text], [sqlserver].[tsql_stack], [sqlserver].[plan_handle], [sqlserver].[query_hash], [sqlserver].[query_plan_hash])
WHERE ( ([database_id] = ( 2 ) or [database_id] = ( 8 ))
AND [session_id] > ( 50 ) ) ),
ADD EVENT [sqlserver].[databases_log_file_used_size_changed] (
ACTION ( [sqlserver].[session_id], [sqlserver].[database_id],
[sqlserver].[client_hostname], [sqlserver].[sql_text], [sqlserver].[tsql_stack], [sqlserver].[plan_handle], [sqlserver].[query_hash], [sqlserver].[query_plan_hash] )
WHERE ( ([database_id] = ( 2 ) or [database_id] = (8))
AND [session_id] > ( 50 ) ) )
ADD TARGET [package0].[asynchronous_file_target] ( SET filename = N'c:\temp\evdbgrowth.xel' ,
metadatafile = N'c:\temp\evdbgrowth.xem' ,
max_file_size = ( 10 ) ,
max_rollover_files = 10 )
WITH ( MAX_MEMORY = 4096 KB ,
EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS ,
MAX_DISPATCH_LATENCY = 1 SECONDS ,
MAX_EVENT_SIZE = 0 KB ,
MEMORY_PARTITION_MODE = NONE ,
TRACK_CAUSALITY = ON ,
STARTUP_STATE = ON );
GO

ALTER EVENT SESSION [EE_DB_File_Growth] ON SERVER STATE = START;



Step 2: Create a Permanent Logging Table to store the extended events data


Create Table OPS.dbo.LOG_FILE_GROWTH (SessionID int, ClientHostName varchar(100), OriginatingDB varchar(50), GrowthDB varchar(50),
GrowthFile varchar(25), DBFileType varchar(25), EventName varchar(100), SizeChangeInKB int, TotalFileSizeInKB int, DurationInMS int,
GrowthTime datetime, QueryText varchar(500), TSQLStack varchar(500), PlanHandle varchar(max), QueryHash varchar(max), QueryPlanHash varchar(max), InsertedDate datetime)



Step 3: Create a Stored Procedure to capture extended events data


Create Procedure dbo.Admin_EE_DB_File_Growth
as

Insert into OPS.dbo.LOG_FILE_GROWTH
(SessionID, ClientHostName, OriginatingDB, GrowthDB, GrowthFile, DBFileType, EventName, SizeChangeInKB, TotalFileSizeInKB, DurationInMS,
GrowthTime, QueryText, TSQLStack, PlanHandle, QueryHash, QueryPlanHash, InsertedDate)

SELECT [evts].[event_data].[value]('(event/action[@name="session_id"]/value)[1]',
'INT') AS [SessionID] ,
[evts].[event_data].[value]('(event/action[@name="client_hostname"]/value)[1]',
'VARCHAR(MAX)') AS [ClientHostName] ,
COALESCE(DB_NAME([evts].[event_data].[value]('(event/action[@name="database_id"]/value)[1]',
'BIGINT')), ';(._.); I AM KING KRAB') AS [OriginatingDB] ,
DB_NAME([evts].[event_data].[value]('(event/data[@name="database_id"]/value)[1]',
'BIGINT')) AS [GrowthDB] ,
[evts].[event_data].[value]('(event/data[@name="file_name"]/value)[1]',
'VARCHAR(MAX)') AS [GrowthFile] ,
[evts].[event_data].[value]('(event/data[@name="file_type"]/text)[1]',
'VARCHAR(MAX)') AS [DBFileType] ,
[evts].[event_data].[value]('(event/@name)[1]', 'VARCHAR(MAX)') AS [EventName] ,
[evts].[event_data].[value]('(event/data[@name="size_change_kb"]/value)[1]',
'BIGINT') AS [SizeChangeInKb] ,
[evts].[event_data].[value]('(event/data[@name="total_size_kb"]/value)[1]',
'BIGINT') AS [TotalFileSizeInKb] ,
[evts].[event_data].[value]('(event/data[@name="duration"]/value)[1]',
'BIGINT') AS [DurationInMS] ,
[evts].[event_data].[value]('(event/@timestamp)[1]', 'VARCHAR(MAX)') AS [GrowthTime] ,
[evts].[event_data].[value]('(event/action[@name="sql_text"]/value)[1]',
'VARCHAR(MAX)') AS [QueryText],
[evts].[event_data].[value]('(event/action[@name="tsql_stack"]/value)[1]',
'VARCHAR(MAX)') AS [TSQLStack],
[evts].[event_data].[value]('(event/action[@name="plan_handle"]/value)[1]',
'VARCHAR(MAX)') AS [PlanHandle],
[evts].[event_data].[value]('(event/action[@name="query_hash"]/value)[1]',
'VARCHAR(MAX)') AS [QueryHash],
[evts].[event_data].[value]('(event/action[@name="query_plan_hash"]/value)[1]',
'VARCHAR(MAX)') AS [QueryPlanHash],
GetDate()
FROM
(SELECT CAST([event_data] AS XML) AS [TargetData] FROM [sys].[fn_xe_file_target_read_file]('c:\temp\evdbgrowth*.xel',NULL,NULL,NULL)) AS [evts] ([event_data])
WHERE [evts].[event_data].[value]('(event/@name)[1]', 'VARCHAR(MAX)') = 'database_file_size_change'
OR [evts].[event_data].[value]('(event/@name)[1]', 'VARCHAR(MAX)') = 'databases_log_file_used_size_changed'
ORDER BY [GrowthTime] ASC;



IF QueryText above is empty, get the QueryText through the PlanHandle field...


Step 4: Create a TMP Table to join with sys.dm_exec_query_plan to get the Execution Plan

Select * Into #TMP from OPS.dbo.LOG_FILE_GROWTH

Update #TMP set PlanHandle = '0x'+PlanHandle


Select 'Select * from sys.dm_exec_query_plan' + '(' + planhandle + ')' from #TMP

Select * from sys.dm_exec_query_plan(0x05000800ec4aaa5110b54bae0c00000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x05000800ec4aaa5110b54bae0c00000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x05000800ec4aaa5110b54bae0c00000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x05000800ec4aaa5110b54bae0c00000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x06000800bffbef2cd0fd42ed0700000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x06000800bffbef2cd0fd42ed0700000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x06000800bffbef2cd0fd42ed0700000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x06000800bffbef2cd0fd42ed0700000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x06000800bffbef2cd0fd42ed0700000001000000000000000000000000000000000000000000000000000000)



Step 5: At this point you have the timestamp(s) of any database file growth events and possibly the root cause data. If you need further information, use the below process.


Ex:

Use TEMPDB
go

DBCC OPENTRAN

Transaction information for database 'tempdb'.

Oldest active transaction:
SPID (server process ID): 90
UID (user ID) : -1
Name : user_transaction
LSN : (3096:70456:190)
Start time : Jun 13 2018 9:00:09:587AM
SID : 0x19be18a29ccb13469e1fdc482b42e979
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

* The above shows we have active open transactions since 9:00AM !!! (7 hours and counting!)



DBCC INPUTBUFFER (90)

select spid, blocked, lastwaittype from sysprocesses where '~90~~98~' like '%~' + cast (spid as nvarchar)+ '~%' and '~90~~98~' like '%~' + cast (blocked as nvarchar)+ '~%'



Select * from sysprocesses where spid = 90

open_tran status hostname cmd programname
3 sleeping VM-PR AWAITING COMMAND Distribution Agent Name

* This information shows that SPID 90 in fact has 3 open transactions and the programname is Replication Related !!! (i.e. From the Distribution Agent on a separate server)

* We stopped that Distribution Agent and the 3 Open Transactions in TEMPDB immediately went away and the free space in TEMPDB went to 90% free.

DBCC OPEN TRAN went from 9:00AM to 4:05PM

Transaction information for database 'tempdb'.

Oldest active transaction:
SPID (server process ID): 77
UID (user ID) : -1
Name : sort_init
LSN : (3338:707992:215)
Start time : Jun 13 2018 4:05:15:453PM
SID : 0x010500000000000515000000bfab95a7da18eca6aa267657eb030000
DBCC execution completed. If DBCC printed error messages, contact your system administrator.


Root Cause of TEMPDB LOG File huge growth = SPID with 3 open transactions from a Replication Distribution Agent.


Resolved !!!