Início / dba / Perguntas / 60830
Accepted
John Russell
Asked: 2014-03-14 03:45:35 +0800 CST

Desempenho do SQL Server: tipo de espera dominante PREEMPTIVE_OS_DELETESECURITYCONTEXT

  • 772

Recebi uma ligação ontem de um cliente reclamando do alto uso da CPU em seu SQL Server. Estamos usando o SQL Server 2012 SE de 64 bits. 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 ter certeza de que o culpado era de fato o SQL Server, dei uma olhada nas principais esperas da instância usando a consulta DMV aqui . As duas primeiras esperas foram: (1) PREEMPTIVE_OS_DELETESECURITYCONTEXTe (2) SOS_SCHEDULER_YIELD.

EDIT : Aqui está o resultado da "consulta de espera superior" (embora alguém tenha reiniciado o servidor esta manhã contra minha vontade):

insira a descrição da imagem aqui

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

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

Os tipos de espera PREEMPTIVE_OS_ são chamadas que deixaram o mecanismo de banco de dados, geralmente para uma API Win32, e executam código fora do SQL Server para várias tarefas. Neste caso, 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 nenhum recurso externo, como servidores vinculados ou tabelas de arquivos. E não fazemos nenhuma representação, etc. Um backup pode ter causado esse pico ou talvez um controlador de domínio com defeito?

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

Editar 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, como você solicitou, aqui estão os resultados de sua consulta. Um pouco diferente do de Paulo:

insira a descrição da imagem aqui

Edit 4: Admito que sou um usuário de eventos estendidos pela primeira vez. 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

sql-server sql-server-2012

2 respostas

  1. Best Answer

    Eu sei que esta questão, com base no título, está principalmente preocupada com o tipo de espera PREEMPTIVE_OS_DELETESECURITYCONTEXT, mas acredito que seja um desvio do verdadeiro problema que é " um cliente que estava reclamando de alto uso de CPU em seu SQL Server ".

    A razão pela qual acredito que o foco nesse tipo de espera específico é uma busca inútil é porque ele aumenta a cada conexão feita. 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 então eu faço qualquer um dos seguintes e executo novamente esta consulta:

    • abrir 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, então devemos olhar o que está rodando para ver quais sessões têm CPU alta:

    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, 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 localizar as consultas de custo mais alto. A primeira consulta abaixo mostrará consultas individuais (mesmo que tenham vários planos) e é ordenada por Average CPU Time, mas você pode facilmente alterar isso para Average Logical Reads. Depois de encontrar uma consulta que parece estar consumindo muitos recursos, copie "sql_handle" e "statement_start_offset" na condição WHERE da segunda consulta abaixo para ver os planos individuais (pode ser mais de 1). Role para a extrema direita e supondo que haja um plano XML, ele será exibido como um link (no modo de grade) que o levará ao visualizador do 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
    • 3

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

    Os 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, você pode querer verificar o gravador de caixa preta, também conhecido como eventos estendidos.

    Você verificou se esses Wait-Types são novos (e em conexão com a alta CPU) ou apenas normais para o seu servidor?

    • 1

relate perguntas