Collecting Wait Stats

Question

We currently use a monitoring tool which shows us our top wait stats either by number of waiting tasks or total wait time. Below are the wait stats by number of tasks waiting and also wait time per task.

We have users complaining of slow down in the system, yet the metrics for server seem fine in terms of Disk IO, memory and CPU. Does anyone know if the PREEMPTIVE waits are an issue?

Number of waiting tasks
SOS_SCHEDULER_YIELD
PAGELATCH_EX
PAGELATCH_SH
PREEMPTIVE_XE_CALLBACKEXECUTE
PREEMPTIVE_XE_GETTARGETSTATE
PREEMPTIVE_XE_SESSIONCOMMIT

Average wait per task
PAGEIOLATCH_SH
PREEMPTIVE_XE_GETTARGETSTATE 

Update:
I ran a query from Paul Randal similar to what you posted and got the following:

WaitType    Wait_S  Resource_S  Signal_S    WaitCount   Percentage  AvgWait_S   AvgRes_S    AvgSig_S
PREEMPTIVE_XE_GETTARGETSTATE    9704.81 9704.81 0.00    604647  44.60   0.0161  0.0161  0.0000

I know this doesn't line up very well, but basically this wait type has accounted for %44.60 of all wait types. Also as there has been no Signal Waits on this type then this indicates no CPU pressure but instead a wait on some other resource. Not sure how I deduce what that resource is however.

Also this is SQL 2012 SP1

Update2 AS requested here is results from your query. In regards extended events the only sessions running is the default system_health one and 2 SharePoint ones I have just noticed, they must have been put there by default. I may switch these off I wonder if these are causing an issue.

Its interesting that my PREEMPTIVE_XE_GETTARGETSTATE doesn't seem to be in this list.

wait_type   wait_time_ms    signal_wait_time_ms resource_wait_time_ms   percent_total_waits percent_total_signal_waits  percent_total_resource_waits
SP_SERVER_DIAGNOSTICS_SLEEP 300014  355508314   0   24.621089361251698  99.883069863550302  0.000000000000000
MSQL_XP 96782   0   4268999 0.295653861591811   0.000000000000000   0.295653861591811
ASYNC_IO_COMPLETION 56193   64  345552  0.023935987107964   0.000017981341700   0.023931554722962
BACKUPTHREAD    41100   6850    265025  0.018828979257262   0.001924565478840   0.018354575549998
LCK_M_U 40500   71  41030   0.002846491499596   0.000019948050948   0.002841574322484
PWAIT_ALL_COMPONENTS_INITIALIZED    31422   0   94205   0.006524262955146   0.000000000000000   0.006524262955146
XE_LIVE_TARGET_TVF  28050   0   33458   0.002317167771915   0.000000000000000   0.002317167771915
LCK_M_X 4027    50  29195   0.002025392177944   0.000014047923203   0.002021929377161
SQLTRACE_INCREMENTAL_FLUSH_SLEEP    4018    613 355390660   24.612983567922965  0.000172227538471   24.612941113985366
CXPACKET    3756    1   14755   0.001021941767062   0.000000280958464   0.001021872511047

Answer 1

SQL Server works in Non preemtive mode which means that if SQLOS asks it to yeild because it got request from windows OS it will ask SQL server to yeild and SQL Server will listen to it and will yeild or will do as SQLOS has asked it to do. This is because SQL server runs as application and is allocated resources by SQLOS which is monitored by windows O. Preemtive wait types occur when SQL server is executing a task and is interrupted by OS and asked to give up the thread it is using so that can be allocated for other tasks and SQL will do it. It will yeild and will wait till the thread is available this waiting will come under PREEMTIVE-XXX waits.

What is version fo SQL server here is it patched to latest Service pack there was a bug in SQL server 2008 which points incorrect value of preemtive wait types.

Can you run sys.dm_exec_requests DMV and see if the process getting preemtive wait types are suspended or running.

Can you please post output of below query(By Jonathan Kehayias) to capture wait stats

SELECT TOP 10
wait_type ,
max_wait_time_ms wait_time_ms ,
signal_wait_time_ms ,
wait_time_ms - signal_wait_time_ms AS resource_wait_time_ms ,
100.0 * wait_time_ms / SUM(wait_time_ms) OVER ( )
AS percent_total_waits ,
100.0 * signal_wait_time_ms / SUM(signal_wait_time_ms) OVER ( )
AS percent_total_signal_waits ,
100.0 * ( wait_time_ms - signal_wait_time_ms )
/ SUM(wait_time_ms) OVER ( ) AS percent_total_resource_waits
FROM sys.dm_os_wait_stats
WHERE wait_time_ms > 0 -- remove zero wait_time
AND wait_type NOT IN -- filter out additional irrelevant waits
( 'SLEEP_TASK', 'BROKER_TASK_STOP', 'BROKER_TO_FLUSH',
'SQLTRACE_BUFFER_FLUSH','CLR_AUTO_EVENT', 'CLR_MANUAL_EVENT',
'LAZYWRITER_SLEEP', 'SLEEP_SYSTEMTASK', 'SLEEP_BPOOL_FLUSH',
'BROKER_EVENTHANDLER', 'XE_DISPATCHER_WAIT', 'FT_IFTSHC_MUTEX',
'CHECKPOINT_QUEUE', 'FT_IFTS_SCHEDULER_IDLE_WAIT',
'BROKER_TRANSMITTER', 'FT_IFTSHC_MUTEX', 'KSOURCE_WAKEUP',
'LOGMGR_QUEUE', 'ONDEMAND_TASK_QUEUE',
'REQUEST_FOR_DEADLOCK_SEARCH', 'XE_TIMER_EVENT', 'BAD_PAGE_PROCESS',
'DBMIRROR_EVENTS_QUEUE', 'BROKER_RECEIVE_WAITFOR',
'PREEMPTIVE_OS_GETPROCADDRESS', 'PREEMPTIVE_OS_AUTHENTICATIONOPS',
'WAITFOR', 'DISPATCHER_QUEUE_SEMAPHORE', 'XE_DISPATCHER_JOIN',
'RESOURCE_QUEUE' )
ORDER BY wait_time_ms DES

What other processes are running on system is OS under load how many CPU cores does system have ?

EDIT: After user pasted output

The output does not gives and concrete picture use my query. Also are you running extended events traces because i can see XE wait types. I consider this wait type as harmful and it seems you are not facing a issue. Monitoring tools sometimes overreact so with result you posted I would just think its normal behavior.

EDIT2: I dont find any issue with the wait stats output you posted. I also assume your server was not restarted recently otherwise waits stats will not be useful.

Answer 2

The preemptive_xe_* wait types are associated with Extended Events from what I understand and can find. Considering that and your first sentence:

We currently use a monitoring tool which shows us our top wait stats either by number of waiting tasks or total wait time.

I would start looking at your monitoring tools as the culprit. However being that your data from Paul's script shows average wait is low I would not put to much concern into it right now.

Your main challenge here that I think you may be overlooking is your user's told you there was a slow down in the system/application. Most will always point to the database/server as the culprit. My general next question when someone tells me that is "what portion of the system is slow". If they tell me things like pages loading slowly, and they are not actually executing any ad-hoc reports or queries, I ask them to check with the server folks or application admins to ensure nothing else is messed up. Then while they are doing that I will go check the database server performance. However as you have shown if the XE wait type is the only one above 10% or so I don't think the issue is with the database server.

If you want to find the culprit of that wait type you can begin querying sys.dm_os_waitting_tasks, this will show you the session_id and wait that is occurring. You can also use sp_WhoIsActive to get similar information a bit more easily. I would bet you are going to find it to be sessions associated with your monitoring tool.

Answer 3

PreEmptive_XXX wait types are those that are:

Used to indicate a worker is running code that is not under the SQLOS Scheduling Systems

So essentially SQL Server is waiting on external processes to complete before it can continue with it's own processing.

It can be caused by the use of CLR or extended stored procedures, so if you have any of those, I'd start by looking there.