Toolbox - How Long Has My Server Been Up?

https://imgflip.com/i/2axp6y

No..not that Up (although it is awesome!)

--

As a remote service provider a common request is to follow up after a server restart (or investigate a possible server restart).  A question that inevitably comes up is "When did the server restart?"

If all you need to know is when the SQL Server service restarted, the easiest thing is the creation date of tempdb since it is recreated as part of SQL Server start-up:

--

SELECT name, create_date
FROM master.sys.databases
WHERE name = 'tempdb'

--

name	create_date
tempdb	05/14/2018 07:31:18

--

The catch is that the SQL service restart often isn't good enough.

When did Windows reboot?

When did the Agent service start?

Why did SQL start before the tempdb create date?

...and more.

I went digging and found an answer I liked online - as usual I modified it for my own wishes while keeping the core of the code:

--

/*
Item Uptime Query
Author Andy Galbraith
Created 2018/01/03
Updated 2018/03/05
Decription Returns uptime for Windows, SQL Server, and SQL Agent
Versions SQL 2005+
Notes In some cases the SQL Server start time may show earlier than the OS start time - this is due
to the particular flags used to show that the system is "up" and is expected.
*/

/*
Queries modified from query in comment at:
https://www.sqlservercentral.com/Forums/Topic1384287-391-1.aspx
*/

SELECT
@@SERVERNAME as Instance_Name
, GETDATE() as Current_Server_Time
, CONVERT(VARCHAR(23),b.OS_Start,121) as OS_Start_Time
, z.SQL_Start as SQL_Server_Start_Time
, CONVERT(VARCHAR(23),a.Agent_Start,121) as SQL_Agent_Start_Time
, CONVERT(VARCHAR(50),
CAST(CAST(right(10000000+datediff(dd,0,GETDATE()-b.OS_Start),4) as INT) as VARCHAR(4))+' days '+
CAST(DATEPART(hh,GETDATE()-b.OS_Start) as VARCHAR) + ' hours, ' +
CAST(DATEPART(mi,GETDATE()-b.OS_Start) as VARCHAR) + ' minutes, ' +
CAST(DATEPART(ss,GETDATE()-b.OS_Start) as VARCHAR) + ' seconds') as OS_Uptime
, CONVERT(VARCHAR(50),
CAST(CAST(right(10000000+datediff(dd,0,GETDATE()-z.SQL_Start),4) as INT) as VARCHAR(4))+' days '+
CAST(DATEPART(hh,GETDATE()-z.SQL_Start) as VARCHAR) + ' hours, ' +
CAST(DATEPART(mi,GETDATE()-z.SQL_Start) as VARCHAR) + ' minutes, ' +
CAST(DATEPART(ss,GETDATE()-z.SQL_Start) as VARCHAR) + ' seconds') as SQL_Uptime
, CONVERT(VARCHAR(50),
CAST(CAST(right(10000000+datediff(dd,0,GETDATE()-a.Agent_Start),4) as INT) as VARCHAR(4))+' days '+
CAST(DATEPART(hh,GETDATE()-a.Agent_Start) as VARCHAR) + ' hours, ' +
CAST(DATEPART(mi,GETDATE()-a.Agent_Start) as VARCHAR) + ' minutes, ' +
CAST(DATEPART(ss,GETDATE()-a.Agent_Start) as VARCHAR) + ' seconds') as Agent_Uptime
FROM
(
SELECT login_time as SQL_Start
FROM sys.dm_exec_sessions WHERE session_id = 1
) z
CROSS JOIN
(
SELECT
NULLIF(min(
case
when aa.program_name like 'SQLAgent %'
then aa.login_time
ELSE '99990101'
end),
CONVERT(datetime,'99990101')) as Agent_Start
FROM master.dbo.sysprocesses aa
WHERE aa.login_time > '20000101'
) a
CROSS JOIN
(
SELECT
DATEADD(ss,bb.[ms_ticks]/-1000,GETDATE()) as OS_Start
FROM sys.[dm_os_sys_info] bb
) b

--

Instance_Name	Current_Server_Time	OS_Start_Time	SQL_Server_Start_Time	SQL_Agent_Start_Time
INSTANCE999	05/24/2018 19:59:48	05/14/2018 07:30:31	05/14/2018 07:31:14	05/14/2018 07:31:24

OS_Uptime	SQL_Uptime	Agent_Uptime
10 days 12 hours, 29 minutes, 17 seconds	10 days 12 hours, 28 minutes, 34 seconds	10 days 12 hours, 28 minutes, 23 seconds

--


As you can see, it leverages sys.dm_exec_sessions and sysprocesses to pull the start times for the SQL services and sys.dm_os_sys_info to pull the OS info.

--

For another option, we can leverage an operating system function, the systeminfo command line tool,

You can use a pipe | to pass a find command into systeminfo, like this:

--

systeminfo|find "Time:"

--

output

System Boot Time:          4/21/2018, 7:41:10 AM

--

To run it, you can run an elevated CMD prompt from windows (right-click and Run as Administrator), or if xp_cmdshell is enabled you can run it from SQL:

--

EXEC xp_cmdshell 'systeminfo|find "Time:"'

--


So we have seen three ways to pull the info - but which one is the most "right"?

Let's compare the results for concurrent runs of the three queries:

--

name	create_date
tempdb	04/21/2018 07:42:44

Instance_Name	OS_Start_Time	SQL_Server_Start_Time	SQL_Agent_Start_Time
INSTANCE999	04/21/2018 07:42:17	04/21/2018 07:42:31	04/21/2018 07:42:47

output

System Boot Time:          4/21/2018, 7:41:10 AM

--

There are times when you need to know pretty specifically what happened and when - so let's review:

1. systeminfo time - 7:41:10AM
2. sys.dm_os_sys_info ms_ticks - 7:42:17AM - more than a minute later!
3. sys.dm_exec_sessions SQL start - 7:41:32AM
4. tempdb create date - 7:42:44AM
5. sysprocesses Agent start - 7:42:47AM

Sometimes you only have access to one datetime or another - especially systeminfo - for example you may be a sysadmin in SQL but not have access to run the Windows command line function - but if you have access to all of these numbers, consider the order of items above.

--

Hope this helps!

When Good Query Plans Go Bad

Today's story starts again with a page escalation:

--

We are seeing very high CPU usage on DistServer01.  Could you please take a look and do a health check on this server?  Please let us know if there is anything we can do to help.

--

I connnected to DistServer01 and, sure enough, there was consistently 99% CPU in Windows and 90%+ of it was from SQL Server.

https://i.imgflip.com/1mqb58.jpg

As you may have guessed, DistServer01 was the Distributor in a very large transactional replication topology.

I checked the active processes looking for something that was abnormally long-running - no good.

I checked the processes again looking for something using high CPU.  The top thing I found was a Distribution Agent for one of the many publications being routed through DistServer01.  I stopped the SQL Agent job for the Distribution Agent - no good, so I resumed the job.

Next place to turn was that warm comfy place...the Glenn Berry DMV scripts!

http://s.quickmeme.com/img/50/50aefd57e50f2014dda55437e3637e9c9efd9c6b2f84a1ad7f0fa3937129794e.jpg

I have heaped praise on Glenn (blog/@GlennAlanBerry) and his scripts before, and they are definitely my go-to when I dive into troubleshooting.

For high CPU an especially useful query is the "top worker time queries" query.  This is the 2008R2 version (but it works on later versions as well):

--

-- Get top total worker time queries for entire instance (Query 33) (Top Worker Time Queries)
SELECT TOP(50) DB_NAME(t.[dbid]) AS [Database Name], t.[text] AS [Query Text],
qs.total_worker_time AS [Total Worker Time], qs.min_worker_time AS [Min Worker Time],
qs.total_worker_time/qs.execution_count AS [Avg Worker Time],
qs.max_worker_time AS [Max Worker Time], qs.execution_count AS [Execution Count],
qs.total_elapsed_time/qs.execution_count AS [Avg Elapsed Time],
qs.total_logical_reads/qs.execution_count AS [Avg Logical Reads],
qs.total_physical_reads/qs.execution_count AS [Avg Physical Reads], qs.creation_time AS [Creation Time]
, qp.query_plan AS [Query Plan] -- comment out this column if copying results to Excel
FROM sys.dm_exec_query_stats AS qs WITH (NOLOCK)
CROSS APPLY sys.dm_exec_sql_text(plan_handle) AS t
CROSS APPLY sys.dm_exec_query_plan(plan_handle) AS qp
ORDER BY qs.total_worker_time DESC OPTION (RECOMPILE);

--

The (truncated) results come out like this:

Database Name	Query Text	Total Worker Time	Min Worker Time	Avg Worker Time	Max Worker Time	Execution Count	Creation Time
NULL	CREATE PROCEDURE sp_MSadd_replcmds( @para	4224360546	0	3920	475776	1077642	05/12/2018 22:55:25
NULL	--  -- Name:   -- fn_repldecryptver4  --   -- Descrip	1724660996	0	89	372022	19285577	05/12/2018 22:55:25
NULL	--  -- Name:  --  fn_MSrepl_isdistdb  --  -- Desc	1066486938	0	53	287015	19817134	05/12/2018 22:55:23
NULL	create procedure sys.sp_MSispeertopeeragent  (	845048463	0	43	203009	19276558	05/12/2018 22:55:26
NULL	CREATE PROCEDURE sys.sp_MSadd_distribution_h	796880096	0	490	368106	1623313	05/13/2018 03:50:07
NULL	CREATE PROCEDURE sys.sp_MSget_subscription_gui	527028755	0	27	379022	19260376	05/12/2018 22:55:27
NULL	create procedure sys.sp_MSispeertopeeragent  (	500954674	0	25	240012	19276558	05/12/2018 22:55:26
distribution	CREATE PROCEDURE sp_MSdelete_publisherdb_trans	434227603	0	204054	5019298	2128	05/12/2018 23:05:04
master	SELECT target_data           FROM sys.dm_xe_session_	342630497	55006	228116	963058	1502	05/13/2018 00:00:08
msdb	CREATE PROCEDURE sp_sqlagent_has_server_access	267846345	30999	763095	21321226	351	05/12/2018 22:55:18

As you can see here, the internal replication process sp_MSadd_replcmds was by far the largest total consumer of CPU, but its average CPU time was still relatively small - it was just called over a million times since the server was last started!

Just to be sure I checked the Missing/Recommended Indexes to make sure there wasn't a glaringly obvious recommendation (sometimes new indexes drastically help CPU) but there was not.

The next place to turn was the query plan...

https://imgflip.com/i/2ajq6z

Query plans can be very complicated subjects.  At the most basic level, query plans are the layout of how a query operates.  It is what we see represented when we look at a graphical execution plan in Management Studio:

Query plans are created on first execution and then are stored in the plan cache on either the first or second execution of the query (depending on whether you have Optimize for Ad Hoc Workloads enabled).

This is beneficial a majority (a vast majority) of the time because generating the query plan takes much more resources that simply looking it up in cache.  The catch is that not all similar queries need the same plan.

The simplest example to me relates to indexing (and is actually one of the reasons my first instinct was to look for missing indexes) - when performing a filtered query (meaning one with a WHERE clause) the amount of data being returned help shape the query plan.  If the estimator expects a large portion of the rows in the table to be returned, it will often ignore nonclustered indexes and simply perform a table scan, checking each row to see if it meets the filter criteria and returning the appropriate rows.  If the estimator expects a more narrow subset and there is a relevant nonclustered index in place, it generates a plan that performs a scan or seek of the nonclustered index and then performs lookups to return any columns not already included in the index.

The problem comes up when the plan that gets cached is built for one of these two cases that is the less frequent of the two.  Using our example above let's say the first run of the query is the large resultset/table scan, which caches that plan.  The next one million runs of the query are the narrow resultset that could have used a nice, small nonclustered index - except there is already a table scan query plan stored in the cache, so SQL Server helpfully does what it's supposed to do any uses that plan, performing a million table scans for our million queries!

http://cdn-webimages.wimages.net/05123d70d127ca613706fc58c0084f07caa772-wm.jpg?v=3

The way to deal with a bad query plan is to get rid of it (Simple, right?)  Many people think you need to dump the full procedure and/or system caches (or even worse, restart SQL Server) to clear this situation (and *DON'T* do that in production!)

What you can do instead is zap a single offending query plan, impacting only that specific query!

As Glenn describes here, you can look up the individual plan handle and then pass it to DBCC FREEPROCCACHE to remove that single plan from the cache.

To look up the plan handle, you can use this query:

--

SELECT cp.plan_handle, cp.objtype, cp.usecounts,
DB_NAME(st.dbid) AS [DatabaseName]
FROM sys.dm_exec_cached_plans AS cp CROSS APPLY sys.dm_exec_sql_text(plan_handle) AS st
WHERE OBJECT_NAME (st.objectid)
LIKE N'%sp_MSadd_replcmds%' OPTION (RECOMPILE);

--

plan_handle	objtype	usecounts	DatabaseName
0x0500FF7FB38EE9D6A03A9D310501000001000000000000000000000000000000000000000000000000000000	Proc	1077642	NULL

--

The next step is to pass this plan_handle to DBCC FREEPROCCACHE:

--

DBCC FREEPROCCACHE(0x0500FF7FB38EE9D6A03A9D310501000001000000000000000000000000000000000000000000000000000000)

--

...in my case - BOOM!  Instantaneous CPU drop from 90%+ to just 5%-10%.

https://revdrbrian.files.wordpress.com/2016/03/and-there-was-much-rejoicing.jpg

Another useful query came from a blog post Chris Skorlinski of Microsoft https://blogs.msdn.microsoft.com/chrissk/2009/05/25/transactional-replication-conversations/

The post is relatively old (2009) but it still is relevant as it talks about troubleshooting replication (which what led me to it, even though my problem ended up not being a replication problem) but the query is useful to find both the plan handles and other relevant information about the top CPU-consuming queries.  It is a useful expansion on the Glenn query above:

--

SELECT TOP 25
st.text,
qp.query_plan,
(qs.total_logical_reads/qs.execution_count) as avg_logical_reads,
(qs.total_logical_writes/qs.execution_count) as avg_logical_writes,
(qs.total_physical_reads/qs.execution_count) as avg_phys_reads,
qs.*
FROM sys.dm_exec_query_stats as qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as st
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) as qp
--WHERE st.text like 'CREATE PROCEDURE sp_MSadd_replcmds%'
ORDER BY qs.total_worker_time DESC

--

I want to repeat that - even though this is a distribution server in a complicated replication topology, this turned out to *not* be a replication problem.

Always review the evidence - error logs, query results, etc. - and follow the trail - never assume.

--

Hope this helps!

Toolbox - Just the Basics

There are many query sets out there to collect varying groups of configuration data - the ones I most frequently use come from Glenn Berry of SQLskills (blog/@GlennAlanBerry) but I have found that there is more data than his basic set that I like to pull, and I wanted a single query that I could run across multiple versions of SQL Server.  Glenn's basic setup is version-specific - one script for 2005, a different for 2008, etc. - and I wanted to be able to just copy-paste my script in and press Execute.

I ended up starting with some base DMV info and ran it trial-and-error against different versions until I found the fields and formats that are different.  The biggest branch is between SQL 2005-2008R2 and 2012+; there were lots of changes to the dynamic management views in SQL 2012 - so many that I ended up creating two separate branches of code with a version check at the top to determine which branch the execution goes down.

There are multiple ways to determine the SQL Server version, but the one I found that I liked the best in this case is the SERVERPROPERTY('ProductVersion'):

SET @SQLVersion = LEFT(CONVERT(VARCHAR, SERVERPROPERTY('ProductVersion')),4)PRINT @SQLVersion

This returned a nice four character value that was easy to use in the code (it's converted to a char so that I can use the LEFT function to trim it):

9.00
10.0
10.5
11.0
12.0
13.0

--

The biggest change between the versions is a new DMV added in SQL 2008R2 SP1, sys.dm_os_windows_info.  I very much like having a DMV with some basic Windows information:

SELECT *
FROM sys.dm_os_windows_info 

windows_release	windows_service_pack_level	windows_sku	os_language_version
6.3		7	1033

...but what I don't like is that it was added in SP1 - SQL 2008R2 RTM doesn't have this view.  What that meant to my code was that I reference this view in the 2012+ branch but not in the 2005-2008R2 branch since I would have to get more specific (to the SP level) to determine whether I could use it in 2008R2.

http://s2.quickmeme.com/img/cc/cc63896fead20f99f3381a5c389587c48263f258d755be752624b60b62769bab.jpg

--

To return RAM info, I ended up using a temp table (not my favorite but it worked here) - there is a deferred name resolution issue with returning the data due to changes in SQL 2012+.  Even with the IF...ELSE code branch I was using to split my code, the changes in this particular query broke without using an up-front temp table to hold the RAM info (which I then added into the data return query).

--

So...the query:

/*
Physical RAM data comes from the sys.dm_os_sys_info DMV 

The catch is that in SQL 2012 the field changed from being measured in bytes to KB and the field name changed. 

I am collecting the data in a Temp Table because it was the only way I could find to handle deferred name resolution - by having the
DMV inline in a regular query the name resolution errors out even inside an IF ELSE statement.

The temp table is then selected from in the actual data return query below.

IF...ELSE...EXEC Code slightly modified from:
https://social.msdn.microsoft.com/Forums/sqlserver/en-US/442ce31a-9f08-4fa2-90ce-aaba23e05fac/gathering-physical-memory-for-sql-2005sql-2014?forum=transactsql
*/

IF OBJECT_ID('tempdb..#RAM') IS NOT NULL
DROP TABLE #RAM

CREATE TABLE #RAM
(
InstanceName SYSNAME,
Physical_Mem_MB INT
)

IF LEFT(CAST(SERVERPROPERTY('ResourceVersion') as VARCHAR(20)),2) in ('11','12','13','14')
EXEC ('INSERT INTO #RAM SELECT @@SERVERNAME, (physical_memory_KB/1024) as Physical_Mem_MB FROM sys.dm_os_sys_info')
ELSE
EXEC ('INSERT INTO #RAM SELECT @@SERVERNAME, (physical_memory_in_bytes/1024/1024) as Physical_Mem_MB FROM sys.dm_os_sys_info')

--

/*
The actual data return query for the Instance settings
There is a major branch for SQL 2005-2008R2 and a separate branch for 2012+, again because of differing field names and new DMVs between versions
Much of the data is selected as inline queries to prevent the need to tack on the Instance Name and then create a huge multi-way join
*/

DECLARE @SQLVersion as NVARCHAR(4)

SET @SQLVersion = LEFT(CONVERT(VARCHAR, SERVERPROPERTY('ProductVersion')),4)

/*
PRINT @SQLVersion
*/

IF @SQLVersion in ('9.00', '10.0', '10.5')
SELECT SERVERPROPERTY('ServerName') as [InstanceName]
, SERVERPROPERTY('ComputerNamePhysicalNetBIOS') as [ComputerNamePhysicalNetBIOS]
, SERVERPROPERTY('ProductVersion') as [SQLProductVersion]
, @SQLVersion as [SQLMajorVersion]
, CASE @SQLVersion
WHEN '9.00' THEN 'SQL Server 2005'
WHEN '10.0' THEN 'SQL Server 2008'
WHEN '10.5' THEN 'SQL Server 2008 R2'
END as [SQLVersionBuild]
, SERVERPROPERTY('ProductLevel') as [SQLServicePack]
, SERVERPROPERTY('Edition') as [SQLEdition]
, (
SELECT RIGHT(SUBSTRING(@@VERSION, CHARINDEX('Windows NT', @@VERSION), 14), 4)
) as [WindowsVersionNumber]
, (
SELECT CASE LTRIM(RIGHT(SUBSTRING(@@VERSION, CHARINDEX('Windows NT', @@VERSION), 14), 4))
/* LTRIM needed to trim leading space in three character version numbers such as 5.0 */
/* No DMV for this in SQL 2005, 2008, or 2008R2 RTM */
WHEN '5.0' THEN 'Windows 2000'
WHEN '5.1' THEN 'Windows XP'
WHEN '5.2' THEN 'Windows Server 2003/2003 R2'
WHEN '6.0' THEN 'Windows Server 2008/Windows Vista'
WHEN '6.1' THEN 'Windows Server 2008 R2/Windows 7'
WHEN '6.2' THEN 'Windows Server 2012/Windows 8'
WHEN '6.3' THEN 'Windows Server 2012 R2'
WHEN '10.0' THEN 'Windows Server 2016'
ELSE 'Windows vNext'
END
) as [WindowsVersionBuild]
, (
SELECT [Physical_Mem_MB]
FROM #RAM
) as [PhysicalMemMB]
, (
SELECT [value_in_use]
FROM sys.configurations
WHERE name LIKE '%min server memory%'
) as [MinServerMemoryMB]
, (
SELECT [value_in_use]
FROM sys.configurations
WHERE name LIKE '%max server memory%'
) as [MaxServerMemoryMB]
, (
SELECT [cpu_count]
FROM sys.dm_os_sys_info
) as [LogicalCPUCount]
, (
SELECT [hyperthread_ratio]
FROM sys.dm_os_sys_info
) as [HyperthreadRatio]
, (
SELECT [cpu_count]/[hyperthread_ratio]
FROM sys.dm_os_sys_info
) as [PhysicalCPUCount]
, (
SELECT [value_in_use]
FROM sys.configurations
WHERE name LIKE '%max degree of parallelism%'
) as [MAXDOP]
, (
SELECT [value_in_use]
FROM sys.configurations
WHERE name LIKE '%cost threshold for parallelism%'
) as [CTOP]

ELSE /* SQL 2012+ */

SELECT SERVERPROPERTY('ServerName') as [InstanceName]
, SERVERPROPERTY('ComputerNamePhysicalNetBIOS') as [ComputerNamePhysicalNetBIOS]
, SERVERPROPERTY('ProductVersion') as [SQLProductVersion]
, @SQLVersion as [SQLMajorVersion]
, CASE @SQLVersion
WHEN '11.0' THEN 'SQL Server 2012'
WHEN '12.0' THEN 'SQL Server 2014'
WHEN '13.0' THEN 'SQL Server 2016'
ELSE 'SQL Server vNext'
END as [SQLVersionBuild]
, SERVERPROPERTY('ProductLevel') as [SQLServicePack]
, SERVERPROPERTY('Edition') as [SQLEdition]
, (
SELECT [windows_release]
FROM sys.dm_os_windows_info
) as [WindowsVersionNumber]
, (
SELECT CASE windows_release
WHEN '5.0' THEN 'Windows 2000'
WHEN '5.1' THEN 'Windows XP'
WHEN '5.2' THEN 'Windows Server 2003/2003 R2'
WHEN '6.0' THEN 'Windows Server 2008/Windows Vista'
WHEN '6.1' THEN 'Windows Server 2008 R2/Windows 7'
WHEN '6.2' THEN 'Windows Server 2012/Windows 8'
WHEN '6.3' THEN 'Windows Server 2012 R2'
WHEN '10.0' THEN 'Windows Server 2016'
ELSE 'Windows vNext'
END
FROM sys.dm_os_windows_info /* New DMV in SQL 2008 R2 SP1*/
) as [WindowsVersionBuild]
, (
SELECT [Physical_Mem_MB]
FROM #RAM
) as [PhysicalMemMB]
, (
SELECT [value_in_use]
FROM sys.configurations
WHERE name LIKE '%min server memory%'
) as [MinServerMemoryMB]
, (
SELECT [value_in_use]
FROM sys.configurations
WHERE name LIKE '%max server memory%'
) as [MaxServerMemoryMB]
, (
SELECT [cpu_count]
FROM sys.dm_os_sys_info
) as [LogicalCPUCount]
, (
SELECT [hyperthread_ratio]
FROM sys.dm_os_sys_info
) as [HyperthreadRatio]
, (
SELECT [cpu_count]/[hyperthread_ratio]
FROM sys.dm_os_sys_info
) as [PhysicalCPUCount]
, (
SELECT [value_in_use]
FROM sys.configurations
WHERE name LIKE '%max degree of parallelism%'
) as [MAXDOP]
, (
SELECT [value_in_use]
FROM sys.configurations
WHERE name LIKE '%cost threshold for parallelism%'
) as [CTOP]

/*
Clean-Up
*/

IF OBJECT_ID('tempdb..#RAM') IS NOT NULL
DROP TABLE [#RAM]

--

The resultset looks like this:

InstanceName	ComputerName PhysicalNetBIOS	SQLProductVersion	SQLMajorVersion
Instance1\I1	Server55	12.0.5000.0	12

SQLVersionBuild	SQLServicePack	SQLEdition
SQL Server 2014	SP2	Standard Edition (64-bit)

Windows Version Number	Windows Version Build	Physical MemMB	MinServer MemoryMB	MaxServer MemoryMB
6.3	Windows Server 2012 R2	81918	64	66560

LogicalCPUCount	HyperthreadRatio	PhysicalCPUCount	MAXDOP	CTOP
12	1	12	1	5

--

I like this a lot as it is a quick way to pull basic SQL, Windows, RAM, and CPU from any SQL 2005+, which is something I need all the time when I touch a new server.

Hope this helps!

Toolbox - IO, IO, Why are You So Slow?

This is the next in a series of blogs I am going to create talking about useful tools (mostly scripts) that I use frequently in my day-to-day life as a production DBA.  I work as a Work-From-Home DBA for a Remote DBA company, but 90+% of my job functions are the same as any other company DBA.

Many of these scripts come directly from blogs and articles created and shared by other members of the SQL Server community; some of them I have slightly modified and some I have lifted directly from those articles.  I will always give attribution back to the original source and note when I have made modifications.

--

Troubleshooting performance in SQL Server (or almost any other system) is often an iterative process of discovering a bottleneck, fixing it, and then discovering the next bottleneck.

https://memegenerator.net/instance/65795220/grumpy-cat-5-bottleneck-sighting-optimize-the-system

SQL Server bottlenecks frequently fall into one of three resource categories:

• CPU
• Memory
• I/O (Disk)

For example, you may find that "your instance is slow" (Client-speak for "I'm unhappy - FIX IT!") and upon investigation you see in your Perfmon collector (you have a Perfmon collector running, right???) that CPU is consistently at 90%+.  You consider the evidence and realize a set of queries is poorly written (darn SharePoint) but you also realize that in this case you can fix them (whew!), and this helps the CPU numbers drop significantly.  You're the hero, right?

...until you realize the instance is still "slow."

https://hakanforss.files.wordpress.com/2014/08/lawofbottlenecks.png

You look at the numbers again, and now you find that disk latency, which had previously been fine, is now completely in the tank during the business day, showing that I/O delays are through the roof.

What happened?

This demonstrates the concept of shifting bottleneck - while CPU use was through the roof, the engine so bogged down that it couldn't generate that much I/O, but once the CPU issue was resolved queries started moving through more quickly until the next choke point was met at the I/O limit.  Odds are once you resolve the I/O situation, you would find a new bottleneck.

How do you ever defeat a bad guy that constantly moves around and frequently changes form?

https://movietalkexpress.files.wordpress.com/2016/08/3.jpg

The next concept in this series is the concept of "good enough" - all computing systems have theoretical top speeds (speed of electrons through the ether, etc.) but you never get there.  At the end of the day the important question is:

How fast does your system need to be to meet the business SLAs and keep your customers happy (aka QUIET)?

Unfortunately in many cases the answer seems to be this:

https://i.kinja-img.com/gawker-media/image/upload/s--Wtfu6LxV--/c_fill,fl_progressive,g_center,h_450,q_80,w_800/1344998898279631762.jpg

--

Once you can determine this "good enough" speed (the whole discussion of  "Do you have SLAs?" could fill dozens of blog posts) you can determine where an acceptable end point is to your iterative process.

--

I have a small handful of things I check when a system is "slow" and one of them is disk latency.  At its core, disk latency is a calculation of how much delay there is between when SQL Server asks for data and when it gets it back.

The data regarding latency comes from the DMV sys.dm_io_virtual_file_stats, and the relevant metrics are io_stall, io_stall_read_ms, and io_stall_write_ms (table from Technet):

Column name	Data type	Description
database_id	smallint	ID of database.
file_id	smallint	ID of file.
sample_ms	int	Number of milliseconds since the computer was started. This column can be used to compare different outputs from this function.
num_of_reads	bigint	Number of reads issued on the file.
num_of_bytes_read	bigint	Total number of bytes read on this file.
io_stall_read_ms	bigint	Total time, in milliseconds, that the users waited for reads issued on the file.
num_of_writes	bigint	Number of writes made on this file.
num_of_bytes_written	bigint	Total number of bytes written to the file.
io_stall_write_ms	bigint	Total time, in milliseconds, that users waited for writes to be completed on the file.
io_stall	bigint	Total time, in milliseconds, that users waited for I/O to be completed on the file.
size_on_disk_bytes	bigint	Number of bytes used on the disk for this file. For sparse files, this number is the actual number of bytes on the disk that are used for database snapshots.
file_handle	varbinary	Windows file handle for this file.

How do you turn these numbers into something meaningful?  As is almost always the case - someone has already done that work - you just need to find it!

Paul Randal (blog/@PaulRandal) has a great blog post "How to examine IO subsystem latencies from within SQL Server" and in that post he references a query created by Jimmy May (blog/@aspiringgeek).  Jimmy was at Microsoft for many years and is currently at the SanDisk Data Propulsion Lab.

Jimmy's query is so useful that it is also included in Glenn Berry's (blog/@glennalanberry) great Diagnostic Information (DMV) Queries.  Here is my *very slightly* modified version of that query:

--

-- Drive level latency information (Query 19) (Drive Level Latency)
-- Based on code from Jimmy May
SELECT @@ServerName as instanceName, [Drive], volume_mount_point,
CASE
WHEN num_of_reads = 0 THEN 0
ELSE (io_stall_read_ms/num_of_reads)
END AS [Read Latency],
CASE
WHEN io_stall_write_ms = 0 THEN 0
ELSE (io_stall_write_ms/num_of_writes)
END AS [Write Latency],
CASE
WHEN (num_of_reads = 0 AND num_of_writes = 0) THEN 0
ELSE (io_stall/(num_of_reads + num_of_writes))
END AS [Overall Latency],
CASE
WHEN num_of_reads = 0 THEN 0
ELSE (num_of_bytes_read/num_of_reads)
END AS [Avg Bytes/Read],
CASE
WHEN io_stall_write_ms = 0 THEN 0
ELSE (num_of_bytes_written/num_of_writes)
END AS [Avg Bytes/Write],
CASE
WHEN (num_of_reads = 0 AND num_of_writes = 0) THEN 0
ELSE ((num_of_bytes_read + num_of_bytes_written)/(num_of_reads + num_of_writes))
END AS [Avg Bytes/Transfer]
FROM (SELECT LEFT(UPPER(mf.physical_name), 2) AS Drive, UPPER (volume_mount_point) as volume_mount_point
,SUM(num_of_reads) AS num_of_reads,
        SUM(io_stall_read_ms) AS io_stall_read_ms, SUM(num_of_writes) AS num_of_writes,
        SUM(io_stall_write_ms) AS io_stall_write_ms, SUM(num_of_bytes_read) AS num_of_bytes_read,
        SUM(num_of_bytes_written) AS num_of_bytes_written, SUM(io_stall) AS io_stall
      FROM sys.dm_io_virtual_file_stats(NULL, NULL) AS vfs
      INNER JOIN sys.master_files AS mf WITH (NOLOCK)
      ON vfs.database_id = mf.database_id AND vfs.file_id = mf.file_id
 CROSS APPLY sys.dm_os_volume_stats(mf.database_id, mf.FILE_ID)
      GROUP BY LEFT(UPPER(mf.physical_name), 2),UPPER (volume_mount_point)) AS tab
ORDER BY [Overall Latency] DESC OPTION (RECOMPILE);
-- Shows you the drive-level latency for reads and writes, in milliseconds
-- Latency above 20-25ms is usually a problem

--

The query performs a calculation comparing the stall in milliseconds to the number of disk operations to create a latency in milliseconds.  A rule of thumb (as noted in the query comments) is that anything >=20ms in latency is pretty bad and worthy of investigation.

Here is a sample output of the query:

--

instanceName	Drive	volume_mount_point	Read Latency	Write Latency	Overall Latency	Avg Bytes/ Read	Avg Bytes/ Write	Avg Bytes/ Transfer
INSTANCE35	F:	F:\SPARE-01\	69	7	64	1002982	236026	940840
INSTANCE35	F:	F:\DATA01\	26	1	25	55005	2629	54384
INSTANCE35	F:	F:\280532-02_SECOND\	8	5	8	105124	8257	105114
INSTANCE35	T:	T:\	2	25	3	65483	64899	65187
INSTANCE35	E:	E:\LOGS01\	7	0	0	20080	51327	51198

--

On this instance you can see that the SPARE-01 and DATA01 mount points on the F: drive have significant overall latency (64ms and 25ms respectively) - significant enough that the users are almost certainly experiencing I/O-related impact.

If you look at the query you will see that the "overall" latency covers both reads and writes and as such is functionally a weighted average of the read and write latencies.  For example you can see that the DATA01 does significantly more reads that writes since the overall latency of 25 is almost equal to the read latency of 26.

One more point from the sample numbers above - look at the T: drive.  The write latency is 25 (bad) but the overall latency is only 3.  Is this a problem?  Usually it is not, because this overall latency shows that this drive does relatively few writes - there are so many reads comparatively that the good read latency heavily outweighs the bad write latency.  In most cases the overall latency is the most important statistic of the three.

(Of course as always this is a big #ItDepends - if you have a known issue with write performance - even for the small number of writes being done on the drive - then the write latency is important!)

--

What causes latency?  There are a wide variety of issues - some inside SQL but many outside the engine as well.  In my experience I usually follow-up on both sides, tasking infrastructure teams to investigate numbers on the storage back-end *and* the storage network while the DBA investigates SQL Server-side I/O-related issues such as poor query plans and missing or bad indexes that cause excessive unnecessary I/O.  Sometimes you will read guidance to investigate SQL first (Paul makes that recommendation in his post referenced above) but I like starting both investigations at once so that you can get both sets of results in a more timely fashion.

Disk Latency is one of the easiest things to find - run the single simple query shown above and look at the numbers.  Once you determine that you *do* have a latency issue, you can move forward with internal SQL Server and external infrastructure investigations.

--

Remember - at the end of the day, you want your customer to think this:

http://imgur.com/waLAsxg

--

Hope this helps!