Kinerja SQL Server: PREEMPTIVE_OS_DELETESECURITYCONTEXT tipe tunggu dominan

Saya menerima telepon kemarin dari pelanggan yang mengeluh tentang penggunaan CPU yang tinggi pada SQL Server mereka. Kami menggunakan SQL Server 2012 64 bit SE. Server menjalankan Windows Server 2008 R2 Standard, 2.20 GHz Intel Xeon (4 Cores), RAM 16 GB.

Setelah memastikan bahwa pelakunya sebenarnya adalah SQL Server, saya melihat contoh menunggu menggunakan instance DMV di sini . Dua menunggu teratas adalah: (1) PREEMPTIVE_OS_DELETESECURITYCONTEXTdan (2) SOS_SCHEDULER_YIELD.

EDIT : Ini adalah hasil dari "permintaan tunggu teratas" (walaupun seseorang me-restart server pagi ini atas keinginan saya):

Kami melakukan banyak perhitungan / konversi yang intens, jadi saya bisa mengerti SOS_SCHEDULER_YIELD. Namun, saya sangat ingin tahu tentang PREEMPTIVE_OS_DELETESECURITYCONTEXTjenis menunggu dan mengapa itu mungkin yang tertinggi.

Deskripsi / diskusi terbaik yang dapat saya temukan pada tipe tunggu ini dapat ditemukan di sini . Disebutkan:

Jenis menunggu PREEMPTIVE_OS_ adalah panggilan yang meninggalkan mesin database, biasanya ke Win32 API, dan sedang melakukan kode di luar SQL Server untuk berbagai tugas. Dalam hal ini, ia menghapus konteks keamanan yang sebelumnya digunakan untuk akses sumber daya jarak jauh. API terkait sebenarnya bernama DeleteSecurityContext ()

Sepengetahuan saya, kami tidak memiliki sumber daya eksternal seperti server atau filetables yang ditautkan. Dan kami tidak melakukan peniruan, dll. Mungkinkah cadangan menyebabkan ini lonjakan atau mungkin pengontrol domain yang salah?

Apa yang bisa menyebabkan ini menjadi tipe tunggu yang dominan? Bagaimana saya bisa melacak jenis tunggu ini lebih jauh?

Sunting 2: Saya memeriksa isi Log Keamanan Windows. Saya melihat beberapa entri yang mungkin menarik, tetapi saya tidak yakin apakah ini normal:

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

Sunting 3 : @Jon Seigel, seperti yang Anda minta, berikut adalah hasil dari kueri Anda. Sedikit berbeda dengan Paul:

Sunting 4: Saya akui, saya adalah pengguna Extended Events yang pertama kali. Saya menambahkan jenis tunggu ini ke acara wait_info_external dan melihat ratusan entri. Tidak ada sql teks atau pegangan paket, hanya tumpukan panggilan. Bagaimana saya bisa melacak sumber lebih jauh?

Saya tahu pertanyaan ini, berdasarkan Judul, terutama berkaitan dengan jenis tunggu PREEMPTIVE_OS_DELETESECURITYCONTEXT, tapi saya percaya itu adalah kesalahan arah masalah sebenarnya yaitu " seorang pelanggan yang mengeluh tentang penggunaan CPU yang tinggi pada SQL Server mereka ".

Alasan saya percaya bahwa fokus pada tipe tunggu khusus ini adalah pengejaran angsa liar adalah karena naik untuk setiap koneksi yang dibuat. Saya menjalankan kueri berikut di laptop saya (artinya saya satu-satunya pengguna):

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

Dan kemudian saya melakukan salah satu dari yang berikut dan menjalankan kembali kueri ini:

• buka tab permintaan baru
• tutup tab permintaan baru
• jalankan yang berikut dari prompt DOS: SQLCMD -E -Q "select 1"

Sekarang, kita tahu bahwa CPU tinggi, jadi kita harus melihat apa yang berjalan untuk melihat sesi apa yang memiliki CPU tinggi:

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

Saya biasanya menjalankan kueri di atas sebagaimana adanya, tetapi Anda juga bisa mengganti klausa ORDER BY yang dikomentari untuk melihat apakah itu memberikan hasil yang lebih menarik / bermanfaat.

Atau Anda dapat menjalankan yang berikut ini, berdasarkan dm_exec_query_stats, untuk menemukan kueri dengan biaya tertinggi. Kueri pertama di bawah ini akan menunjukkan kepada Anda permintaan individual (bahkan jika mereka memiliki beberapa paket) dan dipesan oleh Waktu CPU Rata-rata, tetapi Anda dapat dengan mudah mengubahnya menjadi rata-rata Logical Reads. Setelah Anda menemukan kueri yang sepertinya membutuhkan banyak sumber daya, salin "sql_handle" dan "statement_start_offset" ke dalam kondisi WHERE dari kueri kedua di bawah ini untuk melihat paket individual (bisa lebih dari 1). Gulir ke kanan dan anggap ada Rencana XML, itu akan ditampilkan sebagai tautan (dalam Mode Grid) yang akan membawa Anda ke penampil paket jika Anda mengkliknya.

Permintaan # 1: Dapatkan Info Permintaan

;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

Kueri # 2: Dapatkan Info Paket

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

SecurityContext digunakan oleh server sql di beberapa tempat. Salah satu contoh yang Anda beri nama adalah server dan filetable yang ditautkan. Mungkin Anda menggunakan cmdexec? Pekerjaan SQL Server Agent dengan akun proxy? Memanggil layanan web? Sumber daya jarak jauh dapat menjadi banyak hal lucu.

Peristiwa peniruan dapat dicatat dalam peristiwa keamanan windows. Bisa jadi Anda menemukan petunjuk di sana. Selanjutnya Anda mungkin ingin memeriksa perekam blackbox alias acara yang diperpanjang.

Sudahkah Anda memeriksa apakah Jenis Tunggu ini baru (dan terkait dengan cpu tinggi) atau hanya normal untuk server Anda?