As you said, this wait type indicates that the application is not keeping up with SQL Server. Now what that really means is, that SQL Server can't send the data over the network as fast as it would like.
There can be two underlying causes:
- The app is written inefficiently and does not process the rows fast enough.
- The network is maxed out.
If the application itself is too slow there will be no or no significant impact on the performance of other queries. If on the other hand the pipe is too small, other queries can't send their results either and have to wait.
In the latter case however you would have all connections waiting on ASYNC_NETWORK_IO. You should be able to see that impact clearly.
I know this question, based on the Title, is mainly concerned with the PREEMPTIVE_OS_DELETESECURITYCONTEXT wait type, but I believe that is a misdirection of the true issue which is " a customer who was complaining about high CPU usage on their SQL Server ".
The reason I believe that focusing on this specific wait type is a wild goose chase is because it goes up for every connection made. I am running the following query on my laptop (meaning I am the only user):
SELECT *
FROM sys.dm_os_wait_stats
WHERE wait_type = N'PREEMPTIVE_OS_DELETESECURITYCONTEXT'
And then I do any of the following and re-run this query:
- open a new query tab
- close the new query tab
- run the following from a DOS prompt:
SQLCMD -E -Q "select 1"
Now, we know that CPU is high so we should look at what is running to see what sessions have high CPU:
SELECT req.session_id AS [SPID],
req.blocking_session_id AS [BlockedBy],
req.logical_reads AS [LogReads],
DB_NAME(req.database_id) AS [DatabaseName],
SUBSTRING(txt.[text],
(req.statement_start_offset / 2) + 1,
CASE
WHEN req.statement_end_offset > 0
THEN (req.statement_end_offset - req.statement_start_offset) / 2
ELSE LEN(txt.[text])
END
) AS [CurrentStatement],
txt.[text] AS [CurrentBatch],
CONVERT(XML, qplan.query_plan) AS [StatementQueryPlan],
OBJECT_NAME(qplan.objectid, qplan.[dbid]) AS [ObjectName],
sess.[program_name],
sess.[host_name],
sess.nt_user_name,
sess.total_scheduled_time,
sess.memory_usage,
req.*
FROM sys.dm_exec_requests req
INNER JOIN sys.dm_exec_sessions sess
ON sess.session_id = req.session_id
CROSS APPLY sys.dm_exec_sql_text(req.[sql_handle]) txt
OUTER APPLY sys.dm_exec_text_query_plan(req.plan_handle,
req.statement_start_offset,
req.statement_end_offset) qplan
WHERE req.session_id <> @@SPID
ORDER BY req.logical_reads DESC, req.cpu_time DESC
--ORDER BY req.cpu_time DESC, req.logical_reads DESC
I usually run the above query as it is, but you could also switch which ORDER BY clause is commented out to see if that gives more interesting / helpful results.
Alternatively you can run the following, based on dm_exec_query_stats, to find highest-cost queries. The first query below will show you individual queries (even if they have multiple plans) and is ordered by Average CPU Time, but you can easily change that to be Average Logical Reads. Once you find a query that looks like it is taking a lot of resources, copy the "sql_handle" and "statement_start_offset" into the WHERE condition of the second query below to see the individual plans (can be more than 1). Scroll to the far right and assuming there was an XML Plan, it will display as a link (in Grid Mode) which will take you to the plan viewer if you click on it.
Query #1: Get Query Info
;WITH cte AS
(
SELECT qstat.[sql_handle],
qstat.statement_start_offset,
qstat.statement_end_offset,
COUNT(*) AS [NumberOfPlans],
SUM(qstat.execution_count) AS [TotalExecutions],
SUM(qstat.total_worker_time) AS [TotalCPU],
(SUM(qstat.total_worker_time * 1.0) / SUM(qstat.execution_count)) AS [AvgCPUtime],
MAX(qstat.max_worker_time) AS [MaxCPU],
SUM(qstat.total_logical_reads) AS [TotalLogicalReads],
(SUM(qstat.total_logical_reads * 1.0) / SUM(qstat.execution_count)) AS [AvgLogicalReads],
MAX(qstat.max_logical_reads) AS [MaxLogicalReads],
SUM(qstat.total_rows) AS [TotalRows],
(SUM(qstat.total_rows * 1.0) / SUM(qstat.execution_count)) AS [AvgRows],
MAX(qstat.max_rows) AS [MaxRows]
FROM sys.dm_exec_query_stats qstat
GROUP BY qstat.[sql_handle], qstat.statement_start_offset, qstat.statement_end_offset
)
SELECT cte.*,
DB_NAME(txt.[dbid]) AS [DatabaseName],
SUBSTRING(txt.[text],
(cte.statement_start_offset / 2) + 1,
CASE
WHEN cte.statement_end_offset > 0
THEN (cte.statement_end_offset - cte.statement_start_offset) / 2
ELSE LEN(txt.[text])
END
) AS [CurrentStatement],
txt.[text] AS [CurrentBatch]
FROM cte
CROSS APPLY sys.dm_exec_sql_text(cte.[sql_handle]) txt
ORDER BY cte.AvgCPUtime DESC
Query #2: Get Plan Info
SELECT *,
DB_NAME(qplan.[dbid]) AS [DatabaseName],
CONVERT(XML, qplan.query_plan) AS [StatementQueryPlan],
SUBSTRING(txt.[text],
(qstat.statement_start_offset / 2) + 1,
CASE
WHEN qstat.statement_end_offset > 0
THEN (qstat.statement_end_offset - qstat.statement_start_offset) / 2
ELSE LEN(txt.[text])
END
) AS [CurrentStatement],
txt.[text] AS [CurrentBatch]
FROM sys.dm_exec_query_stats qstat
CROSS APPLY sys.dm_exec_sql_text(qstat.[sql_handle]) txt
OUTER APPLY sys.dm_exec_text_query_plan(qstat.plan_handle,
qstat.statement_start_offset,
qstat.statement_end_offset) qplan
-- paste info from Query #1 below
WHERE qstat.[sql_handle] = 0x020000001C70C614D261C85875D4EF3C90BD18D02D62453800....
AND qstat.statement_start_offset = 164
-- paste info from Query #1 above
ORDER BY qstat.total_worker_time DESC
Best Answer
OLEDB waits cover a variety of states, including (but not limited too) client-side profiler traces, some DBCC commands, materialisation of DMVs, possibly some full-text functions in 2005 (IIRC, most have been split out to FT specific waits in 2008) and also linked server queries as you mentioned.
I'm not aware of UDF functions inherently resulting in OLEDB waits, unless they are performing one of the actions I mentioned above.
Rather than looking at the raw percentage wait time attributed to OLEDB, have you checked the average wait time per wait? It may prove to be so low as to be insignificant.