SQL Server DBA: The worst days

In a recent blog post Steve Jones posed the question; what was the worst day in your career? Great idea by the way.

A couple of experiences that occurred early on in my DBA career sprung to mind. There was the rather nasty corruption of a critical but not highly available application database that happened mid-afternoon which led to a very manual and overnight full restore (legacy system means very legacy hardware).  

The subsequent post-restore checks were also quite lengthy meaning the entire recovery process concluded at around 5.30AM the next morning, which actually wasn't that far from my estimated ETA of a working system. Operationally the effects weren't too bad; transactions were captured using a separate system and then migrated into the restored database when it came back online. I'll never forget the post incident discussion either; no finger pointing, no blame whatsoever just a well done to all for having a successful recovery operation and a genuine interest in how we could further minimise any impact in future. 

Then there was the time the execution of an application patch with a slight (and undiscovered until then) code imperfection brought down an entire production server, that just happened to be attempting to process some rather critical financial workloads from various systems at the same time. In truth it was a completely freak event that had happened on a combination of very old systems that were considered flaky at best.

The systems were brought online quickly enough but tying together the results of the various processes that may or may not have worked took hours and hours of querying with lots of manual updates. It might sound terrible, but because of the coordinated effort between different teams and individuals it had actually taken a fraction of the time that it could have done and not only that, data was confirmed to be 100% accurate.  

Want another corruption tale? Why not. How about the time a system database on a 2005 instance went all corrupt rendering the instance completely useless? Of course it never happens to a system that nobody cares about, no, yet another critical system. The operational teams went to plan B very quickly but even better, a solution that avoided large restores was implemented quickly so the downtime, although handled well, was still significantly reduced.

Looking back there's plenty more, I think it's fair to say that disaster is a real occupational hazard for database professionals. And yet despite being labelled "worst days" I actually look back on them with a large degree of genuine fondness. 

You see disasters are always going to happen when databases are involved, it's a fact and how we deal with them at the time is equally as important as how we learn from these events. In each of these examples a recovery plan was in existence for both technical and operational viewpoints, as well as that everyone involved knew what was happening, what to do and critically not to add any additional pain to the situation but to arrive at the solution as quickly as possible.

Learning from these events meant asking the right questions and not taking a viewpoint of blame. How can we prevent this, how can we make a recovery process more robust and what can we implement technically and operationally to improve our response times and also critically, when can we schedule the next Disaster Recovery test? 

Worst days? In one sense most definitely yes. Nobody wants to be in the middle of a technical disaster that's going to take hours to resolve but a solid recovery plan, collaborative effort to a solution and an open forum to analyse and learn from the event makes these memories much less painful!

New posts on SQL Shack

I've just posted a couple of articles on SQL Shack, the Apex SQL community website. The first post introduces Dynamic Management Objects and how we can use them to monitor SQL Server, it's an entry level read and introduces some T-SQL fundamentals along the way.

Then I've followed up that post with an article focusing on sys.dm_exec_requests. This is a very common DMV to use as it shows all active requests on a SQL Server and this article explains some of the key columns to use in monitoring/troubleshooting.

Here's a link to the first post; sessions and connections and the post contains a link to the next part of the series at the bottom of the page.

Hope you'll find them good reads and as always feedback is more than encouraged, love to know what you think.

Consistency checks on large databases

This is a bit of a follow up from my last post about torn pages in SQL Server. Within that post I mentioned the DBCC CHECKTABLE command which performs a consistency check against a specified table name.

It reminded me of a situation that I've certainly come across a few times where a databases size has meant it's outgrown the acceptable maintenance window and that resource intensive operations like consistency checks are now overlapping into production hours. This can seriously impact items like ETL processes so a clever approach that balances both consistency and resource contention is now required. 

One way to achieve this is to  split up the consistency checks covering smaller objects and native functionality allows us to do just that, we can perform the checks at the table level or indeed if they are implemented at the filegroup level too using the DBCC CHECKFILEGROUP command.

How to go about this is pretty straightforward; take the list of tables, split them into equal(ish) groups. The groups now form a pool of objects and within a nightly (or daily) window perform the check on each object in the pool. This effectively spreads a database consistency check over multiple days, you avoid the impact on production activities but also ensure all objects are checked over time.


DBCC CHECKTABLE ('dbo.ReallyImportantTable')
GO


DBCC CHECKTABLE ('dbo.AnotherReallyImportantTable')
GO

So the next question is how often should consistency checks be performed? For me the answer is simple; as often as possible. I've always suggested nightly checks where possible and if the database size means we can't do this then we start to break down the objects. Perhaps we have two pools of tables and on our first maintenance night we do pool one, night two we perform the checks on pool two and we repeat the process throughout the week. It could be 3 pools, even more - but at least the checks are being performed and are avoiding other processes.

The golden rule is to ensure database consistency and there are occasions that due to its intensive nature we have to find ways of avoiding impact on to production systems. So it's worth knowing that there are options available that make it more manageable, avoid the impact on these other processes and maintain confidence that your databases (or rather their objects) are consistent; and that is the most important thing.

Torn Pages and using DBCC PAGE

Today's post is about torn pages and using the undocumented DBCC PAGE command within SQL. Occasionally you might find you need to run this command and in this example it's because I have received an error message that looks a bit like this:

SQL Server detected a logical consistency-based I/O error: torn page (expected signature: 0xaaaaaaaa; actual signature: 0xa9aaaaaa). It occurred during a read of page (1:25756919) in database ID 9 at offset 0x000031209ee000 in file 'F:\DATA\ScratchDatabase.mdf'

This is an error that has been picked up on one of my test systems and indicates that SQL Server has detected a torn page, that is a page that has been incorrectly written by SQL Server and possibly indicates a problem in the IO subsystem.

The problem here is that whilst we know the database and the page where the error has occurred we don't know the specific table the page belongs and importantly what type of page is in error. The reason why the page type is important is because this will drastically impact our recovery process but the first thing we will do is check a system table to see if any other page errors have been reported:

SELECT * FROM msdb..suspect_pages

database_id	file_id	page_id	event_type	error_count	last_update_date
9	1	25756919	3	1	2017-01-29 08:24:05.760

Here we can see that only one row has been returned, the event_type refers to a torn page, here's the full type descriptions and a link for more information:

1 = An 823 error that causes a suspect page (such as a disk error) or an 824 error other than a bad checksum or a torn page (such as a bad page ID).

2 = Bad checksum.

3 = Torn page.

4 = Restored (page was restored after it was marked bad).

5 = Repaired (DBCC repaired the page).

7 = Deallocated by DBCC.

To identify the table in error we will use DBCC PAGE. This command takes a database id (or name), file id and page id and will return the actual page information back to the results window (we need to enable trace flag 3604 to do this though); for my example I would use the following command:

DBCC PAGE (9, 1, 25756919, 0)

This returns a lot of information to the results window (I can use the option WITH TABLERESULTS for a grid view) so I have removed a fair chunk of it and highlighted the two parts that I really need.

PAGE: (1:25756919)

 

PAGE HEADER:

Page @0x0000000728010000

m_pageId = (1:25756919)             m_headerVersion = 1                 m_type = 2

m_typeFlagBits = 0x0                m_level = 0                         m_flagBits = 0x104

m_objId (AllocUnitId.idObj) = 266296m_indexId (AllocUnitId.idInd) = 256

Metadata: AllocUnitId = 72057611489902592                               

Metadata: PartitionId = 72057607060652032                                Metadata: IndexId = 20

Metadata: ObjectId = 567673070      m_prevPage = (1:25756918)           m_nextPage = (1:38369560)

The first is Metadata: ObjectId = 567673070 which refers to the table that this page belongs to. The second is Metadata: IndexId = 20 which tells me as it isn't 0 (heap) or 1 (clustered index) that the page error is within a non-clustered index and I can use the following code to identify the actual index where the problem lies.

SELECT * FROM sys.indexes WHERE index_id = 20 AND object_id = 567673070

This returns the suspect index and to resolve we can very simply drop and recreate the index effectively reallocating the pages, suspect and all. This is potentially much quicker than performing a full restore and I have lost count of the times I have seen people resort to a full restore without checking the actual type of page corruption that they're attempting to resolve.


Another option here is that because we know the effected table we can run a DBCC CHECKTABLE command (rather than a DBCC CHECKDB on the entire database), passing in the full table name as a parameter; to get the name of the table we use our ObjectId again that was returned from DBCC PAGE with the following:

SELECT OBJECT_NAME (567673070)

This would return the table name that we can use to check the structure to see if our page issue has been resolved:

DBCC CHECKTABLE ('dbo.ETL_TestLoad) WITH NO_INFOMSGS

DBCC results for 'ETL_TestLoad'.
There are 341465 rows in 93513 pages for object "ETL_TestLoad".
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

Using DBCC CHECKTABLE in this scenario may have proven that our torn page has been resolved but you should always, without question, perform a full database consistency check to look for further errors. In the event of IO issues this could easily return more and more page problems, maybe irrecoverable data page ones at that. Any page read/write errors must result in both a full consistency check and a check with the storage people to see if they can see any underlying issues.


For some further reading check out my post: How to consistency check large databases

TRACEWRITE and querying sys.traces

This post is about a wait type that I have seen being safely ignored by admins in the past but actually it does highlight an particular that I like to check up on in systems that I’m maintaining.

The wait type I’m referring to is TRACEWRITE and it’s easy to see why it often gets classed as being safe to ignore. SQL Server does run a default trace continuously so naturally this wait will show up in wait stat queries for your instances and be quite prominent (like the one below) but that said; whilst it’s relatively safe for the default trace to be ruled out of any further investigation what about traces that have been started by other users?

I typically see a scenario in non-production systems where a trace has been turned on to monitor a particular process for testing and then forgotten about and not stopped again once the process has finished. Tracing is not particularly cost friendly at the best of times so one running way beyond its expected duration is something you do want to know about.

The following query looks at what traces are currently running on the system:

SELECT

start_time,

stop_time,

[status],

[path],

is_default,

reader_spid

FROM sys.traces

 

This query returns information on all the current traces running on your system. It’s worth adding at this point that tracing to some degree (I still see tracing, a lot! has been replaced by extended events which are much more lightweight in operation, so another reason to be checking. Here's what a default trace looks like:

The columns returned are pretty self-explanatory, a value of 1 in the status column means the trace is currently running (0 = stopped) and you can use the reader_spid column to return information on who is using it, and who to ask about turning the trace off.


To summarise; in most cases trace related waits like TRACEWRITE are safe to ignore but it's good practice to routinely run a check on those systems where people might be running traces or you could even set up jobs that will automatically stop any traces outside of working hours.


One final point, it is very common for monitoring applications to sue some form of trace analysis, these could well be part of routine maintenance so prior to switching anything off ensure you know how the trace has originated and what its purpose is.

Troubleshooting with Wait Statistics

Troubleshooting is a fundamental activity for any DBA and when it comes to SQL Server one of the most important tasks is analysing the wait statistics that have occurred within the instance.

So what are wait statistics? In short whenever a task is “waiting” its type of wait and duration are recorded by SQL Server. This information is incredibly useful and we can query DMV's (Dynamic Management Views) to obtain this information that we can use to aid our troubleshooting efforts.

One particular view is the sys.dm_os_wait_stats DMV. This is an aggregated view that shows us the waits that have been occurring in our instance since the last restart or when the wait statistics were cleared down. Queries like the one below are typically sorted by the wait_time_ms column to indicate the most prominent wait types that have occurred over time in our SQL server.

SELECT TOP 10 * FROM sys.dm_os_wait_stats

ORDER BY wait_time_ms DESC

Running this query without as it is will produce a lot of different wait types so it’s important to know that many of them are likely to be a result of completely normal operations that are being undertaken by SQL Server. This isn’t the problem with sys.dm_os_wait_stats that I am going to demonstrate today though so I will keep the queries very simplistic. What I want to show you is that although this view is great as a summary, it isn’t necessarily helpful when it comes to real-time analysis.

I’ll start by creating a new table in a non-production database on a non-production instance of SQL Server and insert a handful of rows.

CREATE TABLE [dbo].[tblPeople](

       [ID] [smallint] IDENTITY(1,1) NOT NULL,

       [FirstName] [varchar](50) NULL,

       [LastName] [varchar](50) NULL

) ON [PRIMARY]

GO

USE [TestingDatabase]

GO

INSERT INTO tblPeople (FirstName, LastName) VALUES ('Peter','Morgan');

INSERT INTO tblPeople (FirstName, LastName) VALUES ('Sarah','Jones');

INSERT INTO tblPeople (FirstName, LastName) VALUES ('Liam','Davies');

INSERT INTO tblPeople (FirstName, LastName) VALUES ('Joanne','Jenkins');

In order to remove any previous information and clear down the wait statistics we have to run the following DBCC command:

DBCC SQLPERF('sys.dm_os_wait_stats', CLEAR);

To force a wait in SQL I will create a blocking scenario by issuing an update command on our new table without committing or rolling back the transaction.

BEGIN TRAN

UPDATE tblPeople

SET LastName = 'Davies' WHERE LastName = 'Jenkins'

In another window (to stress, use another window) I will try to select data from that table knowing that I won’t be able to because it is being updated by another transaction. As it cannot acquire a lock my select query it should start to accumulate a LCK wait type.

SELECT TOP 1000 [ID]

      ,[FirstName]

      ,[LastName]

  FROM [TestingDatabase].[dbo].[tblPeople]

I’ll leave that query running for a few seconds and then look at sys.dm_os_wait_satas again and as mentioned previously I’ll order by wait_time_ms descending so I can see the worst offenders in my instance since the stats were cleared down. At this point I might expect that I will see a lock wait type appear very high in the list.

SELECT TOP 10 * FROM sys.dm_os_wait_stats

ORDER BY wait_time_ms DESC

wait_type	waiting_tasks_count	wait_time_ms	max_wait_time_ms	signal_wait_time_ms
SP_SERVER_DIAGNOSTICS_SLEEP	531	300000	299995	300000
LOGMGR_QUEUE	1109	142871	156	6
DIRTY_PAGE_POLL	1417	142842	122	16
SLEEP_SYSTEMTASK	9041	142832	54	98
HADR_FILESTREAM_IOMGR_IOCOMPLETION	285	142670	503	7
LAZYWRITER_SLEEP	150	142097	1008	5
SQLTRACE_INCREMENTAL_FLUSH_SLEEP	35	140008	4000	0
XE_TIMER_EVENT	54	140000	4999	140000
REQUEST_FOR_DEADLOCK_SEARCH	28	139990	5000	139990
QDS_SHUTDOWN_QUEUE	2	120000	60000	0

Odd, no lock waits! We know we have a blocked task because we’ve just created it but it isn’t showing here. Now this might be because my LCK wait type isn’t in the top ten waits based on duration, it’s unlikely, but we can alter our query to just return rows for the sort of wait type that we are after:

SELECT TOP 10 * FROM sys.dm_os_wait_stats

WHERE wait_type LIKE 'LCK%'

ORDER BY wait_time_ms DESC

wait_type	waiting_tasks_count	wait_time_ms	max_wait_time_ms	signal_wait_time_ms
LCK_M_UIX	0	0	0	0
LCK_M_SIX	0	0	0	0
LCK_M_SIU	0	0	0	0
LCK_M_IX	0	0	0	0
LCK_M_IU	0	0	0	0
LCK_M_IS	0	0	0	0
LCK_M_X	0	0	0	0
LCK_M_U	0	0	0	0
LCK_M_S	1	0	0	0
LCK_M_SCH_M	0	0	0	0

Here I can see one waiting task, I know in this test scenario its my task and that is the only thing running but ordinarily, because it's a cumulative value, it's difficult to pinpoint what is happening right now. It's also worth noting that although the waiting task count has incremented the wait time hasn't which begs the question, when do these wait times get populated?

In order to check I'm going to roll back the transaction by running the following command underneath the update statement (the same window this time).

ROLLBACK TRAN

Let’s run the query again to check our running totals now our query has finished and I'll leave the LCK type clause in there.

SELECT TOP 10 * FROM sys.dm_os_wait_stats

WHERE wait_type LIKE 'LCK%'

ORDER BY wait_time_ms DESC

wait_type	waiting_tasks_count	wait_time_ms	max_wait_time_ms	signal_wait_time_ms
LCK_M_S	1	420051	420051	0
LCK_M_SCH_M	0	0	0	0
LCK_M_SCH_S	0	0	0	0
LCK_M_UIX	0	0	0	0
LCK_M_SIX	0	0	0	0
LCK_M_SIU	0	0	0	0
LCK_M_IX	0	0	0	0
LCK_M_IU	0	0	0	0
LCK_M_IS	0	0	0	0
LCK_M_X	0	0	0	0

Now that the transaction has finished we can see that our cumulative values have been updated. I was initially surprised by this as I always considered the DMV to contain “running” totals but looking on the Books Online article on the DMV you will find the following line:

Returns information about all the waits encountered by threads that executed.

Executed; that would be past tense! As we’ve just demonstrated the duration values are only updated after a thread has finished executing. It does make sense as it is an aggregated view after all but as such it does raise an important point; using the sys.dm_os_wait_stats DMV is not the best option for real time troubleshooting.

In order to do that a bit better we have to use a different DMV and one at the task level rather than the summary view that sys.dm_os_wait_stats gives us. So let’s run the update and select query from our previous test again to create the same blocking scenario and after a few seconds run the following script:

SELECT session_id, wait_type, wait_duration_ms, blocking_session_id

FROM sys.dm_os_waiting_tasks

WHERE session_id > 50

This query selects from the sys.dm_os_waiting_tasks management view and shows the tasks that are currently waiting. Here I’m selecting the type of wait, the duration in milliseconds (that we know isn’t available in the sys.dm_os_wait_stats view in real-time) and finally I’ve included the blocking_session_id.

session_id	wait_type	wait_duration_ms	blocking_session_id
58	LCK_M_S	62790	56

Now we get a much better picture of which executing tasks are currently waiting, what the wait types are and importantly (and what we didn’t get before), for how long. You can refresh the queries results to see the duration increase whilst the select query is being locked.

We can now repeat the rollback transaction command (or commit it depending how optimistic you’re feeling) that we did previously and check to see that sys.dm_os_wait_stats has been updated accordingly.

So here are two different ways that we can use SQL Servers wait statistics for troubleshooting purposes. Both views give us really useful information but both have different purposes. If we wanted to look back over time then the sys.dm_os_wait_stats will give us a view of wait time totals. Typically we would capture the information via a scheduled job and analyse the data for spikes during periods where issues might be suspected.

For performing real-time analysis of wait statistics then we should base queries on the sys.dm_os_waiting_tasks view where we can see accurate wait duration values as they are happening within our instance.

In my opinion wait statistics are the most important piece of information when troubleshooting SQL Server so learning about the different types is vital for anyone using SQL. Thankfully there is a wealth of really useful information about wait statistics out there; I’ve listed some of my favourite links below.

More Reading.

Books Online: sys.dm_os_wait_stats

Books Online: sys.dm_os_waiting_tasks

Lots and lots of in-depth and interesting wait stat articles by Paul Randal

Brent Ozar - Triage Wait Stats