Desempenho do SQL Server: PREEMPTIVE_OS_DELETESECURITYCONTEXT tipo de espera dominante

8

Ontem recebi uma ligação de um cliente que estava reclamando sobre o alto uso da CPU no SQL Server. Estamos usando o SQL Server 2012 de 64 bits SE. O servidor está executando o Windows Server 2008 R2 Standard, Intel Xeon de 2,20 GHz (4 núcleos), 16 GB de RAM.

Depois de me certificar de que o culpado era de fato o SQL Server, observei as principais esperas da instância usando a consulta DMV aqui . As duas principais esperas foram: (1) PREEMPTIVE_OS_DELETESECURITYCONTEXTe (2) SOS_SCHEDULER_YIELD.

Edição : Aqui está o resultado da "consulta superior aguarda" (embora alguém tenha reiniciado o servidor esta manhã contra a minha vontade):

insira a descrição da imagem aqui

Fazemos muitos cálculos / conversões intensas, para que eu possa entender SOS_SCHEDULER_YIELD. No entanto, estou muito curioso sobre o PREEMPTIVE_OS_DELETESECURITYCONTEXTtipo de espera e por que ele pode ser o mais alto.

A melhor descrição / discussão que posso encontrar sobre esse tipo de espera pode ser encontrada aqui . Menciona:

Os tipos de espera PREEMPTIVE_OS_ são chamadas que deixaram o mecanismo de banco de dados, normalmente para uma API Win32, e executam código fora do SQL Server para várias tarefas. Nesse caso, ele está excluindo um contexto de segurança usado anteriormente para acesso remoto a recursos. A API relacionada é na verdade chamada DeleteSecurityContext ()

Que eu saiba, não temos recursos externos, como servidores vinculados ou tabelas de arquivos. E não fazemos representação etc. O backup pode ter causado um pico ou talvez um controlador de domínio com defeito?

O que diabos poderia fazer com que este seja o tipo de espera dominante? Como posso acompanhar ainda mais esse tipo de espera?

Edição 2: verifiquei o conteúdo do log de segurança do Windows. Vejo algumas entradas que podem ser interessantes, mas não tenho certeza se são normais:

Special privileges assigned to new logon.

Subject:
    Security ID:        NT SERVICE\MSSQLServerOLAPService
    Account Name:       MSSQLServerOLAPService
    Account Domain:     NT Service
    Logon ID:       0x3143c

Privileges:     SeImpersonatePrivilege

Special privileges assigned to new logon.

Subject:
    Security ID:        NT SERVICE\MSSQLSERVER
    Account Name:       MSSQLSERVER
    Account Domain:     NT Service
    Logon ID:       0x2f872

Privileges:     SeAssignPrimaryTokenPrivilege
            SeImpersonatePrivilege

Editar 3 : @Jon Seigel, conforme solicitado, eis os resultados da sua consulta. Um pouco diferente do de Paulo:

insira a descrição da imagem aqui

Edição 4: Admito que sou o primeiro usuário de Eventos Estendidos. Adicionei esse tipo de espera ao evento wait_info_external e vi centenas de entradas. Não há texto sql ou identificador de plano, apenas uma pilha de chamadas. Como posso rastrear ainda mais a fonte?

insira a descrição da imagem aqui

John Russell
fonte
John, você pode executar sp_whoisactive por um período de tempo (talvez um minuto) e ver o que aparece? Isso pode ajudar a direcionar você / nós para uma solução. sqlblog.com/files/default.aspx #
Mark Wilkinson #
Olá John, na sua pergunta você menciona ter identificado o SQL Server como o culpado. Você poderia descrever os passos que você tomou para chegar a essa conclusão?
Craig Efrein 19/03/2014

Respostas:

3

Sei que esta pergunta, com base no título, está principalmente preocupada com o tipo de espera PREEMPTIVE_OS_DELETESECURITYCONTEXT, mas acredito que essa é uma indicação incorreta do verdadeiro problema que é " um cliente que estava reclamando sobre o alto uso da CPU no SQL Server ".

A razão pela qual acredito que o foco nesse tipo de espera específico é uma loucura, é porque ele aumenta para todas as conexões feitas. Estou executando a seguinte consulta no meu laptop (o que significa que sou o único usuário):

SELECT * 
FROM sys.dm_os_wait_stats
WHERE wait_type = N'PREEMPTIVE_OS_DELETESECURITYCONTEXT'

E, em seguida, execute um dos seguintes procedimentos e execute novamente esta consulta:

  • abra uma nova guia de consulta
  • feche a nova guia de consulta
  • execute o seguinte em um prompt do DOS: SQLCMD -E -Q "select 1"

Agora, sabemos que a CPU está alta, portanto, devemos analisar o que está sendo executado para ver quais sessões têm alta 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

Normalmente, eu executo a consulta acima como está, mas você também pode alternar qual cláusula ORDER BY é comentada para ver se isso fornece resultados mais interessantes / úteis.

Como alternativa, você pode executar o seguinte, com base em dm_exec_query_stats, para encontrar consultas de custo mais alto. A primeira consulta abaixo mostrará consultas individuais (mesmo que tenham vários planos) e é ordenada pelo tempo médio da CPU, mas você pode facilmente mudar para leituras lógicas médias. Depois de encontrar uma consulta que parece consumir muitos recursos, copie "sql_handle" e "statement_start_offset" para a condição WHERE da segunda consulta abaixo para ver os planos individuais (pode ser maior que 1). Role para a extrema direita e, assumindo que havia um plano XML, ele será exibido como um link (no modo de grade) que o levará ao visualizador de plano se você clicar nele.

Consulta nº 1: obter informações da consulta

;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

Consulta nº 2: obter informações do plano

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
Solomon Rutzky
fonte
Eu pensei que o tipo de espera com classificação mais alta do script de Paul, ou seja, PREEMPTIVE_OS_DELETESECURITYCONTEXT, poderia ser a causa da alta CPU. Isso pode ser considerado com segurança um tipo de espera benigna no nosso caso? Em nosso aplicativo, temos alguns serviços do Windows que enviam constantemente comandos (procs armazenados armazenados exec) para o SQL Server. Não consigo discernir muitos padrões de sys.dm_exec_sessions - as sessões não ficam abertas por muito tempo e existem muitos deles. O sys.dm_exec_query_stats fornece algumas informações boas sobre os procs armazenados mais caros, tanto quanto o custo geral da CPU. Este pode ser um bom lugar para começar.
John Russell
Eu só queria ter certeza de que não estava perdendo algo com PREEMPTIVE_OS_DELETESECURITYCONTEXT. Eu não sabia se isso poderia ser rastreado para um controlador de domínio com defeito ou pesquisas do AD?
John Russell
@ JohnRussell: Eu acho que o tipo de espera mais alto normalmente é um bom lugar para começar, mas meu argumento é que esse em particular não é apenas acionado pelo código no SQL Server acessando recursos externos, como o Linked Server ou o SQLCLR ou procs armazenados estendidos (por exemplo, xp_dirtree), portanto, o volume alto não é um indicador verdadeiro. E mesmo se houver latência na rede causando atrasos, isso realmente elevaria a CPU ou apenas aumentaria o bloqueio? E bom ponto, use query_stats. Vou atualizar minha consulta mais tarde com isso.
Solomon Rutzky
11
@ JohnRussell: em relação aos seus "serviços do Windows que estão constantemente enviando comandos", algo mudou recentemente? Eles estão fechando corretamente as conexões? Eles limpam corretamente a conexão se erro durante a conexão? Além disso, você reconstruiu índices recentemente ou pelo menos estatísticas atualizadas em todas as tabelas? Não fazer isso pode levar ao aumento da CPU.
Solomon Rutzky
Obrigado pela compreensão! À medida que olho mais para sys.dm_exec_query_stats e fragmentação de índice em algumas tabelas principais, estou começando a me sentir mais confiante sobre a causa. PREEMPTIVE_OS_DELETESECURITYCONTEXT acabou de me jogar fora.
John Russell
1

O SecurityContext é usado pelo servidor sql em vários locais. Um exemplo que você nomeou são os servidores e as tabelas de arquivos vinculados. Talvez você esteja usando o cmdexec? Trabalhos do SQL Server Agent com contas proxy? Chamando um serviço da web? Recursos remotos podem ser um monte de coisas engraçadas.

Eventos de representação podem ser registrados no evento de segurança do Windows. Pode ser que você esteja encontrando uma pista lá. Além disso, convém verificar o gravador de caixa preta, também conhecido como eventos estendidos.

Você verificou se esses tipos de espera são novos (e em conexão com a CPU alta) ou são normais para o seu servidor?

Jens W.
fonte
Não temos trabalhos do SQL Server Agent nem WebServices. Limpei as estatísticas de espera e executei novamente a consulta original acima, e estatísticas semelhantes ressurgiram. Demorei um pouco para descobrir como reconfigurar a sessão de evento estendida system_health para incluir wait_info_external for waittype = 'PREEMPTIVE_OS_DELETESECURITYCONTEXT', mas finalmente consegui adicioná-lo, posso ver centenas desses eventos nos poucos segundos em que observava os dados ao vivo . Estou procurando uma maneira de decifrar melhor a fonte. Algum conselho sobre como rastrear isso?
John Russell