How It Works: Workers, Tasks, Failed Logins - What is my SQL Server Doing?
Published Jun 07 2022 11:34 AM 1,680 Views
Microsoft

From Customer

BobDorr_0-1654626634577.png

Interesting point here is, current_workers_count is ~10X compared to active_workers_count; means no tasks assigned to 10X threads.

How did threads land with no tasks? Is there orphaned threads not getting cleaned up?

 

My Notes

  • The total workers are divided evenly among the visible schedulers (schedulers that accept incoming query requests.)  For example, a max worker setting of 1000 on a 4-scheduler system is 250 per scheduler.
  • Each scheduler maintains a minimum level of workers, so workers don’t have to be created when new work arrives.  You can think of them as hot workers.
  • Depending on the installation workers greater than minimum are trimmed at different intervals.  See Trimming Behavior below.
  • Tasks can be transactional or permanent.  Requests to the server are transactional.  Acquire a task, bind to worker, perform the query request, unbind the worker, and release the task.   Requests which are permanent are things like checkpoint, lazy writer, etc.  They are bound to worker for the lifetime of the instance.
  • Hidden schedulers are used to handle activities such as backup, create and maintain workers.
  • The task count includes the transactional and permanent task requests.
  • The runnable_tasks_count are those tasks no longer waiting on a resource and available to be scheduled.  Scheduling occurs when the current running worker performs a context switch (yields.)

In the output above I see:  (sys.dm_os_schedulers (Transact-SQL) - SQL Server | Microsoft Docs)

  • current_tasks_count (this includes transactional and permanent tasks)
  • runnable_tasks_count (value is low so likely blocking taking place, preemptive workers, waiting dispatchers, or system timer tasks that are not runnable at time of the capture)
  • current_workers_count (number of workers created to handle tasks)
  • active_workers_count (workers that are bound to tasks in non-preeemptive mode.  The difference in current_tasks_count and active_workers_count is likely the preemptive workers)

Here is my takeaway from just this data point.

  • You have some preemptive activity to handle things like network completion ports, handling network IO for worker, XEvent outputs, etc.   Looking at the sys.dm_exec_requests and joining to sys.dm_os_tasks, sys.dm_os_workers and sys.dm_os_schedulers provides a better picture of the ongoing preemptive work.
  • The same data from dm_exec_requests and SQL OS DMVs helps point out the permanent tasks (Checkpoint, LW, Version Store Cleanup, Ghost Cleanup, …)
  • There are dispatcher tasks that are maintained by the various dispatchers and are returned (called fading) based on the dispatcher fading timeouts.  The dispatcher times out, unbinds the task from the worker and the worker becomes idle. Now the configured SOS idle trimming is applied.
  • Some features, such as HADR, maintain their own worker pool on top SOS (much like a dispatcher pool.)  These queues and associated tasks have separate idle timeouts.  The same DMV queries can point to such tasks.  For example, a task could be bound to a worker and assigned to the HADR worker pool for handling HADR requests.  If there is no HADR work to perform, then the task is waiting on the HADR queue event.  The task is not runnable and the idle timeout for the HADR queue is being applied.
  • The dm_os_waits, dm_os_waiting_tasks and such DMVs are helpful in understanding the wait behaviors.

Failed Logins

The reason the above data was captured was in response to failed loging.  When I add failed logins as a outcome can fill in a bit more information.

 

Yes, logins can be impacted when reaching max worker threads.   The IO completion port accepts the new connection request and enqueues a task to process the login.  This login task is assigned to a visible scheduler.  If a worker cannot be bound and process the task before the login timeout is exceeded the login fails.   You can reproduce this with a simple test, say max workers is set to 1000.  Make 1000 connections (ostress -E -SMyServer -Q”wait for delay ’10:00:00’” -n1000“) which will hold the worker (remember a task is bound to a worker until it completes the task request.)   You can reproduce the same outcome with a long blocking chain, etc.  Now new connection requests timeout.

 

There are some additional issues that can lead to login timeout.  For example, to combat Denial Of Service (DOS) the SSL responses are often limited to 5 or 10 seconds.  If these timeouts occur then the login fails but the task and worker binding was in effect for the login attempt and secondary login attempts would be creating and using additional workers.

 

  • Using the DMVs to understand what the workers are associated with is a great place to start.
  • The connectivity ring buffer (sys.dm_os_ring_buffers) is another excellent source of information.  The error state and the additional login timing information shows where the time was spent attempting to process the login.

Once we can see the worker assignments and ring buffer information the pattern is commonly easy to see, troubleshoot and resolve.

BobDorr_0-1654626725420.png

nocount on
go

use tempdb
go

drop table if exists captureTables
go

create table captureTables(target sysname NOT NULL, source sysname NOT NULL)
go

insert into captureTables values
('cap_dm_os_sys_info', 'sys.dm_os_sys_info'),
('cap_dm_os_schedulers', 'sys.dm_os_schedulers'),
('cap_dm_os_threads', 'sys.dm_os_threads'),
('cap_dm_os_tasks', 'sys.dm_os_tasks'),
('cap_dm_os_workers', 'sys.dm_os_workers'),
('cap_dm_os_dispatchers', 'sys.dm_os_dispatchers'),
('cap_dm_os_dispatcher_pools', 'sys.dm_os_dispatcher_pools'),
('cap_dm_exec_requests', 'sys.dm_exec_requests'),
('cap_dm_exec_sessions', 'sys.dm_exec_sessions')
go

------------------------------------------------
-- Cleanup previous execution
------------------------------------------------
drop procedure if exists spCleanup
go

create procedure spCleanup
as
begin
set nocount on
declare @target sysname

select \* into #captureTables from captureTables 

select TOP 1 @target = target from #captureTables 

 

while (@target is not null) 

begin 

    exec('drop table if exists ' + @target

    delete from #captureTables where target = @target 

    set @target = null 

    select TOP 1 @target = target from #captureTables 

end 

end
go

------------------------------------------------
-- Capture data
------------------------------------------------
drop procedure if exists spCapture
go

create procedure spCapture
as
begin
set nocount on
declare @captureTime sysname= convert(sysname, GetUTCDate(), 109)
declare @target sysname
declare @source sysname

-- Avoid cursor overhead 

-- 

select \* into #captureTables from captureTables 

select TOP 1 @target = target,  @source = source  from #captureTables

 

while (@target is not null) 

begin 

    print 'Processing ' + @target 

    if (object\_id(@target) is null) 

    begin 

        exec('select cast(''' + @captureTime + ''' as datetime) as \[CaptureTime\], \* into ' + @target + '  from ' + @source) 

    end 

    else 

    begin 

        exec('insert into ' + @target + ' select cast(''' + @captureTime + ''' as datetime) as \[CaptureTime\], \* from ' + @source) 

    end

 

    -- exec('select \* from ' + @target

    delete from #captureTables where target = @target 

    set @target = null 

    select TOP 1 @target = target,   @source = source  from #captureTables

 

end 

end
go

exec spCleanup
go

exec spCapture
waitfor delay '00:00:05'
exec spCapture
go

------------------------------------------------
-- Report outs
------------------------------------------------
print 'System Info'
go

select
CaptureTime,
cpu_ticks - LAG(cpu_ticks,1) OVER (ORDER BY CaptureTime) as cpu_ticks_delta,
ms_ticks - LAG(ms_ticks,1) OVER (ORDER BY CaptureTime) as ms_ticks_delta,
committed_kb - LAG(committed_kb,1) OVER (ORDER BY CaptureTime) as committed_kb_delta,
max_workers_count - LAG(max_workers_count,1) OVER (ORDER BY CaptureTime) as max_workers_count_delta,
process_kernel_time_ms - LAG(process_kernel_time_ms,1) OVER (ORDER BY CaptureTime) as process_kernel_time_ms_delta,
process_user_time_ms - LAG(process_user_time_ms,1) OVER (ORDER BY CaptureTime) as process_user_ms_delta
, *
from cap_dm_os_sys_info
go

print 'Scheduler Info'
go

select
CaptureTime,
scheduler_address,
context_switches_count - LAG(context_switches_count,1) OVER (PARTITION BY scheduler_address ORDER BY CaptureTime) as context_switch_delta,
preemptive_switches_count - LAG(preemptive_switches_count,1) OVER (PARTITION BY scheduler_address ORDER BY CaptureTime) as preemptive_switch_delta,
current_tasks_count - LAG(current_tasks_count,1) OVER (PARTITION BY scheduler_address ORDER BY CaptureTime) as current_tasks_count_delta,
runnable_tasks_count - LAG(runnable_tasks_count,1) OVER (PARTITION BY scheduler_address ORDER BY CaptureTime) as runnable_tasks_count_delta,
yield_count - LAG(yield_count,1) OVER (PARTITION BY scheduler_address ORDER BY CaptureTime) as yield_count_delta,
total_cpu_usage_ms - LAG(total_cpu_usage_ms,1) OVER (PARTITION BY scheduler_address ORDER BY CaptureTime) as total_cpu_usage_ms_delta,
*
from cap_dm_os_schedulers
order by 8 desc
go

print 'Thread Info'
go

select
CaptureTime,
os_thread_id,
kernel_time - LAG(kernel_time,1) OVER (PARTITION BY os_thread_id ORDER BY CaptureTime) as kernel_time_delta,
usermode_time - LAG(usermode_time,1) OVER (PARTITION BY os_thread_id ORDER BY CaptureTime) as user_time_delta,
*
from cap_dm_os_threads
order by 4 desc
go

print 'Task Info'
go

select
CaptureTime,
task_address,
context_switches_count - LAG(context_switches_count,1) OVER (PARTITION BY task_address ORDER BY CaptureTime) as context_switch_delta,
*
from cap_dm_os_tasks
order by 3 desc
go

print 'Worker Info'
go

select
CaptureTime,
worker_address,
context_switch_count - LAG(context_switch_count,1) OVER (PARTITION BY worker_address ORDER BY CaptureTime) as context_switch_delta,
quantum_used - LAG(quantum_used,1) OVER (PARTITION BY worker_address ORDER BY CaptureTime) as quantum_used_delta,
*
from cap_dm_os_workers
order by 4 desc
go

print 'Requests Info'
go

select
CaptureTime,
session_id,
request_id,
reads - LAG(reads,1) OVER (PARTITION BY session_id, request_id ORDER BY CaptureTime) as reads_delta,
logical_reads - LAG(logical_reads,1) OVER (PARTITION BY session_id, request_id ORDER BY CaptureTime) as logical_reads_delta,
writes - LAG(writes,1) OVER (PARTITION BY session_id, request_id ORDER BY CaptureTime) as writes_delta,
cpu_time - LAG(cpu_time,1) OVER (PARTITION BY session_id, request_id ORDER BY CaptureTime) as cpu_time_delta,
*
from cap_dm_exec_requests
order by 7 desc
go

print 'Sessions Info'
go

select
CaptureTime,
session_id,
cpu_time - LAG(cpu_time,1) OVER (PARTITION BY session_id ORDER BY CaptureTime) as cpu_time_delta,
total_scheduled_time - LAG(total_scheduled_time,1) OVER (PARTITION BY session_id ORDER BY CaptureTime) as total_scheduled_time_delta,
reads - LAG(reads,1) OVER (PARTITION BY session_id ORDER BY CaptureTime) as reads_delta,
logical_reads - LAG(logical_reads,1) OVER (PARTITION BY session_id ORDER BY CaptureTime) as logical_reads_delta,
writes - LAG(writes,1) OVER (PARTITION BY session_id ORDER BY CaptureTime) as writes_delta,
*
from cap_dm_exec_sessions
order by 4 desc
go

print 'Dispatcher Info'
go

select
d.CaptureTime,
dispatcher_pool_address,
d.task_address,
items_processed - LAG(items_processed,1) OVER (PARTITION BY dispatcher_pool_address, d.task_address ORDER BY d.CaptureTime) as items_processed_delta,
w.quantum_used - LAG(w.quantum_used,1) OVER (PARTITION BY dispatcher_pool_address, d.task_address ORDER BY d.CaptureTime) as quantum_used_delta,
tt.kernel_time - LAG(tt.kernel_time,1) OVER (PARTITION BY dispatcher_pool_address, d.task_address ORDER BY d.CaptureTime) as kernel_time_delta,
tt.usermode_time - LAG(tt.usermode_time,1) OVER (PARTITION BY dispatcher_pool_address, d.task_address ORDER BY d.CaptureTime) as usermode_time_delta,
*
from cap_dm_os_dispatchers d
inner join cap_dm_os_tasks t on t.task_address = d.task_address and t.CaptureTime = d.CaptureTime
inner join cap_dm_os_workers w on w.task_address = t.task_address and w.CaptureTime = t.CaptureTime
inner join cap_dm_os_threads tt on tt.thread_address = w.thread_address and w.CaptureTime = tt.CaptureTime
order by 7 desc
go

print 'Dispatcher Pool Info'
go

select
CaptureTime,
dispatcher_pool_address,
dispatcher_count - LAG(dispatcher_count,1) OVER (PARTITION BY dispatcher_pool_address ORDER BY CaptureTime) as dispatcher_count_delta,
dispatcher_waiting_count - LAG(dispatcher_waiting_count,1) OVER (PARTITION BY dispatcher_pool_address ORDER BY CaptureTime) as dispatcher_waiting_count_delta,
queue_length - LAG(queue_length,1) OVER (PARTITION BY dispatcher_pool_address ORDER BY CaptureTime) as queue_length_delta,
*
from cap_dm_os_dispatcher_pools
order by 5 desc
go

print 'Mappings'

select
ss.*, r.*, w.*, ts.*, t.*, s.*
from cap_dm_os_schedulers s
inner join cap_dm_os_workers w on w.scheduler_address = s.scheduler_address and s.CaptureTime = w.CaptureTime
inner join cap_dm_os_threads t on t.thread_address = w.thread_address and t.CaptureTime = w.CaptureTime
inner join cap_dm_os_tasks ts on ts.task_address = w.task_address and ts.CaptureTime = w.CaptureTime
inner join cap_dm_exec_requests r on r.task_address = ts.task_address and r.CaptureTime = ts.CaptureTime
inner join cap_dm_exec_sessions ss on ss.session_id = r.session_id and ss.CaptureTime = r.CaptureTime
order by ss.session_id, r.request_id, ss.CaptureTime
go

 

Trimming Behavior

The default idle worker timeout is 1500 seconds (BOX, SQLVM.)  However, various deployments may adjust the timeout threshold.

 

Sub-Core set to 120 seconds

Data Warehouse DMS set to 120 seconds
Data Warehouse Engine set to 120 seconds
SQLDB instance set to 900 sec

...

Co-Authors
Version history
Last update:
‎Jun 07 2022 11:33 AM
Updated by: