Disabling Non-Clustered Indexes For Fun and Profit

One of the frequently quoted ETL best practices is to disable your non-clustered indexes during a data load.  Basically the conventional wisdom is that you disable the non-clustered indexes, do your load, and then enable the non-clustered indexes, which functionally rebuilds them with the newly loaded data (a step you should be performing after a load of any size even if you *don't* disable your indexes - rebuild those newly fragmented indexes!)

So why doesn't anybody seem to do this?

https://memegenerator.net/img/instances/53039992/ponder-we-must.jpg

--

IMPORTANT NOTE <cue scary music> - do NOT disable the clustered index when doing data loads or at any other time you want the table to be accessible.  Disabling the clustered index makes the object (table or view) inaccessible.

If you disable the clustered index you are functionally disabling the object, and any attempts to access that object will result in an Error 8655:

Msg 8655, Level 16, State 1, Line 23

The query processor is unable to produce a plan because the index ‘PK_Person_BusinessEntityID’ on table or view ‘Person’ is disabled.

https://memegenerator.net/img/instances/62333367/no-please-dont-do-that.jpg

-- 

I recently had a situation with a client where they have a load process that altogether runs over 24 hours - not one day-long query but rather a string of processes that usually takes 24+ hours to complete.  The situation has worsened to the point where other things are impacted because the process is taking so long, and they asked me to check it out.

I started with all of the basics, and right away Page Life Expectancy during the relevant period jumped out:

The server has 128GB of RAM...so a PLE consistently below 1,000 is pretty low.

I used XEvents to gather queries with large memory grants, and it brought to light an issue that the client has previously considered but not handled - disabling indexes during the load.

** SIDEBAR**

The code for the XEvents session to pull large memory grant queries I used is as follows - it collects any memory grant over 8MB (which you can modify in the WHERE clause) and its calling query:

CREATE EVENT SESSION [Ntirety_MemoryGrantUsage] ON SERVER 

ADD EVENT sqlserver.query_memory_grant_usage

(

ACTION(sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id

,sqlserver.database_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text)

WHERE ([package0].[greater_than_uint64]([granted_memory_kb],(8192))))

ADD TARGET package0.event_file(SET filename=N'Ntirety_MemoryGrantUsage',max_file_size=(256)),

ADD TARGET package0.ring_buffer(SET max_events_limit=(0),max_memory=(1048576))

WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON

)

The query to then retrieve the data is this - it dynamically pulls your default error log path and then queries the XEL output file from the event_file target in the session at that path:

USE master

GO

DECLARE @ErrorLogPath nvarchar(400), @XELPath nvarchar(500)

SET @ErrorLogPath = (

SELECT LEFT(cast(SERVERPROPERTY('ErrorLogFileName') as nvarchar(400)),LEN(cast(SERVERPROPERTY('ErrorLogFileName') as nvarchar(400)))-8)

)

SET @XELPath = @ErrorLogPath+'Ntirety_MemoryGrantUsage*.xel'

SELECT DISTINCT *

FROM 

(

SELECT 

  DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), event_data.value(N'(event/@timestamp)[1]', N'datetime'))as Event_time

, CAST(n.value('(data[@name="granted_memory_kb"]/value)[1]', 'bigint')/1024.0 as DECIMAL(30,2)) AS granted_memory_mb

, CAST(n.value('(data[@name="used_memory_kb"]/value)[1]', 'bigint')/1024.0 as DECIMAL(30,2)) AS used_memory_mb

, n.value('(data[@name="usage_percent"]/value)[1]', 'int') AS usage_percent

, n.value ('(action[@name="database_name"]/value)[1]', 'nvarchar(50)') AS database_name

, n.value ('(action[@name="client_app_name"]/value)[1]','nvarchar(50)') AS client_app_name

, n.value ('(action[@name="client_hostname"]/value)[1]','nvarchar(50)') AS client_hostname

, n.value ('(action[@name="server_principal_name"]/value)[1]','nvarchar(500)') AS [server_principal_name]

, n.value('(@name)[1]', 'varchar(50)') AS event_type

, n.value ('(action[@name="sql_text"]/value)[1]', 'nvarchar(4000)') AS sql_text

FROM 

(

SELECT CAST(event_data AS XML) AS event_data

FROM sys.fn_xe_file_target_read_file(

@XELPath

, NULL

, NULL

, NULL)

) 

AS Event_Data_Table

CROSS APPLY event_data.nodes('event') AS q(n)

) MemoryGrantUsage

ORDER BY event_time desc

** END SIDEBAR **

Looking at the queries that were the top memory consumers over the time period led to some pretty basic queries:

INSERT INTO "dbo"."Junk" 

SELECT "UID"

, "ContainerId"

, "CategoryCode"

, "CategoryName"

, "CategoryDataValue"

, "CharacteristicCode"

, "CharacteristicName"

, "CharacteristicDataValue"

, "DimensionCode"

, "DimensionName"

, "DimensionDataValue"

, "OptionId"

, "NumberOfItems"

, "IsStandard"

, "LanguageId"

, "Market"

, "VehicleType"

, "YearMonth"

, "BatchRefreshDate"

, "CreatedBy"

, "CreatedTimestamp"

, "ModifiedBy"

, "ModifiedTimestamp"

, "BatchId" 

FROM "dbo"."Junk_Stg" 

where "Market" = 'XYZ'       

  

https://media.makeameme.org/created/so-simple-right.jpg

The immediate problem to me was that memory grants usually come from SORT and HASH operations (check out Erik Darling's great description at https://www.erikdarlingdata.com/starting-sql/starting-sql-memory-grants-in-execution-plans/) and this query doesn't obviously do any of that - it is a very straightforward INSERT...SELECT from one table into another, but the query plan looks like this:

 

Pretty crazy right?  With all of those SORT's, no wonder SQL Server wants to give this query a giant memory grant!

But why are there six different SORT operations on this one basic INSERT...SELECT?

Then I realized this is why:

Six SORT's...for SIX non-clustered indexes!

Inserting rows into a table with enabled non-clustered indexes requires a SORT to add rows to that index - the INSERT can't simply dump the rows on to the end of the index, but has to sort the input to match the indexes sort.

As a test I created a copy of the target table that I could tweak the indexes on, and a second copy without the indexes in place, and my INSERT...SELECT query plan against the No Index copy looked a little bit better:

As I test I copy-pasted the two INSERT...SELECT's into a single query window and pulled the plans for each so that I could compare them:

The Query Cost numbers in Management Studio always have to be taken with a grain of salt, but for comparison's sake consider - the six-way insert costs almost four times as much as the no-index query!

To test further I disabled three of the indexes on my copy table and ran the plan again:

Bingo - six streams now down to three for the three remaining enabled indexes.

I disabled the rest of the non-clustered indexes and:

https://memegenerator.net/img/instances/63334945/booyah.jpg

For one final comparison I ran the double query against  my "Indexes All Newly Disabled" copy and my "No Index" copy together:

Spot on!

--

As I mentioned above the cost to this is that at the end of the process you have to have time to enable the indexes again, which does a rebuild of that index.

As always Your Mileage May Vary, as the direct impact will relate to the size of the table, the number of non-clustered indexes in place, and multiple other items - but check it out, especially if your process runs longer than you want - this may be the problem!

Hope this helps!

When Your Options Are Limited

In my role I am still on-call several times each month, and many of the escalations that come are simply things that newer DBA's and Help Desk staff have yet to run into - things that many employees at their level *can* handle, once they have experienced it.

This is one of those stories.

https://memegenerator.net/img/instances/57630989/with-a-one-way-ticket-to-the-twilight-zone.jpg

Our monitoring alerted the Help Desk because a client SQL Server was down (in this case, SQL services were stopped but Windows was not down).  In most cases this is handled between our Help Desk and if needed, the client, but in this case it was paged out to me with this note from the help desk technician:

"Upon checking on server Generic SQL Server, SQL Server Agent and SQL Server are failed - these services have automatic startup type but I can't start the services because the start option is disabled  "

And they added a screen shot:

There are multiple reasons why you can't start a service, most of them around permissions (role memberships, explicit permissions, etc.)  With what we do as a managed services provider (MSP) we usually have extensive administrative privileges on the servers on which we work, so true permissions aren't usually a problem.

But UAC is.

https://pics.ballmemes.com/curses-foiled-again-6891606.png

User Account Control (UAC) was introduced in Windows Vista and has since been expanded across multiple Windows desktop and server platforms.  At a basic level, it is an extra layer of security to make sure that changes to the operating system and it's components are only performed by administrators, and only when actually intended - think of it as an "Are You Sure You Want To Do That?"

https://memegenerator.net/img/instances/55831706/is-that-your-final-answer.jpg

UAC is an important security feature but can also be pretty annoying when you perform administrative tasks all of the time.  When I was looking for a good descriptive link to reference in the paragraph above, five of the top ten items were some variant of "here's an easy way to turn off UAC" (and three of the other five were "why you should never turn off UAC!")

The functional gotcha is the screen shown above.  The technician had not run the services console "as administrator" and as such did not have the token authority to start/stop Windows services.

This is an easy fix, however...instead of double-clicking on the services icon, simply right-click and select "Run As Administrator"

If your login is a Windows administrator. this then runs the services console with the administrator token, and you can then start/stop/manage services (as well as break/delete/befoul services - be careful!) to your heart's content.

If your login is *not* a Windows Admin, you will receive a prompt which will allow you to enter administrative credentials which will be used solely to run the application in question - it isn't a full context switch to that login for your whole session.

Note - you will often also run into this on some systems with SQL Server Management Studio and other SQL Server tools if you are running them locally on a server - if you run the tool and cannot connect to your local SQL Server instance, it may be that you haven't run the tool "as administrator."  Simply right-click the icon for the tool and, as above, select "Run as Administrator."

--

Hope this helps!

Why Can't I Shrink TempDB?

I know, I know....#OMGShrinkingIsBadDontEverDoThatOrElseEtcEtcEtc

We all know that there are simply times you have to shrink some files.  There are risks - blocking, significant I/O, fragmentation, and more - all of which mean you should not shrink a file willy-nilly without considering the impacts...but sometimes you are having a production issue and don't have any choice.  Similarly, sometimes you are in Dev/Test and it is simply more practical to shrink a file than to add drive space or re-architect the full solution.

In many cases it comes down to that unfortunate reality that there's a way the book/class does it, and another way we have to do it "in the field."

http://twitchlol.com/wp-content/uploads/2013/09/Battle-Plan-for-kids.jpg

Of course you also have to remember Law #9842 of being a DBA - all database systems are Production to someone.  It may be a developer or a QA team rather than an end user, but it is still PROD to them!)

--

In this story, TempDB DATA files were using almost all of the space on the drive, meaning TempLog couldn't grow, but the DATA files were mostly empty by the time it escalated to me.

Even though the files were mostly empty, my attempts to shrink them were throwing an error and the files were not shrinking:

--

Msg 5054, Level 16, State 1, Line 1
Could not cleanup worktable IAM chains to allow shrink or remove file operation.  Please try again when tempdb is idle.

--

www.deviantart.com/ieatatwaffenhouse/art/Skeletor-553757222

Googling the message led me to one of my top five authoritative sources, Paul Randal of SQLskills.com (@PaulRandal/blog).  The relevant blog post is https://www.sqlskills.com/blogs/paul/shrinking-tempdb-longer-prohibited/

While my error message isn't featured in the body of the blog post, it *is* in the final comment and reply in the article.  By that information, it appears that this error reflects that certain system structures are on pages that can't be moved without system restart, which means TempDB can't be manually shrunk on this instance w/o SQL service restart.

(Paul does describe in his article the old-school fear that "shrinking TempDB leads to corruption" and how his extensive experience leads him and Microsoft to now believe that is not true *on modern versions of SQL Server (2005+)*)

--

Hope this helps!

Did Not Know That - Redirecting CMD to the Clipboard

One of the items I frequently deal with as a Production DBA is drive alarms.  I have written previously about looking for space inside database files, but what if your problem is non-database files?

The goto tool in Windows for me has always been du (Disk Usage) created by Mark Russinovich (blog/@markrussinovich) as part of his Sysinternals project.

du is a very straightforward command tool the traverses the directory structure below the current path and returns the folder sizes of the given folders.  For example, the output for C:\Windows on a given server looks like this:

Fine to look at, but a bit onerous to manipulate - after all this is just a screenshot.

The first way I knew to deal with this was via the >> redirect:

du -l 1 >> Output4.txt

This would create a text file at the path being searched containing the output from the command, which can then be copy-pasted out to another site:

To clean it up for manipulation (in Excel for example), you can add a parameter to du to turn the output to comma- or tab-delimited format (either -c or -ct):

du -ct -l 1 >> output5.txt

--

The new trick I learned is that you can use a pipe - similar to Powershell - to redirect the output of the du command to another command, and that there is a command to send the output of a command directly to the clipboard (unbelievably enough, called "clip"):

du -ct -l 1 | clip

http://ru.memegenerator.net/instance/57285847/mind-blown-cat-mind-blown

I found this trick in a helpful blog post here.

Once it's in the clipboard, it can be pasted straight into Excel where it can be easily sorted, for example to find the largest directories:

Pretty cool, huh?

This same process of piping into clip works with a wide variety of command line commands, but this is the one for which I see the most immediate value.

--

Hope this helps!

The Mystery of the Exploding T-Log

There were a stack of errors overnight in the DB123 database on SQL01, including one horror show error:

--

Log Name:      Application

Source:        MSSQLSERVER

Date:          5/24/2018 12:49:39 AM

Event ID:      3314

Task Category: Server

Level:         Error

Keywords:      Classic

User:          N/A

Computer:      SQL01.client99.com

Description:

During undoing of a logged operation in database 'DB123', an error occurred at log record ID (195237:96178:4). Typically, the specific failure is logged previously as an error in the Windows Event Log service. Restore the database or file from a backup, or repair the database.

--

https://i.imgflip.com/rlu4s.jpg?a424656

The catch is that when I checked the server, the database was online.

Say what?

--

It started with the LOG drive filling generating a long string of 9002’s:

--

Log Name:      Application

Source:        MSSQLSERVER

Date:          5/24/2018 12:49:39 AM

Event ID:      9002

Task Category: Server

Level:         Error

Keywords:      Classic

User:          N/A

Computer:      SQL01.client99.com

Description:

The transaction log for database 'DB123' is full due to 'ACTIVE_TRANSACTION'.

--

Followed by a “crash” including the horror show error:

--

Log Name:      Application

Source:        MSSQLSERVER

Date:          5/24/2018 12:49:39 AM

Event ID:      9001

Task Category: Server

Level:         Error

Keywords:      Classic

User:          N/A

Computer:      SQL01.client99.com

Description:

The log for database 'DB123' is not available. Check the event log for related error messages. Resolve any errors and restart the database.

--

Log Name:      Application

Source:        MSSQLSERVER

Date:          5/24/2018 12:49:39 AM

Event ID:      3314

Task Category: Server

Level:         Error

Keywords:      Classic

User:          N/A

Computer:      SQL01.client99.com

Description:

During undoing of a logged operation in database 'DB123', an error occurred at log record ID (195237:96178:4). Typically, the specific failure is logged previously as an error in the Windows Event Log service. Restore the database or file from a backup, or repair the database.

--

…which seems scary, but then the database seemed to magically recover on its own:

--

Log Name:      Application

Source:        MSSQLSERVER

Date:          5/24/2018 12:49:41 AM

Event ID:      17137

Task Category: Server

Level:         Information

Keywords:      Classic

User:          N/A

Computer:      SQL01.client99.com

Description:

Starting up database 'DB123'.

--

Log Name:      Application

Source:        MSSQLSERVER

Date:          5/24/2018 12:49:45 AM

Event ID:      3450

Task Category: Server

Level:         Information

Keywords:      Classic

User:          N/A

Computer:      SQL01.client99.com

Description:

Recovery of database 'DB123' (5) is 0%% complete (approximately 4502 seconds remain). Phase 1 of 3. This is an informational message only. No user action is required.

--

There was a huge string of Error 18456 (login failures) since DB123 was unavailable during regular recovery, followed eventually by:

--

Log Name:      Application

Source:        MSSQLSERVER

Date:          5/24/2018 1:08:12 AM

Event ID:      3421

Task Category: Server

Level:         Information

Keywords:      Classic

User:          N/A

Computer:      SQL01.client99.com

Description:

Recovery completed for database DB123 (database ID 5) in 1107 second(s) (analysis 52027 ms, redo 238039 ms, undo 700990 ms.) This is an informational message only. No user action is required.

--

…and all was well.

http://www.thingsmadefromletters.com/wp-content/uploads/2013/10/whut-i-dont-understand-this.jpg

I went looking for similar situations and found this:

https://www.sqlservercentral.com/Forums/Topic1525719-146-1.aspx

In this situation the drive filled and the database crashed, going through recovery once there was additional free space on the drive, which sounded exactly like the situation here.

In short, there was no actual corruption crash, just insufficient disk space.

--

Using the default trace query described here, I checked for autogrowths, and here was what they looked like:

EventName	DatabaseName	FileName	ApplicationName	HostName	LoginName	Duration	TextData
Log File Auto Grow	DB123	DB123_log	.Net SqlClient Data Provider	WEB05	WebLogin01	1013000	NULL
Log File Auto Grow	DB123	DB123_log	.Net SqlClient Data Provider	WEB05	WebLogin01	920000	NULL
Log File Auto Grow	DB123	DB123_log	.Net SqlClient Data Provider	WEB05	WebLogin01	873000	NULL
Log File Auto Grow	DB123	DB123_log	.Net SqlClient Data Provider	WEB05	WebLogin01	1083000	NULL
Log File Auto Grow	DB123	DB123_log	.Net SqlClient Data Provider	WEB05	WebLogin01	646000	NULL
Log File Auto Grow	DB123	DB123_log	Ivanti	WEB05	WebLogin01	903000	NULL
Log File Auto Grow	DB123	DB123_log	.Net SqlClient Data Provider	WEB05	WebLogin01	880000	NULL
Log File Auto Grow	DB123	DB123_log	.Net SqlClient Data Provider	WEB05	WebLogin01	846000	NULL
Log File Auto Grow	DB123	DB123_log	.Net SqlClient Data Provider	WEB05	WebLogin01	1176000	NULL
Log File Auto Grow	DB123	DB123_log	.Net SqlClient Data Provider	WEB05	WebLogin01	846000	NULL
Log File Auto Grow	DB123	DB123_log	.Net SqlClient Data Provider	WEB05	WebLogin01	1416000	NULL

Since the TEXTDATA is NULL I can’t say what process caused the growths for sure, but they started at 12:22am local server time. 

I could tell the client that since they came from the .NET provider they aren’t caused by Index/Statistics maintenance or anything else internal.

--

To try to run down what might be causing the autogrowths I set up an Extended Events session to capture statement completion events (rpc_completed, sp_statement_completed, and sql_batchcompleted) to see what was actually running during the time slice.  Sure enough there was a smoking gun:

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

https://steemitimages.com/DQmarWgB1ztrx628DTGpkteJeKiU3waad9YRtm5jVedJxws/problem.jpg

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

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

--

The DB123 database is in SIMPLE recovery (note - when I find this I 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. (usually!)

A database in SIMPLE recovery growing large LDF/LOG files almost always mean 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 last 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 is 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 turns 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 DB123.dbo.SecurityAction, the table is 13GB with 14 million rows.  Looking at a random TOP 1000 rows I see rows that would satisfy this query that are at least 7 months old (from February 2017) and there may be even older rows – I didn’t want to spend the resources to run an ORDER BY query to find the absolute oldest.  I don’t know if this means this individual statement has been failing for a long time or maybe this DELETE statement is a recent addition to the overnight processes and has been failing since then.

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

The immediate term action they chose was to run a batched DELETE to purge this table down – once it has been purged down maybe the nightly operation will run with a short enough duration to not break the universe.

I told them it should be able to be handled with a TOP DELETE something 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, and then when the user is ready to stop the batch they simply cancel it.

You could write a WHILE clause that actually checks for the existence of rows that meet the criteria, but in this case there were so many rows that meet the criteria that running the check itself is more intensive than simply allowing the DELETE to run over and over.

It took several hours of running the "batched" loop, but eventually the table got down from 14 million rows to 900,000 rows without growing the LDF file past 2GB!

https://memegenerator.net/img/instances/80336841/booyah.jpg

--

Lesson #1 - don't run giant deletes without considering the impact.

Lesson #2 (and maybe the more important) - "horror show" errors aren't always a horror show - always investigate fully!

--

Hope this helps!