Preface
Sooner or later, a DB administrator would like to have a performance indicator for SQL Server queries. As we all know, running Profiler for 24 hours will lead to a considerable system load and therefore, it cannot be considered an optimal solution for databases used in the 24/7 mode.
So, how can we detect the state of SQL Server queries? How can we run trace for detected query-related problems without the human input?
In this article, I will provide an implementation of the SQL Server performance indicator for queries, stored procedures and triggers, as well as its usage for the trace run.
Solution
First of all, let’s take a look at the general approach to implementation of the performance indicator for queries, stored procedures and triggers:
- Creation of required tables for information collection and analysis.
- Creation of a view for information collection.
- Creation of stored procedures for information collection.
- Creation of a view for information output.
And now, let’s consider the implementation:
1. Creation of required tables for information collection and analysis.
1.1. For queries:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO SET ANSI_PADDING ON GO CREATE TABLE [srv].[SQL_StatementExecStat]( [ID] [bigint] IDENTITY(1,1) NOT NULL, [InsertDate] [datetime] NULL, [QueryHash] [binary](8) NULL, [ExecutionCount] [bigint] NULL, [TotalWorkerTime] [bigint] NULL, [StatementText] [nvarchar](max) NULL, [TotalElapsedTime] [bigint] NULL, CONSTRAINT [PK_SQL_StatementExecStat] PRIMARY KEY CLUSTERED ( [ID] ASC )WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY] ) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY] GO SET ANSI_PADDING ON GO
1.2. For stored procedures:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE TABLE [srv].[SQL_ProcedureExecStat]( [ID] [bigint] IDENTITY(1,1) NOT NULL, [InsertDate] [datetime] NULL, [database_id] [int] NULL, [object_id] [int] NULL, [ExecutionCount] [bigint] NULL, [TotalWorkerTime] [bigint] NULL, [TotalElapsedTime] [bigint] NULL, [TotalPhysicalReads] [bigint] NULL, [TotalLogicalReads] [bigint] NULL, [TotalLogicalWrites] [bigint] NULL, CONSTRAINT [PK_SQL_ProcedureExecStat] PRIMARY KEY CLUSTERED ( [ID] ASC )WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY] ) ON [PRIMARY] GO
1.3. For triggers:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE TABLE [srv].[SQL_TriggerExecStat]( [ID] [bigint] IDENTITY(1,1) NOT NULL, [InsertDate] [datetime] NULL, [database_id] [int] NULL, [object_id] [int] NULL, [ExecutionCount] [bigint] NULL, [TotalWorkerTime] [bigint] NULL, [TotalElapsedTime] [bigint] NULL ) ON [PRIMARY] GO
2. Creation of a view for information collection (here we can insert filters for getting rid of the irrelevant information (for instance, queries and procedures with replication triggers, etc).
2.1. For queries:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE view [srv].[vStatementExecInfo] as with info as ( SELECT query_stats.query_hash AS QueryHash, SUM(query_stats.total_worker_time ) / SUM(query_stats.execution_count) AS AvgCPU_Time, SUM(query_stats.execution_count ) AS ExecutionCount, SUM(query_stats.total_worker_time ) AS TotalWorkerTime, MIN(query_stats.statement_text ) AS StatementText, MIN(query_stats.min_worker_time ) AS MinWorkerTime, MAX(query_stats.max_worker_time ) AS MaxWorkerTime, SUM(query_stats.total_physical_reads) AS TotalPhysicalReads, MIN(query_stats.min_physical_reads ) AS MinPhysicalReads, MAX(query_stats.max_physical_reads ) AS MaxPhysicalReads, SUM(query_stats.total_physical_reads) / SUM(query_stats.execution_count) AS AvgPhysicalReads, SUM(query_stats.total_logical_writes) AS TotalLogicalWrites, MIN(query_stats.min_logical_writes ) AS MinLogicalWrites, MAX(query_stats.max_logical_writes ) AS MaxLogicalWrites, SUM(query_stats.total_logical_writes) / SUM(query_stats.execution_count) AS AvgLogicalWrites, SUM(query_stats.total_logical_reads ) AS TotalLogicalReads, MIN(query_stats.min_logical_reads ) AS MinLogicalReads, MAX(query_stats.max_logical_reads ) AS MaxLogicalReads, SUM(query_stats.total_logical_reads ) / SUM(query_stats.execution_count) AS AvgLogicalReads, SUM(query_stats.total_elapsed_time ) AS TotalElapsedTime, MIN(query_stats.min_elapsed_time ) AS MinElapsedTime, MAX(query_stats.max_elapsed_time ) AS MaxElapsedTime, SUM(query_stats.total_elapsed_time ) / SUM(query_stats.execution_count) AS AvgElapsedTime, MIN(query_stats.creation_time ) AS MinCreationTime, MAX(query_stats.last_execution_time ) AS LastExecuteTime FROM (SELECT QS.query_hash ,QS.total_worker_time ,QS.execution_count ,QS.min_worker_time ,QS.max_worker_time ,QS.min_physical_reads ,QS.max_physical_reads ,QS.total_physical_reads ,QS.total_logical_writes ,QS.min_logical_writes ,QS.max_logical_writes ,QS.min_logical_reads ,QS.max_logical_reads ,QS.total_logical_reads ,QS.min_elapsed_time ,QS.max_elapsed_time ,QS.total_elapsed_time ,QS.creation_time ,QS.last_execution_time ,SUBSTRING(ST.text, (QS.statement_start_offset/2) + 1, ((CASE statement_end_offset WHEN -1 THEN DATALENGTH(ST.text) ELSE QS.statement_end_offset END - QS.statement_start_offset)/2) + 1) AS statement_text FROM sys.dm_exec_query_stats AS QS CROSS APPLY sys.dm_exec_sql_text(QS.sql_handle) as ST) as query_stats WHERE execution_count > 1 and last_execution_time >= dateadd(hour,-3,getdate()) GROUP BY query_stats.query_hash) select QueryHash, AvgCPU_Time, ExecutionCount, TotalWorkerTime, StatementText, MinWorkerTime, MaxWorkerTime, TotalPhysicalReads, MinPhysicalReads, MaxPhysicalReads, AvgPhysicalReads, TotalLogicalWrites, MinLogicalWrites, MaxLogicalWrites, AvgLogicalWrites, TotalLogicalReads, MinLogicalReads, MaxLogicalReads, AvgLogicalReads, TotalElapsedTime, MinElapsedTime, MaxElapsedTime, AvgElapsedTime, MinCreationTime, LastExecuteTime from info GO
Here, the following system queries are used: sys.dm_exec_query_stats and sys.dm_exec_sql_text.
2.2. For stored procedures:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE view [srv].[vProcedureExecInfo] as with info as ( SELECT procedure_stats.database_id AS database_id, procedure_stats.object_id AS object_id, MIN(procedure_stats.type) AS type, SUM(procedure_stats.total_worker_time ) / SUM(procedure_stats.execution_count) AS AvgCPU_Time, SUM(procedure_stats.execution_count ) AS ExecutionCount, SUM(procedure_stats.total_worker_time ) AS TotalWorkerTime, MIN(procedure_stats.ProcedureText ) AS ProcedureText, MIN(procedure_stats.min_worker_time ) AS MinWorkerTime, MAX(procedure_stats.max_worker_time ) AS MaxWorkerTime, SUM(procedure_stats.total_physical_reads) AS TotalPhysicalReads, MIN(procedure_stats.min_physical_reads ) AS MinPhysicalReads, MAX(procedure_stats.max_physical_reads ) AS MaxPhysicalReads, SUM(procedure_stats.total_physical_reads) / SUM(procedure_stats.execution_count) AS AvgPhysicalReads, SUM(procedure_stats.total_logical_writes) AS TotalLogicalWrites, MIN(procedure_stats.min_logical_writes ) AS MinLogicalWrites, MAX(procedure_stats.max_logical_writes ) AS MaxLogicalWrites, SUM(procedure_stats.total_logical_writes) / SUM(procedure_stats.execution_count) AS AvgLogicalWrites, SUM(procedure_stats.total_logical_reads ) AS TotalLogicalReads, MIN(procedure_stats.min_logical_reads ) AS MinLogicalReads, MAX(procedure_stats.max_logical_reads ) AS MaxLogicalReads, SUM(procedure_stats.total_logical_reads ) / SUM(procedure_stats.execution_count) AS AvgLogicalReads, SUM(procedure_stats.total_elapsed_time ) AS TotalElapsedTime, MIN(procedure_stats.min_elapsed_time ) AS MinElapsedTime, MAX(procedure_stats.max_elapsed_time ) AS MaxElapsedTime, SUM(procedure_stats.total_elapsed_time ) / SUM(procedure_stats.execution_count) AS AvgElapsedTime, MIN(procedure_stats.cached_time ) AS MinCachedTime, MAX(procedure_stats.last_execution_time ) AS LastExecuteTime FROM (SELECT QS.database_id ,QS.object_id ,QS.type ,QS.total_worker_time ,QS.execution_count ,QS.min_worker_time ,QS.max_worker_time ,QS.min_physical_reads ,QS.max_physical_reads ,QS.total_physical_reads ,QS.total_logical_writes ,QS.min_logical_writes ,QS.max_logical_writes ,QS.min_logical_reads ,QS.max_logical_reads ,QS.total_logical_reads ,QS.min_elapsed_time ,QS.max_elapsed_time ,QS.total_elapsed_time ,QS.cached_time ,QS.last_execution_time ,ST.text as Proceduretext FROM sys.dm_exec_Procedure_stats AS QS CROSS APPLY sys.dm_exec_sql_text(QS.sql_handle) as ST) as procedure_stats WHERE execution_count > 1 and last_execution_time >= dateadd(hour,-3,getdate()) GROUP BY database_id,object_id) select database_id, object_id, type, AvgCPU_Time, ExecutionCount, TotalWorkerTime, ProcedureText, MinWorkerTime, MaxWorkerTime, TotalPhysicalReads, MinPhysicalReads, MaxPhysicalReads, AvgPhysicalReads, TotalLogicalWrites, MinLogicalWrites, MaxLogicalWrites, AvgLogicalWrites, TotalLogicalReads, MinLogicalReads, MaxLogicalReads, AvgLogicalReads, TotalElapsedTime, MinElapsedTime, MaxElapsedTime, AvgElapsedTime, MinCachedTime, LastExecuteTime from info GO
Here, the following system queries are used: sys.dm_exec_Procedure_stats and sys.dm_exec_sql_text.
2.3. For triggers:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE view [srv].[vTriggerExecInfo] as with info as ( SELECT procedure_stats.database_id AS database_id, procedure_stats.object_id AS object_id, MIN(procedure_stats.type) AS type, SUM(procedure_stats.total_worker_time ) / SUM(procedure_stats.execution_count) AS AvgCPU_Time, SUM(procedure_stats.execution_count ) AS ExecutionCount, SUM(procedure_stats.total_worker_time ) AS TotalWorkerTime, MIN(procedure_stats.ProcedureText ) AS ProcedureText, MIN(procedure_stats.min_worker_time ) AS MinWorkerTime, MAX(procedure_stats.max_worker_time ) AS MaxWorkerTime, SUM(procedure_stats.total_physical_reads) AS TotalPhysicalReads, MIN(procedure_stats.min_physical_reads ) AS MinPhysicalReads, MAX(procedure_stats.max_physical_reads ) AS MaxPhysicalReads, SUM(procedure_stats.total_physical_reads) / SUM(procedure_stats.execution_count) AS AvgPhysicalReads, SUM(procedure_stats.total_logical_writes) AS TotalLogicalWrites, MIN(procedure_stats.min_logical_writes ) AS MinLogicalWrites, MAX(procedure_stats.max_logical_writes ) AS MaxLogicalWrites, SUM(procedure_stats.total_logical_writes) / SUM(procedure_stats.execution_count) AS AvgLogicalWrites, SUM(procedure_stats.total_logical_reads ) AS TotalLogicalReads, MIN(procedure_stats.min_logical_reads ) AS MinLogicalReads, MAX(procedure_stats.max_logical_reads ) AS MaxLogicalReads, SUM(procedure_stats.total_logical_reads ) / SUM(procedure_stats.execution_count) AS AvgLogicalReads, SUM(procedure_stats.total_elapsed_time ) AS TotalElapsedTime, MIN(procedure_stats.min_elapsed_time ) AS MinElapsedTime, MAX(procedure_stats.max_elapsed_time ) AS MaxElapsedTime, SUM(procedure_stats.total_elapsed_time ) / SUM(procedure_stats.execution_count) AS AvgElapsedTime, MIN(procedure_stats.cached_time ) AS MinCachedTime, MAX(procedure_stats.last_execution_time ) AS LastExecuteTime FROM (SELECT QS.database_id ,QS.object_id ,QS.type ,QS.total_worker_time ,QS.execution_count ,QS.min_worker_time ,QS.max_worker_time ,QS.min_physical_reads ,QS.max_physical_reads ,QS.total_physical_reads ,QS.total_logical_writes ,QS.min_logical_writes ,QS.max_logical_writes ,QS.min_logical_reads ,QS.max_logical_reads ,QS.total_logical_reads ,QS.min_elapsed_time ,QS.max_elapsed_time ,QS.total_elapsed_time ,QS.cached_time ,QS.last_execution_time ,ST.text as Proceduretext FROM sys.dm_exec_trigger_stats AS QS CROSS APPLY sys.dm_exec_sql_text(QS.sql_handle) as ST) as procedure_stats WHERE execution_count > 1 and last_execution_time >= dateadd(hour,-3,getdate()) GROUP BY database_id,object_id) select database_id, object_id, type, AvgCPU_Time, ExecutionCount, TotalWorkerTime, ProcedureText, MinWorkerTime, MaxWorkerTime, TotalPhysicalReads, MinPhysicalReads, MaxPhysicalReads, AvgPhysicalReads, TotalLogicalWrites, MinLogicalWrites, MaxLogicalWrites, AvgLogicalWrites, TotalLogicalReads, MinLogicalReads, MaxLogicalReads, AvgLogicalReads, TotalElapsedTime, MinElapsedTime, MaxElapsedTime, AvgElapsedTime, MinCachedTime, LastExecuteTime from info GO
Here, the following system queries are used: sys.dm_exec_trigger_stats and sys.dm_exec_sql_text.
3. Creation of stored procedures for information collection.
3.1. For queries:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE PROCEDURE [srv].[InsertForSQL_StatementExecStat] @koef decimal(12,2)=0.0 –collection coefficient --is picked in an experimental way for more exact collection, --in most cases, we can put 0.0, --if frequency of the collection running does not exceed 5 minutes. --Accuracy of calculation depends on the collection frequency and collection coefficient. --The more frequent collection running is, the less influence collection coefficient has. AS BEGIN SET NOCOUNT ON; declare @AvgCPU_Time bigint ,@MaxAvgCPU_Time bigint ,@AvgTotalWorkerTime bigint ,@MaxTotalWorkerTime bigint ,@AvgAvgElapsedTime bigint ,@MaxAvgElapsedTime bigint ,@AvgTotalElapsedTime bigint ,@MaxTotalElapsedTime bigint select @AvgCPU_Time = AVG(AvgCPU_Time), @MaxAvgCPU_Time = max(AvgCPU_Time), @AvgTotalWorkerTime = AVG(TotalWorkerTime), @MaxTotalWorkerTime = max(TotalWorkerTime), @AvgAvgElapsedTime = AVG(AvgElapsedTime), @MaxAvgElapsedTime = max(AvgElapsedTime), @AvgTotalElapsedTime = AVG(TotalElapsedTime), @MaxTotalElapsedTime = max(TotalElapsedTime) from srv.vStatementExecInfo; insert into srv.SQL_StatementExecStat ( [InsertDate] ,[QueryHash] ,[ExecutionCount] ,[TotalWorkerTime] ,[StatementText] ,[TotalElapsedTime]) select getdate() ,[QueryHash] ,[ExecutionCount] ,[TotalWorkerTime] ,[StatementText] ,[TotalElapsedTime] from srv.vStatementExecInfo where(AvgCPU_Time > @AvgCPU_Time + @koef * (@MaxAvgCPU_Time - @AvgCPU_Time)) or (TotalWorkerTime > @AvgTotalWorkerTime + @koef * (@MaxTotalWorkerTime - @AvgTotalWorkerTime)) or (AvgElapsedTime > @AvgAvgElapsedTime + @koef * (@MaxAvgElapsedTime - @AvgAvgElapsedTime)) or (TotalElapsedTime > @AvgTotalElapsedTime + @koef * (@MaxTotalElapsedTime - @AvgTotalElapsedTime)); END GO
3.2. For stored procedures:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE PROCEDURE [srv].[InsertForProcedureExecStat] @koef decimal(12,2)=0.0 --collection coefficient --is picked in an experimental way for more exact collection, --in most cases, we can put 0.0, -- if frequency of the collection running does not exceed 5 minutes. --Accuracy of calculation depends on the collection frequency and collection coefficient. --The more frequent collection running is, the less influence collection coefficient has. AS BEGIN SET NOCOUNT ON; declare @AvgCPU_Time bigint ,@MaxAvgCPU_Time bigint ,@AvgTotalWorkerTime bigint ,@MaxTotalWorkerTime bigint ,@AvgAvgElapsedTime bigint ,@MaxAvgElapsedTime bigint ,@AvgTotalElapsedTime bigint ,@MaxTotalElapsedTime bigint; select @AvgCPU_Time = AVG(AvgCPU_Time), @MaxAvgCPU_Time = max(AvgCPU_Time), @AvgTotalWorkerTime = AVG(TotalWorkerTime), @MaxTotalWorkerTime = max(TotalWorkerTime), @AvgAvgElapsedTime = AVG(AvgElapsedTime), @MaxAvgElapsedTime = max(AvgElapsedTime), @AvgTotalElapsedTime = AVG(TotalElapsedTime), @MaxTotalElapsedTime = max(TotalElapsedTime) from srv.vProcedureExecInfo; insert into srv.SQL_ProcedureExecStat ( [InsertDate] ,database_id ,object_id ,[ExecutionCount] ,[TotalWorkerTime] ,[TotalElapsedTime] ,[TotalPhysicalReads] ,[TotalLogicalReads] ,[TotalLogicalWrites]) select getdate() ,database_id ,object_id ,[ExecutionCount] ,[TotalWorkerTime] ,[TotalElapsedTime] ,[TotalPhysicalReads] ,[TotalLogicalReads] ,[TotalLogicalWrites] from srv.vProcedureExecInfo where(AvgCPU_Time > @AvgCPU_Time + @koef * (@MaxAvgCPU_Time - @AvgCPU_Time)) or (TotalWorkerTime > @AvgTotalWorkerTime + @koef * (@MaxTotalWorkerTime - @AvgTotalWorkerTime)) or (AvgElapsedTime > @AvgAvgElapsedTime + @koef * (@MaxAvgElapsedTime - @AvgAvgElapsedTime)) or (TotalElapsedTime > @AvgTotalElapsedTime + @koef * (@MaxTotalElapsedTime - @AvgTotalElapsedTime)); END GO
3.3. For triggers:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE PROCEDURE [srv].[InsertForTriggerExecStat] @koef decimal(12,2)=0.0 --collection coefficient --is picked in an experimental way for more exact collection, --in most cases, we can put 0.0, --if frequency of the collection running does not exceed 5 minutes. --Accuracy of calculation depends on the collection frequency and collection coefficient. --The more frequent collection running is, the less influence collection coefficient has. AS BEGIN SET NOCOUNT ON; declare @AvgCPU_Time bigint ,@MaxAvgCPU_Time bigint ,@AvgTotalWorkerTime bigint ,@MaxTotalWorkerTime bigint ,@AvgAvgElapsedTime bigint ,@MaxAvgElapsedTime bigint ,@AvgTotalElapsedTime bigint ,@MaxTotalElapsedTime bigint select @AvgCPU_Time = AVG(AvgCPU_Time), @MaxAvgCPU_Time = max(AvgCPU_Time), @AvgTotalWorkerTime = AVG(TotalWorkerTime), @MaxTotalWorkerTime = max(TotalWorkerTime), @AvgAvgElapsedTime = AVG(AvgElapsedTime), @MaxAvgElapsedTime = max(AvgElapsedTime), @AvgTotalElapsedTime = AVG(TotalElapsedTime), @MaxTotalElapsedTime = max(TotalElapsedTime) from srv.vProcedureExecInfo; insert into srv.SQL_TriggerExecStat ( [InsertDate] ,database_id ,object_id ,[ExecutionCount] ,[TotalWorkerTime] ,[TotalElapsedTime]) select getdate() ,database_id ,object_id ,[ExecutionCount] ,[TotalWorkerTime] ,[TotalElapsedTime] from srv.vTriggerExecInfo where(AvgCPU_Time > @AvgCPU_Time + @koef * (@MaxAvgCPU_Time - @AvgCPU_Time)) or (TotalWorkerTime > @AvgTotalWorkerTime + @koef * (@MaxTotalWorkerTime - @AvgTotalWorkerTime)) or (AvgElapsedTime > @AvgAvgElapsedTime + @koef * (@MaxAvgElapsedTime - @AvgAvgElapsedTime)) or (TotalElapsedTime > @AvgTotalElapsedTime + @koef * (@MaxTotalElapsedTime - @AvgTotalElapsedTime)); END GO
4. Creation of a view for the information output.
4.1. For queries:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE VIEW [srv].[vStatementExecTotalInfo] as select ExecutionCount as Num ,TotalWorkerTime as TotalWorkerTime ,TotalElapsedTime as TotalElapsedTime ,convert(decimal(8,2),AvgCPU_Time/1000000.) as AvgWorkerSec ,convert(decimal(8,2),AvgElapsedTime/1000000.) as AvgElapsedSec ,... ,QueryHash ,StatementText from [SRV].[srv].[vStatementExecInfo]; GO
4.2. For stored procedures:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE VIEW [srv].[vProcedureExecTotalInfo] as select ExecutionCount as Num ,TotalWorkerTime as TotalWorkerTime ,TotalElapsedTime as TotalElapsedTime ,convert(decimal(8,2),AvgCPU_Time/1000000.) as AvgWorkerSec ,convert(decimal(8,2),AvgElapsedTime/1000000.) as AvgElapsedSec ,... ,database_id ,object_id ,db_name(database_id) as DB_Name ,OBJECT_SCHEMA_NAME(object_id, database_id) as Schema_Name ,object_name(object_id, database_id) as Procedure_Name from [SRV].[srv].[vProcedureExecInfo]; GO
4.3. Views for triggers are created in a similar way (if required). As for me, I do not need tracing triggers, since if there are any problems with triggers, execution of stored procedures and queries will show them.
The following two parameters have vital importance for the implemented views:
- AvgWorkerSec — query execution time in seconds.
- AvgElapsedSec — wait time, or wait time+AvgWorkerSec.
As for the results of views, the following equality is important:
AvgWorkerSec=AvgElapsedSec
- AvgWorkerSec>AvgElapsedSec – here something loads processor heavily at the moment of query execution (as it turned out, the antivirus software scan was running; it may also be the fault of the plan paralleling).
- AvgWorkerSec
If AvgWorkerSec=AvgElapsedSec is adhered, the long execution time is related to the query itself and its execution time.
What is a criterion of the long query execution?
There is no absolute answer to this question. It depends on what a query does, where and how it is used, etc.
I have the following evaluation for the ad hoc queries and stored procedures:
- Up to 0.5 – good for stored procedures, no problems (no execution waits).
- Up to 0.1 – good for queries, no problems (no execution waits).
- 0.5 — 1.0 – bad for stored procedures, there are problems (there are no execution waits that are visible to a user, but they still exist and require solution).
- 0.1 — 0.5 — bad for queries, there are problems (there are no execution waits that are visible to a user, but they still exist and require solving).
- More than 1.0 – bad for stored procedures, there are problems (there is a high chance that there are waits that are visible to users, the problem require immediate solution).
- More than 0.5 – bad for queries, there are problems (there is a high chance that there are waits that are visible to users, the problem requires immediate solution).
As for the non-ad hoc queries (data upload, data load), the above evaluation is picked on an individual basis. Usually, it massively exceeds evaluations for ad hoc queries and stored procedures.
If all software works through the stored procedures, you can trace stored procedures only, since the work of queries always affects the work of stored procedures. That is why, let’s settle upon analysis of the stored procedures execution.
Let’s create a system for collecting information about the most heavy stored procedures for subsequent analysis and running of autotrace, according to the following algorithm:
1. Creation of a table for storing information:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE TABLE [srv].[SQL_TopProcedureExecStat]( [Row_GUID] [uniqueidentifier] NOT NULL, [SERVER] [nvarchar](255) NOT NULL, [DB_ID] [int] NOT NULL, [OBJECT_ID] [int] NOT NULL, [ExecutionCount] [bigint] NOT NULL, [TotalWorkerTime] [bigint] NULL, [TotalElapsedTime] [bigint] NULL, [Func] [decimal](8, 2) NULL, [AvgWorkerSec] [decimal](8, 2) NULL, [AvgElapsedSec] [decimal](8, 2) NULL, [DB_NAME] [nvarchar](255) NULL, [SCHEMA_NAME] [nvarchar](255) NULL, [OBJECT_NAME] [nvarchar](255) NULL, [InsertUTCDate] [datetime] NOT NULL, [TotalPhysicalReads] [bigint] NULL, [TotalLogicalReads] [bigint] NULL, [TotalLogicalWrites] [bigint] NULL, [AvgPhysicalReads] [bigint] NULL, [AvgLogicalReads] [bigint] NULL, [AvgLogicalWrites] [bigint] NULL, [CategoryName] [nvarchar](255) NULL, CONSTRAINT [PK_SQL_TopProcedureExecStat] PRIMARY KEY CLUSTERED ( [Row_GUID] ASC )WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY] ) ON [PRIMARY] GO ALTER TABLE [srv].[SQL_TopProcedureExecStat] ADD CONSTRAINT [DF_SQL_TopProcedureExecStat_Row_GUID] DEFAULT (newid()) FOR [Row_GUID] GO ALTER TABLE [srv].[SQL_TopProcedureExecStat] ADD CONSTRAINT [DF_SQL_TopProcedureExecStat_SERVER] DEFAULT (@@servername) FOR [SERVER] GO ALTER TABLE [srv].[SQL_TopProcedureExecStat] ADD CONSTRAINT [DF_SQL_TopProcedureExecStat_InsertUTCDate] DEFAULT (getutcdate()) FOR [InsertUTCDate] GO
2. Creation of a stored procedure for collecting information:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE PROCEDURE [srv].[InsertTopProcedureExecStat] @top tinyint=24 – number of days to store records ,@CategoryName nvarchar(255)='AvgWorkerSec' – a category for selection AS BEGIN SET NOCOUNT ON; INSERT INTO [srv].[SQL_TopProcedureExecStat] ([DB_ID] ,[OBJECT_ID] ,[ExecutionCount] ,[TotalWorkerTime] ,[TotalElapsedTime] ,[AvgWorkerSec] ,[AvgElapsedSec] ,[DB_NAME] ,[SCHEMA_NAME] ,[OBJECT_NAME] ,InsertUTCDate ,CategoryName ,TotalPhysicalReads ,TotalLogicalReads ,TotalLogicalWrites ,AvgPhysicalReads ,AvgLogicalReads ,AvgLogicalWrites) select top(@top) [database_id] ,[object_id] ,[Num] ,[TotalWorkerTime] ,[TotalElapsedTime] ,[AvgWorkerSec] ,[AvgElapsedSec] ,[DB_NAME] ,[SCHEMA_NAME] ,[PROCEDURE_NAME] ,InsertUTCDate ,CategoryName ,TotalPhysicalReads ,TotalLogicalReads ,TotalLogicalWrites ,AvgPhysicalReads ,AvgLogicalReads ,AvgLogicalWrites from( select [database_id] ,[object_id] ,[Num] ,[TotalWorkerTime] ,[TotalElapsedTime] ,[AvgWorkerSec] ,[AvgElapsedSec] ,[DB_NAME] ,[SCHEMA_NAME] ,[PROCEDURE_NAME] ,getUTCDate() as InsertUTCDate ,@CategoryName as CategoryName ,TotalPhysicalReads ,TotalLogicalReads ,TotalLogicalWrites ,AvgPhysicalReads ,AvgLogicalReads ,AvgLogicalWrites FROM [srv].[vProcedureExecTotalInfoHour] ) as t order by case @CategoryName when 'TotalWorkerTime' then TotalWorkerTime when 'TotalElapsedTime' then TotalElapsedTime when 'AvgWorkerSec' then AvgWorkerSec when 'AvgElapsedSec' then AvgElapsedSec when 'TotalPhysicalReads' then TotalPhysicalReads when 'TotalLogicalReads' then TotalLogicalReads when 'TotalLogicalWrites' then TotalLogicalWrites when 'AvgPhysicalReads' then AvgPhysicalReads when 'AvgLogicalReads' then AvgLogicalReads when 'AvgLogicalWrites' then AvgLogicalWrites end desc; declare @count int=(select count(*) from [srv].[SQL_TopProcedureExecStat] where CategoryName=@CategoryName); declare @diff int=@count-@top; ;with tbl_del as( select Row_GUID from [srv].[SQL_TopProcedureExecStat] where InsertUTCDate<DateAdd(hour,-24,getUTCDate()) and CategoryName=@CategoryName ) delete from [srv].[SQL_TopProcedureExecStat] where Row_GUID in (select Row_GUID from tbl_del); --if table contains more records that it is specified in @top, the most insignificant records are deleted set @count = (select count(*) from [srv].[SQL_TopProcedureExecStat] where CategoryName=@CategoryName) set @diff = @count - @Top - 3 if(@diff>0) begin ;with tbl_del as( select top(@diff) Row_GUID from [srv].[SQL_TopProcedureExecStat] where CategoryName=@CategoryName order by case @CategoryName when 'TotalWorkerTime' then TotalWorkerTime when 'TotalElapsedTime' then TotalElapsedTime when 'AvgWorkerSec' then AvgWorkerSec when 'AvgElapsedSec' then AvgElapsedSec when 'TotalPhysicalReads' then TotalPhysicalReads when 'TotalLogicalReads' then TotalLogicalReads when 'TotalLogicalWrites' then TotalLogicalWrites when 'AvgPhysicalReads' then AvgPhysicalReads when 'AvgLogicalReads' then AvgLogicalReads when 'AvgLogicalWrites' then AvgLogicalWrites end ) delete from [srv].[SQL_TopProcedureExecStat] where Row_GUID in (select Row_GUID from tbl_del); end declare @DB_ID int declare @OBJECT_ID int declare @top1 int = 3 declare @diff1 int declare @count1 int -- deletion of more than @top1 times repeats of the specific procedure select top (1) @count1 = tp.num ,@DB_ID = tp.DB_ID ,@OBJECT_ID = tp.OBJECT_ID from (select count(*) as num, DB_ID, OBJECT_ID from [srv].[SQL_TopProcedureExecStat] where CategoryName=@CategoryName group by DB_ID, OBJECT_ID) as tp order by tp.num desc; set @diff1 = @count1 - @top1; if(@diff1) > 0 begin ;with tbl_del as( select top(@diff1) Row_GUID from [srv].[SQL_TopProcedureExecStat] where DB_ID = @DB_ID and OBJECT_ID = @OBJECT_ID and CategoryName=@CategoryName order by case @CategoryName when 'TotalWorkerTime' then TotalWorkerTime when 'TotalElapsedTime' then TotalElapsedTime when 'AvgWorkerSec' then AvgWorkerSec when 'AvgElapsedSec' then AvgElapsedSec when 'TotalPhysicalReads' then TotalPhysicalReads when 'TotalLogicalReads' then TotalLogicalReads when 'TotalLogicalWrites' then TotalLogicalWrites when 'AvgPhysicalReads' then AvgPhysicalReads when 'AvgLogicalReads' then AvgLogicalReads when 'AvgLogicalWrites' then AvgLogicalWrites end ) delete from [srv].[SQL_TopProcedureExecStat] where Row_GUID in (select Row_GUID from tbl_del); end -- deletion of more than 1 repeats of the AvgWorkerSec parameter for the specific procedure if @CategoryName = 'AvgWorkerSec' begin declare @AvgWorkerSec decimal(8,2) select top (1) @count1 = tp.num ,@DB_ID = tp.DB_ID ,@OBJECT_ID = tp.OBJECT_ID ,@AvgWorkerSec = tp.AvgWorkerSec from (select count(*) as num, DB_ID, OBJECT_ID, AvgWorkerSec from [srv].[SQL_TopProcedureExecStat] where CategoryName=@CategoryName group by DB_ID, OBJECT_ID,AvgWorkerSec) as tp order by tp.num desc; set @diff1 = @count1 - 1; if(@diff1) > 0 begin ;with tbl_del as( select top(@diff1) Row_GUID from [srv].[SQL_TopProcedureExecStat] where DB_ID = @DB_ID and OBJECT_ID = @OBJECT_ID and CategoryName=@CategoryName and AvgWorkerSec = @AvgWorkerSec order by InsertUTCDate desc ) delete from [srv].[SQL_TopProcedureExecStat] where Row_GUID in (select Row_GUID from tbl_del); end end if @CategoryName = 'AvgElapsedSec' begin declare @AvgElapsedSec decimal(8,2) select top (1) @count1 = tp.num ,@DB_ID = tp.DB_ID ,@OBJECT_ID = tp.OBJECT_ID ,@AvgElapsedSec = tp.AvgElapsedSec from (select count(*) as num, DB_ID, OBJECT_ID, AvgElapsedSec from [srv].[SQL_TopProcedureExecStat] where CategoryName=@CategoryName group by DB_ID, OBJECT_ID,AvgElapsedSec) as tp order by tp.num desc; set @diff1 = @count1 - 1; if(@diff1) > 0 begin ;with tbl_del as( select top(@diff1) Row_GUID from [srv].[SQL_TopProcedureExecStat] where DB_ID = @DB_ID and OBJECT_ID = @OBJECT_ID and CategoryName=@CategoryName and AvgElapsedSec = @AvgElapsedSec order by InsertUTCDate desc ) delete from [srv].[SQL_TopProcedureExecStat] where Row_GUID in (select Row_GUID from tbl_del); end end END GO
It is better to run this stored procedure immediately after collecting information about the stored procedures (we can set up a task in Agent for running it every 5-10 minutes for queries, stored procedures and triggers):
exec [srv].[InsertForSQL_StatementExecStat]; --collecting information about executed queries exec [srv].[InsertForTriggerExecStat]; --collecting information about executed triggers exec [srv].[InsertForProcedureExecStat]; --collecting information about executed stored procedures --collecting information about the most heavy executed stored procedures, according to the criteria exec [srv].[InsertTopProcedureExecStat] @top=@top, @CategoryName='AvgWorkerSec'; exec [srv].[InsertTopProcedureExecStat] @top=@top, @CategoryName='AvgElapsedSec'
3. Running trace (every 5-10 minutes with the help of the Agent tasks, preferably right after collecting information):
USE [DATABASE_NAME]; go --coefficient of transition value of indicator declare @koef_red numeric(8,3)=1.3; --if there are records with the indicator greater than or equal to the --preset indicator coefficient if(exists( SELECT top(1) 1 FROM [srv].[SQL_TopProcedureExecStat] where CategoryName='AvgElapsedSec' or CategoryName='AvgWorkerSec' group by CategoryName having avg([AvgElapsedSec])>=@koef_red or avg([AvgWorkerSec])>=@koef_red)) begin --running autorace exec .[srv].[AutoTrace]; end
The auto-trace stored procedure is implemented on an individual basis. For example:
USE [DATABASE_NAME] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE PROCEDURE [srv].[AutoTrace] @maxfilesize bigint=200 --maximum file size in Mb ,@run_minutes int=60 --tracing length in minutes ,@file_patch nvarchar(255)=N'Path to directory' --directory for trace file ,@file_name nvarchar(255)=N'Profiler' --file name ,@res_msg nvarchar(255)=NULL output --result in the form of messages AS BEGIN SET NOCOUNT ON; declare @rc int; declare @TraceID int; if(@run_minutes>=1200) set @run_minutes=1200; --no longer than 20 hours! declare @finish_dt datetime=DateAdd(minute,@run_minutes,GetDate()); --execution end time --end of trace file declare @finish_dt_inc nvarchar(255)=N'_'+cast(YEAR(@finish_dt) as nvarchar(255))+'_'+cast(MONTH(@finish_dt) as nvarchar(255))+'_'+cast(DAY(@finish_dt) as nvarchar(255)); declare @File nvarchar(255)=@file_patch+@file_name+@finish_dt_inc; --full name of the trace file DECLARE @result bit; DECLARE @msgerrors nvarchar(255); DECLARE @oldDT datetime; --Getting the last date and time if(object_id('DATABASE_NAME.dbo.TraceTable')<>0) begin select @oldDT=max(StartTime) from DATABASE_NAME.dbo.TraceTable where StartTime is not null; end --select @oldDT; --If the last date and time is not specified or it is less than time of trace ending,trace is run. Otherwise, the trace was executed on this date. if(@oldDT is null or @oldDT<DATETIMEFROMPARTS(YEAR(@finish_dt), MONTH(@finish_dt), DAY(@finish_dt), 0, 0, 0, 0)) begin --creating trace exec @rc = sp_trace_create @TraceID=@TraceID output, --Trace ID @Options=0, --tracing options (by default) @TraceFile=@File, --trace file destination @MaxFileSize=@maxfilesize, --maximum size of the trace file (when reaching maximum size, trace stops) @StopTime=@finish_dt--, --end data and time of trace --@FileCount=2; --number of files, at which the previous files are deleted (that are not used in the given set of trace options) --if the trace is created without errors (code 0), we can set up and tun it if (@rc = 0) begin -- Setting event for trace declare @on bit set @on = 1 exec sp_trace_setevent @TraceID, 10, 1, @on exec sp_trace_setevent @TraceID, 10, 9, @on exec sp_trace_setevent @TraceID, 10, 2, @on exec sp_trace_setevent @TraceID, 10, 66, @on exec sp_trace_setevent @TraceID, 10, 10, @on exec sp_trace_setevent @TraceID, 10, 3, @on exec sp_trace_setevent @TraceID, 10, 4, @on exec sp_trace_setevent @TraceID, 10, 6, @on exec sp_trace_setevent @TraceID, 10, 7, @on exec sp_trace_setevent @TraceID, 10, 8, @on exec sp_trace_setevent @TraceID, 10, 11, @on exec sp_trace_setevent @TraceID, 10, 12, @on exec sp_trace_setevent @TraceID, 10, 13, @on exec sp_trace_setevent @TraceID, 10, 14, @on exec sp_trace_setevent @TraceID, 10, 15, @on exec sp_trace_setevent @TraceID, 10, 16, @on exec sp_trace_setevent @TraceID, 10, 17, @on exec sp_trace_setevent @TraceID, 10, 18, @on exec sp_trace_setevent @TraceID, 10, 25, @on exec sp_trace_setevent @TraceID, 10, 26, @on exec sp_trace_setevent @TraceID, 10, 31, @on exec sp_trace_setevent @TraceID, 10, 34, @on exec sp_trace_setevent @TraceID, 10, 35, @on exec sp_trace_setevent @TraceID, 10, 41, @on exec sp_trace_setevent @TraceID, 10, 48, @on exec sp_trace_setevent @TraceID, 10, 49, @on exec sp_trace_setevent @TraceID, 10, 50, @on exec sp_trace_setevent @TraceID, 10, 51, @on exec sp_trace_setevent @TraceID, 10, 60, @on exec sp_trace_setevent @TraceID, 10, 64, @on exec sp_trace_setevent @TraceID, 12, 1, @on exec sp_trace_setevent @TraceID, 12, 9, @on exec sp_trace_setevent @TraceID, 12, 3, @on exec sp_trace_setevent @TraceID, 12, 11, @on exec sp_trace_setevent @TraceID, 12, 4, @on exec sp_trace_setevent @TraceID, 12, 6, @on exec sp_trace_setevent @TraceID, 12, 7, @on exec sp_trace_setevent @TraceID, 12, 8, @on exec sp_trace_setevent @TraceID, 12, 10, @on exec sp_trace_setevent @TraceID, 12, 12, @on exec sp_trace_setevent @TraceID, 12, 13, @on exec sp_trace_setevent @TraceID, 12, 14, @on exec sp_trace_setevent @TraceID, 12, 15, @on exec sp_trace_setevent @TraceID, 12, 16, @on exec sp_trace_setevent @TraceID, 12, 17, @on exec sp_trace_setevent @TraceID, 12, 18, @on exec sp_trace_setevent @TraceID, 12, 26, @on exec sp_trace_setevent @TraceID, 12, 31, @on exec sp_trace_setevent @TraceID, 12, 35, @on exec sp_trace_setevent @TraceID, 12, 41, @on exec sp_trace_setevent @TraceID, 12, 48, @on exec sp_trace_setevent @TraceID, 12, 49, @on exec sp_trace_setevent @TraceID, 12, 50, @on exec sp_trace_setevent @TraceID, 12, 51, @on exec sp_trace_setevent @TraceID, 12, 60, @on exec sp_trace_setevent @TraceID, 12, 64, @on exec sp_trace_setevent @TraceID, 12, 66, @on exec sp_trace_setevent @TraceID, 13, 1, @on exec sp_trace_setevent @TraceID, 13, 9, @on exec sp_trace_setevent @TraceID, 13, 3, @on exec sp_trace_setevent @TraceID, 13, 11, @on exec sp_trace_setevent @TraceID, 13, 4, @on exec sp_trace_setevent @TraceID, 13, 6, @on exec sp_trace_setevent @TraceID, 13, 7, @on exec sp_trace_setevent @TraceID, 13, 8, @on exec sp_trace_setevent @TraceID, 13, 10, @on exec sp_trace_setevent @TraceID, 13, 12, @on exec sp_trace_setevent @TraceID, 13, 14, @on exec sp_trace_setevent @TraceID, 13, 26, @on exec sp_trace_setevent @TraceID, 13, 35, @on exec sp_trace_setevent @TraceID, 13, 41, @on exec sp_trace_setevent @TraceID, 13, 49, @on exec sp_trace_setevent @TraceID, 13, 50, @on exec sp_trace_setevent @TraceID, 13, 51, @on exec sp_trace_setevent @TraceID, 13, 60, @on exec sp_trace_setevent @TraceID, 13, 64, @on exec sp_trace_setevent @TraceID, 13, 66, @on -- Setting filters declare @intfilter int; declare @bigintfilter bigint; exec sp_trace_setfilter @TraceID, 10, 0, 7, N'Application SQL Server Profiler - fa35966e-e426-4d1a-8753-8f971cf89495'; exec sp_trace_setfilter @TraceID, 35, 0, 6, N'%DATABASE_NAME%'; exec sp_trace_setfilter @TraceID, 35, 1, 6, N'%DATABASE_NAME%'; --Running trace exec sp_trace_setstatus @TraceID, 1; --setting execution time wait declare @run_delay int=@run_minutes+1; --increase of wait for 1 minute from the preset trace execution time declare @run_delay_hour int=@run_delay/60; --calculation of wait hours declare @run_delay_minute int=@run_delay-(@run_delay/60)*60; --calculation of the remaining minutes declare @run_delay_hour_str nvarchar(2); --string representation of hours declare @run_delay_minute_str nvarchar(2); --string representation of minutes --adding missing nulls for string representation of hours if(@run_delay_hour=0) set @run_delay_hour_str='00'; else if(@run_delay_hour<10) set @run_delay_hour_str='0'+cast(@run_delay_hour as nvarchar(255)); else if(@run_delay_hour>=10) set @run_delay_hour_str=cast(@run_delay_hour as nvarchar(255)); --select @run_delay_hour, @run_delay_hour_str; --adding missing nulls for string representation of minutes if(@run_delay_minute=0) set @run_delay_minute_str='00'; else if(@run_delay_minute<10) set @run_delay_minute_str='0'+cast(@run_delay_minute as nvarchar(255)); else if(@run_delay_minute>=10) set @run_delay_minute_str=cast(@run_delay_minute as nvarchar(255)); --select @run_delay_minute, @run_delay_minute_str; --the hours:minutes string representation for the wait declare @run_delay_str nvarchar(255)=@run_delay_hour_str+':'+@run_delay_minute_str; --wait WAITFOR DELAY @run_delay_str; --select @run_delay_str; --deletion of the trace table, if it exists if(object_id('DATABASE_NAME.dbo.TraceTable')<>0) begin drop table DATABASE_NAME.dbo.TraceTable; end --creation and filling of the trace table from the trace file SELECT * INTO DATABASE_NAME.dbo.TraceTable FROM ::fn_trace_gettable(@File+'.trc', default); --adding extension to the full file set @File=@File+'.trc'; --here, we need to insert code to delete the trace file declare @str_title nvarchar(max)='There was auto trace on the server'+@@servername, @str_pred_mess nvarchar(max)='На '+@@servername+'The auto trace has been run on the server. You can view the result in the Database_Name.dbo.TraceTable table; --here, we can send the auto trace run notification to administrator end --returning the result set @res_msg=N'ErrorCode='+cast(@rc as nvarchar(255))+'\r\n'+coalesce(@msgerrors, ''); end END GO
For more information on setting trace, refer to How to: Create a Trace (Transact-SQL).
Conclusion
In this article, we considered an example of implementation of a system for collecting information about the state of a database, that does not load the system. In case of problem detection, this system runs the preset trace and saves results into a table. This approach can be extended to several servers. In this case, we need to collect information from all servers for subsequent sending of information to administrators.
It is also important to remember about deletion of old data from the used tables. It is quite sufficient to store data within a month or two weeks.
Also read:
Implementing a Common MS SQL Server Performance Indicator
References
- sys.dm_exec_trigger_stats
- sys.dm_exec_procedure_stats
- sys.dm_exec_query_stats
- sys.dm_exec_sql_text
- How to: Create a Trace (Transact-SQL)