Toolbox - Which Clerk Is Busy?

A few years ago I wrote what would turn out to be my most-hit blog post (so far) titled "Error 701 - Insufficient System Memory - Now what?"

In that post I talk about a troubleshooting scenario that finally led to using DBCC MEMORYSTATUS to find one of the memory clerks (MEMORYCLERK_XE) consuming far too much memory on the instance.  (In that case there was a runaway XEvents session burning lots of RAM).

Bottom line, you should troubleshoot which clerk was the busiest to find the source of the overall problem.

https://dominicantoday.com/wp-content/uploads/2017/09/a-4.jpg

The 701 error (Error 701: “There is insufficient system memory to run this query”) just came up this morning again in our team Skype, and my colleague mentioned that the problem was happening at a time when no one wanted to be on the server watching.

I told him about my previous situation and how looking at DBCC MEMORYSTATUS had led to my smoking gun, and it led to thinking about some way to collect and persist the MEMORYSTATUS data without someone watching live on the system.

Google led me to several variations of a #YouCanDoAnythingWithPowershell script, such as this one from Microsoft Premier Field Engineer (PFE) Tim Chapman (blog/@chapmandew) but I really wanted a Transact-SQL script I could play with myself.

More Google finally led me to a blog post and T-SQL script from the SQL Server Photographer Slava Murygin (blog/@slavasql) (follow his blog for scripts and great photos he takes at all types of SQL events)!

Slava's script translates one of the Powershell scripts into T-SQL, storing the output from DBCC MEMORYSTATUS in a temporary table for output.  The one limitation of this for my needs is that it is an adhoc execution - great to run interactively but not useful to store over time.

It took a few steps to turn Slava's temp table implementation into one that stores the data in a permanent table so that it can be queried after the fact and over time.

A few notes: Slava's script relies on xp_cmdshell, and my modification still does.   My modification stores data in a permanent table, which means it needs to reside in a permanent database.  My script uses the "DBADatabase" including code to create it if it doesn't exist, but it is an easy find-replace to change that name if you'd like:

--

/*

Track DBCC MEMORYSTATUS data over time

Guts of query to parse DBCC results into a temp table from 
http://slavasql.blogspot.com/2016/08/parsing-dbcc-memorystatus-without-using.html

Modified to store those results in a permanent table over time
Intended for use in a scheduled Agent Job but could be run manually as needed

Also modified to run on SQL 2005 (syntax changes)

Relies on xp_cmdshell

Stores data in the "DBADatabase" including creating the database if it doesn't pre-exist

If you wish to use an existing database or a different database 
name simply Find-Replace for the string DBADatabase

*/

SET NOCOUNT ON
GO

IF DB_ID('DBADatabase') IS NULL  /* Check if DBADatabase database exists - if not, create it */
BEGIN
EXECUTE ('CREATE DATABASE DBADatabase')

    ALTER DATABASE DBADatabase SET RECOVERY SIMPLE;

    ALTER AUTHORIZATION ON DATABASE::DBADatabase TO sa;

/* Read the current SQL Server default backup location */  
DECLARE @BackupDirectory NVARCHAR(100)   
EXEC master..xp_instance_regread @rootkey = 'HKEY_LOCAL_MACHINE',  
@key = 'Software\Microsoft\MSSQLServer\MSSQLServer',  
    @value_name = 'BackupDirectory', @BackupDirectory = @BackupDirectory OUTPUT ;  
EXECUTE ('BACKUP DATABASE DBADatabase to DISK = '''+@BackupDirectory+'\DBADatabase.bak'' WITH INIT')
PRINT 'CREATED DATABASE'
    RAISERROR('Ensure that you add the DBADatabase database to backup / maintenance jobs/plans', 10, 1) WITH NOWAIT;
END;
GO

/* If Holding Table doesn't exist, create it */
IF OBJECT_ID('DBADatabase.dbo.DBCCMemoryStatus') IS NULL
CREATE TABLE [DBADatabase].[dbo].[DBCCMemoryStatus](
[Datestamp] [datetime] NOT NULL,
[DataSet] [varchar](100) NULL,
[Measure] [varchar](20) NULL,
[Counter] [varchar](100) NULL,
[Value] [money] NULL
) ON [PRIMARY]

GO

SET ANSI_PADDING OFF
GO

IF OBJECT_ID('tempdb..#tbl_MemoryStatusDump') IS NOT NULL
DROP TABLE #tbl_MemoryStatusDump;
GO
IF OBJECT_ID('tempdb..#tbl_MemoryStatus') IS NOT NULL
DROP TABLE #tbl_MemoryStatus;
GO
CREATE TABLE #tbl_MemoryStatusDump(
 ID INT IDENTITY(1,1) PRIMARY KEY
 , [Dump] VARCHAR(100));
GO
CREATE TABLE #tbl_MemoryStatus(
 ID INT IDENTITY(1,1), 
 [DataSet] VARCHAR(100), 
 [Measure] VARCHAR(20), 
 [Counter] VARCHAR(100), 
 [Value] MONEY);
GO
INSERT INTO #tbl_MemoryStatusDump([Dump])
EXEC ('xp_cmdshell ''sqlcmd -E -S localhost -Q "DBCC MEMORYSTATUS" ''');
GO
DECLARE @f BIT
 , @i SMALLINT
 , @m SMALLINT 
 , @CurSet VARCHAR(100)
 , @CurMeasure VARCHAR(20)
 , @Divider TINYINT
 , @CurCounter VARCHAR(100)
 , @CurValue VARCHAR(20);

SET @f=1
SET @m = (SELECT MAX(ID) FROM #tbl_MemoryStatusDump)
set @i = 1

WHILE @i < @m
BEGIN
 SELECT @Divider = PATINDEX('% %',REVERSE(RTRIM([Dump])))
  , @CurCounter = LEFT([Dump], LEN([Dump]) - @Divider)
  , @CurValue = RIGHT(RTRIM([Dump]), @Divider - 1)
 FROM #tbl_MemoryStatusDump WHERE ID = @i;

 IF @f = 1 
  SELECT @CurSet = @CurCounter, @CurMeasure = @CurValue, @f = 0 
  FROM #tbl_MemoryStatusDump WHERE ID = @i;
 ELSE IF LEFT(@CurCounter,1) = '(' SET @f = 1;
 ELSE IF @CurCounter != 'NULL' and LEFT(@CurCounter,1) != '-'
  INSERT INTO #tbl_MemoryStatus([DataSet], [Measure], [Counter], [Value])
  SELECT @CurSet, @CurMeasure, @CurCounter, CAST(@CurValue as MONEY)
  FROM #tbl_MemoryStatusDump WHERE ID = @i;
 SET @i = @i + 1;
END
GO

/*Send data from temp table to permanent table */
INSERT INTO DBADatabase.dbo.DBCCMemoryStatus
SELECT 
GETDATE() as Datestamp
, DataSet
, Measure
, Counter
, Value 
FROM #tbl_MemoryStatus

/* Purge rows older than 96 hours to manage table size */
DELETE FROM DBADatabase.dbo.DBCCMemoryStatus
WHERE DATEDIFF(hh,DateStamp, GETDATE())>96

/*
SELECT *
FROM DBADatabase.dbo.DBCCMemoryStatus
WHERE counter = 'VM Reserved'
ORDER BY DateStamp DESC
*/


--

Running this statement interactively doesn't return any data - it just loads the data into DBADatabase.dbo.DBCCMemoryStatus.  Running the commented-out SELECT at the bottom of the script as written will query that table for all rows of counter VM Reserved (virtual memory reserved) but there is much more data than that available if you modify the SELECT.

This query can be dropped into a SQL Agent job step as is and it will run - just like the interactive run it will create the database and permanent table if they don't exist and then store those nuggets of data into the permanent table for later use - you never know when you may need them!

https://memegenerator.net/img/instances/400x/57081575/winter-is-coming.jpg

--

Hope this helps!

Toolbox - Why is My Database So Big????

I have written previously (here) about how to tell which database files have free space in them when your drive starts to fill.

What if all of your database files are full and you are still running out of space?

DRIVE	DATABASE NAME	FILENAME	FILETYPE	FILESIZE	SPACEFREE	PHYSICAL_NAME
F	DB03	DB03_MDF	DATA	35.47 GB	225.63 MB	F:\MSSQL\Data\DB03_Data.mdf
F	DB02	DB02Data	DATA	110.25 MB	92.38 MB	F:\MSSQL\Data\DB02.mdf
F	DB01	DB01Data	DATA	142.06 MB	72.69 MB	F:\MSSQL\Data\DB01.mdf
F	DB05	DB05_Data	DATA	35.72 GB	71.44 MB	F:\MSSQL\Data\DB05_Data.mdf
F	DB06	DB06_MDF1	DATA	36.47 GB	58.50 MB	F:\MSSQL\Data\DB06_Data.mdf
F	DB04	DB04Data	DATA	36.47 GB	38.00 MB	F:\MSSQL\Data\DB04_Data.mdf

http://www.joemartinfitness.com/wp-content/uploads/2013/11/Post-holiday-bloat.jpg

The next step is to see what is taking up the space in the individual databases.  Maybe there's an audit table that never gets purged...or a Sales History that can be archived away, it only there were an archive process...

https://s3.amazonaws.com/lowres.cartoonstock.com/business-commerce-work-workers-employee-employer-staff-ear0117_low.jpg

**ALWAYS CREATE AN ARCHIVE/PURGE PROCESS ** #ThisIsNotAnItDepends

--

There is an easy query to return the free space available in the various tables in your database - I found it in an StackOverflow at https://stackoverflow.com/questions/15896564/get-table-and-index-storage-size-in-sql-server and then modified it somewhat to make the result set cleaner (to me anyway):

--

/*
Object Sizes

Modified from http://stackoverflow.com/questions/15896564/get-table-and-index-storage-size-in-sql-server
*/

SELECT 
@@SERVERNAME as InstanceName
, DB_NAME() as DatabaseName
, ISNULL(s.name+'.'+t.NAME, '**TOTAL**')  AS TableName
, SUM(p.rows) AS RowCounts
--, SUM(a.total_pages) * 8 AS TotalSpaceKB
, SUM(a.total_pages) * 8/1024.0 AS TotalSpaceMB
, SUM(a.total_pages) * 8/1024.0/1024.0 AS TotalSpaceGB
, SUM(a.used_pages) * 8/1024.0 AS UsedSpaceMB
, (SUM(a.total_pages) - SUM(a.used_pages)) * 8/1024.0 AS UnusedSpaceMB
FROM sys.tables t
INNER JOIN sys.schemas s 
ON s.schema_id = t.schema_id
INNER JOIN sys.indexes i 
ON t.OBJECT_ID = i.object_id
INNER JOIN sys.partitions p 
ON i.object_id = p.OBJECT_ID AND i.index_id = p.index_id
INNER JOIN sys.allocation_units a 
ON p.partition_id = a.container_id
WHERE t.NAME NOT LIKE 'dt%'    -- filter out system tables for diagramming
AND t.is_ms_shipped = 0
AND i.OBJECT_ID > 255 
GROUP BY s.name+'.'+t.Name
WITH ROLLUP
ORDER BY TotalSpaceMB DESC

--

Running the query against an individual database will return all of the tables in the database and their sizes, as well as the total size of the database (from the ROLLUP):

--

InstanceName	DatabaseName	TableName	RowCounts	TotalSpaceMB	UsedSpaceMB	UnusedSpaceMB
Instance01	Database99	**TOTAL**	148409590	36,042.063	32,890.922	3151.141
Instance01	Database99	dbo.BusinessRulesAuditing	20686280	17,877.813	17,860.938	16.875
Instance01	Database99	dbo.BusinessRulesRuleSet	18840	3,895.766	877.945	3,017.820
Instance01	Database99	dbo.ModelWorkbookVersionExt	4383	1,818.453	1,806.445	12.008
Instance01	Database99	dbo.EquityOutputVersions	35040362	1,746.688	1,739.281	7.406
Instance01	Database99	dbo.NominalOutputs	3592710	258.305	251.047	7.258
Instance01	Database99	dbo.Auditing	173494	33.391	27.586	5.805
Instance01	Database99	dbo.EquityOverrides	13105402	515.859	511.188	4.672
Instance01	Database99	dbo.ContingentOutputs	1371465	364.641	361.719	2.922
Instance01	Database99	dbo.ContingentWSStaging	292907	333.320	329.359	3.961
Instance01	Database99	dbo.TransformedAdminContingent	585848	76.070	73.000	3.070

--

There are two different useful cases I normally find with this result set.

The first (highlighted in aqua) is the very large table.  In this sample my 35GB database has one large 17GB table.  This is a situation where you can investigate the table and see *why* it is so large.  In many cases, this is just the way it is - sometimes one large "mother" table is a fact of life (You take the good, you take the bad, you take them both, and there you have..."

https://memegenerator.net/img/instances/11140850/god-im-old.jpg

Often though you will find that this table is an anomaly.  As mentioned above, maybe there is a missing purge or archive process - with a very large table look at the table definitions to see if their are date/datetime columns, and then select the top 10 order by those columns one by one to see how old the oldest records are.  You may find that you are storing years of data when you only need months and can purge the oldest rows.  You may also find that even though you do need years of data, you may not need them live in production, which allows you to periodically archive them away to another database (maybe even another instance) where they can be accessed only when needed.

https://blog.parse.ly/wp-content/uploads/2015/05/say_big_data.jpg

--

The second case (highlighted in yellow) is a table with significant free space contained in the table itself.  In this example a 3.7GB table has 3.0GB of free space in it!

How do you account for this?  There are a few ways - when you delete large numbers of rows from the table, the space usually isn't released until the next time the related indexes are rebuilt.  Another possibility is index fill factor - the amount of free space that is included in indexes when they are rebuilt.  I have run into several instances where a client DBA misunderstood the meaning of the fill factor and did a reverse to themselves, setting the fill factor to 10 thinking it would leave 10% free space when in fact it left 90% free space, resulting not only in exceeding large indexes but also in very poor performance as the SQL Server needs to scan across many more pages to retrieve your data.

To help determine which index(es) may contribute to the problem, you can add the indexname to the query to break the data out that one more level:

--


/*
Object Sizes With Indexes

Modified from http://stackoverflow.com/questions/15896564/get-table-and-index-storage-size-in-sql-server
*/

SELECT 
@@SERVERNAME as InstanceName
, DB_NAME() as DatabaseName
, ISNULL(s.name+'.'+t.NAME, '**TOTAL**')  AS TableName
, ISNULL(i.Name, '**TOTAL**')  AS IndexName
, SUM(p.rows) AS RowCounts
--, SUM(a.total_pages) * 8 AS TotalSpaceKB
, SUM(a.total_pages) * 8/1024.0 AS TotalSpaceMB
, SUM(a.total_pages) * 8/1024.0/1024.0 AS TotalSpaceGB
, SUM(a.used_pages) * 8/1024.0 AS UsedSpaceMB
, (SUM(a.total_pages) - SUM(a.used_pages)) * 8/1024.0 AS UnusedSpaceMB
FROM sys.tables t
INNER JOIN sys.schemas s 
ON s.schema_id = t.schema_id
INNER JOIN sys.indexes i 
ON t.OBJECT_ID = i.object_id
INNER JOIN sys.partitions p 
ON i.object_id = p.OBJECT_ID AND i.index_id = p.index_id
INNER JOIN sys.allocation_units a 
ON p.partition_id = a.container_id
WHERE t.NAME NOT LIKE 'dt%'    -- filter out system tables for diagramming
AND t.is_ms_shipped = 0
AND i.OBJECT_ID > 255 
GROUP BY s.name+'.'+t.Name
, i.Name
WITH ROLLUP

--

InstanceName	DatabaseName	TableName	IndexName	RowCounts	TotalSpaceMB	UsedSpaceMB	UnusedSpaceMB
Instance01	Database99	**TOTAL**	**TOTAL**	148409590	36,042.063	35,890.922	151.141
Instance01	Database99	BusinessRulesAuditing	PK__BusinessRules	20686280	17,877.813	17,860.938	16.875
Instance01	Database99	BusinessRulesAuditing	**TOTAL**	20686280	17,877.813	17,860.938	16.875
Instance01	Database99	BusinessRulesRuleSet	IX_RuleSet1	18840	2,100.000	137.000	1,963.000
Instance01	Database99	BusinessRulesRuleSet	IX_RuleSet2	18840	190.000	180.000	10.000
Instance01	Database99	BusinessRulesRuleSet	PK_RuleSet	18840	1,600.000	560.000	1,040.000
Instance01	Database99	BusinessRulesRuleSet	**TOTAL**	56520	3,895.766	877.945	3,017.820
Instance01	Database99	EquityOutputVersions	PK_EquityOutputVersions	35040362	1,746.688	1,739.281	7.406
Instance01	Database99	EquityOutputVersions	**TOTAL**	35040362	1,746.688	1,739.281	7.406
Instance01	Database99	EquityOverrides	PK_EquityOverrides	13105402	515.859	511.188	4.672
Instance01	Database99	EquityOverrides	**TOTAL**	13105402	515.859	511.188	4.672
Instance01	Database99	Auditing	PK_Auditing	173494	33.391	27.586	5.805
Instance01	Database99	Auditing	**TOTAL**	173494	33.391	27.586	5.805

<result set snipped for space>

--

In this case you could look at the fill factor of the IX_RuleSet1 and PK_RuleSet indexes to see why there is so much free space.  Failing that it is possible that these indexes need to be rebuilt to release that space, possibly after a large delete from the table cleared that space.


--

I find I use this query more than I ever would have thought with space issues - I start with the Database Free File query (from the previous post) and then move next to this query.

--

Hope this helps!

T-SQL Tuesday #98 – Take Small Bites!

https://media.makeameme.org/created/mega-bytes-well.jpg

It's T-SQL Tuesday time again - the monthly blog party was started by Adam Machanic (blog/@AdamMachanic) and each month someone different selects a new topic.  This month's cycle is hosted by Arun Sirpal (blog/@blobeater1) and his chosen topic is "Your Technical Challenges Conquered" considering technical challenges and what we do to resolve them.

This was kind of a hard one for me because a lot of my blog posts are already about technical challenges from work, which means I have already written about many things that would have qualified for this category - I did find one thing from a few months ago that I hadn't documented yet...

--

As a services/production DBA I frequently get technical challenges related to issues about disk space, which usually tie back to issues about file growth, which usually tie back to issues about code, which usually tie back to issues about people (not necessarily developers - and yes, I do believe developers are people...usually...)

https://i0.wp.com/www.adamtheautomator.com/wp-content/uploads/2015/04/Worked-Fine-In-Dev-Ops-Problem-Now.jpg

--

This story is yet another tale of woe starting with a page at 1am for a filling drive, in this case the LOG drive.

I went to my default trace query (described here) and found...a few...records for growths:

EventName	DatabaseName	FileName	StartTime	ApplicationName	HostName	LoginName
Log File Auto Grow	App01	App01_log	9/26/2017 1:08	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:08	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:08	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:08	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:08	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:07	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:07	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:07	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:07	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:07	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:06	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:05	SQLCMD	DBSQL	NT SERVICE\SQLSERVERAGENT
Log File Auto Grow	App01	App01_log	9/26/2017 1:04	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 1:00	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:59	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:59	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:59	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:59	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:59	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:59	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:58	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:58	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:58	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:58	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:58	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:57	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:57	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:57	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:57	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:57	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:56	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:56	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:56	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:56	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:56	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:56	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:56	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:55	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:55	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:54	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:54	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:53	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:52	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:52	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:51	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:51	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:50	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:49	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:49	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:48	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:48	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:47	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:47	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:46	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:45	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:45	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:44	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:44	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:44	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:43	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:43	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:43	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:43	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:42	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:42	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:42	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:42	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:42	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:41	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:41	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:41	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:41	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:40	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:40	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:40	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:40	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:39	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:39	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:39	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:38	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:38	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:38	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:38	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:38	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:37	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:37	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:37	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:37	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:36	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:36	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:36	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:36	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:36	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:35	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:35	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:35	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:35	NULL	NULL	sa
Log File Auto Grow	App01	App01_log	9/26/2017 0:34	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:33	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:33	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:32	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:32	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:31	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:31	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:31	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:30	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:29	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:29	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:28	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:27	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:26	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:26	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:25	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:25	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:24	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:24	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:23	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:22	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:20	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:19	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:18	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:16	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:15	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:14	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:14	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:13	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:12	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:11	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:10	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:09	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:08	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:07	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:06	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:05	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:04	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:04	.Net SqlClient Data Provider	HostServer01	App01admin
Log File Auto Grow	App01	App01_log	9/26/2017 0:03	.Net SqlClient Data Provider	HostServer01	App01admin

There was a single growth caused by SQLCMD on DBSQL– this was the index maintenance job running directly on the SQL Server.  Almost all of the other growths were triggered by a.NET application on application server HostServer01.  The App01 database's LDF/log file was set to autogrow in increments of 512MB so each row in the table above represents a single instance of that growth – as you can see the unit of work was generating 512MB of work every 30-60 seconds, which is a significant load.

The next step was setting up a basic XEvents session to track what statement(s) might be generating the load - sure enough there was a serious smoking gun:

https://i.pinimg.com/originals/c0/19/57/c01957fd9e59fe4a46a67ad49e049cc0.jpg

Check out the row near the middle with a very large duration, logical_reads count, *and* writes count.

Durations in SQL 2012 Extended Events are in microseconds – a very small unit.

The catch was the duration for this statement was 6,349,645,772 (6 billion) microseconds…105.83 minutes for this one query!

--

The App01 database was in SIMPLE recovery (when I find this in the wild, I always question it – isn’t point-in-time recovery important? – but that is another discussion).  The relevance here is that in SIMPLE recovery, LOG backups are irrelevant (and actually *can’t* be run) – once a transaction or batch completes, the LDF/LOG file space is marked available for re-use, meaning that *usually* the LDF file doesn’t grow very large.

A database in SIMPLE recovery growing large LDF/LOG files almost always means a long-running unit of work or accidentally open transactions (a BEGIN TRAN with no subsequent CLOSE TRAN) – looking at the errors in the SQL Error Log the previous night, the 9002 log file full errors stopped at 1:45:51am server time, which means the offending unit of work ended then one way or another (crash or success).

Sure enough when I filtered the XEvents event file to things with a duration > 100 microseconds and then scanned down to 1:45:00 I quickly saw the row shown above.   Note this doesn’t mean the unit of work was excessively large in CPU/RAM/IO/etc. (and in fact the query errored out due to lack of LOG space) but the excessive duration made all of the tiny units of work over the previous 105 minutes have to persist in the transaction LDF/LOG file until this unit of work completed, preventing all of the LOG from that time to be marked for re-use until this statement ended.

--

The query in question was this:

--

exec sp_executesql N'DELETE from SecurityAction WHERE ActionDate < @1 AND (ActionCode != 102 AND ActionCode != 103 AND ActionCode != 129 AND ActionCode != 130)',N'@1 datetime',@1='2017-09-14 00:00:00'

--

Stripping off the sp_executesql wrapper and the parameter replacement turned it into this:

--

DELETE from SecurityAction
WHERE ActionDate < '2017-09-14 00:00:00'
AND
(
ActionCode != 102
AND ActionCode != 103
AND ActionCode != 129
AND ActionCode != 130
)

--

Checking out App01.dbo.SecurityAction, the table was 13GB with 14 million rows.  Looking at a random TOP 1000 rows I saw some rows that would satisfy this query that were at least 7 months old at the time of this incident (from September 2017) and there may have been even older rows – I didn’t want to spend the resources to run an ORDER BY query to find the absolute oldest row.  I didn’t know based on this evidence whether this meant this individual statement has been failing for a long time or maybe this DELETE statement had been a recent addition to the overnight processes and had been failing since then.

The DELETE looked like it must be a scheduled/regular operation from a .NET application running on HostServer01 since we were seeing it each night in a similar time window.

The immediate term action I recommended to run a batched DELETE to purge this table down – once it had been purged down maybe the nightly operation would run with a short enough duration to not break the universe, a;though I did advise them that changing the nightly process to be batched wouldn't hurt (although they were dealing with a vendor app).

The code I suggested (and we eventually went with) looked like this:

--

WHILE 1=1
BEGIN
       DELETE TOP (10000) from SecurityAction
       WHERE ActionDate < '2017-09-14 00:00:00'
       AND
       (
       ActionCode != 102
       AND ActionCode != 103
       AND ActionCode != 129
       AND ActionCode != 130
       )
END

       
--

This would delete rows in 10,000 row batches; wrapping it in the WHILE 1=1 allows the batch to run over and over without ending.  Once there are no more rows to satisfy the criteria the query *WILL CONTINUE TO RUN* but will simply delete -0- rows each time.

Once you are ready to stop the batch you simply cancel it and it will end in whatever iteration of the loop it is currently in.

I could have written a WHILE clause that actually checks for the existence of rows that meet the criteria, but there were so many rows that met the criteria right then that running the check itself would have been much more intensive than simply allowing the DELETE to run over and over.

We finally ended up going with this code and after a half day of running it had the table purged down from 14 million rows to 700,000, and a run the next day of the unmodified "regular" DELETE statement completed in under a minute.

--

This seems like a very simple fix, and runs contrary to some database teaching that say batches (and their cousins, the cursors) are evil and should be avoided no matter what.  Many blogs, classes, etc. preach the value of set-based operations at all times.

This is where we see the standard DBA trope once again:

https://memegenerator.net/img/instances/58097633/what-if-i-told-you-it-depends.jpg

Always use the right tool for the job - and in a case like this the right tool was a batch-based solution.  You could tune the size of the batches (is 10,000 the best number?  Maybe a 100,000 row batch (or a 1,000 row batch) would have the best performance) but regardless of that a small batch was a better choice than a 13 million row set!

At the end of the day this seems very simple - but you would be amazed to see how often something like this comes up.

To minimize LOG space needed, take small bites!

http://www.nicoleconner.com.au/wp-content/uploads/2016/04/66247903.jpg

Hope this helps!