Logging SQL Server Query Performance with sp_query_logger
Introduction
Why Logging SQL Server Query Performance is Important
Setting Up sp_query_logger
Using sp_query_logger
Understanding the Logged Data
Conclusion
Introduction
Effective database performance tuning and troubleshooting often require detailed insights into SQL Server query execution and behavior. SQL Server provides various
tools to gather and analyze this information. One particularly useful tool is a custom stored procedure,
sp_query_logger, which logs detailed query
statistics and execution plans. This blog will walk you through the setup and usage of
sp_query_logger, highlighting its importance in troubleshooting
performance issues.
Why Logging SQL Server Query Performance is Important
Query logging is essential for several reasons:
- Identify Performance Bottlenecks: By logging query execution statistics, you can identify slow-running queries and understand their impact on overall performance.
- Analyze Query Plans: Capturing query plans helps in understanding how SQL Server executes a query, which is crucial for optimizing performance.
- Track Query Execution: Monitoring query execution over time helps in identifying trends and understanding how changes to the database or application affect performance.
- Troubleshoot Issues: When users report slow performance, query logs provide the data needed to diagnose and resolve these issues quickly.
Setting Up sp_query_logger
The
sp_query_logger stored procedure logs query statistics and plans into a table named
query_logger. Here's how to set it up:
Create the Stored Procedure: This step creates or alters the
sp_query_logger procedure, which captures and logs query performance data.
-- Create or alter the sp_query_logger procedure
if object_id('dbo.sp_query_logger') is null
exec ('create procedure dbo.sp_query_logger as return 0;');
go
alter procedure sp_query_logger
@dbid smallint,
@search_string nvarchar(4000) = N'%%',
@log_retention_days int = 2
with recompile
as
if not exists (select * from information_schema.tables where table_name = N'query_logger')
begin
create table query_logger
(
logged_at datetime,
dbid smallint,
sql_handle varbinary(64),
statement_start_offset int,
statement_end_offset int,
plan_generation_num bigint,
plan_handle varbinary(64),
query_text nvarchar(max),
query_plan xml,
creation_time datetime,
last_execution_time datetime,
total_elapsed_time bigint,
execution_count bigint,
last_elapsed_time bigint,
min_elapsed_time bigint,
max_elapsed_time bigint,
total_rows bigint,
last_rows bigint,
min_rows bigint,
max_rows bigint,
total_worker_time bigint,
last_worker_time bigint,
min_worker_time bigint,
max_worker_time bigint,
total_physical_reads bigint,
last_physical_reads bigint,
min_physical_reads bigint,
max_physical_reads bigint,
total_logical_reads bigint,
last_logical_reads bigint,
min_logical_reads bigint,
max_logical_reads bigint,
total_logical_writes bigint,
last_logical_writes bigint,
min_logical_writes bigint,
max_logical_writes bigint
);
end
delete from query_logger
where logged_at < dateadd(day, datediff(day, 0, getdate()), -@log_retention_days);
insert into query_logger
(
logged_at,
dbid,
sql_handle,
statement_start_offset,
statement_end_offset,
plan_generation_num,
plan_handle,
query_text,
query_plan,
creation_time,
last_execution_time,
total_elapsed_time,
execution_count,
last_elapsed_time,
min_elapsed_time,
max_elapsed_time,
total_rows,
last_rows,
min_rows,
max_rows,
total_worker_time,
last_worker_time,
min_worker_time,
max_worker_time,
total_physical_reads,
last_physical_reads,
min_physical_reads,
max_physical_reads,
total_logical_reads,
last_logical_reads,
min_logical_reads,
max_logical_reads,
total_logical_writes,
last_logical_writes,
min_logical_writes,
max_logical_writes
)
select
getdate(),
dest.dbid,
deqs.sql_handle,
deqs.statement_start_offset,
deqs.statement_end_offset,
deqs.plan_generation_num,
deqs.plan_handle,
dest.text,
deqp.query_plan,
deqs.creation_time,
deqs.last_execution_time,
deqs.total_elapsed_time,
deqs.execution_count,
deqs.last_elapsed_time,
deqs.min_elapsed_time,
deqs.max_elapsed_time,
deqs.total_rows,
deqs.last_rows,
deqs.min_rows,
deqs.max_rows,
deqs.total_worker_time,
deqs.last_worker_time,
deqs.min_worker_time,
deqs.max_worker_time,
deqs.total_physical_reads,
deqs.last_physical_reads,
deqs.min_physical_reads,
deqs.max_physical_reads,
deqs.total_logical_reads,
deqs.last_logical_reads,
deqs.min_logical_reads,
deqs.max_logical_reads,
deqs.total_logical_writes,
deqs.last_logical_writes,
deqs.min_logical_writes,
deqs.max_logical_writes
from
sys.dm_exec_query_stats deqs
cross apply
sys.dm_exec_sql_text(deqs.plan_handle) as dest
cross apply
sys.dm_exec_query_plan(deqs.plan_handle) as deqp
where
dest.dbid = @dbid
and
dest.text like @search_string;
go
Using sp_query_logger
To use
sp_query_logger, execute it with the appropriate parameters. For example, to log queries from database ID 5 that match a specific search string:
execute sp_query_logger
@dbid = 5,
@search_string = N'%SELECT * from AUDITLOG;%',
@log_retention_days = 3;
This setup logs detailed statistics and plans for queries that match the search string, allowing you to analyze performance issues and optimize the query or
index usage. The
sp_query_logger procedure can be scheduled to run a few times a day to record the execution of the SQL query in the search string, capturing insights about the SQL.
select * from query_logger;
Understanding the Logged Data
The
query_logger table captures extensive information about each logged query:
Column | Description
------------------------------------------------------------- | ------------------------------------------------------------
logged_at | Timestamp when the log entry was created.
dbid | Database ID where the query was executed.
sql_handle | A unique identifier for the SQL text of the query.
statement_start_offset | The starting position of the statement within the batch.
statement_end_offset | The ending position of the statement within the batch.
plan_handle | A unique identifier for the query plan.
query_text | The SQL text of the query.
query_plan | The execution plan for the query in XML format.
creation_time | When the query plan was created.
last_execution_time | When the query was last executed.
total_elapsed_time | Total time the query has taken to execute.
execution_count | Number of times the query has been executed.
min_elapsed_time | Minimum execution times.
max_elapsed_time | Maximum execution times.
total_rows, min_rows, max_rows | Row count metrics.
total_worker_time, min_worker_time, max_worker_time | CPU time metrics.
total_physical_reads, min_physical_reads, max_physical_reads | Disk read metrics.
total_logical_reads, min_logical_reads, max_logical_reads | Memory read metrics.
total_logical_writes, min_logical_writes, max_logical_writes: | Memory write metrics.
Conclusion
Implementing
sp_query_logger in SQL Server provides valuable insights into SQL Server query performance, helping you identify
and resolve performance bottlenecks effectively. By logging query statistics and execution plans, you gain a powerful tool for database performance
tuning and troubleshooting.
Related content