Skip to content

Commit 5adffa7

Browse files
BrentOzarBrentOzar
authored
Merge pull request #2924 from erikdarlingdata/issue_2913
Add thread time to wait stats views
2 parents ef0b75e + 0eddc9d commit 5adffa7

File tree

1 file changed

+193
-18
lines changed

1 file changed

+193
-18
lines changed

‎sp_BlitzFirst.sql‎

Lines changed: 193 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -139,7 +139,10 @@ DECLARE @StringToExecute NVARCHAR(MAX),
139139
@UnquotedOutputDatabaseName NVARCHAR(256) = @OutputDatabaseName ,
140140
@UnquotedOutputSchemaName NVARCHAR(256) = @OutputSchemaName ,
141141
@LocalServerName NVARCHAR(128) = CAST(SERVERPROPERTY('ServerName') AS NVARCHAR(128)),
142-
@dm_exec_query_statistics_xml BIT = 0;
142+
@dm_exec_query_statistics_xml BIT = 0,
143+
@total_cpu_usage BIT = 0,
144+
@get_thread_time_ms NVARCHAR(MAX) = N'',
145+
@thread_time_ms FLOAT = 0;
143146

144147
/* Sanitize our inputs */
145148
SELECT
@@ -293,6 +296,54 @@ BEGIN
293296
@FinishSampleTimeWaitFor = DATEADD(ss, @Seconds, GETDATE());
294297

295298

299+
IF EXISTS
300+
(
301+
302+
SELECT
303+
1/0
304+
FROM sys.all_columns AS ac
305+
WHERE ac.object_id = OBJECT_ID('sys.dm_os_schedulers')
306+
AND ac.name = 'total_cpu_usage_ms'
307+
308+
)
309+
BEGIN
310+
311+
SELECT
312+
@total_cpu_usage = 1,
313+
@get_thread_time_ms +=
314+
N'
315+
SELECT
316+
@thread_time_ms =
317+
CONVERT
318+
(
319+
FLOAT,
320+
SUM(s.total_cpu_usage_ms)
321+
)
322+
FROM sys.dm_os_schedulers AS s
323+
WHERE s.status = ''VISIBLE ONLINE''
324+
AND s.is_online = 1
325+
OPTION(RECOMPILE);
326+
';
327+
328+
END
329+
ELSE
330+
BEGIN
331+
SELECT
332+
@total_cpu_usage = 0,
333+
@get_thread_time_ms +=
334+
N'
335+
SELECT
336+
@thread_time_ms =
337+
CONVERT
338+
(
339+
FLOAT,
340+
SUM(s.total_worker_time / 1000.)
341+
)
342+
FROM sys.dm_exec_query_stats AS s
343+
OPTION(RECOMPILE);
344+
';
345+
END
346+
296347
RAISERROR('Now starting diagnostic analysis',10,1) WITH NOWAIT;
297348

298349
/*
@@ -342,7 +393,15 @@ BEGIN
342393

343394
IF OBJECT_ID('tempdb..#WaitStats') IS NOT NULL
344395
DROP TABLE #WaitStats;
345-
CREATE TABLE #WaitStats (Pass TINYINT NOT NULL, wait_type NVARCHAR(60), wait_time_ms BIGINT, signal_wait_time_ms BIGINT, waiting_tasks_count BIGINT, SampleTime DATETIMEOFFSET);
396+
CREATE TABLE #WaitStats (
397+
Pass TINYINT NOT NULL,
398+
wait_type NVARCHAR(60),
399+
wait_time_ms BIGINT,
400+
thread_time_ms FLOAT,
401+
signal_wait_time_ms BIGINT,
402+
waiting_tasks_count BIGINT,
403+
SampleTime datetimeoffset
404+
);
346405

347406
IF OBJECT_ID('tempdb..#FileStats') IS NOT NULL
348407
DROP TABLE #FileStats;
@@ -1293,16 +1352,30 @@ BEGIN
12931352
INSERT INTO #PerfmonCounters ([object_name],[counter_name],[instance_name]) VALUES ('SQL Server 2017 XTP Transactions','Transactions created/sec',NULL);
12941353
END;
12951354

1355+
1356+
IF @total_cpu_usage IN (0, 1)
1357+
BEGIN
1358+
EXEC sys.sp_executesql
1359+
@get_thread_time_ms,
1360+
N'@thread_time_ms FLOAT OUTPUT',
1361+
@thread_time_ms OUTPUT;
1362+
END
1363+
12961364
/* Populate #FileStats, #PerfmonStats, #WaitStats with DMV data.
12971365
After we finish doing our checks, we'll take another sample and compare them. */
12981366
RAISERROR('Capturing first pass of wait stats, perfmon counters, file stats',10,1) WITH NOWAIT;
12991367
SET @StringToExecute = N'
1300-
INSERT #WaitStats(Pass, SampleTime, wait_type, wait_time_ms, signal_wait_time_ms, waiting_tasks_count)
1368+
INSERT #WaitStats(Pass, SampleTime, wait_type, wait_time_ms, thread_time_ms, signal_wait_time_ms, waiting_tasks_count)
13011369
SELECT
13021370
x.Pass,
13031371
x.SampleTime,
13041372
x.wait_type,
13051373
SUM(x.sum_wait_time_ms) AS sum_wait_time_ms,
1374+
CASE @Seconds
1375+
WHEN 0
1376+
THEN 0
1377+
ELSE @thread_time_ms
1378+
END AS thread_time_ms,
13061379
SUM(x.sum_signal_wait_time_ms) AS sum_signal_wait_time_ms,
13071380
SUM(x.sum_waiting_tasks) AS sum_waiting_tasks
13081381
FROM (
@@ -1342,9 +1415,35 @@ BEGIN
13421415
)
13431416
GROUP BY x.Pass, x.SampleTime, x.wait_type
13441417
ORDER BY sum_wait_time_ms DESC;'
1345-
EXEC sp_executesql @StringToExecute, N'@StartSampleTime DATETIMEOFFSET, @Seconds INT', @StartSampleTime, @Seconds;
1346-
1347-
1418+
1419+
EXEC sys.sp_executesql
1420+
@StringToExecute,
1421+
N'@StartSampleTime DATETIMEOFFSET,
1422+
@Seconds INT,
1423+
@thread_time_ms FLOAT',
1424+
@StartSampleTime,
1425+
@Seconds,
1426+
@thread_time_ms;
1427+
1428+
WITH w AS
1429+
(
1430+
SELECT
1431+
total_waits =
1432+
CONVERT
1433+
(
1434+
FLOAT,
1435+
SUM(ws.wait_time_ms)
1436+
)
1437+
FROM #WaitStats AS ws
1438+
WHERE Pass = 1
1439+
)
1440+
UPDATE ws
1441+
SET ws.thread_time_ms += w.total_waits
1442+
FROM #WaitStats AS ws
1443+
CROSS JOIN w
1444+
WHERE ws.Pass = 1
1445+
OPTION(RECOMPILE);
1446+
13481447
INSERT INTO #FileStats (Pass, SampleTime, DatabaseID, FileID, DatabaseName, FileLogicalName, SizeOnDiskMB, io_stall_read_ms ,
13491448
num_of_reads, [bytes_read] , io_stall_write_ms,num_of_writes, [bytes_written], PhysicalName, TypeDesc)
13501449
SELECT
@@ -2450,15 +2549,24 @@ If one of them is a lead blocker, consider killing that query.'' AS HowToStopit,
24502549
WAITFOR TIME @FinishSampleTimeWaitFor;
24512550
END;
24522551

2552+
IF @total_cpu_usage IN (0, 1)
2553+
BEGIN
2554+
EXEC sys.sp_executesql
2555+
@get_thread_time_ms,
2556+
N'@thread_time_ms FLOAT OUTPUT',
2557+
@thread_time_ms OUTPUT;
2558+
END
2559+
24532560
RAISERROR('Capturing second pass of wait stats, perfmon counters, file stats',10,1) WITH NOWAIT;
24542561
/* Populate #FileStats, #PerfmonStats, #WaitStats with DMV data. In a second, we'll compare these. */
24552562
SET @StringToExecute = N'
2456-
INSERT #WaitStats(Pass, SampleTime, wait_type, wait_time_ms, signal_wait_time_ms, waiting_tasks_count)
2563+
INSERT #WaitStats(Pass, SampleTime, wait_type, wait_time_ms, thread_time_ms, signal_wait_time_ms, waiting_tasks_count)
24572564
SELECT
24582565
x.Pass,
24592566
x.SampleTime,
24602567
x.wait_type,
24612568
SUM(x.sum_wait_time_ms) AS sum_wait_time_ms,
2569+
@thread_time_ms AS thread_time_ms,
24622570
SUM(x.sum_signal_wait_time_ms) AS sum_signal_wait_time_ms,
24632571
SUM(x.sum_waiting_tasks) AS sum_waiting_tasks
24642572
FROM (
@@ -2498,7 +2606,35 @@ If one of them is a lead blocker, consider killing that query.'' AS HowToStopit,
24982606
)
24992607
GROUP BY x.Pass, x.SampleTime, x.wait_type
25002608
ORDER BY sum_wait_time_ms DESC;';
2501-
EXEC sp_executesql @StringToExecute, N'@Seconds INT', @Seconds;
2609+
2610+
EXEC sys.sp_executesql
2611+
@StringToExecute,
2612+
N'@StartSampleTime DATETIMEOFFSET,
2613+
@Seconds INT,
2614+
@thread_time_ms FLOAT',
2615+
@StartSampleTime,
2616+
@Seconds,
2617+
@thread_time_ms;
2618+
2619+
WITH w AS
2620+
(
2621+
SELECT
2622+
total_waits =
2623+
CONVERT
2624+
(
2625+
FLOAT,
2626+
SUM(ws.wait_time_ms)
2627+
)
2628+
FROM #WaitStats AS ws
2629+
WHERE Pass = 2
2630+
)
2631+
UPDATE ws
2632+
SET ws.thread_time_ms += w.total_waits
2633+
FROM #WaitStats AS ws
2634+
CROSS JOIN w
2635+
WHERE ws.Pass = 2
2636+
OPTION(RECOMPILE);
2637+
25022638

25032639
INSERT INTO #FileStats (Pass, SampleTime, DatabaseID, FileID, DatabaseName, FileLogicalName, SizeOnDiskMB, io_stall_read_ms ,
25042640
num_of_reads, [bytes_read] , io_stall_write_ms,num_of_writes, [bytes_written], PhysicalName, TypeDesc, avg_stall_read_ms, avg_stall_write_ms)
@@ -3296,6 +3432,36 @@ If one of them is a lead blocker, consider killing that query.'' AS HowToStopit,
32963432

32973433
END; /* IF @Seconds >= 30 */
32983434

3435+
IF /* Let people on <2016 know about the thread time column */
3436+
(
3437+
@Seconds > 0
3438+
AND @total_cpu_usage = 0
3439+
)
3440+
BEGIN
3441+
INSERT INTO
3442+
#BlitzFirstResults
3443+
(
3444+
CheckID,
3445+
Priority,
3446+
FindingsGroup,
3447+
Finding,
3448+
Details,
3449+
URL
3450+
)
3451+
SELECT
3452+
48,
3453+
254,
3454+
N'Informational',
3455+
N'Thread Time comes from the plan cache in versions earlier than 2016, and is not as reliable',
3456+
N'The oldest plan in your cache is from ' +
3457+
CONVERT(nvarchar(30), MIN(s.creation_time)) +
3458+
N' and your server was last restarted on ' +
3459+
CONVERT(nvarchar(30), MAX(o.sqlserver_start_time)),
3460+
N'https://docs.microsoft.com/en-us/sql/relational-databases/system-dynamic-management-views/sys-dm-os-schedulers-transact-sql'
3461+
FROM sys.dm_exec_query_stats AS s
3462+
CROSS JOIN sys.dm_os_sys_info AS o
3463+
OPTION(RECOMPILE);
3464+
END /* Let people on <2016 know about the thread time column */
32993465

33003466
/* If we didn't find anything, apologize. */
33013467
IF NOT EXISTS (SELECT * FROM #BlitzFirstResults WHERE Priority < 250)
@@ -4405,10 +4571,11 @@ If one of them is a lead blocker, consider killing that query.'' AS HowToStopit,
44054571
)
44064572
SELECT TOP 10
44074573
CAST(DATEDIFF(mi,wd1.SampleTime, wd2.SampleTime) / 60.0 AS DECIMAL(18,1)) AS [Hours Sample],
4574+
CAST(c.[Total Thread Time (Seconds)] / 60. / 60. AS DECIMAL(18,1)) AS [Thread Time (Hours)],
44084575
wd1.wait_type,
44094576
COALESCE(wcat.WaitCategory, 'Other') AS wait_category,
4410-
CAST(c.[Wait Time (Seconds)] / 60.0 / 60 AS DECIMAL(18,1)) AS [Wait Time (Hours)],
4411-
CAST((wd2.wait_time_ms - wd1.wait_time_ms) / 1000.0 / cores.cpu_count / DATEDIFF(ss, wd1.SampleTime, wd2.SampleTime) AS DECIMAL(18,1)) AS [Per Core Per Hour],
4577+
CAST(c.[Wait Time (Seconds)] / 60. / 60. AS DECIMAL(18,1)) AS [Wait Time (Hours)],
4578+
CAST((wd2.wait_time_ms - wd1.wait_time_ms) / 1000.0 / cores.cpu_count / DATEDIFF(ss, wd1.SampleTime, wd2.SampleTime) AS DECIMAL(18,1)) AS [Per Core Per Hour],
44124579
(wd2.waiting_tasks_count - wd1.waiting_tasks_count) AS [Number of Waits],
44134580
CASE WHEN (wd2.waiting_tasks_count - wd1.waiting_tasks_count) > 0
44144581
THEN
@@ -4423,8 +4590,10 @@ If one of them is a lead blocker, consider killing that query.'' AS HowToStopit,
44234590
wd2.SampleTime > wd1.SampleTime
44244591
CROSS APPLY (SELECT SUM(1) AS cpu_count FROM sys.dm_os_schedulers WHERE status = 'VISIBLE ONLINE' AND is_online = 1) AS cores
44254592
CROSS APPLY (SELECT
4426-
CAST((wd2.wait_time_ms-wd1.wait_time_ms)/1000. AS NUMERIC(12,1)) AS [Wait Time (Seconds)],
4427-
CAST((wd2.signal_wait_time_ms - wd1.signal_wait_time_ms)/1000. AS NUMERIC(12,1)) AS [Signal Wait Time (Seconds)]) AS c
4593+
CAST((wd2.wait_time_ms-wd1.wait_time_ms)/1000. AS DECIMAL(18,1)) AS [Wait Time (Seconds)],
4594+
CAST((wd2.signal_wait_time_ms - wd1.signal_wait_time_ms)/1000. AS DECIMAL(18,1)) AS [Signal Wait Time (Seconds)],
4595+
CAST((wd2.thread_time_ms)/1000. AS DECIMAL(18,1)) AS [Total Thread Time (Seconds)]
4596+
) AS c
44284597
LEFT OUTER JOIN ##WaitCategories wcat ON wd1.wait_type = wcat.WaitType
44294598
WHERE (wd2.waiting_tasks_count - wd1.waiting_tasks_count) > 0
44304599
AND wd2.wait_time_ms-wd1.wait_time_ms > 0
@@ -4546,10 +4715,11 @@ If one of them is a lead blocker, consider killing that query.'' AS HowToStopit,
45464715
SELECT
45474716
'WAIT STATS' AS Pattern,
45484717
b.SampleTime AS [Sample Ended],
4549-
CAST(DATEDIFF(mi,wd1.SampleTime, wd2.SampleTime) / 60.0 AS DECIMAL(18,1)) AS [Hours Sample],
4718+
CAST(DATEDIFF(mi,wd1.SampleTime, wd2.SampleTime) / 60. AS DECIMAL(18,1)) AS [Hours Sample],
4719+
CAST(c.[Total Thread Time (Seconds)] / 60. / 60. AS DECIMAL(18,1)) AS [Thread Time (Hours)],
45504720
wd1.wait_type,
45514721
COALESCE(wcat.WaitCategory, 'Other') AS wait_category,
4552-
CAST(c.[Wait Time (Seconds)] / 60.0 / 60 AS DECIMAL(18,1)) AS [Wait Time (Hours)],
4722+
CAST(c.[Wait Time (Seconds)] / 60. / 60. AS DECIMAL(18,1)) AS [Wait Time (Hours)],
45534723
CAST((wd2.wait_time_ms - wd1.wait_time_ms) / 1000.0 / cores.cpu_count / DATEDIFF(ss, wd1.SampleTime, wd2.SampleTime) AS DECIMAL(18,1)) AS [Per Core Per Hour],
45544724
CAST(c.[Signal Wait Time (Seconds)] / 60.0 / 60 AS DECIMAL(18,1)) AS [Signal Wait Time (Hours)],
45554725
CASE WHEN c.[Wait Time (Seconds)] > 0
@@ -4570,8 +4740,10 @@ If one of them is a lead blocker, consider killing that query.'' AS HowToStopit,
45704740
wd2.SampleTime > wd1.SampleTime
45714741
CROSS APPLY (SELECT SUM(1) AS cpu_count FROM sys.dm_os_schedulers WHERE status = 'VISIBLE ONLINE' AND is_online = 1) AS cores
45724742
CROSS APPLY (SELECT
4573-
CAST((wd2.wait_time_ms-wd1.wait_time_ms)/1000. AS NUMERIC(12,1)) AS [Wait Time (Seconds)],
4574-
CAST((wd2.signal_wait_time_ms - wd1.signal_wait_time_ms)/1000. AS NUMERIC(12,1)) AS [Signal Wait Time (Seconds)]) AS c
4743+
CAST((wd2.wait_time_ms-wd1.wait_time_ms)/1000. AS DECIMAL(18,1)) AS [Wait Time (Seconds)],
4744+
CAST((wd2.signal_wait_time_ms - wd1.signal_wait_time_ms)/1000. AS DECIMAL(18,1)) AS [Signal Wait Time (Seconds)],
4745+
CAST((wd2.thread_time_ms)/1000. AS DECIMAL(18,1)) AS [Total Thread Time (Seconds)]
4746+
) AS c
45754747
LEFT OUTER JOIN ##WaitCategories wcat ON wd1.wait_type = wcat.WaitType
45764748
WHERE (wd2.waiting_tasks_count - wd1.waiting_tasks_count) > 0
45774749
AND wd2.wait_time_ms-wd1.wait_time_ms > 0
@@ -4588,6 +4760,7 @@ If one of them is a lead blocker, consider killing that query.'' AS HowToStopit,
45884760
'WAIT STATS' AS Pattern,
45894761
b.SampleTime AS [Sample Ended],
45904762
DATEDIFF(ss,wd1.SampleTime, wd2.SampleTime) AS [Seconds Sample],
4763+
c.[Total Thread Time (Seconds)],
45914764
wd1.wait_type,
45924765
COALESCE(wcat.WaitCategory, 'Other') AS wait_category,
45934766
c.[Wait Time (Seconds)],
@@ -4611,8 +4784,10 @@ If one of them is a lead blocker, consider killing that query.'' AS HowToStopit,
46114784
wd2.SampleTime > wd1.SampleTime
46124785
CROSS APPLY (SELECT SUM(1) AS cpu_count FROM sys.dm_os_schedulers WHERE status = 'VISIBLE ONLINE' AND is_online = 1) AS cores
46134786
CROSS APPLY (SELECT
4614-
CAST((wd2.wait_time_ms-wd1.wait_time_ms)/1000. AS NUMERIC(12,1)) AS [Wait Time (Seconds)],
4615-
CAST((wd2.signal_wait_time_ms - wd1.signal_wait_time_ms)/1000. AS NUMERIC(12,1)) AS [Signal Wait Time (Seconds)]) AS c
4787+
CAST((wd2.wait_time_ms-wd1.wait_time_ms)/1000. AS DECIMAL(18,1)) AS [Wait Time (Seconds)],
4788+
CAST((wd2.signal_wait_time_ms - wd1.signal_wait_time_ms)/1000. AS DECIMAL(18,1)) AS [Signal Wait Time (Seconds)],
4789+
CAST((wd2.thread_time_ms - wd1.thread_time_ms)/1000. AS DECIMAL(18,1)) AS [Total Thread Time (Seconds)]
4790+
) AS c
46164791
LEFT OUTER JOIN ##WaitCategories wcat ON wd1.wait_type = wcat.WaitType
46174792
WHERE (wd2.waiting_tasks_count - wd1.waiting_tasks_count) > 0
46184793
AND wd2.wait_time_ms-wd1.wait_time_ms > 0

0 commit comments

Comments
 (0)