Monitoring SQL Server 2012 AlwaysOn Availability Groups Worker Thread Consumption
In most cases, people utilize SQL Server features and capabilities in a common and typical usage pattern. But there are some instances where environments do something just a little different, or fill the bucket to the absolute brim. With the advent of AlwaysOn Availability Groups, it is such a robust high availability and disaster recovery solution that as time goes on database professionals are going to think of really cool and interesting ways to stretch it wide, solving problems that we may not have originally thought of. What brought on the deep dive of this specific topic was that a customer was looking to see what potential CPU problems could arise with 40+ availability groups, and a multiple of that of availability group databases. One of the most devastating bottlenecks is when you start running into exhausted CPUs, but with proper planning and focused monitoring you can minimize that risk and ensure existing functionality.
Take an instance where you want to create and implement a large number of availability groups and/or availability databases. You might be far exceeding what others have published and tested with. When doing this, you will want to keep a close eye on what’s called the HADR Worker Pool. This is basically the shared pool of workers across HADR databases. For more information on specifics of what these tasks would include, please see Bob Dorr’s blog post on the topic. Regardless of what these workers are doing, the overconsumption of them could lead to less-than-optimal performance. As my peer, Denzil Riberio, previously wrote about in his blog post on actual worker threads exceeding max worker threads the contention may not surface itself in the form of a hard cap (although the max worker threads does contribute largely to the calculation of the worker limit, as explained below), but in other forms of CPU/resource contention.
When we run into resource contention, we instinctively do our basic troubleshooting on waits and queues, but the root of the problem may not be completely evident with traditional means. So in order to fill in the blanks, we can look at a handful of corner strategies for troubleshooting HADR worker thread contention.
SQL Server lends us a handful of ways to monitor and troubleshoot this, including XE events. The first one I want to look at is hadr_worker_pool_task. Bob mentions this in his blog post, and it’s not necessarily the actual data and task information I’m concerned with normally (although this information is valuable and vital in dissecting specific problems and abnormal behavior). It’s the count of worker pool tasks that I will utilize for a few reasons: baselining during normal operation, and troubleshooting during abnormal situations. All I pull is the count of these events (utilizing the event_counter XE target), and a comparison of current vs. baseline can provide whether or not HADR is simply doing more now than it typically does.
My first step is to create the XE session to start capturing this data:
create event session HadrWorkerPoolTask
on server
add event sqlserver.hadr_worker_pool_task
add target package0.event_counter
with
(
max_memory = 4096 KB,
event_retention_mode = allow_single_event_loss,
max_dispatch_latency = 30 seconds,
max_event_size = 0 KB,
memory_partition_mode = none,
track_causality = off,
startup_state = on
);
go
Because the event_counter target is a running total, I want a way to have historical data and compare the deltas between two different times. I accomplish this by creating a table in a utility database (in my example, the database is named DBA):
use DBA;
go
create table dbo.HadrWorkerPoolTask
(
TaskLogId int identity(1, 1) not null
constraint PK_HadrWorkerPoolTask_TaskLogId primary key clustered,
LogDateTime datetime2(2) not null,
TaskCount bigint not null
);
go
In order to pull the data from the event_counter, I wrote the following query:
;with cte as
(
select
convert(xml, t.target_data) as target_data
from sys.dm_xe_session_targets t
inner join sys.dm_xe_sessions s
on t.event_session_address = s.address
where s.name = 'HadrWorkerPoolTask'
and t.target_name = 'event_counter'
)
select
a.b.value('./@count', 'varchar(max)') as count
from cte
cross apply cte.target_data.nodes('CounterTarget/Packages/Package/Event') a(b);
This will give you the point-in-time count of this event, but I created the dbo.HadrWorkerPoolTask to routinely dump this count for tracking. Modifying the above query slightly in order to persist the event counts, I end up with the following:
;with cte as
(
select
convert(xml, t.target_data) as target_data
from sys.dm_xe_session_targets t
inner join sys.dm_xe_sessions s
on t.event_session_address = s.address
where s.name = 'HadrWorkerPoolTask'
and t.target_name = 'event_counter'
)
insert into dbo.HadrWorkerPoolTask(LogDateTime, TaskCount)
select
getdate(),
a.b.value('./@count', 'varchar(max)') as count
from cte
cross apply cte.target_data.nodes('CounterTarget/Packages/Package/Event') a(b);
In order to ensure this query is executed routinely, you can create a SQL Server Agent job to execute it every x minutes (or hours, or days, or whatever unit of granularity you are looking to achieve. Just remember that the less frequent you grab and store the count of this event, your points of reference will blur and linearize the times in between possibly hiding trends). So at this point in monitoring you now have a running log of total event counts for the hadr_worker_pool_task. But we need to take this a step further in querying to get the deltas instead of the cumulative amount. The below query will do just that, compare each time slot to the one sequentially before it and do the subtraction of the task count to get the delta:
select
t1.LogDateTime,
t1.TaskCount - t2.TaskCount as HadrTaskCount
from dbo.HadrWorkerPoolTask t1
inner join dbo.HadrWorkerPoolTask t2
on t1.TaskLogId = t2.TaskLogId + 1;
You can take this query and dump the result set into Excel, create an SSRS report, or do whatever you typically do to consume diagnostic data. Here is a little sample of what it may look like (I just copy-pasted into Excel and created a line chart):
Now I have a nice chart of the HADR activity for this time period, and if/when something goes awry I can execute the same query for the current time span and compare the two charts.
Another piece of data that I like to keep an eye on is the hadr_thread_pool_worker_start event. This event fires when SQL Server starts up a new worker if there are no idle workers, or if the amount of required workers exceeds the active worker count (all the while staying within the bounds of the worker limit count). We can consume a couple of things from this event: (1) the recordable demand that HADR is putting on the system by requiring additional workers, and (2) we can watch for the event where we simply can’t create another HADR worker, possibly due to hitting the worker limit (that limit is going to be the effective max worker threads [minus] 40, as explained by Bob Dorr). If SQL Server is unable to start a new HADR worker then it will conveniently tell you this in the event’s output.
In order to create this event, I have implemented the below session definition:
create event session HadrThreadPoolWorkerStart
on server
add event sqlserver.hadr_thread_pool_worker_start
add target package0.event_file
(
set filename = N'<path to XEL file>\HadrThreadPoolWorkerStart.xel'
)
with
(
max_memory = 4096 KB,
event_retention_mode = allow_single_event_loss,
max_dispatch_latency = 30 seconds,
max_event_size = 0 KB,
memory_partition_mode = none,
track_causality = off,
startup_state = on
);
go
To view this session data, you can use the GUI (accessible through viewing the target or live data), or you can use a query like the one below:
declare @top_count int;
set @top_count = 100;
;with xe_cte as
(
select
object_name,
cast(event_data as xml) as event_data
from sys.fn_xe_file_target_read_file
(
'<path to XEL file>\HadrThreadPoolWorkerStart*.xel',
null,
null,
null
)
)
select top (@top_count)
event_data.value('(/event/@timestamp)[1]', 'varchar(32)') as time_stamp,
event_data.value('(/event/data/value)[3]', 'int') as active_workers,
event_data.value('(/event/data/value)[2]', 'int') as idle_workers,
event_data.value('(/event/data/value)[1]', 'int') as worker_limit,
event_data.value('(/event/data/value)[4]', 'varchar(5)') as worker_start_success
from xe_cte
order by time_stamp desc;
This query will return a similar output:
The notable results of this query are active_workers vs. worker_limit (are we getting close to, or have we reached, the worker limit? ), and worker_start_success (were we able to start a new HADR worker when we needed one? ). If you are consistently seeing worker_start_success as false (indicating SQL Server’s inability to start a new HADR worker) then you could be running into HADR worker pool starvation. In the event of excessive worker thread contention and long term failures to start a worker, after 15 minutes there will be a logged message in the error log. It is message id 35217, and in your error log the message will read:
“The thread pool for AlwaysOn Availability Groups was unable to start a new worker thread because there are not enough available worker threads. This may degrade AlwaysOn Availability Groups performance. Use the "max worker threads" configuration option to increase number of allowable threads. ”
As an aside, where does worker_limit come from? It is effective max worker threads – 40. So on my single CPU VM, that’ll be 512 – 40 = 472.
There are other considerations when monitoring and troubleshooting HADR worker consumption and task quantity, but what this all boils down to is CPU contention. Going back to the root of the problem, we can utilize other tried-and-true strategies to analyze this resource contention. For instance, take note of the summary of workers and runnable tasks from the sys.dm_os_schedulers DMV:
select
scheduler_id,
status,
current_tasks_count,
current_workers_count,
active_workers_count,
work_queue_count,
runnable_tasks_count,
load_factor
from sys.dm_os_schedulers
where status = 'VISIBLE ONLINE';
Things to watch out for here are counts of work_queue_count and runnable_tasks_count consistently above zero. Another query to have in your toolbox, looking for wait types associated with thread starvation:
select
wait_type,
count(*) as wait_type_count
from sys.dm_os_waiting_tasks
group by wait_type
order by wait_type_count desc;
This above query will give you a count of all current waiting tasks’ associated wait types.
Lastly, when troubleshooting busy schedulers, I like to see what percentage of the total wait time the signal wait time is (signal wait time is the amount of time that tasks waited between being signaled and starting). A sample query for this could be as follows:
;with cpu_wait_cte as
(
select
sum(wait_time_ms) as sum_wait_time_ms,
sum(signal_wait_time_ms) as sum_signal_wait_time_ms
from sys.dm_os_wait_stats
)
select
convert(
decimal(5, 2), sum_signal_wait_time_ms * 1.0 / sum_wait_time_ms * 100
) as signal_wait_time_percentage
from cpu_wait_cte;
This will be the cumulative stats from the last time the instance started (or this DMV was explicitly cleared), so you may need mold this query into a delta query from a start time to end time (or manually clear this DMV) instead of grabbing the wait stats in its entirety. For all intents and purposes, the above query will give what percentage of the summation of time spent waiting that the signal wait time is. This value should be frequently baselined and compared when troubleshooting possible CPU contention. This could bring to light a higher amount of time waiting on the CPU to pick the task back up, possibly indicating CPU pressure.
I have illustrated a few possible approaches to monitoring and troubleshooting possible HADR worker thread issues and tying it all back to generic CPU contention problems. With the right approach, you can maximize visibility on a commonly foggy aspect of HADR worker thread contention.
Thomas Stringer – SQL Server Premier Field Engineer
Twitter: @SQLife
Comments
Anonymous
September 20, 2013
I'd been searching google since some time to find some information on this and thanks to this post I've got it! This will help me get my web site (www.figurinesanimaux.com) working better !Anonymous
October 30, 2013
Looking to implement SQL Server 2012 Always On Availability Groups for a busy SharePoint environment with 130 databases - what kind of Worker Thread Consumption / CPU usage would this add? Would 20 threads per database sound right?Anonymous
January 23, 2014
We have a customer with 5000 small databases. He has some avaliability requeriments and the idea to use AlwaysOn sound good but I started to prepare a lab and I'm facing some problems. The replication seems to hang and seems that the problems is that you described in your post. Do you have any experience with this amount of databases. The definitive database servers will have 16 cores so how I have to configure the workers for them ?Anonymous
December 23, 2014
Thsi is GREAT! Many thanks for this explanationAnonymous
October 22, 2015
The comment has been removed